Archive for July, 2010

Memory Dump Analysis Services Cap and T-Shirt

Saturday, July 31st, 2010

Started testing marketing materials to increase Dublin people awareness of memory dump analysis. Here are the first exemplars of what I’m going to wear by the end of this week while commuting and in local pubs :-)

 

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Blog (Debugging Slang, Part 15)

Thursday, July 29th, 2010

Blog - Binary log.

Examples: This program blogged. I’m reading its blog now.

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Crash Dump Analysis Patterns (Part 102)

Thursday, July 29th, 2010

Here we show the possible signs of the classical Thread Starvation.
Suppose we have two running threads with a priority 8:

0: kd> !running

System Processors 3 (affinity mask)
  Idle Processors 0

Prcbs  Current   Next   
  0    ffdff120  89a92020            O...............
  1    f7737120  89275020            W...............

0: kd> !thread 89a92020
THREAD 89a92020  Cid 11d8.27d8  Teb: 7ffd9000 Win32Thread: bc1e6860 RUNNING on processor 0
[...]
Priority 8 BasePriority 8 PriorityDecrement 0

0: kd> !thread 89275020
THREAD 89275020  Cid 1cd0.2510  Teb: 7ffa9000 Win32Thread: bc343180 RUNNING on processor 1
[...]
Priority 8 BasePriority 8 PriorityDecrement 0

If we have other threads ready with the same priority contending for the same processors other threads with less priority might starve (shown in red):

0: kd> !ready
Processor 0: Ready Threads at priority 8
    THREAD 894a1db0  Cid 1a98.25c0  Teb: 7ffde000 Win32Thread: bc19cea8 READY
    THREAD 897c4818  Cid 11d8.1c5c  Teb: 7ffa2000 Win32Thread: bc2c5ba8 READY
    THREAD 8911fd18  Cid 2730.03f4  Teb: 7ffd9000 Win32Thread: bc305830 READY

Processor 0: Ready Threads at priority 7
    THREAD 8a9e5ab0  Cid 0250.0470  Teb: 7ff9f000 Win32Thread: 00000000 READY
    THREAD 8a086838  Cid 0250.0654  Teb: 7ff93000 Win32Thread: 00000000 READY
    THREAD 8984b8b8  Cid 0250.1dc4  Teb: 7ff99000 Win32Thread: 00000000 READY
    THREAD 8912a4c0  Cid 0f4c.2410  Teb: 7ff81000 Win32Thread: 00000000 READY
    THREAD 89e5c570  Cid 0f4c.01c8  Teb: 00000000 Win32Thread: 00000000 READY
Processor 0: Ready Threads at priority 6
    THREAD 8a9353b0  Cid 1584.1598  Teb: 7ff8b000 Win32Thread: bc057698 READY
    THREAD 8aba2020  Cid 1584.15f0  Teb: 7ff9f000 Win32Thread: bc2a0ea8 READY
    THREAD 8aab17a0  Cid 1584.01a8  Teb: 7ff92000 Win32Thread: bc316ea8 READY
    THREAD 8a457020  Cid 1584.0634  Teb: 7ff8d000 Win32Thread: bc30fea8 READY
    THREAD 8a3d4020  Cid 1584.1510  Teb: 7ff8f000 Win32Thread: bc15b8a0 READY
    THREAD 8a5f5db0  Cid 1584.165c  Teb: 7ff9d000 Win32Thread: bc171be8 READY
    THREAD 8a297020  Cid 0f4c.0f54  Teb: 7ffde000 Win32Thread: bc20fda0 READY
    THREAD 8a126020  Cid 1584.175c  Teb: 7ffa9000 Win32Thread: 00000000 READY
    THREAD 8a548478  Cid 0250.07b0  Teb: 7ff9a000 Win32Thread: 00000000 READY
    THREAD 8a478020  Cid 0944.0988  Teb: 7ffd9000 Win32Thread: 00000000 READY
    THREAD 8986ad08  Cid 1d2c.1cf0  Teb: 7ffa8000 Win32Thread: bc285800 READY
    THREAD 897f4db0  Cid 1d2c.2554  Teb: 7ffdb000 Win32Thread: bc238e80 READY
    THREAD 89a2e618  Cid 1d2c.1de4  Teb: 7ffdd000 Win32Thread: bc203908 READY
Processor 0: Ready Threads at priority 0
    THREAD 8b184db0  Cid 0004.0008  Teb: 00000000 Win32Thread: 00000000 READY

Processor 1: Ready Threads at priority 8
    THREAD 89d89db0  Cid 1b10.20ac  Teb: 7ffd7000 Win32Thread: bc16e680 READY
    THREAD 891f24a8  Cid 1e2c.20d0  Teb: 7ffda000 Win32Thread: bc1b9ea8 READY
    THREAD 89214db0  Cid 1e2c.24d4  Teb: 7ffd7000 Win32Thread: bc24ed48 READY
    THREAD 89a28020  Cid 1b10.21b4  Teb: 7ffa7000 Win32Thread: bc25b3b8 READY
    THREAD 891e03b0  Cid 1a98.05c4  Teb: 7ffdb000 Win32Thread: bc228bb0 READY
    THREAD 891b0020  Cid 1cd0.0144  Teb: 7ffde000 Win32Thread: bc205ea8 READY

Processor 1: Ready Threads at priority 7
    THREAD 898367a0  Cid 0f4c.1cd4  Teb: 00000000 Win32Thread: 00000000 READY
    THREAD 8a1ac020  Cid 0f4c.1450  Teb: 00000000 Win32Thread: 00000000 READY
    THREAD 8aa1ab90  Cid 0f4c.11b0  Teb: 00000000 Win32Thread: 00000000 READY
    THREAD 89cc92e0  Cid 0f4c.1b34  Teb: 00000000 Win32Thread: 00000000 READY
    THREAD 89579020  Cid 0f4c.2220  Teb: 00000000 Win32Thread: 00000000 READY
Processor 1: Ready Threads at priority 6
    THREAD 8a487db0  Cid 1584.14bc  Teb: 7ffa2000 Win32Thread: bc304ea8 READY
    THREAD 8a3ce020  Cid 1584.0630  Teb: 7ff8e000 Win32Thread: bc293c20 READY
    THREAD 8a1b6db0  Cid 1584.1590  Teb: 7ff8c000 Win32Thread: bc310ea8 READY
    THREAD 8a1fe6e0  Cid 1584.15ec  Teb: 7ffa1000 Win32Thread: bc15bea8 READY
    THREAD 8ac0adb0  Cid 1584.156c  Teb: 7ff8a000 Win32Thread: bc153be8 READY
    THREAD 8b1e35a0  Cid 1584.15f4  Teb: 7ff9e000 Win32Thread: bc0567e8 READY
    THREAD 8a3288e8  Cid 1584.14b8  Teb: 7ff9a000 Win32Thread: bc2fbea8 READY
    THREAD 8a5056a0  Cid 1584.1518  Teb: 7ff91000 Win32Thread: bc337ea8 READY
    THREAD 891afdb0  Cid 1d2c.27e8  Teb: 7ffaf000 Win32Thread: bc217c18 READY
    THREAD 8a07d308  Cid 1d2c.2548  Teb: 7ffae000 Win32Thread: bc235750 READY
    THREAD 8a055d18  Cid 1584.17d0  Teb: 7ffd5000 Win32Thread: 00000000 READY
    THREAD 8ac0b770  Cid 0250.0268  Teb: 7ffde000 Win32Thread: bc2349d8 READY
    THREAD 8a0eeb40  Cid 1584.1560  Teb: 7ffdc000 Win32Thread: 00000000 READY

Here we should also analyze stack traces for running and ready threads with priority 8 and check kernel and user times. If we find anything common between them we should also check ready threads with lower priority to see if that commonality is unique to threads with priority 8. See also the similar pattern: Busy System and the similar starvation pattern resulted from realtime priority threads.

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Contemplating Crash Dumps in Chinese

Thursday, July 29th, 2010

