Archive for July 22nd, 2007

GDB for WinDbg Users (Part 6)

Sunday, July 22nd, 2007

Once we get backtrace in GDB or stack trace in WinDbg we are interested in concrete stack frames, their arguments and local variables. I slightly modified the program used in the previous part to include some local variables:

#include <stdio.h>

void func_1(int param_1, char param_2, int *param_3, char *param_4);
void func_2(int param_1, char param_2, int *param_3, char *param_4);
void func_3(int param_1, char param_2, int *param_3, char *param_4);
void func_4();

int   g_val_1;
char  g_val_2;
int  *g_pval_1 = &g_val_1;
char *g_pval_2 = &g_val_2;

int main()
{
  int   local_0 = 0;
  char *hello = "Hello World!";

  g_val_1 = 1;
  g_val_2 = '1';

  func_1(g_val_1, g_val_2, (int *)g_pval_1, (char *)g_pval_2);
  return 0;
}

void func_1(int param_1, char param_2, int *param_3, char *param_4)
{
   int local_1 = 1;

   g_val_1 = 2;
   g_val_2 = '2';

   param_3 = &local_1;

   func_2(g_val_1, g_val_2, param_3, param_4);
}

void func_2(int param_1, char param_2, int *param_3, char *param_4)
{
   int local_2 = 2;

   g_val_1 = 3;
   g_val_2 = '3';

  

   param_3 = &local_2;

   func_3(g_val_1, g_val_2, param_3, param_4);
}

void func_3(int param_1, char param_2, int *param_3, char *param_4)
{
   int local_3 = 3;

   *g_pval_1 += param_1;
   *g_pval_2 += param_2;

   func_4();
}

void func_4()
{
   puts("Hello World!");
}

In GDB the frame command is used to set the current stack frame. Then info args command can be used to list function arguments and info locals command can be used to list local variables:

(gdb) break func_4
Breakpoint 1 at 0x401455: file test.c, line 61.

(gdb) run
Starting program: C:\MinGW\examples/test.exe

Breakpoint 1, func_4 () at test.c:61
61         puts("Hello World!");

(gdb) bt
#0  func_4 () at test.c:61
#1  0x0040144d in func_3 (param_1=3, param_2=51 '3', param_3=0x22ff10,
    param_4=0x404070 "f") at test.c:56
#2  0x0040140c in func_2 (param_1=2, param_2=50 '2', param_3=0x22ff10,
    param_4=0x404070 "f") at test.c:46
#3  0x004013ba in func_1 (param_1=1, param_2=49 '1', param_3=0x22ff30,
    param_4=0x404070 "f") at test.c:34
#4  0x00401363 in main () at test.c:21

(gdb) frame
#0  func_4 () at test.c:61
61         puts("Hello World!");

(gdb) frame 0
#0  func_4 () at test.c:61
61         puts("Hello World!");

(gdb) info args
No arguments.

(gdb) info locals
No locals.

(gdb) frame 1
#1  0x0040144d in func_3 (param_1=3, param_2=51 '3', param_3=0x22ff10,
    param_4=0x404070 "f") at test.c:56
56         func_4();

(gdb) info args
param_1 = 3
param_2 = 51 '3'
param_3 = (int *) 0x22ff10
param_4 = 0x404070 "f"

(gdb) info locals
local_3 = 3
param_2 = 51 '3'

(gdb) frame 2
#2  0x0040140c in func_2 (param_1=2, param_2=50 '2', param_3=0x22ff10,
    param_4=0x404070 "f") at test.c:46
46         func_3(g_val_1, g_val_2, param_3, param_4);

(gdb) info args
param_1 = 2
param_2 = 50 '2'
param_3 = (int *) 0x22ff10
param_4 = 0x404070 "f"

(gdb) info locals
local_2 = 2
param_2 = 50 '2'

(gdb) frame 3
#3  0x004013ba in func_1 (param_1=1, param_2=49 '1', param_3=0x22ff30,
    param_4=0x404070 "f") at test.c:34
34         func_2(g_val_1, g_val_2, param_3, param_4);

(gdb) info args
param_1 = 1
param_2 = 49 '1'
param_3 = (int *) 0x22ff30
param_4 = 0x404070 "f"

(gdb) info locals
local_1 = 1
param_2 = 49 '1'

