windbg的時間旅行實現對 C# 程式的終極調試

一：什麼是時間旅行簡而言之就是把程式的執行流拍成vlog，這樣就可以對 vlog 快進或者倒退，還可以分享給別人做進一步的分析，是不是想都不敢想。很開心的是 windbg preview 版本中已經實現了，叫做時間旅行調試 TTD，相比傳統的靜態分析不知道好多少倍。為了能提起大家興趣，我 ...

一：什麼是時間旅行

簡而言之就是把程式的執行流拍成vlog，這樣就可以對 vlog 快進或者倒退，還可以分享給別人做進一步的分析，是不是想都不敢想。

很開心的是 windbg preview 版本中已經實現了，叫做 時間旅行調試 TTD，相比傳統的 靜態分析 不知道好多少倍。

為了能提起大家興趣，我就舉二個例子吧。

二：二個有趣的例子

1. 查看程式都觸發了第幾代垃圾回收

為了方便說明，我就用誘導GC手工觸發，然後再觀察都觸發了哪一代的 GC ，參考代碼如下：


        static void Main(string[] args)
        {
            List<string> list = new List<string>();

            //1. 第一次觸發GC
            GC.Collect();

            Console.WriteLine("觸發full gc");

            //2. 第二次觸發GC
            GC.Collect(0);

            Console.WriteLine("觸發 0 代 gc");

            //3.第二次觸發GC
            GC.Collect(1);

            Console.WriteLine("觸發 1 代 gc");
        }

接下來用 windbg 的 launch executeable (advanced) 來附加程式，勾選 Record，然後在彈框中將 vlog 保存到指定目錄，最後點擊 Record 就可以啦！

運行完後，windbg 會自動載入我的 D:\test\ConsoleApp104.run 的 vlog 文件，因為 gc 觸發的底層函數是coreclr!WKS::GCHeap::GarbageCollectGeneration ，所以我們用 bp 給它下一個斷點，運行多次 g 命令。


0:000> bp coreclr!WKS::GCHeap::GarbageCollectGeneration
Bp expression 'coreclr!WKS::GCHeap::GarbageCollectGeneration' could not be resolved, adding deferred bp
0:000> g
Time Travel Position: 3079F:63E
eax=00000001 ebx=00000002 ecx=00000002 edx=00000008 esi=00000002 edi=00000002
eip=02fc4256 esp=0057f204 ebp=0057f214 iopl=0         nv up ei pl nz na po nc
cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000202
coreclr!WKS::GCHeap::GarbageCollectGeneration:
02fc4256 55              push    ebp
0:000> g
Time Travel Position: 34661:AF
eax=00000001 ebx=00000002 ecx=00000000 edx=00000008 esi=00000000 edi=00000002
eip=02fc4256 esp=0057f1f8 ebp=0057f208 iopl=0         nv up ei pl nz na po nc
cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000202
coreclr!WKS::GCHeap::GarbageCollectGeneration:
02fc4256 55              push    ebp
0:000> g
Breakpoint 0 hit
Time Travel Position: 346A5:2CD
eax=00000001 ebx=00000002 ecx=00000001 edx=00000008 esi=00000001 edi=00000002
eip=02fc4256 esp=0057f1f8 ebp=0057f208 iopl=0         nv up ei pl nz na po nc
cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000202
coreclr!WKS::GCHeap::GarbageCollectGeneration:
02fc4256 55              push    ebp

從輸出中可以很清楚的看到，命中了三次 GarbageCollectGeneration 回收，而且從上面的 ecx 寄存器看依次是 2,0,1，對應著 gc 的2代回收，0代回收， 1代回收，這比只有一個靜態的 dump 是不是有優勢的多，要知道我這裡的 ConsoleApp101.run 文件是可以分發給別人分析的哦。

2. 查看新生成的線程曾今都執行了什麼代碼

這個例子源自朋友遇到的一個問題，他的程式跑著跑著，發現 ThreadPool 中有400多待命的工作線程，線程棧大概如下：