Sometimes I accidentally use du WinDbg command (to interpret memory as Unicode) instead of da (to interpret memory as ASCII):

0:000> db 07329f28 l20
07329f28  68 69 64 70 6e 73 74 3d-26 74 78 74 74 6f 3d 26  hidpnst=&txtto=&
07329f38  74 78 74 63 63 3d 26 74-78 74 62 63 63 3d 26 74  txtcc=&txtbcc=&t

0:000> da 07329f28 l20
07329f28  "hidpnst=&txtto=&txtcc=&txtbcc=&t"

0:000> du 07329f28 l10
07329f28  "楨灤獮㵴琦瑸潴.硴捴㵣琦瑸换㵣琦"

This time I tried to get extra hidden meaning from a process dump taken after the process suffered a CPU spike by using Google translator and got this text (I put more lengthy Unicode sequence and removed some offensive words):

"Luan Xian Zhen Qi-bin 㵴 cisternae. Huasong 㵣 Qi, Qi-bin-bin for 㵣 pull 㵪 䕒 .. 䉉 Ya Hui material. Hong SHIKA King. Huajiayuyan nuts .. 䐰 〥 䅁 evil force. Rafter Hui Qi 䤫 Mi cat deterrent Junying hydrogen walk. cisternae Huzhao Man cat Wuzhou Wen Zhen Zhao Zhen Pan scene file Shan. prison Shang Tang. Jue Shi Pan. sewage knock Xi. generous Zhen. 䤫. ice. conflict. cisternae Zhao askance nuts. rafter .. On unfeigned domain knock. Kagesue Mankuo. 㜲 Ruo Yi enemy luster of gems. cisternae Yu Wei Shan scene. Tan knock Shan. tally Xia Pan Ying. rafter. Xia. luster of gems tumultuous. Jing Feng-Tou Airuo enemy luster of gems Yixian … additionally . Tu. civet eliminating the lot Shan Ying RB Thieme, Jr.-Voltage trapping Feng-潷 Man. Tan knock Ruo Yi Xian cat enemy luster of gems. rafter Shi Feng-Tou. Mu. Minli Bang domain sewage Huitangyuzhao Su-hai.-Voltage Jiumi. rafter. Qing Wei Jun. 歳 Mi hai 䤫 Panyu. Zhucuoqufang .. 䐰 〥. 䐰 〥 䥁 hydrogen walk. rafter. Mount Zao Man. .. Run-Voltage Rendering. Tang Ying Yi. Shisuqingshi Fangmaosheji Yu Zhao 䤫 Su-. tide. tatami knock Feng-generous. rafter. Min luster of gems. Que Tu Mei Shi Tang Pan Ying. Jijue-Voltage. rafter. Wei Hui Mongoose Feng-. hunting. rafter. revolves Recent-Voltage sewage 䤫. stay Jiao RB Thieme, Jr soup.潷 Han.’m setback Xun. Han Tun petty. Liaohe. 䥔 end of Tu Feng-generous. rafter Xiang Shan Li Tu. trapping the end of sleep ZHEJIANG NORMAL Feng-Tou Yu Xun Jing Wen Fang 䤫 .. 䠫 pine and methods of disease. tatami knock Feng-generous. apply Feng-evil force fell Junying Su-Ao Po .. knock .. Tan Li Shan Jie look askance alone. ㅆ Guang Tang rafter. pool just cultural and"

From the translation I see previously hidden notions of gems, disease and evil forces :-)

ASCII->Unicode->translation->ASCII

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Dictionary of Debugging: 8

Thursday, July 29th, 2010

8

A separating digit of user space and kernel space in equi-bipartitional 32-bit virtual memory, for example, on x86 Windows systems:

RetAddr
80833491 nt!KiSwapContext+0×26
80828f2b nt!KiSwapThread+0×2e5
8099490a nt!KeDelayExecutionThread+0×2ab
808897cc nt!NtDelayExecution+0×84
7c82860c nt!KiFastCallEntry+0xfc
7c826f69 ntdll!KiFastSystemCallRet
7c83d454 ntdll!NtDelayExecution+0xc
77e6482f ntdll!RtlpTimerThread+0×47
00000000 kernel32!BaseThreadStart+0×34


lkd> lm
start end module name
[…]
77bd0000 77c19000 GDI32
77c20000 77cbf000 RPCRT4
77cd0000 77d5b000 OLEAUT32
77e20000 77eb2000 USER32
77ec0000 77f12000 SHLWAPI
77f30000 77fdc000 ADVAPI32
7c800000 7c915000 kernel32
7c920000 7c9e8000 ntdll
7c9f0000 7d1f9000 SHELL32
7e020000 7e02f000 SAMLIB

80800000 80a5d000 nt
80a5d000 80a89000 hal
bf800000 bf9d0000 win32k
[…]

This number doesn’t continue to be used in the same way on x64 Windows systems, for example:

RetAddr Call Site
fffff800`0167e082 nt!KiSwapContext+0×7a
fffff800`0167a34b nt!KiCommitThreadWait+0×1d2
fffff800`01973def nt!KeWaitForMultipleObjects+0×271
fffff800`019746f6 nt!ObpWaitForMultipleObjects+0×294
fffff800`01675ed3 nt!NtWaitForMultipleObjects+0xe5
00000000`77ca030a nt!KiSystemServiceCopyEnd+0×13

lkd> lm
start end module name
00000000`774a0000 00000000`7756d000 USER32
00000000`77570000 00000000`7769d000 kernel32
00000000`776a0000 00000000`77826000 ntdll
00000000`ffe60000 00000000`ffec0000 services
000007fe`fca90000 000007fe`fca97000 wshtcpip
000007fe`fcae0000 000007fe`fcb0c000 NTMARTA
000007fe`fcbe0000 000007fe`fcc34000 schannel
000007fe`fce10000 000007fe`fce5f000 mswsock
000007fe`fcf60000 000007fe`fcf69000 credssp
000007fe`fcf90000 000007fe`fcf97000 wship6
000007fe`fd0d0000 000007fe`fd207000 CRYPT32
000007fe`fd260000 000007fe`fd279000 MSASN1
000007fe`fd5a0000 000007fe`fd5b6000 NCObjAPI
000007fe`fd5c0000 000007fe`fd625000 SCESRV
000007fe`fd630000 000007fe`fd665000 apphelp
000007fe`fd680000 000007fe`fd6a6000 AUTHZ
000007fe`fd950000 000007fe`fd96c000 Secur32
000007fe`fd970000 000007fe`fd996000 USERENV
000007fe`fd9a0000 000007fe`fd9bc000 SAMLIB
000007fe`fdc80000 000007fe`fdce4000 GDI32
000007fe`fdd10000 000007fe`fdd1d000 LPK
000007fe`fdd20000 000007fe`fde28000 ADVAPI32
000007fe`fde30000 000007fe`fdecc000 msvcrt
000007fe`fded0000 000007fe`fdefd000 IMM32
000007fe`fdf00000 000007fe`fe0d8000 ole32
000007fe`fe0e0000 000007fe`fe0e7000 NSI
000007fe`fe190000 000007fe`fe22a000 USP10
000007fe`fe230000 000007fe`fe373000 RPCRT4
000007fe`ff340000 000007fe`ff395000 WLDAP32
000007fe`ff540000 000007fe`ff584000 WS2_32
000007fe`ff7d0000 000007fe`ff8d2000 MSCTF

fffff800`01802000 fffff800`01848000 hal
fffff800`01848000 fffff800`01d60000 nt
fffff960`000f0000 fffff960`003a1000 win32k
[…]

Synonyms:

Antonyms:

Also: virtual memory, user space, kernel space, x86, x64, 7

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

User/Kernel Diagramming Styles

Tuesday, July 27th, 2010

