Crash Dump Analysis

Today we introduce an icon for Manual Dump (kernel) pattern:

B/W

Color

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

If you attended Fundamentals of Complete Crash and Hang Memory Dump Analysis you probably remember the memory dump visualization question that I repeat here on this slide fragment:

I got a few responses:

“Unfortunately they are not identical - visual inspection shows that. I tried differencing the relevant sub-images in Photoshop and I can’t get zero.  Of course this can be due to compression artifacts and, more likely, the fact that the duplication is not required to be aligned to the borders. A stronger confirmation/refutation would require unrolling the bitmap to one dimension and sliding it back and forth until maximum correlation is found. Since I have not done the examples step by step, I am left guessing about just what the dump you show illustrates. An aliased memory mapped area is my first guess, and a flip/flop garbage collector is my second.”

“perhaps some module such as a .NET assembly is getting loaded twice in a .NET app, pre .NET 4, such as is dicsussed in this thread:
http://forum.sysinternals.com/why-some-net-assemblies-are-duplicated-in-memory_topic15279_post121591.html“

Initially I also thought that there was the same module loaded twice from different location like in Duplicated Module pattern. Unfortunately lm command didn’t show any duplicated loaded and unloaded modules as well as any hidden modules. So I looked at address information and found two identical relatively large regions at the beginning:

0:000> !address
[...]
BaseAddress EndAddress+1 RegionSize Type       State      Protect       Usage
[...]
0`00470000  0`007f0000   0`00380000 MEM_MAPPED MEM_COMMIT PAGE_READONLY <unclassified>
[…]
0`01f10000  0`02290000   0`00380000 MEM_MAPPED MEM_COMMIT PAGE_READONLY <unclassified>
[…]

The image above was scaled by ImageMagic from a bitmap generated by Dump2Picture:

The original image from Dump2Picture had different colors:

I quickly checked the colorimetric structure of those regions: 0`00470000  0`007f0000 and 0`01f10000  0`02290000 using MemPicture WinDbg script and they seem to conform with the magnified picture above:

0:000> $$>a< d:\Dump2Picture\mempicture.txt 0`00470000 L?0`007f0000-0`00470000
Writing 380000 bytes

C:\Program Files\Debugging Tools for Windows (x64)>dump2picture d2p-range.bin d2p-range.bmp

Dump2Picture version 1.1
Written by Dmitry Vostokov, 2007

d2p-range.bmp
d2p-range.bin
        1 file(s) copied.

C:\Program Files\Debugging Tools for Windows (x64)>d2p-range.bmp
.shell: Process exited

Here is the magnified slice from the original picture:

We see the same partitioning if we juxtapose the original picture and the picture of the address region:

Also these regions are completely identical if we compare their data:

0:000> c 0`00470000 L?(0`007f0000-0`00470000)/8 0`01f10000

So it looks like some file was mapped twice. Inspected via dc command it shows remarkable regularity not seen in executable modules. This regularity also manifests itself in color:

In order to verify I modeled this by writing a simple program that maps a file twice passed as a command line parameter:

int _tmain(int argc, _TCHAR* argv[])
{
 if (argc < 2)
 {
  puts("Usage: MappedFiles.exe <File_Name_To_Map>\n");
  return -1;
 }

 HANDLE hf = CreateFile(argv[1], GENERIC_READ, FILE_SHARE_READ, NULL, OPEN_EXISTING, FILE_ATTRIBUTE_NORMAL, NULL);
 HANDLE hm = CreateFileMapping(hf, NULL, PAGE_READONLY, 0, 0, NULL);
 MapViewOfFile(hm, FILE_MAP_READ, 0, 0, 0);

 hf = CreateFile(argv[1], GENERIC_READ, FILE_SHARE_READ, NULL, OPEN_EXISTING, FILE_ATTRIBUTE_NORMAL, NULL);
 hm = CreateFileMapping(hf, NULL, PAGE_READONLY, 0, 0, NULL);
 MapViewOfFile(hm, FILE_MAP_READ, 0, 0, 0);

 DebugBreak();
 return 0;
}

I ran it and chose to map explorer.exe because it was a sufficiently large image file:

C:\MappedFiles\Release>MappedFiles.exe c:\windows\explorer.exe

The dump file was saved and its processing shows this picture:

We clearly see identical regions and double check them from the dump file:

0:000> !address
BaseAddr EndAddr+1 RgnSize Type       State         Protect       Usage
[...]
a60000   d1d000    2bd000  MEM_MAPPED MEM_COMMIT    PAGE_READONLY <unclassified>
d1d000   d20000    3000    MEM_FREE   PAGE_NOACCESS Free
d20000   fdd000    2bd000  MEM_MAPPED MEM_COMMIT    PAGE_READONLY <unclassified>
[…] 

0:000> $$>a< d:\Dump2Picture\mempicture.txt 0`00470000 L?0`007f0000-0`00470000
Writing 380000 bytes