(gdb) frame 4
#4  0x00401363 in main () at test.c:21
21        func_1(g_val_1, g_val_2, (int *)g_pval_1, (char *)g_pval_2);

(gdb) info args
No arguments.

(gdb) info locals
local_0 = 0
hello = 0x403000 "Hello World!"

(gdb)

In WinDbg kn command shows stack trace with frame numbers, knL command additionally omits source code references, .frame command switches to particular stack frame, dv command shows parameters and local variables together, dv /i command classifies them into categories, parameters or locals, dv /V command shows their addresses and offsets for the relevant base frame register, usually EBP, dv /t command shows type information:

Microsoft (R) Windows Debugger  Version 6.7.0005.1
Copyright (c) Microsoft Corporation. All rights reserved.

CommandLine: C:\dmitri\test\release\test.exe
Symbol search path is: SRV*c:\websymbols*http://msdl.microsoft.com/download/symbols
Executable search path is:
ModLoad: 00400000 0040f000   test.exe
ModLoad: 7d4c0000 7d5f0000   NOT_AN_IMAGE
ModLoad: 7d600000 7d6f0000   C:\W2K3\SysWOW64\ntdll32.dll
ModLoad: 7d4c0000 7d5f0000   C:\W2K3\syswow64\kernel32.dll
(e38.ac0): Break instruction exception - code 80000003 (first chance)
eax=7d600000 ebx=7efde000 ecx=00000005 edx=00000020 esi=7d6a01f4 edi=00221f38
eip=7d61002d esp=0012fb4c ebp=0012fcac iopl=0 nv up ei pl nz na po nc
cs=0023 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00000202
ntdll32!DbgBreakPoint:
7d61002d cc              int     3

0:000> bp func_4

0:000> g
ModLoad: 71c20000 71c32000   C:\W2K3\SysWOW64\tsappcmp.dll
ModLoad: 77ba0000 77bfa000   C:\W2K3\syswow64\msvcrt.dll
ModLoad: 00410000 004ab000   C:\W2K3\syswow64\ADVAPI32.dll
ModLoad: 7da20000 7db00000   C:\W2K3\syswow64\RPCRT4.dll
ModLoad: 7d8d0000 7d920000   C:\W2K3\syswow64\Secur32.dll
Breakpoint 0 hit
eax=0040c9d4 ebx=7d4d8df9 ecx=0040c9d4 edx=00000066 esi=00000002 edi=00000ece
eip=00408be0 esp=0012ff10 ebp=0012ff18 iopl=0 nv up ei pl nz na pe nc
cs=0023 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00000206
test!func_4:
00408be0 55              push    ebp

0:000> knL
 # ChildEBP RetAddr
00 0012ff0c 00408c38 test!func_4
01 0012ff18 00408c7c test!func_3+0x38
02 0012ff34 00408ccc test!func_2+0x3c
03 0012ff50 00408d24 test!func_1+0x3c
04 0012ff70 00401368 test!main+0x44
05 0012ffc0 7d4e7d2a test!__tmainCRTStartup+0x15f
06 0012fff0 00000000 kernel32!BaseProcessStart+0x28

0:000> .frame
00 0012ff0c 00408c38 test!func_4 [c:\dmitri\test\test\test.cpp @ 60]

0:000> .frame 0
00 0012ff0c 00408c38 test!func_4 [c:\dmitri\test\test\test.cpp @ 60]

0:000> dv

0:000> .frame 1
01 0012ff18 00408c7c test!func_3+0x38 [c:\dmitri\test\test\test.cpp @ 57]

0:000> dv
        param_1 = 3
        param_2 = 51 '3'
        param_3 = 0x0012ff30
        param_4 = 0x0040c9d4 "f"
        local_3 = 3

0:000> dv /i
prv param  param_1 = 3
prv param  param_2 = 51 '3'
prv param  param_3 = 0x0012ff30
prv param  param_4 = 0x0040c9d4 "f"
prv local  local_3 = 3

0:000> dv /i /V
prv param  0012ff20 @ebp+0x08 param_1 = 3
prv param  0012ff24 @ebp+0x0c param_2 = 51 '3'
prv param  0012ff28 @ebp+0x10 param_3 = 0x0012ff30
prv param  0012ff2c @ebp+0x14 param_4 = 0x0040c9d4 "f"
prv local  0012ff14 @ebp-0x04 local_3 = 3