Similar to different C/C++ styles like where to put the right brace we have User/Kernel Space/Mode architecture diagramming styles. Some prefer to put User part on top (Windows Internals team) and some prefer to put Kernel on top (like me). Marc Sherman in the comment here explains the former style as “calling down into the kernel”. Originally I thought about a psychological explanation where you put on top what you value the most or use the most. However, the reason I put Kernel on top is because I value Space over Mode in depicting memory and dependencies. In stack traces from complete memory dumps you have kernel portions on top as well. Also Google and Bing favour “stack grows down” slightly over “stack grows up” and I prefer “down” as well. Additionally, if you value User on top you would be forced to put Managed on top as well. If you put Kernel on top than Managed is at the bottom like on this flag that became a logo of Memory Dump Analysis Services. So here are two diagrams where I prefer the first (Kernel on top) with any stack growing down (in address decrement sense) and any stack trace from WinDbg having Kernel on top too:

 

The second diagram has any stack growing up:

I also suggest this variant (but people who write and read from right to left may prefer its reflection):

Another diagram style that is consistent with the traditional depiction of Privilege Mode rings (here Kernel is also on top but can be put in any direction):

What style do you favour? Please let me know.

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Icons for Memory Dump Analysis Patterns (Part 62)

Sunday, July 25th, 2010

Today we introduce an icon for Hooked Functions (kernel space) pattern:

B/W

Color

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Feel good this morning :-)

Sunday, July 25th, 2010

Sometimes I do Google search for my site and find various cached dumpanalysis.org site evaluations ranging from 4,000 USD to 200,000 USD. It’s interesting to see that people evaluate how much this site worth. Today I stumbled across another unbelievable evaluation from valuemysite dot com (> 2,000,000 USD) so I checked myself:

“apple.com” is worth $340,512,336 USD
“amazon.com” is worth $340,512,336 USD
“microsoft.com” is worth $340,512,336 USD
“ibm.com” is worth $49,876,253 USD
“dumpanalysis.org” is worth $1,989,157 USD
“google.com” is worth $1,738,123 USD

Looks like some sites have an upper evaluation limit or reached an equilibrium :-)

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Icons for Memory Dump Analysis Patterns (Part 61)

Saturday, July 24th, 2010

Today we introduce an icon for Hooked Functions (user space) pattern:

B/W

Color

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Reading Notebook: 19-July-10

Thursday, July 22nd, 2010

Comments in italics are mine and express my own views, thoughts and opinions

Windows Internals by M. Russinovich, D. Solomon and A. Ionescu:

Viewing the loaded driver list (pp. 546 - 547) - if we don’t see company information in lmv command output we can examine raw driver data like in this pattern: http://www.dumpanalysis.org/blog/index.php/2007/08/16/crash-dump-analysis-patterns-part-22/

DriverEntry (p. 548) - consider this as similar to main (console) or WinMain (Win32). For example, if you are writing a Windows service you have to register certain functions with SCM.

Dispatch routines (p. 548) - if you know C++ consider them as class functions for a device object where DeviceObject is a this parameter (C++ class function implementation in C where an implicit this becomes the first function argument):

NTSTATUS (*PDRIVER_DISPATCH) (IN PDEVICE_OBJECT DeviceObject, IN PIRP Irp);

and a driver object can be seen as a container for a virtual function table (vtable) for a device object (purely from implementation perspective): devObj->DriverObject->MajorFunction[IRP_MJ_XXX]

Relationship between device and driver objects (pp. 553 - 554) - long time ago when I was preparing a presentation about Windows drivers for escalation engineers I created some UML diagrams you can see in the following blog post: http://www.dumpanalysis.org/blog/index.php/2006/10/08/uml-and-device-drivers/ 

AttachedDevice vs. AttachedTo (p.554)

File object structure and extension (pp. 556 - 557) - Here are driver, device and file object structures from x64 W2K8:

0: kd> dt _DRIVER_OBJECT
ntdll!_DRIVER_OBJECT
+0x000 Type             : Int2B
+0x002 Size             : Int2B
+0x008 DeviceObject     : Ptr64 _DEVICE_OBJECT
+0x010 Flags            : Uint4B
+0x018 DriverStart      : Ptr64 Void
+0x020 DriverSize       : Uint4B
+0x028 DriverSection    : Ptr64 Void
+0x030 DriverExtension  : Ptr64 _DRIVER_EXTENSION
+0x038 DriverName       : _UNICODE_STRING
+0x048 HardwareDatabase : Ptr64 _UNICODE_STRING
+0x050 FastIoDispatch   : Ptr64 _FAST_IO_DISPATCH
+0x058 DriverInit       : Ptr64     long
+0x060 DriverStartIo    : Ptr64     void
+0x068 DriverUnload     : Ptr64     void
+0x070 MajorFunction    : [28] Ptr64     long

0: kd> dt _DEVICE_OBJECT
ntdll!_DEVICE_OBJECT
+0x000 Type             : Int2B
+0x002 Size             : Uint2B
+0x004 ReferenceCount   : Int4B
+0x008 DriverObject     : Ptr64 _DRIVER_OBJECT
+0x010 NextDevice       : Ptr64 _DEVICE_OBJECT
+0x018 AttachedDevice   : Ptr64 _DEVICE_OBJECT
+0x020 CurrentIrp       : Ptr64 _IRP
+0x028 Timer            : Ptr64 _IO_TIMER
+0x030 Flags            : Uint4B
+0x034 Characteristics  : Uint4B
+0x038 Vpb              : Ptr64 _VPB
+0x040 DeviceExtension  : Ptr64 Void
+0x048 DeviceType       : Uint4B
+0x04c StackSize        : Char
+0x050 Queue            : <unnamed-tag>
+0x098 AlignmentRequirement : Uint4B
+0x0a0 DeviceQueue      : _KDEVICE_QUEUE
+0x0c8 Dpc              : _KDPC
+0x108 ActiveThreadCount : Uint4B
+0x110 SecurityDescriptor : Ptr64 Void
+0x118 DeviceLock       : _KEVENT
+0x130 SectorSize       : Uint2B
+0x132 Spare1           : Uint2B
+0x138 DeviceObjectExtension : Ptr64 _DEVOBJ_EXTENSION
+0x140 Reserved         : Ptr64 Void

0: kd> dt _FILE_OBJECT
ntdll!_FILE_OBJECT
+0x000 Type             : Int2B
+0x002 Size             : Int2B
+0x008 DeviceObject     : Ptr64 _DEVICE_OBJECT
+0x010 Vpb              : Ptr64 _VPB
+0x018 FsContext        : Ptr64 Void
+0x020 FsContext2       : Ptr64 Void
+0x028 SectionObjectPointer : Ptr64 _SECTION_OBJECT_POINTERS
+0x030 PrivateCacheMap  : Ptr64 Void
+0x038 FinalStatus      : Int4B
+0x040 RelatedFileObject : Ptr64 _FILE_OBJECT
+0x048 LockOperation    : UChar
+0x049 DeletePending    : UChar
+0x04a ReadAccess       : UChar
+0x04b WriteAccess      : UChar
+0x04c DeleteAccess     : UChar
+0x04d SharedRead       : UChar
+0x04e SharedWrite      : UChar
+0x04f SharedDelete     : UChar
+0x050 Flags            : Uint4B
+0x058 FileName         : _UNICODE_STRING
+0x068 CurrentByteOffset : _LARGE_INTEGER
+0x070 Waiters          : Uint4B
+0x074 Busy             : Uint4B
+0x078 LastLock         : Ptr64 Void
+0x080 Lock             : _KEVENT
+0x098 Event            : _KEVENT
+0x0b0 CompletionContext : Ptr64 _IO_COMPLETION_CONTEXT
+0x0b8 IrpListLock      : Uint8B
+0x0c0 IrpList          : _LIST_ENTRY
+0x0d0 FileObjectExtension : Ptr64 Void

WDPF book is available on Kindle platform

Thursday, July 22nd, 2010

I’m pleased to announce that my book Windows Debugging: Practical Foundations is available on Amazon Kindle platform. It has been reformatted and edited to make it fit into the smallest Kindle device and pictures were specifically tailored to improve their viewing experience. The price has dropped to $9.99 (excluding possible VAT and international delivery if any). Please let me know if you have any problems with the content and I make any changes as soon as possible.