C:\Program Files\Debugging Tools for Windows (x64)>dump2picture d2p-range.bin d2p-range.bmp 

Dump2Picture version 1.1
Written by Dmitry Vostokov, 2007

d2p-range.bmp
d2p-range.bin
        1 file(s) copied.

C:\Program Files\Debugging Tools for Windows (x64)>d2p-range.bmp
.shell: Process exited

We see the same partitioning if we juxtapose results:

The application can be downloaded from here: MappedFiles.zip

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

Finally I compiled a Questions and Answers page with all necessary links and examples during the weekend:

http://www.dumpanalysis.com/FCMDA-Q-A

I also added text versions of logs (in addition to zip files) to a Webinar materials page:

http://www.dumpanalysis.com/FCMDA-materials

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

Today we introduce an icon for Special Stack Trace pattern:

B/W

Color

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

The presentation materials from the webinar (18th and 23rd of August, 2010) are available for download:

http://www.dumpanalysis.com/FCMDA-materials

Thanks to everyone who registered and attended!

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

Today we introduce an icon for Custom Exception Handler pattern:

B/W

Color

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

In a complete memory dump we could see ALPC wait chains leading to ServiceA.exe process with a queue of 372 messages. Additionally we could also see ServiceB.exe process waiting for ServiceC.exe with the latter having a queue of 201 messages. Threads that were supposed to process some messages didn’t exist. ServiceC process had a thread that was waiting for ServiceA.exe as well. But there was no any indication for a thread-2-thread deadlock. We could also see that threads waiting for ServiceA.exe sometimes had the greater waiting time than threads waiting for ServiceC so it could be the case that the problem initially started with ServiceA.exe. However, after more thorough analysis we could also see several terminating ApplicationD.exe processes with just one thread waiting in ModuleE with the waiting time exceeding the waiting time of blocked threads waiting for ServiceA and ServiceC. Because of semantic process coupling between ServiceA and ApplicationD it was decided that ModuleE was responsible and its vendor was contacted for updates.

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

Today we introduce an icon for Coupled Processes (semantics) pattern:

B/W

Color

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

The one obvious pattern that is shown in many case studies on this blog is Exception Stack Trace (or Exception Thread). This is a stack trace that has exception processing functions, for example:

   9  Id: 1df4.a08 Suspend: -1 Teb: 7fff4000 Unfrozen