0:000> .frame 4
04 0012ff70 00401368 test!main+0x44 [c:\dmitri\test\test\test.cpp @ 21]

0:000> dv
        local_0 = 0
          hello = 0x0040a274 "Hello World!"

0:000> dv /i
prv local          local_0 = 0
prv local            hello = 0x0040a274 "Hello World!"

0:000> dv /i /V
prv local  0012ff68 @ebp-0x08         local_0 = 0
prv local  0012ff6c @ebp-0x04           hello = 0x0040a274 "Hello World!"

0:000> dv /t
int local_0 = 0
char * hello = 0x0040a274 "Hello World!"

Our comparison table grows a bit:

Action                      | GDB                 | WinDbg
----------------------------------------------------------------
Start the process           | run                 | g
Exit                        | (q)uit              | q
Disassemble (forward)       | (disas)semble       | uf, u
Disassemble N instructions  | x/<N>i              | -
Disassemble (backward)      | -                   | ub
Stack trace                 | backtrace (bt)      | k
Full stack trace            | bt full             | kv
Stack trace with parameters | bt full             | kP
Partial trace (innermost)   | bt <N>              | k <N>
Partial trace (outermost)   | bt -<N>             | -
Stack trace for all threads | thread apply all bt | ~*k
Breakpoint                  | break               | bp
Frame numbers               | any bt command      | kn
Select frame                | frame               | .frame
Display parameters          | info args           | dv /t /i /V
Display locals              | info locals         | dv /t /i /V

- Dmitry Vostokov @ DumpAnalysis.org -

Crash Dump Analysis Patterns (Part 19)

Sunday, July 22nd, 2007

Almost all threads in any system are waiting for resources or waiting in a ready-to-run queues to be scheduled. At any moment of time the number of running threads is equal to the number of processors. The rest, hundreds and thousands of threads, are waiting. Looking at their waiting times in kernel and complete memory dumps provides some interesting observations that worth their own pattern name: Waiting Thread Time.

When a thread starts waiting that time is recorded in WaitTime field of _KTHREAD structure:

1: kd> dt _KTHREAD 8728a020
   +0x000 Header           : _DISPATCHER_HEADER
   +0x010 MutantListHead   : _LIST_ENTRY [ 0x8728a030 - 0x8728a030 ]
   +0x018 InitialStack     : 0xa3a1f000
   +0x01c StackLimit       : 0xa3a1a000
   +0x020 KernelStack      : 0xa3a1ec08
   +0x024 ThreadLock       : 0
   +0x028 ApcState         : _KAPC_STATE
   +0x028 ApcStateFill     : [23]  "H???"
   +0x03f ApcQueueable     : 0x1 ''
   +0x040 NextProcessor    : 0x3 ''
   +0x041 DeferredProcessor : 0x3 ''
   +0x042 AdjustReason     : 0 ''
   +0x043 AdjustIncrement  : 1 ''
   +0x044 ApcQueueLock     : 0
   +0x048 ContextSwitches  : 0x6b7
   +0x04c State            : 0x5 ''
   +0x04d NpxState         : 0xa ''
   +0x04e WaitIrql         : 0 ''
   +0x04f WaitMode         : 1 ''
   +0x050 WaitStatus       : 0
   +0x054 WaitBlockList    : 0x8728a0c8 _KWAIT_BLOCK
   +0x054 GateObject       : 0x8728a0c8 _KGATE
   +0x058 Alertable        : 0 ''
   +0x059 WaitNext         : 0 ''
   +0x05a WaitReason       : 0x11 ''
   +0x05b Priority         : 12 ''
   +0x05c EnableStackSwap  : 0x1 ''
   +0x05d SwapBusy         : 0 ''
   +0x05e Alerted          : [2]  ""
   +0x060 WaitListEntry    : _LIST_ENTRY [ 0x88091e10 - 0x88029ce0 ]
   +0x060 SwapListEntry    : _SINGLE_LIST_ENTRY
   +0x068 Queue            : (null)
   +0×06c WaitTime         : 0×82de9b
   +0×070 KernelApcDisable : 0


This value is also displayed in decimal format as Wait Start TickCount when you list threads or use !thread command:

0: kd> ? 0x82de9b
Evaluate expression: 8576667 = 0082de9b