Windows Debugging: Practical Foundations (Kindle Edition)

Buy Kindle from Amazon

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Icons for Memory Dump Analysis Patterns (Part 60)

Thursday, July 22nd, 2010

Today we introduce an icon for High Contention (processors) pattern:

B/W

Color

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Crash Dump Analysis Patterns (Part 29c)

Wednesday, July 21st, 2010

This is a variant of High Contention pattern for processors where we have more threads at the same priority than the available processors. All these threads share the same notification event (or any other similar synchronization mechanism) and rush once it is signalled. If this happens often the system becomes sluggish or even appears frozen.

0: kd> !running

System Processors 3 (affinity mask)
  Idle Processors 0

Prcbs  Current   Next   
  0    ffdff120  89a92020            O...............
  1    f7737120  89275020            W...............

0: kd> !ready
Processor 0: Ready Threads at priority 8
    THREAD 894a1db0  Cid 1a98.25c0  Teb: 7ffde000 Win32Thread: bc19cea8 READY
    THREAD 897c4818  Cid 11d8.1c5c  Teb: 7ffa2000 Win32Thread: bc2c5ba8 READY
    THREAD 8911fd18  Cid 2730.03f4  Teb: 7ffd9000 Win32Thread: bc305830 READY
Processor 1: Ready Threads at priority 8
    THREAD 89d89db0  Cid 1b10.20ac  Teb: 7ffd7000 Win32Thread: bc16e680 READY
    THREAD 891f24a8  Cid 1e2c.20d0  Teb: 7ffda000 Win32Thread: bc1b9ea8 READY
    THREAD 89214db0  Cid 1e2c.24d4  Teb: 7ffd7000 Win32Thread: bc24ed48 READY
    THREAD 89a28020  Cid 1b10.21b4  Teb: 7ffa7000 Win32Thread: bc25b3b8 READY
    THREAD 891e03b0  Cid 1a98.05c4  Teb: 7ffdb000 Win32Thread: bc228bb0 READY
    THREAD 891b0020  Cid 1cd0.0144  Teb: 7ffde000 Win32Thread: bc205ea8 READY

All these threads have common stack trace (I show only a few threads here):

0: kd> !thread 89a92020 1f
THREAD 89a92020  Cid 11d8.27d8  Teb: 7ffd9000 Win32Thread: bc1e6860 RUNNING on processor 0
Not impersonating
DeviceMap                 e502b248
Owning Process            89e2a020       Image:         ProcessA.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      336581         Ticks: 0
Context Switch Count      61983                 LargeStack
UserTime                  00:00:00.156
KernelTime                00:00:00.281
Win32 Start Address ntdll!RtlpWorkerThread (0x7c839f2b)
Start Address kernel32!BaseThreadStartThunk (0x77e617ec)
Stack Init f3730000 Current f372f7e0 Base f3730000 Limit f372c000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0
ChildEBP RetAddr 
f3cc98e8 f6e21915 DriverA+0x1e4d
[...]
f3cc9ac0 f67f05dc nt!IofCallDriver+0x45
[...]
02e7ff44 7c83aa3b ntdll!RtlpWorkerCallout+0x71
02e7ff64 7c83aab2 ntdll!RtlpExecuteWorkerRequest+0x4f
02e7ff78 7c839f90 ntdll!RtlpApcCallout+0x11
02e7ffb8 77e6482f ntdll!RtlpWorkerThread+0x61
02e7ffec 00000000 kernel32!BaseThreadStart+0x34

0: kd> !thread 89275020 1f
THREAD 89275020  Cid 1cd0.2510  Teb: 7ffa9000 Win32Thread: bc343180 RUNNING on processor 1
Not impersonating
DeviceMap                 e1390978
Owning Process            89214708       Image:         ProcessB.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      336581         Ticks: 0
Context Switch Count      183429                 LargeStack
UserTime                  00:00:00.171
KernelTime                00:00:00.484
Win32 Start Address ntdll!RtlpWorkerThread (0x7c839f2b)
Start Address kernel32!BaseThreadStartThunk (0x77e617ec)
Stack Init b9f6e000 Current b9f6d7e0 Base b9f6e000 Limit b9f6a000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0
ChildEBP RetAddr 
b9f6d87c f6e22d4b nt!KeWaitForSingleObject+0x497
b9f6d8e8 f6e21915 DriverA+0x1e4d
[...]
b9f6dac0 f67f05dc nt!IofCallDriver+0x45
[...]
0507ff44 7c83aa3b ntdll!RtlpWorkerCallout+0x71
0507ff64 7c83aab2 ntdll!RtlpExecuteWorkerRequest+0x4f
0507ff78 7c839f90 ntdll!RtlpApcCallout+0x11
0507ffb8 77e6482f ntdll!RtlpWorkerThread+0x61
0507ffec 00000000 kernel32!BaseThreadStart+0x34

0: kd> !thread 89d89db0 1f
THREAD 89d89db0  Cid 1b10.20ac  Teb: 7ffd7000 Win32Thread: bc16e680 READY
Not impersonating
DeviceMap                 e4e3a0b8
Owning Process            898cb020       Image:         ProcessC.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      336581         Ticks: 0
Context Switch Count      159844                 LargeStack
UserTime                  00:00:00.234
KernelTime                00:00:00.484
Win32 Start Address ntdll!RtlpWorkerThread (0x7c839f2b)
Start Address kernel32!BaseThreadStartThunk (0x77e617ec)
Stack Init b9e1e000 Current b9e1d7e0 Base b9e1e000 Limit b9e1a000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0
ChildEBP RetAddr 
b9e1d7f8 80831292 nt!KiSwapContext+0x26
b9e1d818 80828c73 nt!KiExitDispatcher+0xf8
b9e1d830 80829c72 nt!KiAdjustQuantumThread+0x109
b9e1d87c f6e22d4b nt!KeWaitForSingleObject+0x536
b9e1d8e8 f6e21915 DriverA+0x1e4d
[...]
b9e1dac0 f67f05dc nt!IofCallDriver+0x45
[...]
014dff44 7c83aa3b ntdll!RtlpWorkerCallout+0x71
014dff64 7c83aab2 ntdll!RtlpExecuteWorkerRequest+0x4f
014dff78 7c839f90 ntdll!RtlpApcCallout+0x11
014dffb8 77e6482f ntdll!RtlpWorkerThread+0x61

They also share the same synchronization object:

0: kd> .thread 89275020
Implicit thread is now 89275020

0: kd> kv 1
ChildEBP RetAddr  Args to Child             
b9f6d87c f6e22d4b f6e25130 00000006 00000001 nt!KeWaitForSingleObject+0×497

0: kd> .thread 89d89db0
Implicit thread is now 89d89db0

0: kd> kv 4
ChildEBP RetAddr  Args to Child             
b9e1d7f8 80831292 f7737120 f7737b50 f7737a7c nt!KiSwapContext+0x26
b9e1d818 80828c73 00000000 89d89db0 89d89e58 nt!KiExitDispatcher+0xf8
b9e1d830 80829c72 f7737a7c 00000102 00000001 nt!KiAdjustQuantumThread+0x109
b9e1d87c f6e22d4b f6e25130 00000006 00000001 nt!KeWaitForSingleObject+0×536

0: kd> dt _DISPATCHER_HEADER f6e25130
ntdll!_DISPATCHER_HEADER
   +0×000 Type             : 0 ”
   +0×001 Absolute         : 0 ”
   +0×001 NpxIrql          : 0 ”
   +0×002 Size             : 0×4 ”
   +0×002 Hand             : 0×4 ”
   +0×003 Inserted         : 0 ”
   +0×003 DebugActive      : 0 ”
   +0×000 Lock             : 262144
   +0×004 SignalState      : 1
   +0×008 WaitListHead     : _LIST_ENTRY [ 0xf6e25138 - 0xf6e25138 ]

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Icons for Memory Dump Analysis Patterns (Part 59)

