PerfView專題 (第十四篇)： 洞察那些 C# 程式碼中的短命執行緒
一：背景
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真的很輕，而且無侵入性，這兩個工具真的是珠聯璧合，相得益彰。
