PerfView專題 (第十四篇)：洞察那些 C# 代碼中的短命線程

## 一：背景 ### 1. 講故事這篇文章源自於分析一些疑難dump的思考而產生的靈感，在dump分析中經常要尋找的一個答案就是如何找到死亡線程的生前都做了一些什麼？參考如下輸出： ``` C# 0:001> !t ThreadCount: 22 UnstartedThread: 0 Backg ...

一：背景

1. 講故事

這篇文章源自於分析一些疑難dump的思考而產生的靈感，在dump分析中經常要尋找的一個答案就是如何找到死亡線程的生前都做了一些什麼？參考如下輸出：


0:001> !t
ThreadCount:      22
UnstartedThread:  0
BackgroundThread: 1
PendingThread:    0
DeadThread:       20
Hosted Runtime:   no
                                                                         Lock  
       ID OSID ThreadOBJ    State GC Mode     GC Alloc Context  Domain   Count Apt Exception
   0    1 3a74 00efb368     2a020 Preemptive  02F2AF48:00000000 00ec2fa0 1     MTA 
   5    2 6758 00f07a48     2b220 Preemptive  00000000:00000000 00ec2fa0 0     MTA (Finalizer) 
XXXX    3    0 00f31df0   1039820 Preemptive  00000000:00000000 00ec2fa0 0     Ukn (Threadpool Worker) 
XXXX    4    0 00f34080   1039820 Preemptive  00000000:00000000 00ec2fa0 0     Ukn (Threadpool Worker) 
XXXX    5    0 00f363a8   1039820 Preemptive  00000000:00000000 00ec2fa0 0     Ukn (Threadpool Worker) 
XXXX    6    0 00f372e8   1039820 Preemptive  00000000:00000000 00ec2fa0 0     Ukn (Threadpool Worker) 
XXXX    7    0 00f39f80   1039820 Preemptive  00000000:00000000 00ec2fa0 0     Ukn (Threadpool Worker) 
XXXX    8    0 00f3cbd0   1039820 Preemptive  00000000:00000000 00ec2fa0 0     Ukn (Threadpool Worker) 
XXXX    9    0 00f3d128   1039820 Preemptive  00000000:00000000 00ec2fa0 0     Ukn (Threadpool Worker) 
XXXX   10    0 00f40630   1039820 Preemptive  00000000:00000000 00ec2fa0 0     Ukn (Threadpool Worker) 
XXXX   11    0 00f43310   1039820 Preemptive  00000000:00000000 00ec2fa0 0     Ukn (Threadpool Worker) 
XXXX   12    0 00f42db8   1039820 Preemptive  00000000:00000000 00ec2fa0 0     Ukn (Threadpool Worker) 
XXXX   13    0 00f49180   1039820 Preemptive  00000000:00000000 00ec2fa0 0     Ukn (Threadpool Worker) 
XXXX   14    0 00f4a228   1039820 Preemptive  00000000:00000000 00ec2fa0 0     Ukn (Threadpool Worker) 
XXXX   15    0 00f53a28   1039820 Preemptive  00000000:00000000 00ec2fa0 0     Ukn (Threadpool Worker) 
XXXX   16    0 00f56598   1039820 Preemptive  00000000:00000000 00ec2fa0 0     Ukn (Threadpool Worker) 
XXXX   17    0 00f59180   1039820 Preemptive  00000000:00000000 00ec2fa0 0     Ukn (Threadpool Worker) 
XXXX   18    0 00f59b28   1039820 Preemptive  00000000:00000000 00ec2fa0 0     Ukn (Threadpool Worker) 
XXXX   19    0 00f5e8a0   1039820 Preemptive  00000000:00000000 00ec2fa0 0     Ukn (Threadpool Worker) 
XXXX   20    0 00f5f248   1039820 Preemptive  00000000:00000000 00ec2fa0 0     Ukn (Threadpool Worker) 
XXXX   21    0 00f63fc0   1039820 Preemptive  00000000:00000000 00ec2fa0 0     Ukn (Threadpool Worker) 
XXXX   22    0 00f66b50   1039820 Preemptive  00000000:00000000 00ec2fa0 0     Ukn (Threadpool Worker)

前面的 XXXX 代表線程已死亡，那誰能告訴我 ID=22 的線程生前執行了什麼代碼呢？其實去年我寫了一篇如何用 WinDbg 去尋找程式中的短命線程。 TTD 專題 (第一篇)：C# 那些短命線程都在乾什麼？

雖然可以用 WinDbg 的 TTD 來解決，但也有很多的限制，諸如：

生產環境不能安裝 windbg 或者安裝不上
不能對生產程式進行附加

所以這兩點也制約了 TTD 的強大威力，那有沒有輕量級以及無侵入的方式洞察呢？最近在看 perfview 的文檔，發現完全可以使用內核中Thread 的 ETW相關事件來搞定。

二：Thread 的ETW事件

1. 使用 Thread 的短命線程

如果死亡線程背後沒有標記 Threadpool Worker 的話，那就說明是代碼自己用 new Thread 創建出來的線程，這種比較簡單，觀察 Windows Kernel/Thread/Start 或者 Microsoft-Windows-DotNETRunning/Thread/Creating 的ETW事件即可。

接下來寫一段簡單的案例代碼：


    internal class Program
    {
        static void Main(string[] args)
        {
            for (int i = 0; i < 5000; i++)
            {
                Test1();
            }

            Console.ReadLine();
        }
        public static int index = 1;

        public static void Test1()
        {
            new Thread(() => { Test2(); }).Start();
        }

        public static void Test2()
        {
            Thread.Sleep(10);

            var i = 10;
            var j = 20;

            var sum = i + j;

            Console.WriteLine($"i={index++},sum={sum}");
        }
    }