Wednesday, July 21st, 2010

Today we introduce an icon for Early Crash Dump pattern:

B/W

Color

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Fabric of Memory Dumps

Monday, July 19th, 2010











- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Forthcoming Webinar: Fundamentals of Complete Crash and Hang Memory Dump Analysis

Sunday, July 18th, 2010

Complete Memory Dump Analysis Logo

Memory Dump Analysis Services (DumpAnalysis.com) organizes a free webinar

Date: 18th of August 2010
Time: 21:00 (BST) 16:00 (Eastern) 13:00 (Pacific)
Duration: 90 minutes

Topics include:

- User vs. kernel vs. physical (complete) memory space
- Challenges of complete memory dump analysis
- Common WinDbg commands
- Patterns
- Common mistakes
- Fiber bundles
- Hands-on exercise: a complete memory dump analysis
- A guide to DumpAnalysis.org case studies

Prerequisites: working knowledge of basic user process and kernel memory dump analysis or live debugging using WinDbg 

The webinar link will be posted before 18th of August on DumpAnalysis.com

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Can A Memory Dump Be Blue?

Sunday, July 18th, 2010

Yes, it can. Here’s the Dump2Picture image of a kernel memory dump (3 GB) from a 128 GB system:

Now it’s time to listen to Klaus Schulze album In Blue again.

Buy from Amazon

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Stack trace collection, special process, LPC and critical section wait chains, blocked thread, coupled machines, thread waiting time and IRP distribution anomaly: pattern cooperation

Sunday, July 18th, 2010

It was reported that new remote sessions couldn’t be created. A complete memory dump stack trace collection log lists a special process that would not normally be present in a fully initialized session: userinit.exe. One of its threads is blocked waiting for an LPC response:

kd> !process 0 ff
**** NT ACTIVE PROCESS DUMP ****

[...]

PROCESS 89cf4870  SessionId: 0  Cid: 0fa4    Peb: 7ffde000  ParentCid: 0228
    DirBase: 3c9e6000  ObjectTable: e1627410  HandleCount:  81.
    Image: userinit.exe
    VadRoot 89a80168 Vads 161 Clone 0 Private 517. Modified 4. Locked 0.
    DeviceMap e1003170
    Token                             e1575030
    ElapsedTime                       05:34:29.046
    UserTime                          00:00:00.046
    KernelTime                        00:00:00.234
    QuotaPoolUsage[PagedPool]         42916
    QuotaPoolUsage[NonPagedPool]      7176
    Working Set Sizes (now,min,max)  (1289, 50, 345) (5156KB, 200KB, 1380KB)
    PeakWorkingSetSize                1291
    VirtualSize                       33 Mb
    PeakVirtualSize                   34 Mb
    PageFaultCount                    1411
    MemoryPriority                    BACKGROUND
    BasePriority                      8
    CommitCharge                      866

[...]

THREAD 89d475a8  Cid 0fa4.0f48  Teb: 7ffda000 Win32Thread: 00000000 WAIT: (WrLpcReply) UserMode Non-Alertable
    89d4779c  Semaphore Limit 0x1
Waiting for reply to LPC MessageId 0000acfd:
Current LPC port e5501c28
Not impersonating
DeviceMap                 e1003170
Owning Process            0       Image:         <Unknown>
Attached Process          89cf4870       Image:         userinit.exe
Wait Start TickCount      1845699        Ticks: 1284370 (0:05:34:28.281)
Context Switch Count      149            
UserTime                  00:00:00.000
KernelTime                00:00:00.093
Win32 Start Address PAUTOENR!AEMainThreadProc (0×5e95a798)
Start Address kernel32!BaseThreadStartThunk (0×7c8106f9)
Stack Init b88a1000 Current b88a0c50 Base b88a1000 Limit b889e000 Call 0
Priority 7 BasePriority 7 PriorityDecrement 0 DecrementCount 0
Kernel stack not resident.
ChildEBP RetAddr 
b88a0c68 804e1bf2 nt!KiSwapContext+0×2f
b88a0c74 804e1c3e nt!KiSwapThread+0×8a
b88a0c9c 8057d073 nt!KeWaitForSingleObject+0×1c2
b88a0d50 804dd99f nt!NtRequestWaitReplyPort+0×63d
b88a0d50 7c90e514 nt!KiFastCallEntry+0xfc (TrapFrame @ b88a0d64)
00a8f064 7c90daea ntdll!KiFastSystemCallRet
00a8f068 77e7cac1 ntdll!ZwRequestWaitReplyPort+0xc
00a8f0b4 77e7a33e RPCRT4!LRPC_CCALL::SendReceive+0×228
00a8f0c0 77e7a36f RPCRT4!I_RpcSendReceive+0×24
00a8f0d4 77ef4675 RPCRT4!NdrSendReceive+0×2b
00a8f4b0 76f235e7 RPCRT4!NdrClientCall2+0×222
00a8f4c4 76f2357b DNSAPI!R_ResolverQuery+0×1b
00a8f520 71a526c6 DNSAPI!DnsQuery_W+0×14f
00a8f554 71a5266f mswsock!HostentBlob_Query+0×29
00a8f580 71a51b0a mswsock!Rnr_DoDnsLookup+0×7d
00a8f9c8 71ab32b0 mswsock!NSPLookupServiceNext+0×533
00a8f9e0 71ab3290 WS2_32!NSPROVIDER::NSPLookupServiceNext+0×17
00a8f9fc 71ab325a WS2_32!NSPROVIDERSTATE::LookupServiceNext+0×1c
00a8fa28 71ab31f8 WS2_32!NSQUERY::LookupServiceNext+0xae
00a8fa48 76f775eb WS2_32!WSALookupServiceNextW+0×78
00a8faec 76f6a9d2 WLDAP32!GetHostByNameW+0xef
00a8fb38 76f6667b WLDAP32!OpenLdapServer+0×435
00a8fb58 76f6fb05 WLDAP32!LdapConnect+0×169
00a8fef8 76f704f3 WLDAP32!LdapBind+0×34
00a8ff20 5e95651a WLDAP32!ldap_bind_sW+0×2c
00a8ff68 5e95a887 PAUTOENR!AERobustLdapBind+0xc9
00a8ffb4 7c80b729 PAUTOENR!AEMainThreadProc+0xef
00a8ffec 00000000 kernel32!BaseThreadStart+0×37

We start following the LPC wait chain

kd> !lpc message 0000acfd
Searching message acfd in threads …
    Server thread 89a80328 is working on message acfd                        
Client thread 89d475a8 waiting a reply from acfd                         
Searching thread 89d475a8 in port rundown queues …

Server communication port 0xe12fc438
    Handles: 1   References: 1
    The LpcDataInfoChainHead queue is empty
        Connected port: 0xe5501c28      Server connection port: 0xe1640798

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

Server connection port e1640798  Name: DNSResolver
    Handles: 1   References: 17
    Server process  : 899a0020 (svchost.exe)
    Queue semaphore : 89dabdf0
    Semaphore state 0 (0x0)
    The message queue is empty
    The LpcDataInfoChainHead queue is empty
Done.

kd> !thread 89a80328 1f
THREAD 89a80328  Cid 03c8.0644  Teb: 7ffd7000 Win32Thread: 00000000 WAIT: (WrLpcReply) UserMode Non-Alertable
    89a8051c  Semaphore Limit 0×1
