TTD 專題 (第一篇)：C# 那些短命執行緒都在幹什麼？
2022-10-06 12:01:49
一：背景
1.講故事
在分析的眾多dump中，經常會遇到各種奇葩的問題，僅通過dump這種快照形式還是有很多問題搞不定，而通過 perfview 這種粒度又太粗，很難找到問題之所在，真的很頭疼，比如本篇的 短命執行緒 問題，參考圖如下：
我們在 t2 時刻抓取的dump對檢視 短命執行緒 毫無幫助，我根本就不知道這個執行緒生前執行了什麼程式碼，為什麼這麼短命，還就因為這樣的短命讓 執行緒池 的執行緒暴增。
為了能盡最大努力解決此類問題，武器庫中還得再充實一下，比如本系列要聊的 Time Travel Debug，即時間旅行偵錯。
二： Time Travel Debug
1. 什麼是 時間旅行偵錯
如果說 dump 是程式的一張照片，那 TTD 就是程式的一個短視訊，很顯然短視訊的資訊量遠大於一張照片，因為視訊記錄著疑難雜症的前因後果，參考價值巨大，簡直就是銀彈般的存在。
三：案例演示
1. 參考程式碼
這是我曾經遇到的一個真實案例，在沒有 TTD 的協助下最終也艱難的找到了問題，但如果有 TTD 的協助簡直就可以秒殺，為了方便說明，先上一個測試程式碼。
internal class Program
{
static void Main(string[] args)
{
for (int i = 0; i < 200; i++)
{
Task.Run(() =>
{
Test();
});
}
Console.ReadLine();
}
public static int index = 1;
static void Test()
{
Thread.Sleep(1000);
var i = 10;
var j = 20;
var sum = i + j;
Console.WriteLine($"i={index++},sum={sum}");
}
}
程式跑完之後，我們抓一個dump檔案，輸出如下。
0:000> !t
ThreadCount: 20
UnstartedThread: 0
BackgroundThread: 7
PendingThread: 0
DeadThread: 13
Hosted Runtime: no
Lock
DBG ID OSID ThreadOBJ State GC Mode GC Alloc Context Domain Count Apt Exception
0 1 12f8 00C4AF20 80030220 Preemptive 03C3FFAC:03C40000 00c462f8 -00001 Ukn
6 2 6a70 00C5BBD8 2b220 Preemptive 03C521B8:03C53FE8 00c462f8 -00001 MTA (Finalizer)
XXXX 4 0 00C9FEB0 1039820 Preemptive 00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
7 5 6694 00CA0990 302b220 Preemptive 03C40314:03C41FE8 00c462f8 -00001 MTA (Threadpool Worker)
XXXX 6 0 00CB53B8 1039820 Preemptive 00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
XXXX 7 0 00CB5958 1039820 Preemptive 00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
XXXX 8 0 00CB4338 1039820 Preemptive 00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
XXXX 9 0 00CB4C58 1039820 Preemptive 00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
XXXX 10 0 08879278 1039820 Preemptive 00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
8 11 5d10 08879E90 102b220 Preemptive 03C2AC2C:03C2BFE8 00c462f8 -00001 MTA (Threadpool Worker)
XXXX 12 0 0887D1F8 1039820 Preemptive 00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
XXXX 13 0 0887C0D8 1039820 Preemptive 00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
XXXX 14 0 0887AB70 1039820 Preemptive 00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
XXXX 15 0 0887B400 1039820 Preemptive 00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
XXXX 16 0 0887D640 1039820 Preemptive 00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
XXXX 17 0 0887A728 1039820 Preemptive 00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
9 18 5658 0887C520 102b220 Preemptive 03C46684:03C47FE8 00c462f8 -00001 MTA (Threadpool Worker)
10 19 564 0887C968 102b220 Preemptive 03C4A664:03C4BFE8 00c462f8 -00001 MTA (Threadpool Worker)
XXXX 20 0 0887AFB8 1039820 Preemptive 00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
11 3 547c 0887A2E0 2b220 Preemptive 03C50008:03C51FE8 00c462f8 -00001 MTA
2. 為什麼會有很多短命執行緒
從 windbg 的輸出看有很多的 XXX，那原因是什麼呢？ 還得先觀察下程式碼，可以看到程式碼會給 ThreadPool 分發 100 次任務，每個任務也就 1s 的執行時間，這樣的程式碼會造成 ThreadPool 的工作執行緒處理不及繼而會產生更多的工作執行緒，在某一時刻那些 Sleep 後的執行緒又會規模性喚醒，ThreadPool 為了能夠平衡工作者執行緒，就會滅掉很多的執行緒，造成 ThreadPool 中的暴漲暴跌現象。
因果關係是搞清楚了，但對於落地是沒有任何幫助的，比如執行緒列表倒數第二行已死掉的執行緒：
XXXX 20 0 0887AFB8 1039820 Preemptive 00000000:00000000 00c462f8 -00001 Ukn (Threadpool Worker)
你是沒法讓它起死回生的，對吧？這時候就必須藉助 TTD 錄製一個小視訊。
3. TTD 錄製
錄製非常簡單，選擇 Lauch executable (advanced) 項再勾選 Record 即可，截圖如下：
等程式執行完了或者你覺得時機合適再點選 Stop and Debug 停止錄製，截圖如下：
稍等片刻，你會得到如下三個檔案。
- ConsoleApp101.run 錄製檔案
- ConsoleApp101.idx 錄製的索引檔案
- ConsoleApp101.out 紀錄檔檔案
4. 分析思路
- 找到 tid=20 的 OSID 執行緒ID
因為此時的 tid=20 的 OSID 已經不存在了，所以用 !tt 在時間刻度上折半查詢 OSID 存在的 position。
0:007> !tt 94
Setting position to 94% into the trace
Setting position: 396DB:0
(5ac8.20): Break instruction exception - code 80000003 (first/second chance not available)
Time Travel Position: 396DB:0
eax=00be602c ebx=00c7c2b0 ecx=00be6028 edx=0024e000 esi=00be6028 edi=00000000
eip=77d8e925 esp=07acf1c8 ebp=07acf1c8 iopl=0 nv up ei pl nz na po nc
cs=0023 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00000202
ntdll!RtlEnterCriticalSection+0x15:
77d8e925 f00fba3000 lock btr dword ptr [eax],0 ds:002b:00be602c=ffffffff
0:007> !t
ThreadCount: 20
UnstartedThread: 0
BackgroundThread: 19
PendingThread: 0
DeadThread: 0
Hosted Runtime: no
Lock
DBG ID OSID ThreadOBJ State GC Mode GC Alloc Context Domain Count Apt Exception
...
24 20 145c 0887AFB8 302b220 Preemptive 03C4C1A4:03C4DFE8 00c462f8 -00001 MTA (Threadpool Worker)
可以清楚的看到原來是 OSID =145c 及WindbgID=24 有了這個資訊不代表此時它正在執行託管方法，所以我們還需要找到這個 145c 是何時出生的？
- 找到當前視訊中所有的
ThreadCreated事件。
可以在 Events 輸出資訊中檢索 id=0x145c 的執行緒出生資訊。
0:024> dx -r2 @$curprocess.TTD.Events.Where(t => t.Type == "ThreadCreated").Select(t => t.Thread).Where(t=>t.Id==0x145c).Select(t=>t)
@$curprocess.TTD.Events.Where(t => t.Type == "ThreadCreated").Select(t => t.Thread).Where(t=>t.Id==0x145c).Select(t=>t)
[0x0] : UID: 27, TID: 0x145C
UniqueId : 0x1b
Id : 0x145c
Lifetime : [38B21:0, 3BB45:0]
ActiveTime : [38B6A:0, 3BB45:0]
GatherMemoryUse [Gather inputs, outputs and memory used by a range of execution within a thread]
從輸出中可以看到, Lifetime 表示這個執行緒的一生, ActiveTime 則是從執行緒的Start處開始的，畫個圖如下：
接下來將進度條調到 !tt 38B21:0 處，那如何看程式碼進入到託管方法中呢？這個就得各顯神通，我知道的有這麼幾種。
- 使用單步偵錯
先用 !tt 調整大致範圍，然後用 p,pc,pt,t,tc,tt 微調，比如我們這篇的 !tt 94 就能獲取到 tid=20 號執行緒的託管部分。
0:024> !tt 94
Setting position to 94% into the trace
Setting position: 396DB:0
(5ac8.20): Break instruction exception - code 80000003 (first/second chance not available)
Time Travel Position: 396DB:0
eax=00be602c ebx=00c7c2b0 ecx=00be6028 edx=0024e000 esi=00be6028 edi=00000000
eip=77d8e925 esp=07acf1c8 ebp=07acf1c8 iopl=0 nv up ei pl nz na po nc
cs=0023 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00000202
ntdll!RtlEnterCriticalSection+0x15:
77d8e925 f00fba3000 lock btr dword ptr [eax],0 ds:002b:00be602c=ffffffff
0:007> ~24s
eax=00000000 ebx=0b1bfab8 ecx=00000000 edx=00000000 esi=00000001 edi=0b1bfab8
eip=77dc196c esp=0b1bfa78 ebp=0b1bfadc iopl=0 nv up ei pl nz na pe nc
cs=0023 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00000206
ntdll!NtDelayExecution+0xc:
77dc196c c20800 ret 8
0:024> !clrstack
OS Thread Id: 0x145c (24)
Child SP IP Call Site
0B1BFB50 77dc196c [HelperMethodFrame: 0b1bfb50] System.Threading.Thread.SleepInternal(Int32)
0B1BFBBC 07b90694
0B1BFBD0 03b99078 ConsoleApp1.Program.Test()
0B1BFC04 03b98a03 ConsoleApp1.Program+c.b__0_0()
0B1BFC10 07b9065d System.Threading.Tasks.Task.InnerInvoke() [/_/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs @ 2387]
0B1BFC1C 07b900cd System.Threading.Tasks.Task+c.<.cctor>b__272_0(System.Object) [/_/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs @ 2375]
0B1BFC24 07b90047 System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(System.Threading.Thread, System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) [/_/src/libraries/System.Private.CoreLib/src/System/Threading/ExecutionContext.cs @ 268]
0B1BFC54 07b907d2 System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef, System.Threading.Thread) [/_/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs @ 2337]
0B1BFCB8 03b9ff34 System.Threading.Tasks.Task.ExecuteEntryUnsafe(System.Threading.Thread) [/_/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs @ 2277]
0B1BFCC8 070f7a36 System.Threading.ThreadPoolWorkQueue.Dispatch()
0B1BFD24 070ff222 System.Threading.PortableThreadPool+WorkerThread.WorkerThreadStart() [/_/src/libraries/System.Private.CoreLib/src/System/Threading/PortableThreadPool.WorkerThread.cs @ 63]
0B1BFDB0 070e6545 System.Threading.Thread.StartCallback() [/_/src/coreclr/System.Private.CoreLib/src/System/Threading/Thread.CoreCLR.cs @ 105]
0B1BFF04 0307b9cf [DebuggerU2MCatchHandlerFrame: 0b1bff04]
- 對 compileMethod 方法下斷點
C# 的一個特性就是很多方法都是由 JIT 動態編譯的，因為很多方法都是未編譯，所以遇到編譯事件的時候執行流很大概率就在託管層。
0:024> bp clrjit!CILJit::compileMethod
0:024> g
Breakpoint 0 hit
Time Travel Position: 3939B:12E9
eax=07acf8c8 ebx=07acf9d4 ecx=503d34b0 edx=00000000 esi=502bca30 edi=503d34b0
eip=502bca30 esp=07acf784 ebp=07acf9c8 iopl=0 nv up ei ng nz na po nc
cs=0023 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00000282
clrjit!CILJit::compileMethod:
502bca30 55 push ebp