0:011> k
 # ChildEBP RetAddr      
00 0564fc6c 7531f0ca     ntdll!NtRemoveIoCompletion+0xc
01 0564fc6c 78480b69     KERNELBASE!GetQueuedCompletionStatus+0x2a
02 0564fcb8 7847d92b     coreclr!CLRLifoSemaphore::WaitForSignal+0x29 [d:\a\_work\1\s\src\vm\synch.cpp @ 654] 
03 0564fd08 7847cf04     coreclr!CLRLifoSemaphore::Wait+0x13b [d:\a\_work\1\s\src\vm\synch.cpp @ 897] 
04 0564fdd4 783f2910     coreclr!ThreadpoolMgr::WorkerThreadStart+0x234 [d:\a\_work\1\s\src\vm\win32threadpool.cpp @ 2121] 
05 0564ff70 7703fa29     coreclr!Thread::intermediateThreadProc+0x50 [d:\a\_work\1\s\src\vm\threads.cpp @ 2110] 
06 0564ff80 772175f4     KERNEL32!BaseThreadInitThunk+0x19
07 0564ffdc 772175c4     ntdll!__RtlUserThreadStart+0x2f
08 0564ffec 00000000     ntdll!_RtlUserThreadStart+0x1b

因為給我的是 靜態dump，所以我無法尋找 11號線程 曾今執行了什麼托管代碼，因為時間不能倒流，但現在有了 TTD，真的可以讓時間倒流啦。。。太有意思了，哈哈，既然能倒流，那就一定有辦法找到破綻。

為了方便講解，寫一個簡單例子。


        static void Main(string[] args)
        {
            Task.Factory.StartNew(() =>
            {
                Console.WriteLine("我是 task 線程");
            });

            Console.ReadLine();
        }

接下來我們一起探究下最後生成的 Thread WorkThread 曾今都執行了什麼？深挖思路大概是這樣的。

先將進度條拉到底，然後用 !bpmd System_Private_CoreLib System.Threading.Tasks.Task.InnerInvoke 下一個斷點，最後將時間倒流，看誰命中了這個 task。


0:000> g
TTD: End of trace reached.
(4f20.4d0c): Break instruction exception - code 80000003 (first/second chance not available)
Time Travel Position: 36F51:0
eax=00070053 ebx=00000000 ecx=8a60f857 edx=77237170 esi=7845e6c0 edi=00000000
eip=771a7000 esp=0602fe90 ebp=0602ff70 iopl=0         nv up ei pl zr na pe nc
cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000246
771a7000 ea09701a773300  jmp     0033:771A7009

0:009> !bpmd System_Private_CoreLib System.Threading.Tasks.Task.InnerInvoke
MethodDesc = 06A29704
Setting breakpoint: bp 05A915C7 [System.Threading.Tasks.Task.InnerInvoke()]
Adding pending breakpoints...

0:009> g-
Breakpoint 1 hit
Time Travel Position: 32DF4:AC
eax=05a915c0 ebx=00000000 ecx=0349a864 edx=0349a864 esi=0349a864 edi=0349a7c8
eip=05a915c7 esp=066afa14 ebp=066afa1c iopl=0         nv up ei pl zr na pe nc
cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000246
System_Private_CoreLib!System.Threading.Tasks.Task.InnerInvoke()$##6002185+0x7:
05a915c7 8b7e04          mov     edi,dword ptr [esi+4] ds:002b:0349a868=0349a800