Waiting for reply to LPC MessageId 0000acfe:
Current LPC port e10b6b00
Not impersonating
DeviceMap                 e1b093c8
Owning Process            0       Image:         <Unknown>
Attached Process          899a0020       Image:         svchost.exe
Wait Start TickCount      1845699        Ticks: 1284370 (0:05:34:28.281)
Context Switch Count      1208            
UserTime                  00:00:00.000
KernelTime                00:00:00.000
Win32 Start Address 0×0000acfd
LPC Server thread working on message Id acfd
Start Address kernel32!BaseThreadStartThunk (0×7c8106f9)
Stack Init b7a33000 Current b7a32c50 Base b7a33000 Limit b7a30000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0 DecrementCount 0
Kernel stack not resident.
ChildEBP RetAddr 
b7a32c68 804e1bf2 nt!KiSwapContext+0×2f
b7a32c74 804e1c3e nt!KiSwapThread+0×8a
b7a32c9c 8057d073 nt!KeWaitForSingleObject+0×1c2
b7a32d50 804dd99f nt!NtRequestWaitReplyPort+0×63d
b7a32d50 7c90e514 nt!KiFastCallEntry+0xfc (TrapFrame @ b7a32d64)
00a9eb3c 7c90daea ntdll!KiFastSystemCallRet
00a9eb40 77e7cac1 ntdll!ZwRequestWaitReplyPort+0xc
00a9eb8c 77e7a33e RPCRT4!LRPC_CCALL::SendReceive+0×228
00a9eb98 77e7a36f RPCRT4!I_RpcSendReceive+0×24
00a9ebac 77ef4675 RPCRT4!NdrSendReceive+0×2b
00a9ef88 662e0c48 RPCRT4!NdrClientCall2+0×222
00a9ef9c 662dafa9 hnetcfg!FwOpenDynamicFwPort+0×1b
00a9f048 71a55025 hnetcfg!IcfOpenDynamicFwPort+0×6a
00a9f0e4 71a590f2 mswsock!WSPBind+0×332
00a9f200 71ab2fd7 mswsock!WSPSendTo+0×230
00a9f250 76f252c0 WS2_32!sendto+0×88
00a9f280 76f251ea DNSAPI!SendMessagePrivate+0×18d
00a9f2a0 76f2517c DNSAPI!SendUsingServerInfo+0×33
00a9f2c8 76f25436 DNSAPI!SendUdpToNextDnsServers+0×80
00a9f314 76f24dec DNSAPI!Dns_SendAndRecvUdp+0×121
00a9f34c 76f24d20 DNSAPI!Dns_SendAndRecv+0×7b
00a9f37c 76f24a7d DNSAPI!Query_SingleName+0×8b
00a9f3b0 7677373a DNSAPI!Query_Main+0×11a
00a9f3c8 7677303f dnsrslvr!ResolverQuery+0×48
00a9f8bc 77e799f4 dnsrslvr!R_ResolverQuery+0×111
00a9f8e4 77ef421a RPCRT4!Invoke+0×30
00a9fcf4 77ef46ee RPCRT4!NdrStubCall2+0×297
00a9fd10 77e794bd RPCRT4!NdrServerCall2+0×19
00a9fd44 77e79422 RPCRT4!DispatchToStubInC+0×38
00a9fd98 77e7934e RPCRT4!RPC_INTERFACE::DispatchToStubWorker+0×113
00a9fdbc 77e7be64 RPCRT4!RPC_INTERFACE::DispatchToStub+0×84
00a9fdf8 77e7bcc1 RPCRT4!LRPC_SCALL::DealWithRequestMessage+0×2db
00a9fe1c 77e7bc05 RPCRT4!LRPC_ADDRESS::DealWithLRPCRequest+0×16d
00a9ff80 77e76caf RPCRT4!LRPC_ADDRESS::ReceiveLotsaCalls+0×310
00a9ff88 77e76ad1 RPCRT4!RecvLotsaCallsWrapper+0xd
00a9ffa8 77e76c97 RPCRT4!BaseCachedThreadRoutine+0×79
00a9ffb4 7c80b729 RPCRT4!ThreadStartRoutine+0×1a
00a9ffec 00000000 kernel32!BaseThreadStart+0×37

We notice that an endpoint is blocked waiting for a critical section:

kd> !lpc message 0000acfe
Searching message acfe in threads …
    Server thread 89b452e8 is working on message acfe
Client thread 89a80328 waiting a reply from acfe                         
Searching thread 89a80328 in port rundown queues …

Server communication port 0xe11152f8
    Handles: 1   References: 1
    The LpcDataInfoChainHead queue is empty
        Connected port: 0xe10b6b00      Server connection port: 0xe1633380

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

Server connection port e1633380  Name: trkwks
    Handles: 1   References: 19
    Server process  : 89a20858 (svchost.exe)
    Queue semaphore : 89af47e8
    Semaphore state 0 (0x0)
    The message queue is empty
    The LpcDataInfoChainHead queue is empty
Done.

kd> !thread 89b452e8 1f
THREAD 89b452e8  Cid 03a8.0a28  Teb: 7ff94000 Win32Thread: 00000000 WAIT: (UserRequest) UserMode Non-Alertable
    89b466c0  SynchronizationEvent
IRP List:
    89b49008: (0006,01d8) Flags: 00000030  Mdl: 00000000
Not impersonating
DeviceMap                 e1003170
Owning Process            0       Image:         <Unknown>
Attached Process          89a20858       Image:         svchost.exe
Wait Start TickCount      1845699        Ticks: 1284370 (0:05:34:28.281)
Context Switch Count      5            
UserTime                  00:00:00.000
KernelTime                00:00:00.000
Win32 Start Address 0×0000acfe
LPC Server thread working on message Id acfe
Start Address kernel32!BaseThreadStartThunk (0×7c8106f9)
Stack Init b88dd000 Current b88dcca0 Base b88dd000 Limit b88da000 Call 0
Priority 9 BasePriority 8 PriorityDecrement 0 DecrementCount 0
Kernel stack not resident.
ChildEBP RetAddr 
b88dccb8 804e1bf2 nt!KiSwapContext+0×2f
b88dccc4 804e1c3e nt!KiSwapThread+0×8a
b88dccec 8056dff6 nt!KeWaitForSingleObject+0×1c2
b88dcd50 804dd99f nt!NtWaitForSingleObject+0×9a
b88dcd50 7c90e514 nt!KiFastCallEntry+0xfc (TrapFrame @ b88dcd64)
036ef714 7c90df5a ntdll!KiFastSystemCallRet
036ef718 7c91b24b ntdll!ZwWaitForSingleObject+0xc
036ef7a0 7c901046 ntdll!RtlpWaitForCriticalSection+0×132
036ef7a8 6648a33b ntdll!RtlEnterCriticalSection+0×46

036ef7b0 6648c2ed ipnathlp!FwLock+0xa
036ef808 6648c705 ipnathlp!FwDynPortAdd+0×1d
036ef8c4 77e799f4 ipnathlp!FwOpenDynamicFwPort+0×125
036ef8e8 77ef421a RPCRT4!Invoke+0×30
036efcf4 77ef46ee RPCRT4!NdrStubCall2+0×297
036efd10 77e794bd RPCRT4!NdrServerCall2+0×19
036efd44 77e79422 RPCRT4!DispatchToStubInC+0×38
036efd98 77e7934e RPCRT4!RPC_INTERFACE::DispatchToStubWorker+0×113
036efdbc 77e7be64 RPCRT4!RPC_INTERFACE::DispatchToStub+0×84
036efdf8 77e7bcc1 RPCRT4!LRPC_SCALL::DealWithRequestMessage+0×2db
036efe1c 77e7bc05 RPCRT4!LRPC_ADDRESS::DealWithLRPCRequest+0×16d
036eff80 77e76caf RPCRT4!LRPC_ADDRESS::ReceiveLotsaCalls+0×310
036eff88 77e76ad1 RPCRT4!RecvLotsaCallsWrapper+0xd
036effa8 77e76c97 RPCRT4!BaseCachedThreadRoutine+0×79
036effb4 7c80b729 RPCRT4!ThreadStartRoutine+0×1a
036effec 00000000 kernel32!BaseThreadStart+0×37

In 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 walk thread stack trace parameters:

kd> .process /r /p 89a20858
Implicit process is now 89a20858