1: kd> !thread 8728a020
THREAD 8728a020  Cid 4c9c.59a4  Teb: 7ffdf000 Win32Thread: bc012008 WAIT: (Unknown) UserMode Non-Alertable
    8728a20c  Semaphore Limit 0x1
Waiting for reply to LPC MessageId 017db413:
Current LPC port e5fcff68
Impersonation token:  e2b07028 (Level Impersonation)
DeviceMap                 e1da6518
Owning Process            89d20740       Image:         winlogon.exe
Wait Start TickCount      8576667        Ticks: 7256 (0:00:01:53.375)
Context Switch Count      1719                 LargeStack
UserTime                  00:00:00.0359
KernelTime                00:00:00.0375

Tick is a system unit of time and KeTimeIncrement double word value contains its equivalent as the number of 100-nanosecond units:

0: kd> dd KeTimeIncrement l1
808a6304  0002625a

0: kd> ? 0002625a
Evaluate expression: 156250 = 0002625a

0: kd> ?? 156250.0/10000000.0
double 0.015625

Therefore on that system one tick is 0.015625 of a second.

The current tick count is available via KeTickCount variable:

0: kd> dd KeTickCount l1
8089c180  0082faf3

If we subtract the recorded start wait time from the current tick count we get the number of ticks passed since the thread began waiting:

0: kd> ? 0082faf3-82de9b
Evaluate expression: 7256 = 00001c58

Using our previously calculated constant of the number of seconds per tick (0.015625) we get the number of seconds passed:

0: kd> ?? 7256.0 * 0.015625
double 113.37499999999999

113.375 seconds is 1 minute 53 seconds and 375 milliseconds:

0: kd> ?? 113.375-60.0
double 53.374999999999986

We can see that this value corresponds to Ticks value that WinDbg shows for the thread:

Wait Start TickCount 8576667 Ticks: 7256 (0:00:01:53.375)

Why do we need to concern ourselves with these ticks? If we know that some activity was frozen for 15 minutes we can filter out threads from our search space because threads with significantly less number of ticks were running at some time and were not waiting for 15 minutes.

Threads with low number of ticks were running recently:

THREAD 86ced020  Cid 0004.3908  Teb: 00000000 Win32Thread: 00000000 WAIT: (Unknown) KernelMode Non-Alertable
    b99cb7d0  QueueObject
    86ced098  NotificationTimer
Not impersonating
DeviceMap                 e10038e0
Owning Process            8ad842a8       Image:         System
Wait Start TickCount      8583871        Ticks: 52 (0:00:00:00.812)
Context Switch Count      208
UserTime                  00:00:00.0000
KernelTime                00:00:00.0000
Start Address rdbss!RxWorkerThreadDispatcher (0xb99cdc2e)
Stack Init ad21d000 Current ad21ccd8 Base ad21d000 Limit ad21a000 Call 0
Priority 8 BasePriority 8 PriorityDecrement
ChildEBP RetAddr
ad21ccf0 808330c6 nt!KiSwapContext+0×26
ad21cd1c 8082af7f nt!KiSwapThread+0×284
ad21cd64 b99c00e9 nt!KeRemoveQueue+0×417
ad21cd9c b99cdc48 rdbss!RxpWorkerThreadDispatcher+0×4b
ad21cdac 80948e74 rdbss!RxWorkerThreadDispatcher+0×1a
ad21cddc 8088d632 nt!PspSystemThreadStartup+0×2e
00000000 00000000 nt!KiThreadStartup+0×16

Another application would be to find all threads from different processes whose wait time roughly corresponds to 15 minutes and therefore they might be related to the same frozen activity. For example, these RPC threads below from different processes are most likely related because one is the RPC client thread, the other is the RPC server thread waiting for some object and their common Ticks value is the same: 15131.

THREAD 89cc9750  Cid 0f1c.0f60  Teb: 7ffd6000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable
    89cc993c  Semaphore Limit 0x1