ChildEBP RetAddr 
1022f5a8 7c90df4a ntdll!KiFastSystemCallRet
1022f5ac 7c8648a2 ntdll!ZwWaitForMultipleObjects+0xc
1022f900 7c83ab50 kernel32!UnhandledExceptionFilter+0×8b9
1022f908 7c839b39 kernel32!BaseThreadStart+0×4d
1022f930 7c9032a8 kernel32!_except_handler3+0×61
1022f954 7c90327a ntdll!ExecuteHandler2+0×26
1022fa04 7c90e48a ntdll!ExecuteHandler+0×24
1022fa04 7c812afb ntdll!KiUserExceptionDispatcher+0xe
1022fd5c 0b82e680 kernel32!RaiseException+0×53
WARNING: Stack unwind information not available. Following frames may be wrong.
1022fd94 0b82d2f2 DllA+0×21e640
1022fde8 7753004f DllA+0×21d4f2
1022fdfc 7753032f ole32!CClassCache::CDllPathEntry::CanUnload_rl+0×3b
1022ff3c 7753028b ole32!CClassCache::FreeUnused+0×70
1022ff4c 775300b5 ole32!CoFreeUnusedLibrariesEx+0×36
1022ff58 77596af5 ole32!CoFreeUnusedLibraries+0×9
1022ff6c 77566ff9 ole32!CDllHost::MTAWorkerLoop+0×25
1022ff8c 7752687c ole32!CDllHost::WorkerThread+0xc1
1022ff94 774fe3ee ole32!DLLHostThreadEntry+0xd
1022ffa8 774fe456 ole32!CRpcThread::WorkerLoop+0×1e
1022ffb4 7c80b729 ole32!CRpcThreadCache::RpcWorkerThreadEntry+0×1b
1022ffec 00000000 kernel32!BaseThreadStart+0×37

Such exceptions can be detected by the default analysis command (for example, !analyze -v WinDbg command) or by inspecting a stack trace collection. However if we didn’t see any exception thread it doesn’t mean that no exception had occurred. There could be hidden exceptions on raw stack data. 

In our case we can get the exception information by looking at parameters to in unhandled exception filter:

0:009> kv 3
ChildEBP RetAddr Args to Child
1022f5a8 7c90df4a 7c8648a2 00000002 1022f730 ntdll!KiFastSystemCallRet
1022f5ac 7c8648a2 00000002 1022f730 00000001 ntdll!ZwWaitForMultipleObjects+0xc
1022f900 7c83ab50 1022f928 7c839b39 1022f930 kernel32!UnhandledExceptionFilter+0×8b9

0:009> .exptr 1022f928

----- Exception record at 1022fa1c:
ExceptionAddress: 7c812afb (kernel32!RaiseException+0x00000053)
  ExceptionCode: e06d7363 (C++ EH exception)
  ExceptionFlags: 00000001
NumberParameters: 3
  Parameter[0]: 19930520
  Parameter[1]: 1022fda4
  Parameter[2]: 0b985074
  pExceptionObject: 1022fda4
  _s_ThrowInfo : 0b985074

----- Context record at 1022fa3c:
eax=1022fd0c ebx=00000001 ecx=00000000 edx=1022fda4 esi=1022fd94 edi=77606068
eip=7c812afb esp=1022fd08 ebp=1022fd5c iopl=0 nv up ei pl nz na pe nc
cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00000206
kernel32!RaiseException+0x53:
7c812afb 5e pop esi

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

Sometimes we get memory dumps that are difficult to analyze in full because some if not most of information was omitted during saving. These are usually small memory dumps (contrasted with kernel and complete) and user process minidumps. We can easily recognize that when we open a dump:

User Mini Dump File: Only registers, stack and portions of memory are available

or

Mini Kernel Dump File: Only registers and stack trace are available

The same also applies to user dumps where thread times information is omitted so it is not possible to use !runaway WinDbg command or to a dump saved with various options of .dump command (including privacy-aware) instead of /ma or deprecated /f option. On the contrary, manually erased data in crash dumps looks more like an example of another pattern called Lateral Damage.

The similar cases of abridged dumps are discussed in Wrong Dump and Missing Space antipatterns.

Anyway, we shouldn’t dismiss such dumps and should try to analyze them. For example, some approaches (including using image binaries) are listed in kernel minidump analysis series. We can even see portions of raw stack data in search of execution residue:

0: kd> !thread
GetPointerFromAddress: unable to read from 81d315b0
THREAD 82f49020  Cid 0004.0034  Teb: 00000000 Win32Thread: 00000000 RUNNING on processor 0
IRP List:
    Unable to read nt!_IRP @ 8391e008