kd> !cs -l -o -s
-----------------------------------------
DebugInfo          = 0x7c97e500
Critical section   = 0x7c980600 (ntdll!FastPebLock+0x0)
LOCKED
LockCount          = 0x10
OwningThread       = 0x000004a8
RecursionCount     = 0x1
LockSemaphore      = 0xC20
SpinCount          = 0x00000000
OwningThread       = .thread 89cd9c10
ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled.
-----------------------------------------
DebugInfo          = 0x000d7f08
Critical section   = 0x01e700d4 (+0x1E700D4)
LOCKED
LockCount          = 0x0
OwningThread       = 0x000001b8
RecursionCount     = 0x1
LockSemaphore      = 0x0
SpinCount          = 0x00000000
OwningThread       = .thread 89b3b348
ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled.
-----------------------------------------
DebugInfo          = 0x000d96e0
Critical section   = 0x767e406c (w32time!g_state+0x24)
LOCKED
LockCount          = 0x3
OwningThread       = 0x00000f70
RecursionCount     = 0x2
LockSemaphore      = 0x7FC
SpinCount          = 0x00000000
OwningThread       = .thread 89a6a268
ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled.
-----------------------------------------
DebugInfo          = 0x000e74f0
Critical section   = 0x01e70cc8 (+0x1E70CC8)
LOCKED
LockCount          = 0x2
OwningThread       = 0x00000514
RecursionCount     = 0x1
LockSemaphore      = 0xBA8
SpinCount          = 0x00000000
OwningThread       = .thread 8996a338
ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled.
-----------------------------------------
DebugInfo          = 0x00103d58
Critical section   = 0x0272a8b4 (+0x272A8B4)
LOCKED
LockCount          = 0x0
OwningThread       = 0x00000d38
RecursionCount     = 0x1
LockSemaphore      = 0x0
SpinCount          = 0x00000000
OwningThread       = .thread 89912860
ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled.
-----------------------------------------
DebugInfo          = 0x0010e8f0
Critical section   = 0x664a3fe0 (ipnathlp!gFwMain+0x0)
LOCKED
LockCount          = 0x6
OwningThread       = 0x000009e8
RecursionCount     = 0x1
LockSemaphore      = 0xC48
SpinCount          = 0x00000000
OwningThread       = .thread 898aa600
ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled.
-----------------------------------------
DebugInfo          = 0x0010a7d8
Critical section   = 0x00138cd0 (+0x138CD0)
LOCKED
LockCount          = 0x0
OwningThread       = 0x00000510
RecursionCount     = 0x1
LockSemaphore      = 0x0
SpinCount          = 0x00000000
OwningThread       = .thread 89a2eda8
ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled.
-----------------------------------------
DebugInfo          = 0x00109cb0
Critical section   = 0x02750f18 (+0x2750F18)
LOCKED
LockCount          = 0x0
OwningThread       = 0x00000c84
RecursionCount     = 0x1
LockSemaphore      = 0x0
SpinCount          = 0x00000000
OwningThread       = .thread 898ba3d0
ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled.

kd> .thread 89b452e8
Implicit thread is now 89b452e8

kd> kv 0n10
ChildEBP RetAddr  Args to Child             
b88dccb8 804e1bf2 89b45358 89b452e8 804e1c3e nt!KiSwapContext+0x2f
b88dccc4 804e1c3e 00000000 00000000 00000000 nt!KiSwapThread+0x8a
b88dccec 8056dff6 00000001 00000006 b88dcd01 nt!KeWaitForSingleObject+0x1c2
b88dcd50 804dd99f 00000c48 00000000 00000000 nt!NtWaitForSingleObject+0x9a
b88dcd50 7c90e514 00000c48 00000000 00000000 nt!KiFastCallEntry+0xfc (TrapFrame @ b88dcd64)
036ef714 7c90df5a 7c91b24b 00000c48 00000000 ntdll!KiFastSystemCallRet
036ef718 7c91b24b 00000c48 00000000 00000000 ntdll!ZwWaitForSingleObject+0xc
036ef7a0 7c901046 004a3fe0 6648a33b 664a3fe0 ntdll!RtlpWaitForCriticalSection+0x132
036ef7a8 6648a33b 664a3fe0 6648c2ed 00000000 ntdll!RtlEnterCriticalSection+0×46
036ef7b0 6648c2ed 00000000 00000000 00000001 ipnathlp!FwLock+0xa

The thread above is waiting for the critical section 664a3fe0 which has the owner thread 898aa600:

[...]
Critical section = 0×664a3fe0 (ipnathlp!gFwMain+0×0)
LOCKED
LockCount = 0×6
OwningThread = 0×000009e8
RecursionCount = 0×1
LockSemaphore = 0xC48
SpinCount = 0×00000000
OwningThread = .thread 898aa600
[…]

kd> .thread 898aa600
Implicit thread is now 898aa600

kd> kv 0n10
ChildEBP RetAddr  Args to Child             
b7b46cb8 804e1bf2 898aa670 898aa600 804e1c3e nt!KiSwapContext+0x2f
b7b46cc4 804e1c3e 00000000 00000000 00000000 nt!KiSwapThread+0x8a
b7b46cec 8056dff6 00000001 00000006 ffffff01 nt!KeWaitForSingleObject+0x1c
b7b46d50 804dd99f 00000c20 00000000 00000000 nt!NtWaitForSingleObject+0x9a
b7b46d50 7c90e514 00000c20 00000000 00000000 nt!KiFastCallEntry+0xfc (TrapFrame @ b7b46d64)
029ef324 7c90df5a 7c91b24b 00000c20 00000000 ntdll!KiFastSystemCallRet
029ef328 7c91b24b 00000c20 00000000 00000000 ntdll!ZwWaitForSingleObject+0xc
029ef3b0 7c901046 00980600 7c910435 7c980600 ntdll!RtlpWaitForCriticalSection+0x132
029ef3b8 7c910435 7c980600 00000000 00000000 ntdll!RtlEnterCriticalSection+0×46
029ef3f8 7c9145d1 00121abe 00121ab0 00000020 ntdll!RtlAcquirePebLock+0×28

The thread 898aa600 is waiting for the critical section 7c980600 which has the owner thread 89cd9c10:

[...]
Critical section = 0×7c980600 (ntdll!FastPebLock+0×0)
LOCKED
LockCount = 0×10
OwningThread = 0×000004a8
RecursionCount = 0×1
LockSemaphore = 0xC20
SpinCount = 0×00000000
OwningThread = .thread 89cd9c10
[…]

kd> .thread 89cd9c10
Implicit thread is now 89cd9c10

