0

windbg的时间旅行实现对 C# 程序的终极调试 - 一线码农

 3 months ago
source link: https://www.cnblogs.com/huangxincheng/p/16265551.html
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.

一:什么是时间旅行

简而言之就是把程序的执行流拍成vlog,这样就可以对 vlog 快进或者倒退,还可以分享给别人做进一步的分析,是不是想都不敢想。

很开心的是 windbg preview 版本中已经实现了,叫做 时间旅行调试 TTD,相比传统的 静态分析 不知道好多少倍。

a683b601de364138a9ec5a576652bc6e~tplv-k3u1fbpfcp-zoom-1.image

为了能提起大家兴趣,我就举二个例子吧。

二:二个有趣的例子

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 就可以啦!

496544a797354435a8adf6d70d4292f1~tplv-k3u1fbpfcp-zoom-1.image

运行完后,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 查看。

cfdcc64f0cfd42bfa2362b2a9799612e~tplv-k3u1fbpfcp-zoom-1.image

总的来说,要复现还是挺考验基本功的。

图片名称

About Joyk


Aggregate valuable and interesting links.
Joyk means Joy of geeK