TTD 專題 (第一篇)：C# 那些短命線程都在乾什麼？

一：背景 1.講故事在分析的眾多dump中，經常會遇到各種奇葩的問題，僅通過dump這種快照形式還是有很多問題搞不定，而通過 perfview 這種粒度又太粗，很難找到問題之所在，真的很頭疼，比如本篇的短命線程問題，參考圖如下：我們在 t2 時刻抓取的dump對查看短命線程毫無幫助，我根 ...

一：背景

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