0:008> !clrstack 
OS Thread Id: 0x44a8 (8)
Child SP       IP Call Site
066AFA14 05a915c7 System.Threading.Tasks.Task.InnerInvoke() [/_/src/System.Private.CoreLib/shared/System/Threading/Tasks/Task.cs @ 2437]
066AFA24 05a915bb System.Threading.Tasks.Task+c.<.cctor>b__274_0(System.Object) [/_/src/System.Private.CoreLib/shared/System/Threading/Tasks/Task.cs @ 2427]
066AFA2C 05a91567 System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(System.Threading.Thread, System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) [/_/src/System.Private.CoreLib/shared/System/Threading/ExecutionContext.cs @ 289]
066AFA5C 05a912d1 System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef, System.Threading.Thread) [/_/src/System.Private.CoreLib/shared/System/Threading/Tasks/Task.cs @ 2389]
066AFABC 05a911d7 
066AFACC 05a9118b System.Threading.Tasks.Task.ExecuteFromThreadPool(System.Threading.Thread) [/_/src/System.Private.CoreLib/shared/System/Threading/Tasks/Task.cs @ 2312]
066AFAD0 05a90e58 System.Threading.ThreadPoolWorkQueue.Dispatch() [/_/src/System.Private.CoreLib/shared/System/Threading/ThreadPool.cs @ 663]
066AFB1C 05a90c6f 
066AFD10 784fa0ef [DebuggerU2MCatchHandlerFrame: 066afd10]

熟悉 Task 的朋友應該知道: System.Threading.Tasks.Task.InnerInvoke 的下一步就是執行我的回調函數，而此時 回調函數 還沒有被 JIT 編譯，這時候我們可以在 bp clrjit!CILJit::compileMethod 中去攔截 JIT 對此方法的編譯，然後從 compileMethod 中提取 mt。


0:008> bp clrjit!CILJit::compileMethod
0:008> g
Breakpoint 1 hit
Time Travel Position: 32E36:C18
eax=7933ad50 ebx=066af5c8 ecx=792c8770 edx=066af5c8 esi=7932d164 edi=00cbbf90
eip=792c8770 esp=066af3ec ebp=066af44c iopl=0         nv up ei pl zr na pe nc
cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000246
clrjit!CILJit::compileMethod:
792c8770 55              push    ebp

0:008> kb
 # ChildEBP RetAddr      Args to Child              
00 066af44c 78428db2     7933ad50 066af5c8 066af4f0 clrjit!CILJit::compileMethod [d:\a\_work\1\s\src\jit\ee_il_dll.cpp @ 294] 
...

0:008> dp 066af4f0 L1
066af4f0  06a2ae04

0:008> !dumpmd 06a2ae04
Method Name:          ConsoleApp1.dll!Unknown
Class:                032fa0dc
MethodTable:          06a2ae14
mdToken:              06000005
Module:               02c5d7d0
IsJitted:             no
Current CodeAddr:     ffffffff
Version History:
  ILCodeVersion:      00000000
  ReJIT ID:           0
  IL Addr:            00000000
     CodeAddr:           00000000  (MinOptJitted)
     NativeCodeVersion:  00000000

很奇怪的是提取的 md 目前還不能顯示完全名字，不過沒關係，我們繼續 g ，然後再重覆執行一下命令。


0:009> g
TTD: End of trace reached.
(4f20.4d0c): Break instruction exception - code 80000003 (first/second chance not available)
Time Travel Position: 36F51:0
eax=00070053 ebx=00000000 ecx=8a60f857 edx=77237170 esi=7845e6c0 edi=00000000
eip=771a7000 esp=0602fe90 ebp=0602ff70 iopl=0         nv up ei pl zr na pe nc
cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000246
771a7000 ea09701a773300  jmp     0033:771A7009
0:009> !dumpmd 06a2ae04
Method Name:          ConsoleApp1.Program+<>c.<Main>b__0_0()
Class:                032fa0dc
MethodTable:          06a2ae14
mdToken:              06000005
Module:               02c5d7d0
IsJitted:             yes
Current CodeAddr:     06133300
Version History:
  ILCodeVersion:      00000000
  ReJIT ID:           0
  IL Addr:            00000000
     CodeAddr:           06133300  (MinOptJitted)
     NativeCodeVersion:  00000000

當時間線結束的時候，我們終於看到了，原來 Task 執行的是 ConsoleApp1.Program+<>c.<Main>b__0_0() 方法，那這個方法邏輯是什麼呢？可以用 ILSpy 查看。