一:什么是时间旅行
简而言之就是把程序的执行流拍成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 查看。
总的来说,要复现还是挺考验基本功的。
以上就是c#程序终极调试实现windbg的时间旅行的详细内容,更多关于c#程序调试windbg时间旅行的资料请关注其它相关文章!