Waiting for reply to LPC MessageId 0000a7e7:
Current LPC port e18fcae8
Not impersonating
DeviceMap                 e10018a8
Owning Process            88d3b938       Image:         svchost.exe
Wait Start TickCount      29614          Ticks: 15131 (0:00:03:56.421)
Context Switch Count      45
UserTime                  00:00:00.0000
KernelTime                00:00:00.0000
Win32 Start Address 0×0000a7e6
LPC Server thread working on message Id a7e6
Start Address kernel32!BaseThreadStartThunk (0×7c82b5bb)
Stack Init f29a6000 Current f29a5c08 Base f29a6000 Limit f29a3000 Call 0
Priority 11 BasePriority 10 PriorityDecrement 0
Kernel stack not resident.
ChildEBP RetAddr
f29a5c20 80832f7a nt!KiSwapContext+0×26
f29a5c4c 8082927a nt!KiSwapThread+0×284
f29a5c94 8091df86 nt!KeWaitForSingleObject+0×346
f29a5d50 80888c6c nt!NtRequestWaitReplyPort+0×776
f29a5d50 7c94ed54 nt!KiFastCallEntry+0xfc
0090f6b8 7c941c94 ntdll!KiFastSystemCallRet
0090f6bc 77c42700 ntdll!NtRequestWaitReplyPort+0xc
0090f708 77c413ba RPCRT4!LRPC_CCALL::SendReceive+0×230
0090f714 77c42c7f RPCRT4!I_RpcSendReceive+0×24
0090f728 77cb5d63 RPCRT4!NdrSendReceive+0×2b
0090f9cc 67b610ca RPCRT4!NdrClientCall+0×334
0090f9dc 67b61c07 component!NotifyOfEvent+0×14



0090ffec 00000000 kernel32!BaseThreadStart+0×34

THREAD 89b49590  Cid 098c.01dc  Teb: 7ff92000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable
    88c4e020  Thread
    89b49608  NotificationTimer
Not impersonating
DeviceMap                 e10018a8
Owning Process            89d399c0       Image:         MyService.exe
Wait Start TickCount      29614          Ticks: 15131 (0:00:03:56.421)
Context Switch Count      310
UserTime                  00:00:00.0015
KernelTime                00:00:00.0000
Win32 Start Address 0×0000a7e7
LPC Server thread working on message Id a7e7
Start Address kernel32!BaseThreadStartThunk (0×7c82b5bb)
Stack Init f2862000 Current f2861c60 Base f2862000 Limit f285f000 Call 0
Priority 11 BasePriority 10 PriorityDecrement 0
Kernel stack not resident.
ChildEBP RetAddr
f2861c78 80832f7a nt!KiSwapContext+0×26
f2861ca4 8082927a nt!KiSwapThread+0×284
f2861cec 80937e4c nt!KeWaitForSingleObject+0×346
f2861d50 80888c6c nt!NtWaitForSingleObject+0×9a
f2861d50 7c94ed54 nt!KiFastCallEntry+0xfc
0a6cf590 7c942124 ntdll!KiFastSystemCallRet
0a6cf594 7c82baa8 ntdll!NtWaitForSingleObject+0xc
0a6cf604 7c82ba12 kernel32!WaitForSingleObjectEx+0xac
0a6cf618 3f691c11 kernel32!WaitForSingleObject+0×12
0a6cf658 09734436 component2!WaitForResponse+0×75



0a6cf8b4 77cb23f7 RPCRT4!Invoke+0×30
0a6cfcb4 77cb26ed RPCRT4!NdrStubCall2+0×299
0a6cfcd0 77c409be RPCRT4!NdrServerCall2+0×19
0a6cfd04 77c4093f RPCRT4!DispatchToStubInCNoAvrf+0×38
0a6cfd58 77c40865 RPCRT4!RPC_INTERFACE::DispatchToStubWorker+0×117
0a6cfd7c 77c357eb RPCRT4!RPC_INTERFACE::DispatchToStub+0xa3
0a6cfdbc 77c41e26 RPCRT4!RPC_INTERFACE::DispatchToStubWithObject+0xc0
0a6cfdfc 77c41bb3 RPCRT4!LRPC_SCALL::DealWithRequestMessage+0×42c
0a6cfe20 77c45458 RPCRT4!LRPC_ADDRESS::DealWithLRPCRequest+0×127
0a6cff84 77c2778f RPCRT4!LRPC_ADDRESS::ReceiveLotsaCalls+0×430
0a6cff8c 77c2f7dd RPCRT4!RecvLotsaCallsWrapper+0xd
0a6cffac 77c2de88 RPCRT4!BaseCachedThreadRoutine+0×9d
0a6cffb8 7c826063 RPCRT4!ThreadStartRoutine+0×1b
0a6cffec 00000000 kernel32!BaseThreadStart+0×34

- Dmitry Vostokov @ DumpAnalysis.org -