一:什么是时间旅行
简而言之就是把程序的执行流拍成vlog,这样就可以对 vlog 快进或者倒退,还可以分享给别人做进一步的分析,是不是想都不敢想。
很开心的是 windbg preview
版本中已经实现了,叫做 时间旅行调试 TTD
,相比传统的 静态分析
不知道好多少倍。
为了能提起大家兴趣,我就举二个例子吧。
二:二个有趣的例子
1. 查看程序都触发了第几代垃圾回收
为了方便说明,我就用诱导GC手工触发,然后再观察都触发了哪一代的 GC ,参考代码如下:
static void Main(string[] args){List<string> list = new List<string>();//1. 第一次触发GCGC.Collect();Console.WriteLine("触发full gc");//2. 第二次触发GCGC.Collect(0);Console.WriteLine("触发 0 代 gc");//3.第二次触发GCGC.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:771A70090: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=0349a8000: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 ebp0: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 06a2ae040:008> !dumpmd 06a2ae04
Method Name: ConsoleApp1.dll!Unknown
Class: 032fa0dc
MethodTable: 06a2ae14
mdToken: 06000005
Module: 02c5d7d0
IsJitted: no
Current CodeAddr: ffffffff
Version History:ILCodeVersion: 00000000ReJIT ID: 0IL Addr: 00000000CodeAddr: 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: 00000000ReJIT ID: 0IL Addr: 00000000CodeAddr: 06133300 (MinOptJitted)NativeCodeVersion: 00000000
当时间线结束的时候,我们终于看到了,原来 Task
执行的是 ConsoleApp1.Program+<>c.<Main>b__0_0()
方法,那这个方法逻辑是什么呢?可以用 ILSpy 查看。
总的来说,要复现还是挺考验基本功的。