Not impersonating
GetUlongFromAddress: unable to read from 81d0ad90
Owning Process            82f00ab0       Image:         System
Attached Process          N/A            Image:         N/A
ffdf0000: Unable to get shared data
Wait Start TickCount      4000214     
Context Switch Count      21886            
ReadMemory error: Cannot get nt!KeMaximumIncrement value.
UserTime                  00:00:00.000
KernelTime                00:00:00.000
Win32 Start Address nt!ExpWorkerThread (0x81c78ea3)
Stack Init 85be0000 Current 85bdf7c0 Base 85be0000 Limit 85bdd000 Call 0
Priority 14 BasePriority 12 PriorityDecrement 0 IoPriority 2 PagePriority 5
[…]

0: kd> dps 85bdd000 85be0000
85bdd000  ????????
85bdd004  ????????
85bdd008  ????????
85bdd00c  ????????
85bdd010  ????????
85bdd014  ????????
85bdd018  ????????
85bdd01c  ????????
85bdd020  ????????
85bdd024  ????????
85bdd028  ????????
[...]
85bdf8c4  ????????
85bdf8c8  ????????
85bdf8cc  ????????
85bdf8d0  0000000a
85bdf8d4  a112883e
85bdf8d8  0000001b
85bdf8dc  00000000
85bdf8e0  81c28750 nt!KeSetEvent+0x4d
85bdf8e4  85bdf8e8
85bdf8e8  85bdf970
85bdf8ec  81c28750 nt!KeSetEvent+0x4d
85bdf8f0  badb0d00
85bdf8f4  00000000
85bdf8f8  00000000
85bdf8fc  81cf4820 nt!KiInitialPCR+0x120
85bdf900  00000000
85bdf904  85bdf938
85bdf908  81cf4820 nt!KiInitialPCR+0x120
85bdf90c  00000000
85bdf910  81d32300 nt!IopTimerLock
85bdf914  00000000
85bdf918  81fa0000 nt!_NULL_IMPORT_DESCRIPTOR <PERF> (nt+0x3a0000)
85bdf91c  85bd0023
85bdf920  00000023
85bdf924  00000000
85bdf928  81d323c0 nt!KiDispatcherLock
85bdf92c  a1128828
85bdf930  85bdf9b4
85bdf934  85bdfdb0
85bdf938  00000030
85bdf93c  84ca6f40
85bdf940  84ca6f38
85bdf944  00000001
85bdf948  85bdf970
85bdf94c  00000000
85bdf950  81c28750 nt!KeSetEvent+0x4d
85bdf954  00000008
85bdf958  00010246
85bdf95c  00000000
85bdf960  84ca68a0
[...]
85bdfd2c  82f49020
85bdfd30  835ca4d0
85bdfd34  a6684538
85bdfd38  81cfde7c nt!ExWorkerQueue+0x3c
85bdfd3c  00000001
85bdfd40  00000000
85bdfd44  85bdfd7c
85bdfd48  81c78fa0 nt!ExpWorkerThread+0xfd
85bdfd4c  835ca4d0
85bdfd50  00000000
85bdfd54  82f49020
85bdfd58  00000000
85bdfd5c  00000000
85bdfd60  0069000b
85bdfd64  00000000
85bdfd68  00000001
85bdfd6c  00000000
85bdfd70  835ca4d0
85bdfd74  81da9542 nt!PnpDeviceEventWorker
85bdfd78  00000000
85bdfd7c  85bdfdc0
85bdfd80  81e254e0 nt!PspSystemThreadStartup+0x9d
85bdfd84  835ca4d0
85bdfd88  85bd4680
85bdfd8c  00000000
85bdfd90  00000000
85bdfd94  00000000
85bdfd98  00000002
85bdfd9c  00000000
85bdfda0  00000000
85bdfda4  00000001
85bdfda8  85bdfd88
85bdfdac  85bdfdbc
85bdfdb0  ffffffff
85bdfdb4  81c8aad5 nt!_except_handler4
85bdfdb8  81c9ddb8 nt!`string'+0x4
85bdfdbc  00000000
85bdfdc0  00000000
85bdfdc4  81c9159e nt!KiThreadStartup+0x16
85bdfdc8  81c78ea3 nt!ExpWorkerThread
85bdfdcc  00000001
85bdfdd0  00000000
85bdfdd4  00000000
85bdfdd8  002e0069
85bdfddc  006c0064
85bdfde0  004c006c
85bdfde4  00000000
85bdfde8  000007f0
85bdfdec  00010000
85bdfdf0  0000027f
85bdfdf4  00000000
85bdfdf8  00000000
85bdfdfc  00000000
85bdfe00  00000000
85bdfe04  00000000
85bdfe08  00001f80
85bdfe0c  0000ffff
85bdfe10  00000000
85bdfe14  00000000
85bdfe18  00000000
[...]
85bdffe4  00000000
85bdffe8  00000000
85bdffec  00000000
85bdfff0  00000000
85bdfff4  00000000
85bdfff8  00000000
85bdfffc  00000000
85be0000  ????????

User minidumps are similar here:

0:001> k
ChildEBP RetAddr 
099bfe147c90daaa ntdll!KiFastSystemCallRet
099bfe18 77e765e3 ntdll!NtReplyWaitReceivePortEx+0xc
099bff80 77e76caf rpcrt4!LRPC_ADDRESS::ReceiveLotsaCalls+0×12a
099bff88 77e76ad1 rpcrt4!RecvLotsaCallsWrapper+0xd
099bffa8 77e76c97 rpcrt4!BaseCachedThreadRoutine+0×79
099bffb4 7c80b729 rpcrt4!ThreadStartRoutine+0×1a
099bffec 00000000 kernel32!BaseThreadStart+0×37

0:001> dd 099bfe14
099bfe14  099bfe24 7c90daaa 77e765e3 00000224
099bfe24  099bff74 00000000 2db87ae8 099bff48
099bfe34  fbf58e18 00000040 fd629338 b279dbbc
099bfe44  fd5928b8 fbf58ebc b279dbbc e0c1e002
099bfe54  00000000 00000006 00000001 00000000
099bfe64  e637d218 00000000 00000006 00000006
099bfe74  00000006 e1f79698 e39b8b60 00000000
099bfe84  fbe33c40 00000001 e5ce12f8 b279db9c

0:001> dd 099bfe14-20
099bfdf4  ???????? ???????? ???????? ????????
099bfe04  ???????? ???????? ???????? ????????
099bfe14  099bfe24 7c90daaa 77e765e3 00000224
099bfe24  099bff74 00000000 2db87ae8 099bff48
099bfe34  fbf58e18 00000040 fd629338 b279dbbc
099bfe44  fd5928b8 fbf58ebc b279dbbc e0c1e002
099bfe54  00000000 00000006 00000001 00000000
099bfe64  e637d218 00000000 00000006 00000006

As a warning here it is possible to conclude that minidumps can also reveal private information especially when ASCII or Unicode buffers are seen on raw stack data.

I was thinking how to name this pattern and Oxford Thesaurus of English suggested the following name: Abridged Dump by analogy with an abridged book.

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

In addition to strong and weak process coupling patterns we also have another variant that I call semantic coupling. Some processes (not necessarily from the same vendor) cooperate to provide certain functionality. The cooperation might not involve trackable and visible inter-process communication such as (A)LPC/RPC or pipes but involve events, shared memory and other possible mechanisms not explicitly visible when we look at memory dumps. In many cases, after finding problems in one or several processes from a semantic group we also look at the remaining processes from that group to see if there are some anomalies there as well. The one example I encounter often can be generalized as follows: we have an ALPC wait chain ProcessA -> ProcessB <-> ProcessC (not necessarily a deadlock) but the crucial piece of functionality is also implemented in ProcessD. Sometimes ProcessD is healthy and the problem resides in ProcessC or ProcessB, and sometimes, when we look at ProcessD we find evidence of an earlier problem pattern there so the focus of recommendations shifts to one of ProcessD modules. The case study is coming soon.

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

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 -

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

B/W

Color

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

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

B/W

Color

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

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

B/W

Color

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

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 -

Today we introduce an icon for Early Crash Dump pattern:

B/W

Color

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

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 -

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 -

Today we introduce an icon for Local Buffer Overflow pattern:

B/W

Color

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