kd> kv 100
ChildEBP RetAddr  Args to Child             
b881c8d4 804e1bf2 89cd9c80 89cd9c10 804e1c3e nt!KiSwapContext+0x2f
b881c8e0 804e1c3e 00000000 89e35b08 89e35b34 nt!KiSwapThread+0x8a
b881c908 f783092e 00000000 00000006 00000000 nt!KeWaitForSingleObject+0x1c2
b881c930 f7830a3b 89e35b08 00000000 f78356d8 Mup!PktPostSystemWork+0x3d
b881c94c f7836712 b881c9b0 b881c9b0 b881c9b8 Mup!PktGetReferral+0xce
b881c980 f783644f b881c9b0 b881c9b8 00000000 Mup!PktCreateDomainEntry+0x224
b881c9d0 f7836018 0000000b 00000000 b881c9f0 Mup!DfsFsctrlIsThisADfsPath+0x2bb
b881ca14 f7835829 89a2e130 899ba350 b881caac Mup!CreateRedirectedFile+0x2cd
b881ca70 804e13eb 89f46ee8 89a2e130 89a2e130 Mup!MupCreate+0x1cb
b881ca80 805794b6 89f46ed0 89df3c44 b881cc18 nt!IopfCallDriver+0x31
b881cb60 8056d03b 89f46ee8 00000000 89df3ba0 nt!IopParseDevice+0xa12
b881cbd8 805701e7 00000000 b881cc18 00000042 nt!ObpLookupObjectName+0x53c
b881cc2c 80579b12 00000000 00000000 00003801 nt!ObOpenObjectByName+0xea
b881cca8 80579be1 00cff67c 00100020 00cff620 nt!IopCreateFile+0x407
b881cd04 80579d18 00cff67c 00100020 00cff620 nt!IoCreateFile+0x8e
b881cd44 804dd99f 00cff67c 00100020 00cff620 nt!NtOpenFile+0x27
b881cd44 7c90e514 00cff67c 00100020 00cff620 nt!KiFastCallEntry+0xfc (TrapFrame @ b881cd64)
00cff5f0 7c90d5aa 7c91e8dd 00cff67c 00100020 ntdll!KiFastSystemCallRet
00cff5f4 7c91e8dd 00cff67c 00100020 00cff620 ntdll!ZwOpenFile+0xc
00cff69c 7c831e58 00cff6a8 00460044 0078894a ntdll!RtlSetCurrentDirectory_U+0x169
00cff6b0 7731889e 0078894a 00000000 00000001 kernel32!SetCurrentDirectoryW+0×2b
00cffb84 7730ffbb 00788450 00788b38 00cffbe0 schedsvc!CSchedWorker::RunNTJob+0×221
00cffe34 7730c03a 01ea9108 8ed032d4 00787df8 schedsvc!CSchedWorker::RunJobs+0×304
00cffe74 77310e4d 7c80a749 00000000 00000000 schedsvc!CSchedWorker::RunNextJobs+0×129
00cfff28 77310efc 7730b592 00000000 000ba4bc schedsvc!CSchedWorker::MainServiceLoop+0×6d9
00cfff2c 7730b592 00000000 000ba4bc 0009a2bc schedsvc!SchedMain+0xb
00cfff5c 7730b69f 00000001 000ba4b8 00cfffa0 schedsvc!SchedStart+0×266
00cfff6c 010011cc 00000001 000ba4b8 00000000 schedsvc!SchedServiceMain+0×33
00cfffa0 77df354b 00000001 000ba4b8 0007e898 svchost!ServiceStarter+0×9e
00cfffb4 7c80b729 000ba4b0 00000000 0007e898 ADVAPI32!ScSvcctrlThreadA+0×12
00cfffec 00000000 77df3539 000ba4b0 00000000 kernel32!BaseThreadStart+0×37

kd> du /c 90 0078894a
0078894a  “\\SERVER_B\Share_X$\Folder_Q”

The thread above is blocked trying to set the current directory residing on another server SERVER_B. Its waiting time is almost 13 min 34 sec:

kd> !thread 89cd9c10 7
THREAD 89cd9c10  Cid 03a8.04a8  Teb: 7ffd5000 Win32Thread: e1cdc2c0 WAIT: (UserRequest) KernelMode Non-Alertable
    89e35b34  SynchronizationEvent
IRP List:
    89a2e130: (0006,0094) Flags: 00000884  Mdl: 00000000
    89a13008: (0006,01b4) Flags: 00000000  Mdl: 00000000
Impersonation token:  e2deea00 (Level Impersonation)
DeviceMap                 e1cfe618
Owning Process            0       Image:         <Unknown>
Attached Process          89a20858       Image:         svchost.exe
Wait Start TickCount      4392           Ticks: 3125677 (0:13:33:58.703)
Context Switch Count      202                 LargeStack
UserTime                  00:00:00.031
KernelTime                00:00:00.015
Win32 Start Address ADVAPI32!ScSvcctrlThreadA (0×77df3539)
Start Address kernel32!BaseThreadStartThunk (0×7c8106f9)
Stack Init b881d000 Current b881c8bc Base b881d000 Limit b8819000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0 DecrementCount 0
ChildEBP RetAddr  Args to Child             
[…] 

Looking at the previous !process 0 ff output we also find the similar system thread running through the same drivers and having the same waiting time:

THREAD 8a04cb30  Cid 0004.0014  Teb: 00000000 Win32Thread: 00000000 WAIT: (Executive) KernelMode Non-Alertable
    89e344a8  SynchronizationEvent
IRP List:
    89901348: (0006,0094) Flags: 00000884  Mdl: 00000000
Not impersonating
DeviceMap                 e1003170
Owning Process            0       Image:         <Unknown>
Attached Process          8a04d830       Image:         System
Wait Start TickCount      4392           Ticks: 3125677 (0:13:33:58.703)
Context Switch Count      1890            
UserTime                  00:00:00.000
KernelTime                00:00:00.109
Start Address nt!ExpWorkerThread (0×804e2311)
Stack Init f78b3000 Current f78b27c0 Base f78b3000 Limit f78b0000 Call 0
Priority 13 BasePriority 13 PriorityDecrement 0 DecrementCount 16
ChildEBP RetAddr 
f78b27d8 804e1bf2 nt!KiSwapContext+0×2f
f78b27e4 804e1c3e nt!KiSwapThread+0×8a
f78b280c f7836328 nt!KeWaitForSingleObject+0×1c2
f78b282c f783622a Mup!MupiIssueQueryRequest+0×2f
f78b2854 f7836069 Mup!MupiResolvePrefix+0×11b
f78b2898 f7835829 Mup!CreateRedirectedFile+0×35d
f78b28f4 804e13eb Mup!MupCreate+0×1cb
f78b2904 805794b6 nt!IopfCallDriver+0×31
f78b29e4 8056d03b nt!IopParseDevice+0xa12
f78b2a5c 805701e7 nt!ObpLookupObjectName+0×53c
f78b2ab0 80579b12 nt!ObOpenObjectByName+0xea
f78b2b2c 80579be1 nt!IopCreateFile+0×407
f78b2b88 80573e2b nt!IoCreateFile+0×8e
f78b2bc8 804dd99f nt!NtCreateFile+0×30
f78b2bc8 804e3597 nt!KiFastCallEntry+0xfc (TrapFrame @ f78b2bfc)
f78b2c6c f78368ca nt!ZwCreateFile+0×11
f78b2cd4 f78306fa Mup!DfsCreateIpcConnection+0×9c
f78b2d60 f7830aae Mup!_PktGetReferral+0×11d
f78b2d7c 804e23d5 Mup!PktWorkInSystemContext+0×4c
f78b2dac 80576316 nt!ExpWorkerThread+0xef
f78b2ddc 804ec6f9 nt!PspSystemThreadStartup+0×34
00000000 00000000 nt!KiThreadStartup+0×16

It has an IRP having file object pointing the same server SERVER_B:

kd> !irp 89901348
Irp is active with 1 stacks 1 is current (= 0×899013b8)
 No Mdl: No System Buffer: Thread 8a04cb30:  Irp stack trace. 
     cmd  flg cl Device   File     Completion-Context
>[  0, 0]   0  0 89f46ee8 899ab170 00000000-00000000   
        \FileSystem\Mup
   Args: f78b2930 03000020 00070080 00000000
kd> !fileobj 899ab170

\SERVER_B\IPC$

Device Object: 0x89f46ee8   \FileSystem\Mup
Vpb is NULL

Flags:  0x2
 Synchronous IO

CurrentByteOffset: 0

So it looks like we have an instance of Coupled Machines pattern. We also notice that wait chain threads have various Windows socket modules on their thread stacks and we check if there is any IRP distribution anomaly using !irpfind command. Counting IRPs we find the most of them are directed towards HTTP, Tcpip and AFD drivers:

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

HCI (Debugging Slang, Part 14)

Friday, July 16th, 2010

HCI - Hang-Crash Interruption. Based on Human-Computer Interaction.

Examples: I see an HCI issue again and again.

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

On Unconscious

Friday, July 16th, 2010

Computer software is said to be simple and predictable as any mechanism (*). We can debug it, we can completely trace what it is doing. It seems rational to us. Let’s then label it as Conscious. On the outside there is an irrational human being who did program that software. Let’s then label that person’s mind as Unconscious. What about hardware and body? They form parts of HCI (Human-Computer Interaction or Interface).

(*) Is there any life inside Windows?

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -