OpenTask Begins Restructuring Program
Monday, February 9th, 2009OpenTask, the publisher of my books, announces restructuring:
http://www.opentask.com/restructuring-2009
- Dmitry Vostokov @ DumpAnalysis.org -
Archive for February 9th, 2009
Swarm of shared locks, blocked threads and waiting time: pattern cooperation
Monday, February 9th, 2009Here is further analysis of a memory dump used to illustrate Swarm of Shared Locks pattern. In that dump there were also exclusively held locks with many blocked threads:
Resource @ 0x8a04c408 Exclusively owned
Contention Count = 344875
NumberOfExclusiveWaiters = 6
Threads: 87eb3db0-01<*>
Threads Waiting On Exclusive Access:
88573db0 87b90378 86a49db0 891f4610
8662b020 87127db0
Resource @ 0x89678e80 Exclusively owned
Contention Count = 10261
NumberOfExclusiveWaiters = 2
Threads: 87eb3db0-01<*>
Threads Waiting On Exclusive Access:
89131bf0 88d12db0
Resource @ 0x88d099d8 Exclusively owned
Contention Count = 562811
NumberOfExclusiveWaiters = 4
Threads: 873611d8-01<*>
Threads Waiting On Exclusive Access:
88b8bb88 88a72c50 89359af0 88d865e8
Resource @ 0x86db9248 Exclusively owned
Contention Count = 1382269
NumberOfSharedWaiters = 2
NumberOfExclusiveWaiters = 11
Threads: 86ab2020-01<*> 8769cdb0-01 880c77b8-01
Threads Waiting On Exclusive Access:
87bf4020 890dc020 874c01c0 884ef020
86913af8 875bab10 88e8a0d8 8923cdb0
894eca18 86aa6830 86f293a8
Resource @ 0x873a88d0 Exclusively owned
Contention Count = 719758
NumberOfExclusiveWaiters = 8
Threads: 88d5f990-01<*>
Threads Waiting On Exclusive Access:
8759ea88 871b6db0 88117710 87cb4718
883eb638 87239020 881ad020 891b9188
Resource @ 0x88c379a0 Exclusively owned
Contention Count = 126686
NumberOfSharedWaiters = 1
NumberOfExclusiveWaiters = 8
Threads: 882b8020-01<*> 88951520-01
Threads Waiting On Exclusive Access:
877d34a8 8939fdb0 87fc5668 8851fdb0
86fad850 87f1f450 8a1749f0 876a78d0
Resource @ 0x88ca9250 Exclusively owned
Contention Count = 319721
NumberOfExclusiveWaiters = 4
Threads: 88607908-01<*>
Threads Waiting On Exclusive Access:
86829370 892ae8e8 87205208 87b6d7e0
Resource @ 0x86a90ef8 Exclusively owned
Contention Count = 852830
NumberOfExclusiveWaiters = 12
Threads: 87571640-01<*>
Threads Waiting On Exclusive Access:
88a9c9b0 88a50db0 87117928 890e4c50
874ffb30 88b540f8 8705d020 8687edb0
87143188 8703e430 885b6aa0 8842bc50
Resource @ 0x88954538 Exclusively owned
Contention Count = 40708
NumberOfExclusiveWaiters = 1
Threads: 87571640-01<*>
Threads Waiting On Exclusive Access:
878ee980
Resource @ 0x88617eb8 Exclusively owned
Contention Count = 43531
NumberOfExclusiveWaiters = 2
Threads: 87571640-01<*>
Threads Waiting On Exclusive Access:
88851db0 87382c50
Resource @ 0x87288bc8 Exclusively owned
Contention Count = 644675
NumberOfExclusiveWaiters = 2
Threads: 874e4508-01<*>
Threads Waiting On Exclusive Access:
88863b08 89479650
Resource @ 0x87c3d8b0 Exclusively owned
Contention Count = 335064
NumberOfExclusiveWaiters = 8
Threads: 87f44520-01<*>
Threads Waiting On Exclusive Access:
88277190 88eceb48 87f0d308 8694d460
88461db0 876734a8 871721b0 88c2adb0
All threads owning various locks exclusively are stuck in processing page fault code, for example:
0: kd> !thread 87eb3db0 1f
THREAD 87eb3db0 Cid 47ac.57c8 Teb: 7ffd7000 Win32Thread: bc151230 WAIT: (Unknown) KernelMode Non-Alertable
8743e4e0 NotificationEvent
IRP List:
8660c900: (0006,0094) Flags: 00000900 Mdl: 00000000
Not impersonating
DeviceMap e1003890
Owning Process 88e49918 Image: csrss.exe
Wait Start TickCount 15420972 Ticks: 2527 (0:00:00:39.484)
Context Switch Count 1430991 LargeStack
UserTime 00:00:00.000
KernelTime 00:00:02.734
Start Address 0×75a8e96c
Stack Init a3cf7000 Current a3cf6430 Base a3cf7000 Limit a3cf4000 Call 0
Priority 14 BasePriority 13 PriorityDecrement 0
ChildEBP RetAddr
a3cf6448 8083d5b1 nt!KiSwapContext+0×26
a3cf6474 8083df9e nt!KiSwapThread+0×2e5
a3cf64bc 8082629e nt!KeWaitForSingleObject+0×346
a3cf64e4 80826480 nt!MiWaitForInPageComplete+0×1f
a3cf656c 8084790e nt!MiDispatchFault+0xda3
a3cf65c8 80836c2a nt!MmAccessFault+0×64a
a3cf65c8 bfa38de0 nt!KiTrap0E+0xdc (TrapFrame @ a3cf65e0)
a3cf6a24 bf854a72 win32k!vSetPointer+0×36f
a3cf6a50 bf8b1b74 win32k!GreSetPointer+0×66
a3cf6a7c bf883183 win32k!zzzUpdateCursorImage+0×1cc
a3cf6a8c bf884b06 win32k!zzzSetFMouseMoved+0xd5
a3cf6ad4 bf81530a win32k!ProcessQueuedMouseEvents+0×1c4
a3cf6d30 bf86fd25 win32k!RawInputThread+0×5b4
a3cf6d40 bf898a52 win32k!xxxCreateSystemThreads+0×60
a3cf6d54 80833bef win32k!NtUserCallOneParam+0×23
a3cf6d54 7c8285ec nt!KiFastCallEntry+0xfc (TrapFrame @ a3cf6d64)
0: kd> !thread 87571640 1f
THREAD 87571640 Cid 49f4.65b4 Teb: 7ffdf000 Win32Thread: bc011680 WAIT: (Unknown) KernelMode Non-Alertable
8870db90 NotificationEvent
Not impersonating
DeviceMap e24f6570
Owning Process 87be4a00 Image: ApplicationC.EXE
Wait Start TickCount 15420974 Ticks: 2525 (0:00:00:39.453)
Context Switch Count 25640 LargeStack
UserTime 00:00:00.921
KernelTime 00:00:03.859
Win32 Start Address 0×30002658
Start Address 0×77e617f8
Stack Init 9a318600 Current 9a317b70 Base 9a319000 Limit 9a314000 Call 9a31860c
Priority 14 BasePriority 8 PriorityDecrement 0
ChildEBP RetAddr
9a317b88 8083d5b1 nt!KiSwapContext+0×26
9a317bb4 8083df9e nt!KiSwapThread+0×2e5
9a317bfc 8082629e nt!KeWaitForSingleObject+0×346
9a317c24 80826480 nt!MiWaitForInPageComplete+0×1f
9a317cac 8084790e nt!MiDispatchFault+0xda3
9a317d08 80836c2a nt!MmAccessFault+0×64a
9a317d08 bf8b5485 nt!KiTrap0E+0xdc (TrapFrame @ 9a317d20)
9a317db4 bf8b526c win32k!vSolidFillRect1+0xb0
9a317f58 bf8ad7d2 win32k!vDIBSolidBlt+0×102
9a317fc4 bfa285d1 win32k!EngBitBlt+0xe1
9a3180c8 bf899b57 win32k!GrePatBltLockedDC+0×1ea
9a318160 bf8b32bb win32k!GrePolyPatBltInternal+0×17c
9a31819c bf8bd71c win32k!GrePolyPatBlt+0×45
9a31822c bf85e3d5 win32k!DrawEdge+0×23a
9a318274 bf8ae338 win32k!xxxDrawWindowFrame+0×170
9a3182d4 bf8847d1 win32k!xxxRealDefWindowProc+0×7a7
9a3182ec bf884801 win32k!xxxWrapRealDefWindowProc+0×16
9a318308 bf8c1769 win32k!NtUserfnDWORD+0×27
9a318340 80833bef win32k!NtUserMessageCall+0xc0
9a318340 7c8285ec nt!KiFastCallEntry+0xfc (TrapFrame @ 9a318364)
We also see that their waiting time is almost the same, 39 seconds. This means that the problem with paging probably started at that time before the crash dump was forced.
- Dmitry Vostokov @ DumpAnalysis.org -
Crash Dump Analysis Patterns (Part 79)
Monday, February 9th, 2009Sometimes there are so many shared locks on the system that it might point to some problems in subsystems that own them. For example, there are two large swarms of them in this memory dump from a system running 90 user sessions:
0: kd> !session
Sessions on machine: 90
0: kd> !locks
**** DUMP OF ALL RESOURCE OBJECTS ****
KD: Scanning for held locks....
Resource @ nt!CmpRegistryLock (0x808ad4c0) Shared 210 owning threads
Contention Count = 1432
Threads: 88bf1590-01<*> 8a78a660-01<*> 8a787660-01<*> 8825a3a8-01<*>
89003358-01<*> 86723b90-01<*> 865bbb00-01<*> 89634638-01<*>
888d9508-01<*> 88da6b48-01<*> 87db9db0-01<*> 86a9e610-01<*>
89ff7410-01<*> 87450db0-01<*> 86bdedb0-01<*> 86d604c8-01<*>
88d465d8-01<*> 86c3b6a0-01<*> 87c89020-01<*> 88e73db0-01<*>
865fe5b0-01<*> 88450020-01<*> 86bd9db0-01<*> 8a73e838-01<*>
88dc3db0-01<*> 88035708-01<*> 8833a2f0-01<*> 88608350-01<*>
87aca020-01<*> 87e007c0-01<*> 86ec39b8-01<*> 893be1b8-01<*>
8671ddb0-01<*> 8679a718-01<*> 89fe34c8-01<*> 86ccd720-01<*>
881b1db0-01<*> 86771b20-01<*> 86d71db0-01<*> 89574db0-01<*>
87dfac50-01<*> 86597020-01<*> 874b3488-01<*> 873b59b0-01<*>
88e792f8-01<*> 878d2430-01<*> 8853d480-01<*> 889e2020-01<*>
88c36db0-01<*> 8824f990-01<*> 8719b830-01<*> 884ba020-01<*>
88e1d768-01<*> 89523db0-01<*> 896529f8-01<*> 887e2870-01<*>
8a022db0-01<*> 867253a0-01<*> 865f0448-01<*> 87d35640-01<*>
8715d968-01<*> 87ce0c50-01<*> 87d44730-01<*> 86d69aa8-01<*>
88e5b020-01<*> 88734410-01<*> 898f2b40-01<*> 8a00a510-01<*>
87e69db0-01<*> 8722b860-01<*> 86d8e308-01<*> 87263c50-01<*>
8706ddb0-01<*> 892136e8-01<*> 8875b020-01<*> 8833ca48-01<*>
8a100db0-01<*> 86b77590-01<*> 888bc020-01<*> 865c3db0-01<*>
89fba910-01<*> 8a789660-01<*> 8670b2a8-01<*> 868737a8-01<*>
868326d0-01<*> 871cdaf0-01<*> 8852edb0-01<*> 882b23b8-01<*>
877e29e0-01<*> 8774f558-01<*> 876aa020-01<*> 89187518-01<*>
8664b8e0-01<*> 865b4478-01<*> 88135020-01<*> 8686f020-01<*>
866a0190-01<*> 87316758-01<*> 894dab18-01<*> 87938560-01<*>
8658f5f0-01<*> 88e54020-01<*> 867f6350-01<*> 89246af8-01<*>
86801430-01<*> 86db2af0-01<*> 865cf588-01<*> 86ab64f8-01<*>
8a4a61e8-01<*> 885f3020-01<*> 86ea9af0-01<*> 8a4a7ba8-01<*>
8a746b08-01<*> 89fc4790-01<*> 87093b10-01<*> 8659bc50-01<*>
86681db0-01<*> 87102228-01<*> 866145a0-01<*> 866dddb0-01<*>
86bda990-01<*> 88257db0-01<*> 8687d590-01<*> 867a9db0-01<*>
89898848-01<*> 8a49b920-01<*> 86596db0-01<*> 8a0f7db0-01<*>
866c1b40-01<*> 8754e020-01<*> 87fc1428-01<*> 8658c870-01<*>
880d6a90-01<*> 88be6c50-01<*> 86bbcdb0-01<*> 8a37b8f8-01<*>
866a13e0-01<*> 873e33d0-01<*> 87d43db0-01<*> 88a5adb0-01<*>
884a5440-01<*> 883646f0-01<*> 87128020-01<*> 88e1d020-01<*>
888e6418-01<*> 875c7c50-01<*> 871dd020-01<*> 890d5838-01<*>
88d061f0-01<*> 88a09428-01<*> 8972f780-01<*> 87325b08-01<*>
86deb020-01<*> 878b31b8-01<*> 891ac8a8-01<*> 86b234c0-01<*>
86dd2190-01<*> 875f9db0-01<*> 87bbf200-01<*> 8a1a9c40-01<*>
88628020-01<*> 87919020-01<*> 87c2a660-01<*> 877dc7c0-01<*>
8a08adb0-01<*> 87c0f628-01<*> 87ca9a28-01<*> 8880a210-01<*>
86ec0020-01<*> 88571020-01<*> 8a01edb0-01<*> 88115db0-01<*>
87a9adb0-01<*> 879ecdb0-01<*> 8868ddb0-01<*> 872bcb58-01<*>
884a0100-01<*> 8929f020-01<*> 87087020-01<*> 886e75a8-01<*>
885a5908-01<*> 8762c020-01<*> 89550db0-01<*> 8a554768-01<*>
89f10680-01<*> 87b322e8-01<*> 87cc74d0-01<*> 883ee2d0-01<*>
8956caf8-01<*> 8788f330-01<*> 87d5c320-01<*> 86b99db0-01<*>
876f42e0-01<*> 88e812d0-01<*> 8687cdb0-01<*> 8677a310-01<*>
89711b40-01<*> 89b013a8-01<*> 86abcdb0-01<*> 89fd7bb0-01<*>
877c22b0-01<*> 883fc850-01<*> 889e11f8-01<*> 892ff0e0-01<*>
878ac490-01<*> 86de5c50-01<*> 87741db0-01<*> 8679f020-01<*>
880ac6d0-01<*> 86d8fb00-01<*>
KD: Scanning for held locks….
Resource @ Ntfs!NtfsData (0xf71665b0) Shared 1 owning threads
Threads: 8a78d660-01<*>
KD: Scanning for held locks.
Resource @ 0x8a5c7734 Shared 1 owning threads
Contention Count = 507565
NumberOfSharedWaiters = 128
NumberOfExclusiveWaiters = 1
Threads: 894b4db0-01 87c773e0-01 88de7020-01 891c9db0-01
894d2020-01 865af5f8-01 87867340-01 88c964a0-01<*>
88e57c98-01 87ae3020-01 86dbe730-01 88343790-01
871102e8-01 8855f020-01 87c99920-01 8796a318-01
88028db0-01 88ad6610-01 88b73db0-01 89fba3f0-01
87d8bc00-01 86f4c5c8-01 8a028608-01 88c783f0-01
88c138e0-01 89236910-01 896fbb78-01 88523600-01
8926f3b0-01 88a49a48-01 87c19750-01 86c88c50-01
88adfad8-01 872b0020-01 87ecab18-01 88b02020-01
875f9b10-01 8755e020-01 86f9fdb0-01 86a1cab8-01
86816858-01 881eedb0-01 894a99f0-01 87c97740-01
8a3bf4b0-01 867765a8-01 8a787660-01 86810330-01
876ad268-01 87af3320-01 865fedb0-01 88eb8230-01
86b0c438-01 881c0230-01 888b67c8-01 883e3210-01
87acbc50-01 873d6648-01 86ed0db0-01 88e2d020-01
89fdadb0-01 8934e830-01 870f89f0-01 8756c5e0-01
878c88d0-01 86fec608-01 88fdb420-01 87fa0628-01
87cad8d8-01 88ee3978-01 86fc49a0-01 875d5020-01
871a5020-01 89667a60-01 87170db0-01 88254ae0-01
8775e408-01 88204db0-01 87989890-01 873b89a8-01
888e6bf8-01 88cc3db0-01 88bf1590-01 879565a0-01
86773db0-01 8731a020-01 88aa7a78-01 8759cdb0-01
87e555f8-01 86de5678-01 86e28020-01 86ec9320-01
86871af0-01 8719cba0-01 8723f820-01 884dac20-01
89249020-01 889da168-01 8900b810-01 8a78d660-01
88cac758-01 892984c8-01 87d0c020-01 87ecec50-01
87ad8c90-01 88109aa8-01 86ef5bf0-01 8a78d3f0-01
88d2b020-01 88640db0-01 86fec878-01 895b12d8-01
86dd6708-01 87386930-01 888e34e0-01 86a56c50-01
8815f768-01 886c42a0-01 898f2020-01 87ca3610-01
886dd448-01 86ada210-01 8a37adb0-01 8896c940-01
8800e898-01 8733d4b8-01 865fa358-01 88ae1af0-01
868dd020-01
Threads Waiting On Exclusive Access:
8a78b020
Both swarms are grouped around NTFS structures as can be seen from thread stack traces but also have another module in common: PGPsdk
0: kd> !thread 88bf1590 1f
THREAD 88bf1590 Cid 4354.2338 Teb: 7ffdf000 Win32Thread: bc3e88f8 WAIT: (Unknown) KernelMode Non-Alertable
8a7a73d8 Semaphore Limit 0x7fffffff
88bf1608 NotificationTimer
IRP List:
86fb39d0: (0006,0268) Flags: 00000004 Mdl: 00000000
Not impersonating
DeviceMap e13c9ca0
Owning Process 869a6d88 Image: ApplicationA.exe
Wait Start TickCount 15423469 Ticks: 30 (0:00:00:00.468)
Context Switch Count 6465 LargeStack
UserTime 00:00:00.343
KernelTime 00:00:01.062
Win32 Start Address 0x0056f122
Start Address 0x77e617f8
Stack Init 97e9d000 Current 97e9c788 Base 97e9d000 Limit 97e98000 Call 0
Priority 14 BasePriority 8 PriorityDecrement 6
ChildEBP RetAddr
97e9c7a0 8083d5b1 nt!KiSwapContext+0x26
97e9c7cc 8083df9e nt!KiSwapThread+0x2e5
97e9c814 8081e05b nt!KeWaitForSingleObject+0x346
97e9c850 80824ba8 nt!ExpWaitForResource+0xd5
97e9c870 f718a07d nt!ExAcquireResourceSharedLite+0xf5
97e9c884 f717b2eb Ntfs!NtfsAcquireSharedVcb+0×23
97e9c8f0 f717a2e2 Ntfs!NtfsCommonFlushBuffers+0xf5
97e9c954 80840153 Ntfs!NtfsFsdFlushBuffers+0×92
97e9c968 f7272c45 nt!IofCallDriver+0×45
97e9c990 80840153 fltmgr!FltpDispatch+0×6f
97e9c9a4 f6fb1835 nt!IofCallDriver+0×45
WARNING: Stack unwind information not available. Following frames may be wrong.
97e9c9b8 f6fad69a PGPsdk+0×5835
97e9c9c4 80840153 PGPsdk+0×169a
86fb39d0 00000000 nt!IofCallDriver+0×45
0: kd> !thread 88c964a0 1f
THREAD 88c964a0 Cid 323c.43f0 Teb: 7ffad000 Win32Thread: bc2ceea8 WAIT: (Unknown) KernelMode Non-Alertable
88268338 SynchronizationEvent
88c96518 NotificationTimer
IRP List:
86dad430: (0006,0268) Flags: 00000404 Mdl: 00000000
Not impersonating
DeviceMap e16c8eb0
Owning Process 8886ac88 Image: ApplicationB.EXE
Wait Start TickCount 15423352 Ticks: 147 (0:00:00:02.296)
Context Switch Count 1660 LargeStack
UserTime 00:00:00.078
KernelTime 00:00:00.109
Win32 Start Address 0x14225c34
Start Address 0x77e617ec
Stack Init 96835000 Current 96834640 Base 96835000 Limit 96832000 Call 0
Priority 14 BasePriority 8 PriorityDecrement 6
ChildEBP RetAddr
96834658 8083d5b1 nt!KiSwapContext+0x26
96834684 8083df9e nt!KiSwapThread+0x2e5
968346cc 8081e05b nt!KeWaitForSingleObject+0x346
96834708 8082e012 nt!ExpWaitForResource+0xd5
96834728 f714b89b nt!ExAcquireResourceExclusiveLite+0x8d
96834738 f718b194 Ntfs!NtfsAcquirePagingResourceExclusive+0×20
9683493c f718b8d9 Ntfs!NtfsCommonCleanup+0×193
96834aac 80840153 Ntfs!NtfsFsdCleanup+0xcf
96834ac0 f7272c45 nt!IofCallDriver+0×45
96834ae8 80840153 fltmgr!FltpDispatch+0×6f
96834afc f6fb196c nt!IofCallDriver+0×45
WARNING: Stack unwind information not available. Following frames may be wrong.
96834b10 f6fad69a PGPsdk+0×596c
96834b1c 80840153 PGPsdk+0×169a
86dad430 00000000 nt!IofCallDriver+0×45
Because no processors are busy except the one that processes crash dump request via NMI interrupt and there are no ready threads it would be natural to assume that the problem with paging started some time ago and some checks for 3rd-party volume encryption software are necessary as PGP name of the module suggests:
0: kd> lmv m PGPsdk
start end module name
f6fac000 f6fb7000 PGPsdk (no symbols)
Loaded symbol image file: PGPsdk.sys
Image path: \SystemRoot\System32\Drivers\PGPsdk.sys
Image name: PGPsdk.sys
Timestamp: Wed Jun 09 11:44:04 2004 (40C6E9F4)
CheckSum: 00010F72
ImageSize: 0000B000
Translations: 0000.04b0 0000.04e0 0409.04b0 0409.04e0
0: kd> !running
System Processors f (affinity mask)
Idle Processors e
Prcb Current Next
0 ffdff120 808a68c0 86841588 ................
0: kd> !thread 808a68c0 1f
THREAD 808a68c0 Cid 0000.0000 Teb: 00000000 Win32Thread: 00000000 RUNNING on processor 0
Not impersonating
Owning Process 808a6b40 Image: Idle
Wait Start TickCount 0 Ticks: 15423499 (2:18:56:32.171)
Context Switch Count 100782385
UserTime 00:00:00.000
KernelTime 2 Days 12:18:49.343
Stack Init 808a38b0 Current 808a35fc Base 808a38b0 Limit 808a08b0 Call 0
Priority 0 BasePriority 0 PriorityDecrement 0
ChildEBP RetAddr
808a07bc 80a84df7 nt!KeBugCheckEx+0x1b
808a080c 80834b83 hal!HalHandleNMI+0x1a5
808a080c 80a80853 nt!KiTrap02+0x136 (TrapFrame @ 808a0820)
808a3570 f7659ca2 hal!HalpClockInterrupt+0xff (TrapFrame @ 808a3570)
808a3600 80839b12 intelppm!AcpiC1Idle+0x12
808a3604 00000000 nt!KiIdleLoop+0xa
0: kd> !ready
Processor 0: No threads in READY state
Processor 1: No threads in READY state
Processor 2: No threads in READY state
Processor 3: No threads in READY state
- Dmitry Vostokov @ DumpAnalysis.org -
Print on Demand is the Future
Monday, February 9th, 2009Here is the message from John R. Ingram:
http://www.lightningsource.com/podnow.aspx
All my books are printed on demand. For me it is the most economical way to publish and I look forward to seeing POD offering more formats.
- Dmitry Vostokov @ DumpAnalysis.org -