Memory Dump Analysis Services plans a Webinar about crash and hang memory dump analysis in cloud computing environments:
http://www.dumpanalysis.com/cloud-memory-dump-analysis
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
Today we introduce an icon for Zombie Processes pattern:
B/W
Color
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
Sometimes added instrumentation via gflags, application and driver verifier options affect system, service or application performance and resources. I call this pattern Instrumentation Side Effect. For example, after enabling full page heap, one process on an x64 machine was growing up to 24GB and its user memory dump shows that every heap allocation was recorded in a stack trace database:
0:055> !gflag
Current NtGlobalFlag contents: 0x02000000
hpa - Place heap allocations at ends of pages
0:055> ~*kc
[...]
48 Id: 117fc.c164 Suspend: 1 Teb: 000007ff`fff52000 Unfrozen
Call Site
ntdll!ZwWaitForSingleObject
ntdll!RtlpWaitOnCriticalSection
ntdll!RtlEnterCriticalSection
verifier!AVrfpDphEnterCriticalSection
verifier!AVrfpDphPreProcessing
verifier!AVrfDebugPageHeapAllocate
ntdll!RtlDebugAllocateHeap
ntdll! ?? ::FNODOBFM::`string’
ntdll!RtlAllocateHeap
msvcrt!malloc
ModuleA!foo1
[…]
49 Id: 117fc.de80 Suspend: 1 Teb: 000007ff`fff54000 Unfrozen
Call Site
ntdll!RtlCompareMemory
ntdll!RtlpLogCapturedStackTrace
ntdll!RtlLogStackTrace
verifier!AVrfpDphPlaceOnFreeList
verifier!AVrfDebugPageHeapFree
ntdll!RtlDebugFreeHeap
ntdll! ?? ::FNODOBFM::`string’
ntdll!RtlFreeHeap
kernel32!HeapFree
msvcrt!free
ModuleB!foo2
[…]
50 Id: 117fc.3700 Suspend: 1 Teb: 000007ff`fff4e000 Unfrozen
Call Site
ntdll!ZwWaitForSingleObject
ntdll!RtlpWaitOnCriticalSection
ntdll!RtlEnterCriticalSection
verifier!AVrfpDphEnterCriticalSection
verifier!AVrfpDphPreProcessing
verifier!AVrfDebugPageHeapFree
ntdll!RtlDebugFreeHeap
ntdll! ?? ::FNODOBFM::`string’
ntdll!RtlFreeHeap
kernel32!HeapFree
msvcrt!free
ModuleC!foo3
[…]
0:055> !runaway
User Mode Time
Thread Time
38:d090 0 days 0:02:28.793
44:ca48 0 days 0:01:04.459
48:c164 0 days 0:00:56.909
43:4458 0 days 0:00:54.475
50:3700 0 days 0:00:43.992
45:6f98 0 days 0:00:38.953
49:de80 0 days 0:00:24.211
1:391c 0 days 0:00:00.639
0:7e90 0 days 0:00:00.109
55:a300 0 days 0:00:00.046
34:10c9c 0 days 0:00:00.015
21:d054 0 days 0:00:00.015
56:b0a0 0 days 0:00:00.000
54:8b78 0 days 0:00:00.000
53:155b8 0 days 0:00:00.000
52:b444 0 days 0:00:00.000
Top modules ModuleA(B, C) from the spiking and heap intensive threads are from the same vendor.
I was able to get a 200×27349 slice from that dump using ImageMagick and it shows almost all virtual memory space filled with traces of this pictorial form (magnified by x8):
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
Today we introduce an icon for Blocked Thread (hardware) pattern:
B/W
Color
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
Got an insider information from Memory Dump Analysis Services that they are developing a Prolog extension for memory dump analysis. Indeed, after asking their development team, I got a proof of concept extension DLL that works on my computer after installing x64 version of SWI-Prolog and copying wdes.dll to pl \ bin installation folder:
0: kd> .load C:\Program Files\pl\bin\wdes.dll
0: kd> !help
Help for Windows Debugging Expert System wdes.dll
help - Shows this help
pload - Loads Prolog interpretor
0: kd> !pload
SWI-Prolog has been loaded
So far so good. Waiting for more extension commands. Perhaps, one day, this extension realizes my dream reminisced while testing a Python extension.
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
Finally had time today to test python WinDbg extension. I installed python 2.6.6 and used Debugging Tools for Windows x64. The script I used was from the extension web site blog slightly modified and called processes.py:
from pykd import *
nt = loadModule( "nt" )
processList = typedVarList( nt.PsActiveProcessHead, "nt", "_EPROCESS", "ActiveProcessLinks" )
for process in processList:
dprintln( "".join( [ chr(i) for i in process.ImageFileName.values() ] ) )
dprintln( "\r" )
I loaded x64 version of pykd.pyd extension and executed the script:
0: kd> !py c:\PyScripts\processes.py
System
smss.exe
csrss.exe
csrss.exe
psxss.exe
winlogon.exe
wininit.exe
services.exe
lsass.exe
lsm.exe
svchost.exe
svchost.exe
svchost.exe
svchost.exe
svchost.exe
svchost.exe
svchost.exe
svchost.exe
spoolsv.exe
mdm.exe
svchost.exe
svchost.exe
svchost.exe
taskhost.exe
dwm.exe
explorer.exe
DTLite.exe
mmc.exe
WZQKPICK.EXE
concentr.exe
pnamain.exe
jusched.exe
wfcrun32.exe
msdtc.exe
iexplore.exe
iexplore.exe
iexplore.exe
splwow64.exe
iexplore.exe
jucheck.exe
iexplore.exe
notepad.exe
notepad.exe
iexplore.exe
notepad.exe
iexplore.exe
notepad.exe
notepad.exe
iexplore.exe
audiodg.exe
CDViewer.exe
wfica32.exe
iexplore.exe
notepad.exe
cmd.exe
conhost.exe
wuauclt.exe
wfica32.exe
wlrmdr.exe
TrustedInstall
wfica32.exe
notepad.exe
iexplore.exe
wmplayer.exe
VISIO.EXE
mspaint.exe
svchost.exe
sppsvc.exe
windbg.exe
mmc.exe
LogonUI.exe
taskeng.exe
NotMyfault.exe
Very good so far. I’m learning now Python language to write more interesting scripts for crash dump analysis pattern diagnostics, mining statistics, formatting and visualization. After browsing Amazon for some time I chose this book for study:
A Primer on Scientific Programming with Python
About 5 or 6 years ago I was thinking about using a Prolog interpreter to write an expert system for crash dump analysis. I even wrote a simple Prolog program to match product hotfixes and was contemplating writing a WinDbg extension especially after I learnt that SWI-Prolog system I used had an interpreter DLL that could be dynamically loaded into a Win32 API application.
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
Similar to Message Box and String Parameter patterns we also have Dialog Box pattern (I’m grateful to Etienne Jeanneau for this suggestion) where we can see dialog window caption and contents when we examine function parameters (I guess this information comes from dialog box template). Although in the examples below we know the dialog purpose from friendly call stack function names for many 3rd-party applications we either don’t have symbols or no such helper functions but we want to know what was on the screen when screenshots were not collected.
The first 2 examples are from notepad and the 3rd is from IE:
0:000> kv
ChildEBP RetAddr Args to Child
0017f5c4 777b073f 777c3c9f 000d023c 00000001 ntdll!KiFastSystemCallRet
0017f5c8 777c3c9f 000d023c 00000001 00000000 user32!NtUserWaitMessage+0xc
0017f5fc 777c2dc0 00310778 000d023c 00000001 user32!DialogBox2+0x202
0017f624 777c2eec 76460000 02a6bc60 000d023c user32!InternalDialogBox+0xd0
0017f644 76489a65 76460000 02a6bc60 000d023c user32!DialogBoxIndirectParamAorW+0×37
0017f680 76489ccf 0017f68c 00000001 0017f6d4 comdlg32!ChooseFontX+0×1ba
0017f6bc 006741c7 0017f6d4 00000111 00000000 comdlg32!ChooseFontW+0×2e
0017f734 0067164a 000d023c 00000021 00000000 notepad!NPCommand+0×4c7
0017f758 777afd72 000d023c 00000111 00000021 notepad!NPWndProc+0×4cf
0017f784 777afe4a 0067146c 000d023c 00000111 user32!InternalCallWinProc+0×23
0017f7fc 777b018d 00000000 0067146c 000d023c user32!UserCallWinProcCheckWow+0×14b
0017f860 777b022b 0067146c 00000000 0017f8a4 user32!DispatchMessageWorker+0×322
0017f870 00671465 0017f888 00000000 0067a21c user32!DispatchMessageW+0xf
0017f8a4 0067195d 00670000 00000000 00231cfa notepad!WinMain+0xe3
0017f934 7652d0e9 7ffd9000 0017f980 77b019bb notepad!_initterm_e+0×1a1
0017f940 77b019bb 7ffd9000 78f7b908 00000000 kernel32!BaseThreadInitThunk+0xe
0017f980 77b0198e 006731ed 7ffd9000 00000000 ntdll!__RtlUserThreadStart+0×23
0017f998 00000000 006731ed 7ffd9000 00000000 ntdll!_RtlUserThreadStart+0×1b
0:000> dc 02a6bc60 l50
02a6bc60 80c800c4 00000000 000d0014 011f0036 ............6...
02a6bc70 000000c4 00460000 006e006f 00000074 ......F.o.n.t…
02a6bc80 004d0008 00200053 00680053 006c0065 ..M.S. .S.h.e.l.
02a6bc90 0020006c 006c0044 00000067 50020000 l. .D.l.g……P
02a6bca0 00000000 00070007 00090028 ffff0440 ……..(…@…
02a6bcb0 00260082 006f0046 0074006e 0000003a ..&.F.o.n.t.:…
02a6bcc0 00000000 50210b51 00000000 00100007 ….Q.!P……..
02a6bcd0 004c0062 ffff0470 00000085 00000000 b.L.p………..
02a6bce0 50020000 00000000 0007006e 0009002c …P….n…,…
02a6bcf0 ffff0441 00460082 006e006f 00200074 A…..F.o.n.t. .
02a6bd00 00740073 00790026 0065006c 0000003a s.t.&.y.l.e.:…
02a6bd10 00000000 50210041 00000000 0010006e ….A.!P….n…
02a6bd20 004c004a ffff0471 00000085 00000000 J.L.q………..
02a6bd30 50020000 00000000 000700bd 0009001e …P…………
02a6bd40 ffff0442 00260082 00690053 0065007a B…..&.S.i.z.e.
02a6bd50 0000003a 00000000 50210b51 00000000 :…….Q.!P….
02a6bd60 001000be 004c0024 ffff0472 00000085 ….$.L.r…….
02a6bd70 00000000 50020007 00000000 00610007 …….P……a.
02a6bd80 00480062 ffff0430 00450080 00660066 b.H.0…..E.f.f.
02a6bd90 00630065 00730074 00000000 50010003 e.c.t.s……..P
0:000> kv
ChildEBP RetAddr Args to Child
0017f5a8 777b073f 777c3c9f 000d023c 00000001 ntdll!KiFastSystemCallRet
0017f5ac 777c3c9f 000d023c 00000001 00000000 user32!NtUserWaitMessage+0xc
0017f5e0 777c2dc0 0044034a 000d023c 00000001 user32!DialogBox2+0x202
0017f608 777c2eec 768a0000 029030bc000d023c user32!InternalDialogBox+0xd0
0017f628 777c10ef 768a0000 029030bc 000d023c user32!DialogBoxIndirectParamAorW+0×37
0017f64c 7695d877 768a0000 00003810 000d023c user32!DialogBoxParamW+0×3f
0017f670 76a744dc 768a0000 00003810 000d023c shell32!SHFusionDialogBoxParam+0×32
0017f6b0 00674416 000d023c 002530dc 00672fc4 shell32!ShellAboutW+0×4d
0017f734 0067164a 000d023c 00000041 00000000 notepad!NPCommand+0×718
0017f758 777afd72 000d023c 00000111 00000041 notepad!NPWndProc+0×4cf
0017f784 777afe4a 0067146c 000d023c 00000111 user32!InternalCallWinProc+0×23
0017f7fc 777b018d 00000000 0067146c 000d023c user32!UserCallWinProcCheckWow+0×14b
0017f860 777b022b 0067146c 00000000 0017f8a4 user32!DispatchMessageWorker+0×322
0017f870 00671465 0017f888 00000000 0067a21c user32!DispatchMessageW+0xf
0017f8a4 0067195d 00670000 00000000 00231cfa notepad!WinMain+0xe3
0017f934 7652d0e9 7ffd9000 0017f980 77b019bb notepad!_initterm_e+0×1a1
0017f940 77b019bb 7ffd9000 78f7b908 00000000 kernel32!BaseThreadInitThunk+0xe
0017f980 77b0198e 006731ed 7ffd9000 00000000 ntdll!__RtlUserThreadStart+0×23
0017f998 00000000 006731ed 7ffd9000 00000000 ntdll!_RtlUserThreadStart+0×1b
0:000> dc 029030bc l50
029030bc ffff0001 00000000 00000000 80c800cc ................
029030cc 0014000c 01130014 000000ee 00410000 ..............A.
029030dc 006f0062 00740075 00250020 00000073 b.o.u.t. .%.s…
029030ec 00000008 004d0000 00200053 00680053 ……M.S. .S.h.
029030fc 006c0065 0020006c 006c0044 00000067 e.l.l. .D.l.g…
0290310c 00000000 00000000 50000043 00370007 ……..C..P..7.
0290311c 00140015 00003009 0082ffff 0000ffff …..0……….
0290312c 00000000 00000000 00000000 5000008c ……………P
0290313c 00370023 000a00c8 00003500 0082ffff #.7……5……
0290314c 00000000 00000000 00000000 5000008c ……………P
0290315c 00410023 000a00eb 0000350b 0082ffff #.A……5……
0290316c 00000000 00000000 00000000 50000080 ……………P
0290317c 004b0023 000a00d2 0000350a 0082ffff #.K……5……
0290318c 00000000 00000000 00000000 50000080 ……………P
0290319c 00550023 002800d2 00003513 0082ffff #.U…(..5……
029031ac 00680054 00200065 00570025 004e0049 T.h.e. .%.W.I.N.
029031bc 004f0044 00530057 004c005f 004e004f D.O.W.S._.L.O.N.
029031cc 00250047 006f0020 00650070 00610072 G.%. .o.p.e.r.a.
029031dc 00690074 0067006e 00730020 00730079 t.i.n.g. .s.y.s.
029031ec 00650074 0020006d 006e0061 00200064 t.e.m. .a.n.d. .
16 Id: 10fc.124c Suspend: 0 Teb: 7ffd7000 Unfrozen
ChildEBP RetAddr Args to Child
053f8098 777b073f 777c3c9f 003d0650 00000001 ntdll!KiFastSystemCallRet
053f809c 777c3c9f 003d0650 00000001 00000000 user32!NtUserWaitMessage+0xc
053f80d0 777c2dc0 002e0378 003d0650 00000001 user32!DialogBox2+0x202
053f80f8 777c2eec 6f270000 03387bd4 003d0650 user32!InternalDialogBox+0xd0
053f8118 777c10ef 6f270000 03387bd4 003d0650 user32!DialogBoxIndirectParamAorW+0×37
053f813c 6f2c5548 6f270000 00005398 003d0650 user32!DialogBoxParamW+0×3f
053f8164 6f2c5743 6f270000 00005398 003d0650 ieframe!Detour_DialogBoxParamW+0×47
053f8188 6f2c56f5 6f270000 00005398 001905ea ieframe!SHFusionDialogBoxParam+0×32
053f9228 6f2c5378 001905ea 053fb540 00000104 ieframe!DoAddToFavDlgEx+0xcf
053fbb5c 6f2c58f9 001905ea 0e69a0c0 053fbff0 ieframe!AddToFavoritesEx+0×349
053fbdb8 6f2c57ee 00000000 053fbff0 00000000 ieframe!CBaseBrowser2::_AddToFavorites+0xe9
053fc0f4 6f2c3e5e 00000000 00000000 00000001 ieframe!CBaseBrowser2::_ExecAddToFavorites+0×123
053fc124 6f39ca4e 6f39c524 00000008 00000001 ieframe!CBaseBrowser2::_ExecExplorer+0xbe
053fc14c 6f39cee8 114ea39c 6f39c524 00000008 ieframe!CBaseBrowser2::Exec+0×12d
053fc17c 6f39cf17 6f39c524 00000008 00000001 ieframe!CShellBrowser2::_Exec_CCommonBrowser+0×80
053fc414 6f498284 114ea39c 6f39c524 00000008 ieframe!CShellBrowser2::Exec+0×626
053fc43c 6f49e5cd 0000a173 00000000 ffffff71 ieframe!CShellBrowser2::_FavoriteOnCommand+0×75
053fc458 6f3c5ea8 0000a173 00000000 00000111 ieframe!CShellBrowser2::_OnDefault+0×3e
053fd6f0 6f394194 0000a173 00000000 0000031a ieframe!CShellBrowser2::v_OnCommand+0xa7b
053fd70c 6f39898d 001905ea 00000111 0000a173 ieframe!CBaseBrowser2::v_WndProc+0×247
053fd770 6f3988db 001905ea 00000111 0000a173 ieframe!CShellBrowser2::v_WndProc+0×3fe
053fd794 777afd72 001905ea 00000111 0000a173 ieframe!CShellBrowser2::s_WndProc+0xfb
053fd7c0 777afe4a 6f39887a 001905ea 00000111 user32!InternalCallWinProc+0×23
053fd838 777b0943 00000000 6f39887a 001905ea user32!UserCallWinProcCheckWow+0×14b
053fd878 777b0b36 00252838 01223dc0 0000a173 user32!SendMessageWorker+0×4b7
053fd898 6f3cf032 001905ea 00000111 0000a173 user32!SendMessageW+0×7c
053fd8d0 6f396ead 0056049c 00000111 0000a173 ieframe!CInternetToolbarHost::v_WndProc+0xf8
053fd8f4 777afd72 0056049c 00000111 0000a173 ieframe!CImpWndProc::s_WndProc+0×65
053fd920 777afe4a 6f396e6e 0056049c 00000111 user32!InternalCallWinProc+0×23
053fd998 777b018d 00000000 6f396e6e 0056049c user32!UserCallWinProcCheckWow+0×14b
053fd9fc 777b022b 6f396e6e 00000000 053ffb14 user32!DispatchMessageWorker+0×322
053fda0c 6f39c1f5 053fda30 00000000 10eec4c0 user32!DispatchMessageW+0xf
053ffb14 6f34337f 0e7c3708 00000000 11bd8dc8 ieframe!CTabWindow::_TabWindowThreadProc+0×54c
053ffbcc 77525179 10eec4c0 00000000 053ffbe8 ieframe!LCIETab_ThreadProc+0×2c1
053ffbdc 7652d0e9 11bd8dc8 053ffc28 77b019bb iertutil!CIsoScope::RegisterThread+0xab
053ffbe8 77b019bb 11bd8dc8 7dd62326 00000000 kernel32!BaseThreadInitThunk+0xe
053ffc28 77b0198e 7752516b 11bd8dc8 00000000 ntdll!__RtlUserThreadStart+0×23
053ffc40 00000000 7752516b 11bd8dc8 00000000 ntdll!_RtlUserThreadStart+0×1b
0:000> dc 03387bd4 l50
03387bd4 ffff0001 00000000 00000000 80c808c0 ................
03387be4 0000000a 011f0000 00000064 00410000 ........d.....A.
03387bf4 00640064 00610020 00460020 00760061 d.d. .a. .F.a.v.
03387c04 0072006f 00740069 00000065 00000008 o.r.i.t.e…….
03387c14 004d0000 00200053 00680053 006c0065 ..M.S. .S.h.e.l.
03387c24 0020006c 006c0044 00000067 00000000 l. .D.l.g…….
03387c34 00000000 50000003 0007000f 00140015 …….P……..
03387c44 00009760 0082ffff 00bfffff 00000000 `……………
03387c54 00000000 00000000 50020000 00070035 ………..P5…
03387c64 000800db 000003f4 0082ffff 00640041 …………A.d.
03387c74 00200064 00200061 00610046 006f0076 d. .a. .F.a.v.o.
03387c84 00690072 00650074 00000000 00000000 r.i.t.e………
03387c94 00000000 50020000 00110035 001000db …….P5…….
03387ca4 000003f5 0082ffff 00640041 00200064 ……..A.d.d. .
03387cb4 00680074 00730069 00770020 00620065 t.h.i.s. .w.e.b.
03387cc4 00610070 00650067 00610020 00200073 p.a.g.e. .a.s. .
03387cd4 00200061 00610066 006f0076 00690072 a. .f.a.v.o.r.i.
03387ce4 00650074 0020002e 006f0054 00610020 t.e… .T.o. .a.
03387cf4 00630063 00730065 00200073 006f0079 c.c.e.s.s. .y.o.
03387d04 00720075 00660020 00760061 0072006f u.r. .f.a.v.o.r.
Stack traces with DialogBoxIndirectParam call and x64 complicates the picture a bit and are subject of another post. Please also note that a user might not see the dialog box you see on a stack trace due to many reasons like terminal session problems or a process running in a non-interactive session.
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
Today we introduce an icon for Blocked Thread (software) pattern:
B/W
Color
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
Stack Trace is a general pattern and there can always be found fine-grained patterns in stack traces as well. Here we discuss the general category of such stack trace patterns called Technology-Specific Subtrace (TSST) and give examples related to COM technology.
Consider this trace:
1: kd> k250
ChildEBP RetAddr
8d5d2808 82a7eb15 nt!KiSwapContext+0x26
8d5d2840 82a7d403 nt!KiSwapThread+0x266
8d5d2868 82a772cf nt!KiCommitThreadWait+0x1df
8d5d28e0 82550d75 nt!KeWaitForSingleObject+0x393
8d5d293c 82550e10 win32k!xxxRealSleepThread+0x1d7
8d5d2958 824ff4b0 win32k!xxxSleepThread+0x2d
8d5d29cc 825547e8 win32k!xxxInterSendMsgEx+0xb1c
8d5d2a1c 825546a4 win32k!xxxSendMessageTimeout+0x13b
8d5d2a44 82533843 win32k!xxxSendMessage+0×28
8d5d2b08 824fd865 win32k!xxxCalcValidRects+0xf7
8d5d2b64 82502c98 win32k!xxxEndDeferWindowPosEx+0×100
8d5d2b84 825170c9 win32k!xxxSetWindowPos+0xf6
8d5d2c08 82517701 win32k!xxxActivateThisWindow+0×2b1
8d5d2c38 82517537 win32k!xxxActivateWindow+0×144
8d5d2c4c 824fd9dd win32k!xxxSwpActivate+0×44
8d5d2ca4 82502c98 win32k!xxxEndDeferWindowPosEx+0×278
8d5d2cc4 824fff82 win32k!xxxSetWindowPos+0xf6
8d5d2d10 82a5342a win32k!NtUserSetWindowPos+0×140
8d5d2d10 76ee64f4 nt!KiFastCallEntry+0×12a (TrapFrame @ 8d5d2d34)
01e2cea0 7621358d ntdll!KiFastSystemCallRet
01e2cea4 6a8fa0eb USER32!NtUserSetWindowPos+0xc
01e2cf14 6a894b13 IEFRAME!SHToggleDialogExpando+0×15a
01e2cf28 6a894d5d IEFRAME!EleDlg::ToggleExpando+0×20
01e2d74c 6a895254 IEFRAME!EleDlg::OnInitDlg+0×229
01e2d7b8 762186ef IEFRAME!EleDlg::DlgProcEx+0×189
01e2d7e4 76209eb2 USER32!InternalCallWinProc+0×23
01e2d860 7620b98b USER32!UserCallDlgProcCheckWow+0xd6
01e2d8a8 7620bb7b USER32!DefDlgProcWorker+0xa8
01e2d8c4 762186ef USER32!DefDlgProcW+0×22
01e2d8f0 76218876 USER32!InternalCallWinProc+0×23
01e2d968 76217631 USER32!UserCallWinProcCheckWow+0×14b
01e2d9a8 76209b1d USER32!SendMessageWorker+0×4d0
01e2da64 76235500 USER32!InternalCreateDialog+0xb0d
01e2da94 76235553 USER32!InternalDialogBox+0xa7
01e2dab4 76235689 USER32!DialogBoxIndirectParamAorW+0×37
01e2dad8 6a5d4952 USER32!DialogBoxParamW+0×3f
01e2db00 6a5d5024 IEFRAME!Detour_DialogBoxParamW+0×47
01e2db24 6a8956df IEFRAME!SHFusionDialogBoxParam+0×32
01e2db58 6a8957bb IEFRAME!EleDlg::ShowDialog+0×398
01e2e638 6a8959d3 IEFRAME!ShowDialogBox+0xb6
01e2eb9c 6a9013ed IEFRAME!ShowElevationPrompt+0×1dd
01e2f010 7669fc8f IEFRAME!CIEUserBrokerObject::BrokerCoCreateInstance+0×202
01e2f040 76704c53 RPCRT4!Invoke+0×2a
01e2f448 76d9d936 RPCRT4!NdrStubCall2+0×2d6
01e2f490 76d9d9c6 ole32!CStdStubBuffer_Invoke+0xb6
01e2f4d8 76d9df1f ole32!SyncStubInvoke+0×3c
01e2f524 76cb213c ole32!StubInvoke+0xb9
01e2f600 76cb2031 ole32!CCtxComChnl::ContextInvoke+0xfa
01e2f61c 76d9a754 ole32!MTAInvoke+0×1a
01e2f64c 76d9dcbb ole32!AppInvoke+0xab
01e2f72c 76d9a773 ole32!ComInvokeWithLockAndIPID+0×372
01e2f778 7669f34a ole32!ThreadInvoke+0×302
01e2f7b4 7669f4da RPCRT4!DispatchToStubInCNoAvrf+0×4a
01e2f80c 7669f3c6 RPCRT4!RPC_INTERFACE::DispatchToStubWorker+0×16c
01e2f834 766a0cef RPCRT4!RPC_INTERFACE::DispatchToStub+0×8b
01e2f86c 7669f882 RPCRT4!RPC_INTERFACE::DispatchToStubWithObject+0xb2
01e2f8b8 7669f7a4 RPCRT4!LRPC_SCALL::DispatchRequest+0×23b
01e2f8d8 7669f763 RPCRT4!LRPC_SCALL::QueueOrDispatchCall+0xbd
01e2f8f4 7669f5ff RPCRT4!LRPC_SCALL::HandleRequest+0×34f
01e2f928 7669f573 RPCRT4!LRPC_SASSOCIATION::HandleRequest+0×144
01e2f960 7669ee4f RPCRT4!LRPC_ADDRESS::HandleRequest+0xbd
01e2f9dc 7669ece7 RPCRT4!LRPC_ADDRESS::ProcessIO+0×50a
01e2f9e8 766a1357 RPCRT4!LrpcServerIoHandler+0×16
01e2f9f8 76ecd3a3 RPCRT4!LrpcIoComplete+0×16
01e2fa20 76ed0748 ntdll!TppAlpcpExecuteCallback+0×1c5
01e2fb88 76e11174 ntdll!TppWorkerThread+0×5a4
01e2fb94 76efb3f5 kernel32!BaseThreadInitThunk+0xe
01e2fbd4 76efb3c8 ntdll!__RtlUserThreadStart+0×70
01e2fbec 00000000 ntdll!_RtlUserThreadStart+0×1b
In the middle of the stack trace we see COM interface invocation in IEFRAME module. The similar stack trace fragment can be found in the following stack trace where COM IRemUnknown interface implementation resides in .NET CLR mscorwks module:
0:000> kL
ChildEBP RetAddr
0018a924 68b5f8f0 mscorwks!SafeReleaseHelper+0x77
0018a958 68b04a99 mscorwks!SafeRelease+0x2f
0018a98c 68b04860 mscorwks!IUnkEntry::Free+0x68
0018a9a0 68b049b5 mscorwks!RCW::ReleaseAllInterfaces+0x18
0018a9d0 68b049e1 mscorwks!RCW::ReleaseAllInterfacesCallBack+0xbd
0018aa00 68c0a108 mscorwks!RCW::Cleanup+0x22
0018aa0c 68c0a570 mscorwks!RCWCleanupList::ReleaseRCWListRaw+0x16
0018aa3c 68bd4b3d mscorwks!RCWCleanupList::ReleaseRCWListInCorrectCtx+0xdf
0018aa4c 75dd8c2e mscorwks!CtxEntry::EnterContextCallback+0×89
0018aa68 763c586c ole32!CRemoteUnknown::DoCallback+0×7a
0018aa84 764405f1 rpcrt4!Invoke+0×2a
0018ae88 75efd936 rpcrt4!NdrStubCall2+0×2ea
0018aed0 75efd9c6 ole32!CStdStubBuffer_Invoke+0xb6
0018af18 75efdf1f ole32!SyncStubInvoke+0×3c
0018af64 75e1223c ole32!StubInvoke+0xb9
0018b040 75e12131 ole32!CCtxComChnl::ContextInvoke+0xfa
0018b05c 75e130fa ole32!MTAInvoke+0×1a
0018b088 75efde47 ole32!STAInvoke+0×46
0018b0bc 75efdcbb ole32!AppInvoke+0xab
0018b19c 75efe34c ole32!ComInvokeWithLockAndIPID+0×372
0018b1c4 75e12ed2 ole32!ComInvoke+0xc5
0018b1d8 75e12e91 ole32!ThreadDispatch+0×23
0018b21c 75a06238 ole32!ThreadWndProc+0×161
0018b248 75a068ea user32!InternalCallWinProc+0×23
0018b2c0 75a07d31 user32!UserCallWinProcCheckWow+0×109
0018b320 75a07dfa user32!DispatchMessageWorker+0×3bc
0018b330 75ddd6be user32!DispatchMessageW+0xf
0018b360 75ddd66d ole32!CCliModalLoop::PeekRPCAndDDEMessage+0×4c
0018b390 75ddd57e ole32!CCliModalLoop::FindMessage+0×30
0018b3f0 75ddd633 ole32!CCliModalLoop::HandleWakeForMsg+0×41
0018b408 75dd1117 ole32!CCliModalLoop::BlockFn+0xc3
0018b488 68a6c905 ole32!CoWaitForMultipleHandles+0xcd
0018b4a8 68a6c866 mscorwks!NT5WaitRoutine+0×51
0018b514 68a6c7ca mscorwks!MsgWaitHelper+0xa5
0018b534 68b5fbe4 mscorwks!Thread::DoAppropriateAptStateWait+0×28
0018b5b8 68b5fc79 mscorwks!Thread::DoAppropriateWaitWorker+0×13c
0018b608 68b5fdf9 mscorwks!Thread::DoAppropriateWait+0×40
0018b664 68a1c5b6 mscorwks!CLREvent::WaitEx+0xf7
0018b678 68b1adb4 mscorwks!CLREvent::Wait+0×17
0018b6c8 68b1ab2a mscorwks!WKS::GCHeap::FinalizerThreadWait+0xfb
0018b764 08fa12c1 mscorwks!GCInterface::RunFinalizers+0×99
[…]
A TSST usually spans several modules. In any stack trace we can also find several TSST that may be overlapping. For example, in the first stack trace above we can discern fragments of COM, RPC, LPC, GUI Dialog, Window Management, and Window Messaging subtraces. In the second trace we can also see GC, Modal Loop, COM Wrapper, and Interface Management stack frames.
The closest software trace analysis pattern here is Implementation Discourse.
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
Finally I got a few good crash dumps illustrating Livelock pattern when 2 threads are looping while acquiring and releasing a resource but not progressing. We have these signs in selected WinDbg output below:
- high contention patterns or context switch counts
- increased CPU time in user and / or kernel mode
- at least one livelocked thread is scheduled for execution
- one of livelocked threads has unusual priority boost
- the same thread stack trace for both livelocked threads having similar stats like spent time and context switch counts
- zero waiting ticks
1: kd> !locks
Resource @ 0xfffffa8008464528 Exclusively owned
Contention Count = 43743004
NumberOfExclusiveWaiters = 1
Threads: fffffa8008315b60-01<*>
Threads Waiting On Exclusive Access:
fffffa8005769660
41080 total locks, 1 locks currently held
1: kd> !running
Prcbs Current Next
1 fffff88001e68180 fffff88001e72fc0 fffffa8008315b60 …………….
We have these stack traces from stack trace collection:
THREAD fffffa8008315b60 Cid 0724.2a28 Teb: 000007fffff9c000 Win32Thread: 0000000000000000 ????
IRP List:
fffffa80082e5990: (0006,0118) Flags: 00060000 Mdl: 00000000
Not impersonating
DeviceMap fffff8a009f434e0
Owning Process fffffa8005726360 Image: ProcessA.exe
Attached Process N/A Image: N/A
Wait Start TickCount 522197 Ticks: 0
Context Switch Count 21665144
UserTime 00:00:40.373
KernelTime 00:02:42.791
Win32 Start Address 0×000007fef6939430
Stack Init fffff88007321db0 Current fffff88007321520
Base fffff88007322000 Limit fffff8800731c000 Call 0
Priority 8 BasePriority 6 UnusualBoost 1 ForegroundBoost 0 IoPriority 2 PagePriority 5
Child-SP RetAddr Call Site
fffff880`07321560 fffff800`0168a992 nt!KiSwapContext+0×7a
fffff880`073216a0 fffff800`0168ccff nt!KiCommitThreadWait+0×1d2
fffff880`07321730 fffff800`0164c242 nt!KeWaitForSingleObject+0×19f
fffff880`073217d0 fffff800`0168b5ac nt!ExpWaitForResource+0xae
fffff880`07321840 fffff880`04608d91 nt!ExAcquireResourceExclusiveLite+0×14f
fffff880`073218b0 fffff880`04609e4e DriverA!foo+0×42
[…]
fffff880`07321a10 fffff800`0199ef66 nt!IopXxxControlFile+0×607
fffff880`07321b40 fffff800`01682993 nt!NtDeviceIoControlFile+0×56
fffff880`07321bb0 00000000`76ffff2a nt!KiSystemServiceCopyEnd+0×13 (TrapFrame @ fffff880`07321c20)
00000000`03a1f488 000007fe`fd06b399 ntdll!NtDeviceIoControlFile+0xa
00000000`03a1f490 00000000`76ea610f KERNELBASE!DeviceIoControl+0×75
00000000`03a1f500 000007fe`f74f3d7c kernel32!DeviceIoControlImplementation+0×7f
[…]
THREAD fffffa8005769660 Cid 0724.10b0 Teb: 000007fffffa6000 Win32Thread: 0000000000000000 WAIT: (WrResource) KernelMode Non-Alertable
fffffa8006661f20 SynchronizationEvent
IRP List:
fffffa8006b1ac10: (0006,0118) Flags: 00060000 Mdl: 00000000
Not impersonating
DeviceMap fffff8a009f434e0
Owning Process fffffa8005726360 Image: ProcessA.exe
Attached Process N/A Image: N/A
Wait Start TickCount 522197 Ticks: 0
Context Switch Count 21601988
UserTime 00:00:30.147
KernelTime 00:02:30.972
Win32 Start Address 0×000007fef6939430
Stack Init fffff880071bbdb0 Current fffff880071bb520
Base fffff880071bc000 Limit fffff880071b6000 Call 0
Priority 7 BasePriority 6 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5
Child-SP RetAddr Call Site
fffff880`071bb560 fffff800`0168a992 nt!KiSwapContext+0×7a
fffff880`071bb6a0 fffff800`0168ccff nt!KiCommitThreadWait+0×1d2
fffff880`071bb730 fffff800`0164c242 nt!KeWaitForSingleObject+0×19f
fffff880`071bb7d0 fffff800`0168b5ac nt!ExpWaitForResource+0xae
fffff880`071bb840 fffff880`04608d91 nt!ExAcquireResourceExclusiveLite+0×14f
fffff880`071bb8b0 fffff880`04609e4e DriverA!foo+0×42
[…]
fffff880`071bba10 fffff800`0199ef66 nt!IopXxxControlFile+0×607
fffff880`071bbb40 fffff800`01682993 nt!NtDeviceIoControlFile+0×56
fffff880`071bbbb0 00000000`76ffff2a nt!KiSystemServiceCopyEnd+0×13 (TrapFrame @ fffff880`071bbc20)
00000000`033bf708 000007fe`fd06b399 ntdll!NtDeviceIoControlFile+0xa
00000000`033bf710 00000000`76ea610f KERNELBASE!DeviceIoControl+0×75
00000000`033bf780 000007fe`f74f3d7c kernel32!DeviceIoControlImplementation+0×7f
[…]
In both traces we have DriverA as Blocking Module.
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
Today we introduce an icon for Wait Chain (named pipes) pattern:
B/W
Color
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
An IE window was frozen and user process memory dump files from all IE process instances inside a user session were saved. The first instance revealed a main thread which self-diagnosed a hang tab and was blocked in a window message chain:
0:000> kL
ChildEBP RetAddr
0012ea84 7e4194be ntdll!KiFastSystemCallRet
0012eac0 7e4292e3 user32!NtUserMessageCall+0xc
0012eae0 3e4171a1 user32!SendMessageW+0×7f
0012eaf4 3e41863f ieframe!CTabWindow::_MakeBlockingCallToHungTabToTriggerNtUserHangDetection+0×11
0012eb00 3e31d261 ieframe!CTabWindow::MarkTabAsHung+0×48
0012eb1c 7e418734 ieframe!FrameTabWndProc+0×5c
0012eb48 7e418816 user32!InternalCallWinProc+0×28
0012ebb0 7e4189cd user32!UserCallWinProcCheckWow+0×150
0012ec10 7e418a10 user32!DispatchMessageWorker+0×306
0012ec20 3e2ed530 user32!DispatchMessageW+0xf
0012ec88 3e204dd9 ieframe!CBrowserFrame::FrameMessagePump+0×3d7
0012ecd0 3e1ea0a7 ieframe!BrowserThreadProc+0xf7
0012ecf0 3e1ea004 ieframe!BrowserNewThreadProc+0×88
0012fd60 3e1e9f26 ieframe!SHOpenFolderWindow+0×10e
0012fd84 3e1e9c75 ieframe!IEWinMainEx+0×1ff
0012fda0 3e1ebf1d ieframe!IEWinMain+0×77
0012fdd8 00402e11 ieframe!LCIEStartAsFrame+0×252
0012ff2c 0040128e iexplore!wWinMain+0×368
0012ffc0 7c817077 iexplore!_initterm_e+0×1b1
0012fff0 00000000 kernel32!BaseProcessStart+0×23
We looked at other IE instances and found the one thread with a blocking module:
0:017> kL 100
ChildEBP RetAddr
02c34100 7c90df5a ntdll!KiFastSystemCallRet
02c34104 7c8025db ntdll!ZwWaitForSingleObject+0xc
02c34168 7c802542 kernel32!WaitForSingleObjectEx+0xa8
02c3417c 009f0ed9 kernel32!WaitForSingleObject+0x12
WARNING: Stack unwind information not available. Following frames may be wrong.
02c34a08 00bc2c9a ModuleA!DllCanUnloadNow+0×6db39
02c3526c 00bc2fa4 ModuleA!DllCanUnloadNow+0×23f8fa
02c35ae0 00f6413c ModuleA!DllCanUnloadNow+0×23fc04
02c363e8 00c761ab ModuleA!DllCanUnloadNow+0×5e0d9c
02c36c74 00c74daa ModuleA!DllCanUnloadNow+0×2f2e0b
02c374e4 3d1a9eb4 ModuleA!DllCanUnloadNow+0×2f1a0a
02c3753c 3d0ed032 mshtml!CView::SetObjectRectsHelper+0×98
02c37578 3cf7e43b mshtml!CView::EndDeferSetObjectRects+0×75
02c375bc 3cf2542d mshtml!CView::EnsureView+0×39f
02c375d8 3cf4072c mshtml!CElement::EnsureRecalcNotify+0×17c
02c37614 3cf406ce mshtml!CElement::get_clientHeight_Logical+0×54
02c37628 3d0822a1 mshtml!CElement::get_clientHeight+0×27
02c37648 3cf8ad53 mshtml!G_LONG+0×7b
02c376bc 3cf96e21 mshtml!CBase::ContextInvokeEx+0×5d1
02c3770c 3cfa2baf mshtml!CElement::ContextInvokeEx+0×9d
02c37738 3cf8a751 mshtml!CElement::VersionedInvokeEx+0×2d
02c37788 3d7c389a mshtml!PlainInvokeEx+0xea
02c377c8 3d7c37e6 jscript!IDispatchExInvokeEx2+0xf8
02c37804 3d7c4d26 jscript!IDispatchExInvokeEx+0×6a
02c378c4 3d7c4c80 jscript!InvokeDispatchEx+0×98
02c378f8 3d7c4996 jscript!VAR::InvokeByName+0×135
02c37a90 3d7c11ab jscript!CScriptRuntime::Run+0×654
02c37b78 3d7c10e5 jscript!ScrFncObj::CallWithFrameOnStack+0xff
02c37bc4 3d7c48ac jscript!ScrFncObj::Call+0×8f
02c37c48 3d7c26c5 jscript!NameTbl::InvokeInternal+0×137
02c37c7c 3d7c2f14 jscript!VAR::InvokeByDispID+0×17c
02c37e18 3d7c11ab jscript!CScriptRuntime::Run+0×29e0
02c37f00 3d7c10e5 jscript!ScrFncObj::CallWithFrameOnStack+0xff
02c37f4c 3d7c48ac jscript!ScrFncObj::Call+0×8f
02c37fd0 3d7c26c5 jscript!NameTbl::InvokeInternal+0×137
02c38004 3d7c4d93 jscript!VAR::InvokeByDispID+0×17c
02c381a0 3d7c11ab jscript!CScriptRuntime::Run+0×2abe
02c38288 3d7c10e5 jscript!ScrFncObj::CallWithFrameOnStack+0xff
02c382d4 3d7c48ac jscript!ScrFncObj::Call+0×8f
02c38358 3d7c26c5 jscript!NameTbl::InvokeInternal+0×137
02c3838c 3d7c4d93 jscript!VAR::InvokeByDispID+0×17c
02c38528 3d7c11ab jscript!CScriptRuntime::Run+0×2abe
02c38610 3d7c10e5 jscript!ScrFncObj::CallWithFrameOnStack+0xff
02c3865c 3d7c2805 jscript!ScrFncObj::Call+0×8f
02c386e0 3d7c26c5 jscript!NameTbl::InvokeInternal+0×2a2
02c38714 3d7c41fc jscript!VAR::InvokeByDispID+0×17c
02c38754 3d7c22c1 jscript!VAR::InvokeJSObj<SYM *>+0xb8
02c38790 3d7c2b6d jscript!VAR::InvokeByName+0×170
02c387dc 3d7c4035 jscript!VAR::InvokeDispName+0×7a
02c3880c 3d7c4d93 jscript!VAR::InvokeByDispID+0xce
02c389a8 3d7c11ab jscript!CScriptRuntime::Run+0×2abe
02c38a90 3d7c10e5 jscript!ScrFncObj::CallWithFrameOnStack+0xff
02c38adc 3d7c48ac jscript!ScrFncObj::Call+0×8f
02c38b60 3d7c26c5 jscript!NameTbl::InvokeInternal+0×137
02c38b94 3d7c4d93 jscript!VAR::InvokeByDispID+0×17c
02c38d30 3d7c11ab jscript!CScriptRuntime::Run+0×2abe
02c38e18 3d7c10e5 jscript!ScrFncObj::CallWithFrameOnStack+0xff
02c38e64 3d7c2805 jscript!ScrFncObj::Call+0×8f
02c38ee8 3d7c26c5 jscript!NameTbl::InvokeInternal+0×2a2
02c38f1c 3d7c41fc jscript!VAR::InvokeByDispID+0×17c
02c38f5c 3d7c22c1 jscript!VAR::InvokeJSObj<SYM *>+0xb8
02c38f98 3d7c2b6d jscript!VAR::InvokeByName+0×170
02c38fe4 3d7c4035 jscript!VAR::InvokeDispName+0×7a
02c39014 3d7c2f14 jscript!VAR::InvokeByDispID+0xce
02c391b0 3d7c11ab jscript!CScriptRuntime::Run+0×29e0
02c39298 3d7c10e5 jscript!ScrFncObj::CallWithFrameOnStack+0xff
02c392e4 3d7c0f13 jscript!ScrFncObj::Call+0×8f
02c39360 3d7a3ea3 jscript!CSession::Execute+0×175
02c393ac 3d7a552f jscript!COleScript::ExecutePendingScripts+0×1c0
02c39410 3d7a5345 jscript!COleScript::ParseScriptTextCore+0×29a
02c39438 3ceca304 jscript!COleScript::ParseScriptText+0×30
02c39490 3d0955af mshtml!CScriptCollection::ParseScriptText+0×219
02c3b528 3d07a59c mshtml!CWindow::ExecuteScriptUri+0×19f
02c3b570 3d0958fd mshtml!CWindow::NavigateEx+0×5a
02c3b5dc 3d10a995 mshtml!CDoc::ExecuteScriptUri+0×262
02c3b648 3d056840 mshtml!CWindow::SuperNavigateInternal+0×335
02c3b67c 3e27d357 mshtml!CWindow::SuperNavigate2WithBindFlags+0×29
02c3b70c 3e27d1fb ieframe!CDocObjectHost::_NavigateDocument+0×1d9
02c3c7b0 3e27ab0e ieframe!CDocObjectHost::SetTarget+0×37b
02c3c7e8 3e27a8f1 ieframe!CDocObjectView::CreateViewWindow2+0xea
02c3c820 3e27a22a ieframe!CDocObjectView::CreateViewWindow+0×49
02c3c8dc 3e27a149 ieframe!FileCabinet_CreateViewWindow2+0×29d
02c3c900 3e27a067 ieframe!CBaseBrowser2::_CreateViewWindow+0×2b
02c3c940 3e279f1b ieframe!CBaseBrowser2::_CreateNewShellView+0×1a6
02c3c970 3e279e4e ieframe!CBaseBrowser2::_CreateNewShellViewPidl+0xe1
02c3d9f4 3e27c2dd ieframe!CBaseBrowser2::v_NavigateToPidl+0×2c3
02c3dc44 3e2ad948 ieframe!CBaseBrowser2::_OnGoto+0×2fb
02c3dc58 3e2e8a01 ieframe!CBaseBrowser2::v_WndProc+0×340
02c3dcbc 3e2e894f ieframe!CShellBrowser2::v_WndProc+0×3fe
02c3dce0 7e418734 ieframe!CShellBrowser2::s_WndProc+0xfb
02c3dd0c 7e418816 user32!InternalCallWinProc+0×28
02c3dd74 7e4189cd user32!UserCallWinProcCheckWow+0×150
02c3ddd4 7e418a10 user32!DispatchMessageWorker+0×306
02c3dde4 3e2ec2a5 user32!DispatchMessageW+0xf
02c3feec 3e293357 ieframe!CTabWindow::_TabWindowThreadProc+0×54c
02c3ffa4 3e134435 ieframe!LCIETab_ThreadProc+0×2c1
02c3ffb4 7c80b729 iertutil!CIsoScope::RegisterThread+0xab
02c3ffec 00000000 kernel32!BaseThreadStart+0×37
The ModuleA component was quite ubiquitous and seen in other threads from the same process:
1 Id: e8c.b5c Suspend: 1 Teb: 7ffdc000 Unfrozen
ChildEBP RetAddr
01f9f698 7c90d21a ntdll!KiFastSystemCallRet
01f9f69c 7c8023f1 ntdll!NtDelayExecution+0xc
01f9f6f4 7c802455 kernel32!SleepEx+0x61
01f9f704 009d284a kernel32!Sleep+0xf
WARNING: Stack unwind information not available. Following frames may be wrong.
01f9ffb4 7c80b729 ModuleA!DllCanUnloadNow+0×4f4aa
01f9ffec 00000000 kernel32!BaseThreadStart+0×37
25 Id: e8c.f20 Suspend: 1 Teb: 7ff9c000 Unfrozen
ChildEBP RetAddr
086acac4 7c90df5a ntdll!KiFastSystemCallRet
086acac8 7c8025db ntdll!ZwWaitForSingleObject+0xc
086acb2c 7c802542 kernel32!WaitForSingleObjectEx+0xa8
086acb40 00fbba3a kernel32!WaitForSingleObject+0x12
WARNING: Stack unwind information not available. Following frames may be wrong.
086ad3c8 00fbc139 ModuleA!DllCanUnloadNow+0×63869a
086adc38 00faba75 ModuleA!DllCanUnloadNow+0×638d99
086ae4c8 00fa0da8 ModuleA!DllCanUnloadNow+0×6286d5
086aed60 00a45331 ModuleA!DllCanUnloadNow+0×61da08
086af6c4 00a44b10 ModuleA!DllCanUnloadNow+0xc1f91
086affb4 7c80b729 ModuleA!DllCanUnloadNow+0xc1770
086affec 00000000 kernel32!BaseThreadStart+0×37
Fortunately we also had a complete memory dump generated shortly after hang and from it we could find dual stack traces from the same processes and find that blocked threads were waiting for named pipes with endpoints on another PC. So we advised to take a complete memory dump from the coupled machine.
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
This is the variant of the general Wait Chain pattern where threads are waiting for named pipes. This is visible when we examining the pending IRP of a blocked thread:
THREAD 88ec9020 Cid 17a0.2034 Teb: 7ffad000 Win32Thread: bc28c6e8 WAIT: (Unknown) UserMode Non-Alertable
89095f48 Semaphore Limit 0x10000
IRP List:
89a5a370: (0006,0094) Flags: 00000900 Mdl: 00000000
Not impersonating
DeviceMap d6c30c48
Owning Process 88fffd88 Image: ApplicationA.exe
Attached Process N/A Image: N/A
Wait Start TickCount 5632994 Ticks: 2980 (0:00:00:46.562)
Context Switch Count 2269 LargeStack
UserTime 00:00:00.000
KernelTime 00:00:00.000
Win32 Start Address 0×00a262d0
Start Address kernel32!BaseThreadStartThunk (0×77e617ec)
Stack Init b204c000 Current b204bc60 Base b204c000 Limit b2048000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0
ChildEBP RetAddr
b204bc78 80833ec5 nt!KiSwapContext+0×26
b204bca4 80829c14 nt!KiSwapThread+0×2e5
b204bcec 8093b174 nt!KeWaitForSingleObject+0×346
b204bd50 8088b41c nt!NtWaitForSingleObject+0×9a
b204bd50 7c82860c nt!KiFastCallEntry+0xfc (TrapFrame @ b204bd64)
058fcabc 7c827d29 ntdll!KiFastSystemCallRet
058fcac0 77e61d1e ntdll!ZwWaitForSingleObject+0xc
058fcb30 77e61c8d kernel32!WaitForSingleObjectEx+0xac
058fcb44 00f98b4a kernel32!WaitForSingleObject+0×12
[…]
058fffec 00000000 kernel32!BaseThreadStart+0×34
0: kd> !irp 89a5a370
Irp is active with 1 stacks 1 is current (= 0×89a5a3e0)
No Mdl: No System Buffer: Thread 88ec9020: Irp stack trace.
cmd flg cl Device File Completion-Context
>[ 3, 0] 0 1 89ebee90 891d4f90 00000000-00000000 pending
\FileSystem\Npfs
Args: 00000100 00000000 00000000 00000000
0: kd> !fileobj 891d4f90
\ServiceB\SVC
Device Object: 0x89ebee90 \FileSystem\Npfs
Vpb is NULL
Flags: 0x40080
Named Pipe
Handle Created
FsContext: 0xdaeca230 FsContext2: 0x8949bdb0
Private Cache Map: 0x00000001
CurrentByteOffset: 0
The pipe chain can also extend from thread to thread and even cross machine boundary.
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
When loading a process user memory dump we recognized it as abridged and embedded comment pointed to a spiking thread:
Loading Dump File [ApplicationA_101212_165342.dmp]
User Mini Dump File: Only registers, stack and portions of memory are available
Comment: '
*** procdump -c 60 -s 5 -n 3 ApplicationA.exe
*** Process exceeded 60% CPU for 5 seconds. Thread consuming CPU: 540 (0×21c)‘
This thread is already default:
0:005> ~
0 Id: c1c.c20 Suspend: 0 Teb: 7ffdf000 Unfrozen
1 Id: c1c.c44 Suspend: 0 Teb: 7ffde000 Unfrozen
2 Id: c1c.d34 Suspend: 0 Teb: 7ffdc000 Unfrozen
3 Id: c1c.d38 Suspend: 0 Teb: 7ffda000 Unfrozen
4 Id: c1c.d3c Suspend: 0 Teb: 7ffd9000 Unfrozen
. 5 Id: c1c.21c Suspend: 0 Teb: 7ffd8000 Unfrozen
6 Id: c1c.1c10 Suspend: 0 Teb: 7ffdd000 Unfrozen
7 Id: c1c.1678 Suspend: 0 Teb: 7ffd6000 Unfrozen
8 Id: c1c.cbc Suspend: 0 Teb: 7ffd5000 Unfrozen
9 Id: c1c.1754 Suspend: 0 Teb: 7ffaf000 Unfrozen
10 Id: c1c.c40 Suspend: 0 Teb: 7ffad000 Unfrozen
11 Id: c1c.1d24 Suspend: 0 Teb: 7ffd7000 Unfrozen
The stack trace looks incorrect:
0:005> kL
ChildEBP RetAddr
01abc4d8 6efba23d ntdll!KiFastSystemCallRet
WARNING: Stack unwind information not available. Following frames may be wrong.
01abc988 7c820833 ModuleB+0×2a23d
01abcbe4 7c8207f6 kernel32!GetVolumeNameForRoot+0×26
01abcc0c 7c82e6de kernel32!BasepGetVolumeNameForVolumeMountPoint+0×75
01abcc54 6efaf70b kernel32!GetVolumePathNameW+0×18a
01abccdc 6efbd1a6 ModuleB+0×1f70b
01abcce0 00000000 ModuleB+0×2d1a6
However, we see a 3rd party top module and advise to keep an eye on it:
0:005> lmt m ModuleB
start end module name
6ef90000 6efff000 ModuleB Wed Mar 10 20:18:21 2010
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
Similar to Blocking Module pattern we also have Top Module pattern where the difference is in stack trace syntax only. A top module is any module we choose that is simply on top of a stack trace. Most of the time it is likely to be a non-OS vendor module. Whether the stack trace is well-formed and semantically sound or incorrect is irrelevant:
0:005> kL
ChildEBP RetAddr
01abc4d8 6efba23d ntdll!KiFastSystemCallRet
WARNING: Stack unwind information not available. Following frames may be wrong.
01abc988 7c820833 ModuleB+0×2a23d
01abcbe4 7c8207f6 kernel32!GetVolumeNameForRoot+0×26
01abcc0c 7c82e6de kernel32!BasepGetVolumeNameForVolumeMountPoint+0×75
01abcc54 6efaf70b kernel32!GetVolumePathNameW+0×18a
01abccdc 6efbd1a6 ModuleB+0×1f70b
01abcce0 00000000 ModuleB+0×2d1a6
Here we can also check the validity of ModuleB code by backwards disassembly of 6efba23d return address (ub command) unless we have an abridged dump file (minidump) and we need to specify the image file path in WinDbg,
Why a top module is important? In various troubleshooting scenarious we can check the module timestamp (Not My Version pattern) and other useful information (lmv and !lmi WinDbg commands). If we suspect the module belonging to hooksware we can also recommend removing it or its software vendor package for testing purposes.
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
With the new year starts the new initiative to integrate traditional multidisciplinary debugging approaches and methodologies with multiplatform pattern-driven software problem solving, unified debugging patterns, best practices in memory dump analysis and software tracing, computer security, economics, and the new emerging trends I’m going to write about during this year.
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
Easy to remember abbreviation SCP (Software Crash Patterns) consists of 3 practices:
- Scripts
- Checklists
- Patterns
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
The following pattern is useful for inconsistent dumps or incomplete supporting information: Environment Hint. It is mostly environment variable information for troubleshooting suggestions such as product elimination for testing purposes and / or necessary upgrade, for example:
0: kd> !peb
PEB at 7ffd7000
InheritedAddressSpace: No
ReadImageFileExecOptions: Yes
BeingDebugged: No
ImageBaseAddress: 01000000
Ldr 7c8897e0
Ldr.Initialized: Yes
Ldr.InInitializationOrderModuleList: 00081f18 . 000f9e88
Ldr.InLoadOrderModuleList: 00081eb0 . 000f9e78
Ldr.InMemoryOrderModuleList: 00081eb8 . 000f9e80
Base TimeStamp Module
1000000 45d6a03c Feb 17 06:27:08 2007 C:\WINNT\system32\svchost.exe
7c800000 49900d60 Feb 09 11:02:56 2009 C:\WINNT\system32\ntdll.dll
[...]
SubSystemData: 00000000
ProcessHeap: 00080000
ProcessParameters: 00020000
WindowTitle: 'C:\WINNT\system32\svchost.exe'
ImageFile: 'C:\WINNT\system32\svchost.exe'
CommandLine: 'C:\WINNT\system32\svchost.exe -k rpcss'
DllPath: [...]
Environment: 00010000
ALLUSERSPROFILE=C:\Documents and Settings\All Users
[...]
PROTECTIONDIR=C:\Documents and Settings\All Users\Application Data\3rdPartyAntivirus\Protection
[…]
Path= […]
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
Dual Stack Trace is the kernel mode and space counterpart to a user mode and space stack trace and vice versa, for example:
25 Id: e8c.f20 Suspend: 1 Teb: 7ff9c000 Unfrozen
ChildEBP RetAddr
086acac4 7c90df5a ntdll!KiFastSystemCallRet
086acac8 7c8025db ntdll!ZwWaitForSingleObject+0xc
086acb2c 7c802542 kernel32!WaitForSingleObjectEx+0xa8
086acb40 00fbba3a kernel32!WaitForSingleObject+0×12
WARNING: Stack unwind information not available. Following frames may be wrong.
086ad3c8 00fbc139 ModuleA!DllCanUnloadNow+0×638b4a
086adc38 00faba75 ModuleA!DllCanUnloadNow+0×639249
086ae4c8 00fa0da8 ModuleA!DllCanUnloadNow+0×629b25
086aed60 00a45331 ModuleA!DllCanUnloadNow+0×61ee48
086af6c4 00a44b10 ModuleA!DllCanUnloadNow+0xc6de1
086affb4 7c80b729 ModuleA!DllCanUnloadNow+0xc65c0
086affec 00000000 kernel32!BaseThreadStart+0×37
0: kd> !thread 88ec9020 1f
THREAD 88ec9020 Cid 17a0.2034 Teb: 7ffad000 Win32Thread: bc28c6e8 WAIT: (Unknown) UserMode Non-Alertable
89095f48 Semaphore Limit 0x10000
IRP List:
89a5a370: (0006,0094) Flags: 00000900 Mdl: 00000000
Not impersonating
DeviceMap d6c30c48
Owning Process 88fffd88 Image: iexplore.exe
Attached Process N/A Image: N/A
Wait Start TickCount 5632994 Ticks: 2980 (0:00:00:46.562)
Context Switch Count 2269 LargeStack
UserTime 00:00:00.000
KernelTime 00:00:00.000
Win32 Start Address 0x00a262d0
Start Address kernel32!BaseThreadStartThunk (0x77e617ec)
Stack Init b204c000 Current b204bc60 Base b204c000 Limit b2048000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0
ChildEBP RetAddr
b204bc78 80833ec5 nt!KiSwapContext+0×26
b204bca4 80829c14 nt!KiSwapThread+0×2e5
b204bcec 8093b174 nt!KeWaitForSingleObject+0×346
b204bd50 8088b41c nt!NtWaitForSingleObject+0×9a
b204bd50 7c82860c nt!KiFastCallEntry+0xfc (TrapFrame @ b204bd64)
058fcabc 7c827d29 ntdll!KiFastSystemCallRet
058fcac0 77e61d1e ntdll!ZwWaitForSingleObject+0xc
058fcb30 77e61c8d kernel32!WaitForSingleObjectEx+0xac
058fcb44 00f98b4a kernel32!WaitForSingleObject+0×12
WARNING: Stack unwind information not available. Following frames may be wrong.
058fd3cc 00f99249 ModuleA+0×638b4a
058fdc3c 00f89b25 ModuleA+0×639249
058fe4cc 00f7ee48 ModuleA+0×629b25
058fed64 00a26de1 ModuleA+0×61ee48
058ff6c8 00a265c0 ModuleA+0xc6de1
058fffb8 77e6482f ModuleA+0xc65c0
058fffec 00000000 kernel32!BaseThreadStart+0×34
This pattern is helpful when we have both process user space memory dumps and kernel and complete memory dumps and want to match stack traces of interest between them. See also patterns Stack Trace and Stack Trace Collection.
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
In addition to Blocked Thread and endpoint threads of Wait Chain patterns we would like to add Blocking Module pattern to account for modules calling waiting or delaying functions, for example:
0:017> kL
ChildEBP RetAddr
02c34100 7c90df5a ntdll!KiFastSystemCallRet
02c34104 7c8025db ntdll!ZwWaitForSingleObject+0xc
02c34168 7c802542 kernel32!WaitForSingleObjectEx+0xa8
02c3417c 009f0ed9 kernel32!WaitForSingleObject+0×12
02c34a08 00bc2c9a ModuleA!DllCanUnloadNow+0×6db39
02c3526c 00bc2fa4 ModuleA!DllCanUnloadNow+0×23f8fa
02c35ae0 00f6413c ModuleA!DllCanUnloadNow+0×23fc04
02c363e8 00c761ab ModuleA!DllCanUnloadNow+0×5e0d9c
02c36c74 00c74daa ModuleA!DllCanUnloadNow+0×2f2e0b
02c374e4 3d1a9eb4 ModuleA!DllCanUnloadNow+0×2f1a0a
02c3753c 3d0ed032 mshtml!CView::SetObjectRectsHelper+0×98
02c37578 3cf7e43b mshtml!CView::EndDeferSetObjectRects+0×75
02c375bc 3cf2542d mshtml!CView::EnsureView+0×39f
02c375d8 3cf4072c mshtml!CElement::EnsureRecalcNotify+0×17c
02c37614 3cf406ce mshtml!CElement::get_clientHeight_Logical+0×54
02c37628 3d0822a1 mshtml!CElement::get_clientHeight+0×27
02c37648 3cf8ad53 mshtml!G_LONG+0×7b
02c376bc 3cf96e21 mshtml!CBase::ContextInvokeEx+0×5d1
02c3770c 3cfa2baf mshtml!CElement::ContextInvokeEx+0×9d
02c37738 3cf8a751 mshtml!CElement::VersionedInvokeEx+0×2d
[…]
This pattern will help to make pattern interaction cases studies more fine grained.
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