代碼非常簡單，用 new Thread 創建了一個短命線程，接下來打開 Perfview 使用預設配置，完整的 Command 命令如下：


PerfView.exe  "/DataFile:PerfViewData.etl" /BufferSizeMB:256 /StackCompression /CircularMB:500 /ClrEvents:GC,Binder,Security,AppDomainResourceManagement,Contention,Exception,Threading,JITSymbols,Type,GCHeapSurvivalAndMovement,GCHeapAndTypeNames,Stack,ThreadTransfer,Codesymbols,Compilation /NoGui /NoNGenRundown /Merge:True /Zip:True collect

程式跑完後可以用 WinDbg 的 !t 去看看凌亂現場，可以發現有大量的 XXX 線程。


0:008> !t
ThreadCount:      1386
UnstartedThread:  0
BackgroundThread: 2
PendingThread:    0
DeadThread:       1383
Hosted Runtime:   no
                                                                             Lock  
 DBG   ID     OSID ThreadOBJ    State GC Mode     GC Alloc Context  Domain   Count Apt Exception
   0    1     4114 02CAC9C8     2a020 Preemptive  0559F108:0559FFEC 02c9c488 -00001 MTA 
   6    2     31b4 02CBA5F0     2b220 Preemptive  00000000:00000000 02c9c488 -00001 MTA (Finalizer) 
XXXX    3        0 02CCEC48     39820 Preemptive  00000000:00000000 02c9c488 -00001 Ukn 
XXXX  694        0 116C5B18     39820 Preemptive  00000000:00000000 02c9c488 -00001 Ukn 
XXXX  695        0 116C0578     39820 Preemptive  00000000:00000000 02c9c488 -00001 Ukn 
XXXX  696        0 116C1250     39820 Preemptive  00000000:00000000 02c9c488 -00001 Ukn 
XXXX  697        0 116BF8A0     39820 Preemptive  00000000:00000000 02c9c488 -00001 Ukn 
XXXX  698        0 116C5F60     39820 Preemptive  00000000:00000000 02c9c488 -00001 Ukn 
XXXX  699        0 116C38D8     39820 Preemptive  00000000:00000000 02c9c488 -00001 Ukn 
XXXX  700        0 116C74C8     39820 Preemptive  00000000:00000000 02c9c488 -00001 Ukn 
...
XXXX 1380        0 115097C0     39820 Preemptive  00000000:00000000 02c9c488 -00001 Ukn 
XXXX 1381        0 115079C8     39820 Preemptive  00000000:00000000 02c9c488 -00001 Ukn 
XXXX 1382        0 1150B170     39820 Preemptive  00000000:00000000 02c9c488 -00001 Ukn 
XXXX 1383        0 1150AD28     39820 Preemptive  00000000:00000000 02c9c488 -00001 Ukn 
XXXX 1384        0 11508258     39820 Preemptive  00000000:00000000 02c9c488 -00001 Ukn 
XXXX 1385        0 11505BD0     39820 Preemptive  00000000:00000000 02c9c488 -00001 Ukn 
   7 1386     6114 1150CF68     20220 Preemptive  055A07A8:055A1FEC 02c9c488 -00001 Ukn

收集一會之後停止收集，選中Thread的內核事件 Thread/Start，截圖如下：

從卦中可以看到有大量的 Start 事件，我們挑選其中一個觀察下線程棧，右鍵 Open Any Stacks 看看到底是什麼代碼發出了這個 ETW 事件，截圖如下：

從卦中可以清晰的看到，原來是 Main() -> Test1() 方法創建的哈，終於水落石出。

2. 使用 ThreadPool 的短命線程

在真實場景中也有很多代碼是用 ThreadPool 創建出來的短命線程，這種短命線程其實有一個特點，那就是曾經有大量的任務進隊列，導致 ThreadPool 被迫生成很多的線程來應付，當任務全部被消滅後，ThreadPool 就會把那些被迫生成的線程全部給裁掉。

卸磨殺驢，真的好像我們的職場/(ㄒoㄒ)/~~。

所以突破點就是統計下 ThreadPoolEnqueueWork 事件，有了思路之後修改下測試代碼。


        public static void Test1()
        {
            Task.Run(() => { Test2(); });
        }

這裡有一個註意點，程式跑完之後還要稍等一兩分鐘，就是讓ThreadPool把多餘的Thread給滅掉，用 windbg 觀察到的效果圖就是 講故事 那一節的，停止 perfview 收集後,尋找 ThreadPoolEnqueueWork 事件，截圖如下：

從卦中可以看到有大量的 ThreadPoolEnqueueWork 事件，接下來可以選擇右鍵菜單 Save View as Excel 導出到 Excel 中，然後對 Time Msec 進行分組排序，看下哪一個時間段有大量的任務進隊列，指標高的時間段自然就是重點懷疑的。

這裡要說一點 Time MSec 是 Trace Start Time 基礎上的毫秒級偏移值。

舉個例子: 4377.032 (4.37s) + 15:56:25.566 = 15:56:29.866

有了這些概念之後，找到問題區域的進隊任務，觀察下調用棧，大概率也能找到問題，從調用棧來看，原來是 Test1() 所致哈。。。截圖如下：

三：總結

相比WinDbg TTD的重模式，Perfiew真的很輕，而且無侵入性，這兩個工具真的是珠聯璧合，相得益彰。

PerfView專題 (第十四篇)： 洞察那些 C# 代碼中的短命線程