Using CMKD to find function arguments in x64 dumps

by Max Galkin

Finding the root cause of a 64-bit native service crash using a mini dump can be difficult. The main challenge is that the stack trace left by the optimized code implementing the x64 calling convention lacks important data: the first four function arguments are not saved on the stack typically but just passed in registers. You may endeavor to analyze the assembly code up and down the call graph to find out whether any of those registers got pushed on stack somewhere else or were stored in memory, but this could be time-consuming and error-prone1.

One mitigation for this problem we use in our team is a customized crash handling script to preserve recent pieces of rolling service logs together with the crash dump to help the crash investigation. This post demonstrates another approach: using CMKD debugger extension to recover some of the arguments via automated code analysis.

So, your 64-bit service has crashed and you are ready to find the root cause:

  • you have collected the crash dump, the executable and the symbols (the pdb file) from the crash scene;
  • you have installed the latest x64 WinDbg;
  • you have set the symbols path to your product symbols server: set _NT_SYMBOL_PATH=srv*c:\symbols*http://symbol_server_url
  • you have obtained the 64-bit CMKD.dll and put it next to the WinDbg.exe;

Start WinDbg from the folder with the dump and other files you collected, this will help WinDbg discover the symbols. Open the dump (Ctrl+D):

 Loading Dump File [C:\dump\MyApp.dmp]
 User Mini Dump File: Only registers, stack and portions of memory are available

 [ ... ]
 .......................................................
 This dump file has an exception of interest stored in it.
 The stored exception information can be accessed via .ecxr.
 (2660.1e74): Access violation - code c0000005 (first/second chance not available)
 ntdll!ZwGetContextThread+0xa:
 000007fa`4b04398b c3 ret

 

By default, your debugging context is set to the crashed thread, but if the crash was caused by an unhandled exception, you will not immediately see the stack trace you expect from k command or such, because the exception unwinds the stack. As WinDbg suggests, you want to first execute the .ecxr command:


0:034> .ecxr
 rax=0000000000000000 rbx=0000000000000027 rcx=00000000000dbba0
 rdx=000007f775ce1f20 rsi=0000000000000000 rdi=0000000000000000
 rip=000007f776393d90 rsp=000000000a6c5ea0 rbp=000000000a6c5f50
 r8=0000000000000067 r9=0000000000000027 r10=0000000000000000
 r11=0000000000000200 r12=000007f775ce1fb0 r13=000007f775ce1f50
 r14=000007f775ce1f20 r15=0000000000000067
 iopl=0 nv up ei pl nz na po nc
 cs=0033 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00010206
 MyApp!sdk::Logger::TriggerAccessViolation+0x10:
 000007f7`76393d90 c70000000000 mov dword ptr [rax],0 ds:00000000`00000000=????????

This should reset the stack to the state right before the throw. You can now load the CMKD extension and use the !stack extension. Command line parameter –p will display the first four arguments for each function in the stack, parameter –t will also explain how CMKD has recovered the particular parameter, so you can double-check that each parameter was recovered correctly. Below is an excerpt from the WinDbg log comparing the arguments shown by the standard kb command versus the !stack command:

0:034> kb 6
 RetAddr : Args to Child : Call Site
 000007f7`76393d62 : 00000000`00000006 00000000`00000200 00000000`00000006 00000000`6d0ce908 : TriggerAccessViolation+0x10
 000007f7`7638fcb7 : 00000000`000dbba0 00000000`0a6c6040 00000002`f5b6e430 00000000`6d0720da : WriteInternalMiniDump+0x12
 000007f7`76223ed3 : 00000000`00000000 000007f7`75c9f340 00000002`8ded1e30 00000000`00000003 : Logger::LogV+0xe7
 000007f7`7639113d : 00000002`8ded1e30 00008173`dbcffd42 00000000`0a6c6800 00000000`00000000 : LogTraceInfo::operator()+0x33
 000007f7`763ea517 : 000007f7`75ce1f50 000007f7`75ce1f20 00000000`00000067 00000000`00000027 : Logger::LogV+0x7d
 000007f7`76223efd : 00000000`0a6c6820 00000000`0a6c6560 00000000`0a6c64d0 00000002`aaad4d00 : StringBuilder::AppendVarArg+0x277
0:034> .load cmkd
 0:034> !stack -p -t
 Call Stack : 24 frames
 ## Stack-Pointer Return-Address Call-Site
 00 000000000a6c5ea0 000007f776393d62 MyApp!sdk::Logger::TriggerAccessViolation+10
 Parameter[0] = (unknown) :
 Parameter[1] = (unknown) :
 Parameter[2] = (unknown) :
 Parameter[3] = (unknown) :
 01 000000000a6c5ec0 000007f77638fcb7 MyApp!sdk::Logger::WriteInternalMiniDump+12
 Parameter[0] = 00000000000dbba0 : rcx setup in parent frame by movb instruction @ 000007f77638fcad from immediate data
 Parameter[1] = (unknown) :
 Parameter[2] = (unknown) :
 Parameter[3] = (unknown) :
 02 000000000a6c5f00 000007f776223ed3 MyApp!sdk::Logger::LogV+e7
 Parameter[0] = 00000002353c0080 : rcx saved in current frame into NvReg r13 which is saved by child frames
 Parameter[1] = 00000002353d8dd8 : rdx saved in current frame into NvReg r14 which is saved by child frames
 Parameter[2] = 00000002353d8e20 : r8 saved in current frame into NvReg r15 which is saved by child frames
 Parameter[3] = 00000002353d8e20 : r9 saved in current frame into NvReg rbx which is saved by child frames
 03 000000000a6c61f0 000007f77639113d MyApp!sdk::LogTraceInfo::operator()+33
 Parameter[0] = 000000000a6c6290 : rcx setup in parent frame by lea instruction @ 000007f776391134 from mem @ 000000000a6c6290
 Parameter[1] = 0000000000000027 : rdx setup in parent frame by mov instruction @ 000007f776391132 from NvReg rsi which is saved by child frame
 Parameter[2] = 0000000000000005 : r8 setup in parent frame by mov instruction @ 000007f77639112b from mem @ 000000000a6c6350
 Parameter[3] = 000007f775ce1fb0 : r9 setup in parent frame by mov instruction @ 000007f776391124 from mem @ 000000000a6c6358
 04 000000000a6c6240 000007f7763ea517 MyApp!sdk::Logger::LogV+7d
 Parameter[0] = 000007f775ce1f50 : rcx setup in parent frame by lea instruction @ 000007f7763ea4ea
 Parameter[1] = 000007f775ce1f20 : rdx setup in parent frame by lea instruction @ 000007f7763ea4e3
 Parameter[2] = 0000000000000067 : r8 saved in current frame into stack
 Parameter[3] = 0000000000000027 : r9 setup in parent frame by movb instruction @ 000007f7763ea4fb from immediate data
 05 000000000a6c6330 000007f776223efd MyApp!StringBuilder::AppendVarArg+277 (perf)
 Parameter[0] = 000007f775ce1fb0 : rcx saved in current frame into NvReg rdi which is saved by child frames
 Parameter[1] = 000007f777bff60f : rdx saved in current frame into NvReg rbp which is saved by child frames
 Parameter[2] = 000000000a6c63c0 : r8 setup in parent frame by lea instruction @ 000007f776223ef3 from mem @ 000000000a6c63c0
 Parameter[3] = (unknown) :

To further explore the newly retrieved arguments, you can use WinDbg — dt MyType_Ptr* 0x000000000a6cf338 —, or continue in Visual Studio and use Watch window to interpret the memory, e.g. by casting an address like this (MyType_Ptr*)(0x000000000a6cf338). The memory address in the example is from the truncated part of the log and is only here to demonstrate the syntax of the commands one would use.

  1. More details on the x64 calling convention and techniques of the assembly-level analysis are available here: http://blogs.msdn.com/b/ntdebugging/archive/2009/01/09/challenges-of-debugging-optimized-x64-code.aspx []