Crash Dump Analysis Patterns (Part 42b)
Here is another example of Wait Chain pattern where objects are critical sections.
WinDbg can detect them if we use !analyze -v -hang command but it detects only one and not necessarily the longest or widest chain in cases with multiple wait chains:
DERIVED_WAIT_CHAIN:
Dl Eid Cid WaitType
-- --- ------- --------------------------
2 8d8.90c Critical Section -->
4 8d8.914 Critical Section -->
66 8d8.f9c Unknown
Looking at threads we see this chain and we also see that the final thread is blocked waiting for socket.
0:167> ~~[90c]kvL
ChildEBP RetAddr Args to Child
00bbfd9c 7c942124 7c95970f 00000ea0 00000000 ntdll!KiFastSystemCallRet
00bbfda0 7c95970f 00000ea0 00000000 00000000 ntdll!NtWaitForSingleObject+0xc
00bbfddc 7c959620 00000000 00000004 00000000 ntdll!RtlpWaitOnCriticalSection+0x19c
00bbfdfc 6748d2f9 06018b50 00000000 00000000 ntdll!RtlEnterCriticalSection+0xa8
…
…
…
00bbffb8 7c82608b 00315218 00000000 00000000 msvcrt!_endthreadex+0xa3
00bbffec 00000000 77b9b4bc 00315218 00000000 kernel32!BaseThreadStart+0×34
0:167> ~~[914]kvL 100
ChildEBP RetAddr Args to Child
00dbf1cc 7c942124 7c95970f 000004b0 00000000 ntdll!KiFastSystemCallRet
00dbf1d0 7c95970f 000004b0 00000000 00000000 ntdll!NtWaitForSingleObject+0xc
00dbf20c 7c959620 00000000 00000004 0031abcc ntdll!RtlpWaitOnCriticalSection+0x19c
00dbf22c 6748d244 0031abd8 003174e0 00dbf254 ntdll!RtlEnterCriticalSection+0xa8
…
…
…
00dbffb8 7c82608b 00315218 00000000 00000000 msvcrt!_endthreadex+0xa3
00dbffec 00000000 77b9b4bc 00315218 00000000 kernel32!BaseThreadStart+0×34
0:167> ~~[f9c]kvL 100
ChildEBP RetAddr Args to Child
0fe2a09c 7c942124 71933a09 00000b50 00000001 ntdll!KiFastSystemCallRet
0fe2a0a0 71933a09 00000b50 00000001 0fe2a0c8 ntdll!NtWaitForSingleObject+0xc
0fe2a0dc 7194576e 00000b50 00000234 00000000 mswsock!SockWaitForSingleObject+0x19d
0fe2a154 71a12679 00000234 0fe2a1b4 00000001 mswsock!WSPRecv+0x203
0fe2a190 62985408 00000234 0fe2a1b4 00000001 WS2_32!WSARecv+0x77
0fe2a1d0 6298326b 00000234 0274ebc6 00000810 component!wait+0x338
...
...
...
0fe2ffb8 7c82608b 060cfc70 00000000 00000000 msvcrt!_endthreadex+0xa3
0fe2ffec 00000000 77b9b4bc 060cfc70 00000000 kernel32!BaseThreadStart+0x34
If we look at all held critical sections we would see another thread that blocked +125 other threads:
0:167> !locks
CritSec +31abd8 at 0031abd8
WaiterWoken No
LockCount 6
RecursionCount 1
OwningThread f9c
EntryCount 0
ContentionCount 17
*** Locked
CritSec +51e4bd8 at 051e4bd8
WaiterWoken No
LockCount 125
RecursionCount 1
OwningThread 830
EntryCount 0
ContentionCount 7d
*** Locked
CritSec +5f40620 at 05f40620
WaiterWoken No
LockCount 0
RecursionCount 1
OwningThread 920
EntryCount 0
ContentionCount 0
*** Locked
CritSec +60b6320 at 060b6320
WaiterWoken No
LockCount 1
RecursionCount 1
OwningThread 8a8
EntryCount 0
ContentionCount 1
*** Locked
CritSec +6017c60 at 06017c60
WaiterWoken No
LockCount 0
RecursionCount 1
OwningThread 914
EntryCount 0
ContentionCount 0
*** Locked
CritSec +6018b50 at 06018b50
WaiterWoken No
LockCount 3
RecursionCount 1
OwningThread 914
EntryCount 0
ContentionCount 3
*** Locked
CritSec +6014658 at 06014658
WaiterWoken No
LockCount 2
RecursionCount 1
OwningThread 928
EntryCount 0
ContentionCount 2
*** Locked
0:167> ~~[830]kvL 100
ChildEBP RetAddr Args to Child
0ff2f300 7c942124 7c95970f 000004b0 00000000 ntdll!KiFastSystemCallRet
0ff2f304 7c95970f 000004b0 00000000 00000000 ntdll!NtWaitForSingleObject+0xc
0ff2f340 7c959620 00000000 00000004 0031abcc ntdll!RtlpWaitOnCriticalSection+0x19c
0ff2f360 6748d244 0031abd8 003174e0 0ff2f388 ntdll!RtlEnterCriticalSection+0xa8
…
…
…
0ff2ffb8 7c82608b 060cf9a0 00000000 00000000 msvcrt!_endthreadex+0xa3
0ff2ffec 00000000 77b9b4bc 060cf9a0 00000000 kernel32!BaseThreadStart+0×34
Searching for any thread waiting for critical section 051e4bd8 gives us:
8 Id: 8d8.924 Suspend: 1 Teb: 7ffd5000 Unfrozen
ChildEBP RetAddr Args to Child
011ef8e0 7c942124 7c95970f 00000770 00000000 ntdll!KiFastSystemCallRet
011ef8e4 7c95970f 00000770 00000000 00000000 ntdll!NtWaitForSingleObject+0xc
011ef920 7c959620 00000000 00000004 00000000 ntdll!RtlpWaitOnCriticalSection+0x19c
011ef940 677b209d 051e4bd8 011efa0c 057bd36c ntdll!RtlEnterCriticalSection+0xa8
…
…
…
011effb8 7c82608b 00315510 00000000 00000000 msvcrt!_endthreadex+0xa3
011effec 00000000 77b9b4bc 00315510 00000000 kernel32!BaseThreadStart+0×34
and we can construct yet another wait chain:
8 8d8.924 Critical Section -->
67 8d8.830 Critical Section -->
66 8d8.f9c Unknown
- Dmitry Vostokov @ DumpAnalysis.org -
July 30th, 2008 at 12:44 am
[…] is too small unless we have obvious crash or hang signs inside, for example, exceptions, deadlock, wait chain or blocked thread waiting for another coupled […]
January 26th, 2009 at 1:24 am
[…] 117 and 13 were waiting for a critical section […]
March 14th, 2009 at 8:37 am
[…] As usual the critical section list was checked for any locked sections and to find wait chains: […]
July 3rd, 2009 at 4:42 pm
[…] didn’t allow a user connection to proceed. If more users tried to connect we would have seen critical section wait chains that are absent in this […]
September 18th, 2009 at 12:15 pm
[…] Wait Chain (critical sections) […]
October 9th, 2009 at 2:32 pm
[…] problem was gone away. A complete memory dump was saved on the next occurrence and it revealed critical section wait chains in that process but no critical section […]
April 19th, 2010 at 11:38 pm
[…] spooler service process was hanging and its user memory dump shows many threads blocked waiting for critical sections including the main […]
April 26th, 2010 at 8:00 pm
[…] command shows wait chains and signs of critical section corruption. Here is the commented […]
July 18th, 2010 at 2:08 pm
[…] order to get a critical section wait chain starting from the above thread we need to set the process context, use !cs WinDbg command, then […]