一：背景
1. 講故事
這篇文章源自于分析一些疑難dump的思考而產(chǎn)生的靈感，在dump分析中經(jīng)常要尋找的一個答案就是如何找到死亡線程的生前都做了一些什么？參考如下輸出：
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 的線程生前執(zhí)行了什么代碼呢？其實(shí)去年我寫了一篇如何用 WinDbg 去尋找程序中的短命線程。 TTD 專題 (第一篇)：C# 那些短命線程都在干什么？
雖然可以用 WinDbg 的 TTD 來解決，但也有很多的限制，諸如：
- 生產(chǎn)環(huán)境不能安裝 windbg 或者 安裝不上
- 不能對生產(chǎn)程序進(jìn)行附加
所以這兩點(diǎn)也制約了 TTD 的強(qiáng)大威力，那有沒有輕量級以及無侵入的方式洞察呢？最近在看 perfview 的文檔，發(fā)現(xiàn)完全可以使用內(nèi)核中Thread 的 ETW相關(guān)事件來搞定。
二：Thread 的ETW事件
1. 使用 Thread 的短命線程
如果死亡線程背后沒有標(biāo)記 Threadpool Worker 的話，那就說明是代碼自己用 new Thread 創(chuàng)建出來的線程，這種比較簡單，觀察 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 創(chuàng)建了一個短命線程，接下來打開 Perfview 使用默認(rèn)配置，完整的 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 去看看凌亂現(xiàn)場，可以發(fā)現(xiàn)有大量的 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的內(nèi)核事件 Thread/Start，截圖如下：
從卦中可以看到有大量的 Start 事件，我們挑選其中一個觀察下線程棧，右鍵 Open Any Stacks 看看到底是什么代碼發(fā)出了這個 ETW 事件，截圖如下：
從卦中可以清晰的看到，原來是 Main() -> Test1() 方法創(chuàng)建的哈，終于水落石出。
2. 使用 ThreadPool 的短命線程
在真實(shí)場景中也有很多代碼是用 ThreadPool 創(chuàng)建出來的短命線程，這種短命線程其實(shí)有一個特點(diǎn)，那就是曾經(jīng)有大量的任務(wù)進(jìn)隊(duì)列，導(dǎo)致 ThreadPool 被迫生成很多的線程來應(yīng)付，當(dāng)任務(wù)全部被消滅后，ThreadPool 就會把那些被迫生成的線程全部給裁掉。
卸磨殺驢，真的好像我們的職場/(ㄒoㄒ)/~~。
所以突破點(diǎn)就是統(tǒng)計(jì)下 ThreadPoolEnqueueWork 事件，有了思路之后修改下測試代碼。
public static void Test1()
{
Task.Run(() => { Test2(); });
}
這里有一個注意點(diǎn)，程序跑完之后還要稍等一兩分鐘，就是讓ThreadPool把多余的Thread給滅掉，用 windbg 觀察到的效果圖就是 講故事 那一節(jié)的，停止 perfview 收集后,尋找 ThreadPoolEnqueueWork 事件，截圖如下：
從卦中可以看到有大量的 ThreadPoolEnqueueWork 事件，接下來可以選擇右鍵菜單 Save View as Excel 導(dǎo)出到 Excel 中，然后對 Time Msec 進(jìn)行分組排序，看下哪一個時間段有大量的任務(wù)進(jìn)隊(duì)列，指標(biāo)高的時間段自然就是重點(diǎn)懷疑的。
這里要說一點(diǎn) Time MSec 是 Trace Start Time 基礎(chǔ)上的毫秒級偏移值。
舉個例子: 4377.032 (4.37s) + 15:56:25.566 = 15:56:29.866
有了這些概念之后，找到問題區(qū)域的進(jìn)隊(duì)任務(wù)，觀察下調(diào)用棧，大概率也能找到問題，從調(diào)用棧來看，原來是 Test1() 所致哈。。。 截圖如下：
文章來源：http://www.zghlxwxcb.cn/news/detail-581072.html
三：總結(jié)
相比WinDbg TTD的重模式，Perfiew真的很輕，而且無侵入性，這兩個工具真的是珠聯(lián)璧合，相得益彰。文章來源地址http://www.zghlxwxcb.cn/news/detail-581072.html
到了這里，關(guān)于PerfView專題 (第十四篇)： 洞察那些 C# 代碼中的短命線程的文章就介紹完了。如果您還想了解更多內(nèi)容，請?jiān)谟疑辖撬阉鱐OY模板網(wǎng)以前的文章或繼續(xù)瀏覽下面的相關(guān)文章，希望大家以后多多支持TOY模板網(wǎng)！
