Crash Dump Analysis Patterns (Part 19)

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 @ -

11 Responses to “Crash Dump Analysis Patterns (Part 19)”

  1. Dmitry Vostokov Says:

    To convert ticks to time interval you can use !whattime command:

    3: kd> !whattime 0n7256
    7256 Ticks in Standard Time: 01:53.375s

  2. Dmitry Vostokov Says:

    !stacks command shows Ticks data for threads

  3. Crash Dump Analysis » Blog Archive » Crash Dump Analysis Patterns (Part 19b) Says:

    […] I wrote about how to calculate thread waiting time in kernel and complete memory dumps (Waiting Thread Time pattern). Now I show how to do it for user dumps. Unfortunately this information is not available […]

  4. Crash Dump Analysis » Blog Archive » Truncated dump, stack trace collection, waiting thread time and wait chains: pattern cooperation Says:

    […] but most of kernel and user space stack traces not present in the output. ServiceA has many threads waiting for LPC requests during last 5 minutes (the bugcheck was forced after 3 - 4 minutes the issue […]

  5. Crash Dump Analysis » Blog Archive » Wait chain, blocked thread, waiting thread time, IRP distribution anomaly and stack trace collection: pattern cooperation Says:

    […] The blocking thread 86d14ae8 had been blocked waiting for a notification event for more than 2 hours: […]

  6. Crash Dump Analysis » Blog Archive » Inconsistent dump, stack trace collection, LPC, thread, process, executive resource wait chains, missing threads and waiting thread time: pattern cooperation Says:

    […] see this thread is also blocked by DriverA. We also check thread waiting times. All threads involved in wait chains have their Ticks value less than 86ba5638. This means that […]

  7. Crash Dump Analysis » Blog Archive » Icons for Memory Dump Analysis Patterns (Part 35) Says:

    […] Today we introduce an icon for Waiting Thread Time (kernel dumps) pattern: […]

  8. Crash Dump Analysis » Blog Archive » Stack trace collection, special process, LPC and critical section wait chains, blocked thread, coupled machines, thread waiting time and IRP distribution anomaly: pattern cooperation Says:

    […] above is blocked trying to set the current directory residing on another server SERVER_B. Its waiting time is almost 13 min 34 […]

  9. Crash Dump Analysis » Blog Archive » Stack trace collection, missing threads, waiting time, critical section and LPC wait chains: pattern cooperation Says:

    […] the question arises: who was freezing first, ServiceA or ServiceB? We can compare waiting times to answer. We see that waiting time for ServiceB request thread is 3:05:19 and for ServiceA […]

  10. Crash Dump Analysis » Blog Archive » ALPC wait chain, waiting thread time and semantic process coupling: pattern cooperation Says:

    […] deadlock. We could also see that threads waiting for ServiceA.exe sometimes had the greater waiting time than threads waiting for ServiceC so it could be the case that the problem initially started with […]

  11. Dmitry Vostokov Says:

    Example: a cllent LPC thread was waiting but the corresponding server thread value was missing in the output of !lpc extension. Because the server process name was known from the output the server thread was found by the same waiting value:

    THREAD 894e13a8 Cid 02d4.0e28 Teb: 7ffdf000 Win32Thread: e6e7cea8 WAIT: (Unknown) KernelMode Non-Alertable
    894e1594 Semaphore Limit 0x1
    Waiting for reply to LPC MessageId 3786440d:
    Current LPC port e6edd680
    IRP List:
    894cb818: (0006,01d8) Flags: 00000884 Mdl: 00000000
    Impersonation token: e76aa028 (Level Impersonation)
    DeviceMap e558a008
    Owning Process 895497d0 Image: ApplicationA.exe
    Attached Process N/A Image: N/A
    Wait Start TickCount 9426151 Ticks: 162368 (0:00:42:17.000)
    Context Switch Count 1297 LargeStack
    UserTime 00:00:00.031
    KernelTime 00:00:00.359
    Start Address 0x0103e1b0
    Stack Init b7ad8000 Current b7ad7174 Base b7ad8000 Limit b7ad3000 Call 0
    Priority 15 BasePriority 15 PriorityDecrement 0

    0: kd> !lpc message 3786440d
    Searching message 3786440d in threads ...
    Client thread 894e13a8 waiting a reply from 3786440d
    Searching thread 894e13a8 in port rundown queues ...

    Server communication port 0xe71e7f08
    Handles: 1 References: 1
    The LpcDataInfoChainHead queue is empty
    Connected port: 0xe6edd680 Server connection port: 0xe4f348e0

    Client communication port 0xe6edd680
    Handles: 0 References: 1
    The LpcDataInfoChainHead queue is empty

    Server connection port e4f348e0 Name: ServiceBPort
    Handles: 1 References: 156
    Server process : 8a75f438 (ServiceB.exe)
    Queue semaphore : 8a6c4908
    Semaphore state 0 (0x0)
    The message queue is empty
    The LpcDataInfoChainHead queue is empty

    THREAD 8a6439d8 Cid 0234.02b0 Teb: 7ffa5000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Alertable
    8a63b7f0 NotificationEvent
    IRP List:
    8a229a50: (0006,0094) Flags: 00000900 Mdl: 00000000
    Not impersonating
    DeviceMap e1001840
    Owning Process 8a75f438 Image: ServiceB.exe
    Attached Process N/A Image: N/A
    Wait Start TickCount 9426151 Ticks: 162368 (0:00:42:17.000)
    Context Switch Count 31433
    UserTime 00:00:00.375
    KernelTime 00:00:02.625
    Win32 Start Address 0x4ab8f3f1
    Start Address kernel32!BaseThreadStartThunk (0x77e617ec)
    Stack Init ba466000 Current ba465c60 Base ba466000 Limit ba463000 Call 0
    Priority 13 BasePriority 9 PriorityDecrement 0
    ChildEBP RetAddr
    ba465c78 80833491 nt!KiSwapContext+0x26
    ba465ca4 80829a82 nt!KiSwapThread+0x2e5
    ba465cec 80938e0a nt!KeWaitForSingleObject+0x346
    ba465d50 808897ec nt!NtWaitForSingleObject+0x9a
    ba465d50 7c82845c nt!KiFastCallEntry+0xfc (TrapFrame @ ba465d64)
    00ebf250 7c827b79 ntdll!KiFastSystemCallRet
    00ebf254 77e61d1e ntdll!ZwWaitForSingleObject+0xc
    00ebf2c4 77c6a927 kernel32!WaitForSingleObjectEx+0xac
    00ebf2e0 77c69cbf RPCRT4!UTIL_WaitForSyncIO+0x20
    00ebf304 77c6cef0 RPCRT4!UTIL_GetOverlappedResultEx+0x1d
    00ebf32c 77c6b02a RPCRT4!CO_SyncRecv+0x71
    00ebf354 77c6972f RPCRT4!OSF_CCONNECTION::TransSendReceive+0xb8
    00ebf3dc 77c6969c RPCRT4!OSF_CCONNECTION::SendFragment+0x2ae
    00ebf434 77c69842 RPCRT4!OSF_CCALL::SendNextFragment+0x1e2
    00ebf47c 77c69aba RPCRT4!OSF_CCALL::FastSendReceive+0x148
    00ebf498 77c69a3d RPCRT4!OSF_CCALL::SendReceiveHelper+0x5b
    00ebf4c8 77c7feb0 RPCRT4!OSF_CCALL::SendReceive+0x41
    00ebf4d4 77c80845 RPCRT4!I_RpcSendReceive+0x24
    00ebf4e8 77ce415a RPCRT4!NdrSendReceive+0x2b
    00ebf8d8 7d1fac12 RPCRT4!NdrClientCall2+0x22e

Leave a Reply