Archive for the ‘Crash Dump Patterns’ Category

Memory Consumption Patterns

Tuesday, February 17th, 2009

While preparing a presentation for an engineering conference I found that yet another page to reference different kinds of insufficient memory patterns is necessary, so I created this post:

I’ll update it as soon as I add more similar patterns.

- Dmitry Vostokov @ DumpAnalysis.org -

Dynamic Memory Corruption Patterns

Tuesday, February 17th, 2009

While preparing a presentation for an engineering conference I found that another page to reference different kinds of dynamic memory corruption patterns is necessary, so I created this post too:

I’ll update it as soon as I add more similar patterns.

- Dmitry Vostokov @ DumpAnalysis.org -

Deadlock and Livelock Patterns

Tuesday, February 17th, 2009

While preparing a presentation for an engineering conference I found that a page to reference all different kinds of deadlocks is necessary, so I created this post:

I’ll update it as soon as I add more similar patterns.

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

Insufficient memory, handle leak, process factory, high contention and busy system: pattern cooperation

Monday, February 16th, 2009

It was reported that one system became slower and slower and eventually the complete memory dump was generated for analysis. Usual !vm 4 command shows pool allocation errors and particularly insufficient session pool memory for user session 1:

1: kd> !vm 4

*** Virtual Memory Usage ***
 Physical Memory:     1048503 (   4194012 Kb)
 Page File: \??\C:\pagefile.sys
   Current:   5109760 Kb  Free Space:   3668764 Kb
   Minimum:   5109760 Kb  Maximum:      5109760 Kb
 Available Pages:      409409 (   1637636 Kb)
 ResAvail Pages:       708135 (   2832540 Kb)
 Locked IO Pages:         108 (       432 Kb)
 Free System PTEs:     137566 (    550264 Kb)
 Free NP PTEs:          27288 (    109152 Kb)
 Free Special NP:           0 (         0 Kb)
 Modified Pages:          780 (      3120 Kb)
 Modified PF Pages:       771 (      3084 Kb)
 NonPagedPool Usage:    37587 (    150348 Kb)
 NonPagedPool Max:      65214 (    260856 Kb)

 PagedPool 0 Usage:     21583 (     86332 Kb)
 PagedPool 1 Usage:      3054 (     12216 Kb)
 PagedPool 2 Usage:      3076 (     12304 Kb)
 PagedPool 3 Usage:      3050 (     12200 Kb)
 PagedPool 4 Usage:      3040 (     12160 Kb)
 PagedPool Usage:       33803 (    135212 Kb)
 PagedPool Maximum:     66560 (    266240 Kb)

 ********** 185454 pool allocations have failed **********

 Shared Commit:        123289 (    493156 Kb)
 Special Pool:              0 (         0 Kb)
 Shared Process:       101937 (    407748 Kb)
 PagedPool Commit:      33850 (    135400 Kb)
 Driver Commit:          1697 (      6788 Kb)
 Committed pages:     1159581 (   4638324 Kb)
 Commit limit:        2283111 (   9132444 Kb)

[...]

 Session ID 1 @ af925000:
 Paged Pool Usage:       16868K

 *** 371034 Pool Allocation Failures ***

 Commit Usage:           17960K

 Session ID 2 @ af927000:
 Paged Pool Usage:        2856K
 Commit Usage:            3860K

[...]

The exploration of session 1 processes shows Process Factory pattern (5,000 launched processes) with explorer.exe ran amok:

1: kd> !sprocess 1
Dumping Session 1

_MM_SESSION_SPACE af925000
_MMSESSION        af925d80
PROCESS 87db34a0  SessionId: 1  Cid: 4a68    Peb: 7ffd4000  ParentCid: 01b8
    DirBase: cffb6d20  ObjectTable: e6084268  HandleCount: 11677.
    Image: csrss.exe

PROCESS 86083020  SessionId: 1  Cid: 4560    Peb: 7ffde000  ParentCid: 2978
    DirBase: cffb6f40  ObjectTable: e6c41410  HandleCount:  79.
    Image: AnotherApp.exe

PROCESS 8607c020  SessionId: 1  Cid: 44c8    Peb: 7ffdc000  ParentCid: 4cf8
    DirBase: cffb7080  ObjectTable: e3c9fd38  HandleCount: 25407.
    Image: explorer.exe

[...]

PROCESS 85e94738  SessionId: 1  Cid: 4868    Peb: 7ffde000  ParentCid: 44c8
    DirBase: cffb7c00  ObjectTable: e7038840  HandleCount:  39.
    Image: application.exe

PROCESS 85e5c020  SessionId: 1  Cid: 4668    Peb: 7ffd4000  ParentCid: 4a50
    DirBase: cffb7de0  ObjectTable: e11891d0  HandleCount: 172.
    Image: application.exe

PROCESS 85e51578  SessionId: 1  Cid: 4c9c    Peb: 7ffde000  ParentCid: 44c8
    DirBase: cffb7e40  ObjectTable: e2ee0070  HandleCount:  39.
    Image: application.exe

[...]

PROCESS 85c81020  SessionId: 1  Cid: 53a4    Peb: 7ffd7000  ParentCid: 44c8
    DirBase: cffb89c0  ObjectTable: e6d2f600  HandleCount:  39.
    Image: application.exe

PROCESS 85c6fb18  SessionId: 1  Cid: 53a8    Peb: 7ffd7000  ParentCid: 44c8
    DirBase: cffb89e0  ObjectTable: e54df078  HandleCount:  39.
    Image: application.exe

PROCESS 85c60020  SessionId: 1  Cid: 53bc    Peb: 7ffdf000  ParentCid: 44c8
    DirBase: cffb8a40  ObjectTable: e1214e90  HandleCount:  39.
    Image: application.exe

[...]

We can also see the very big number of handles in both csrss.exe and explorer.exe. If we look at one of 5,000 application.exe processes we would see that it is a GUI application and this explains session pool exhaustion:

1: kd> !process 85c60020 1f
PROCESS 85c60020  SessionId: 1  Cid: 53bc    Peb: 7ffdf000  ParentCid: 44c8
    DirBase: cffb8a40  ObjectTable: e1214e90  HandleCount:  39.
    Image: application.exe
    VadRoot 85c97450 Vads 80 Clone 0 Private 173. Modified 159. Locked 0.
    DeviceMap e3743340
    Token                             e2ead5e0
    ElapsedTime                       00:54:17.218
    UserTime                          00:00:00.015
    KernelTime                        00:00:00.000
    QuotaPoolUsage[PagedPool]         32460
    QuotaPoolUsage[NonPagedPool]      3200
    Working Set Sizes (now,min,max)  (30, 50, 345) (120KB, 200KB, 1380KB)
    PeakWorkingSetSize                778
    VirtualSize                       16 Mb
    PeakVirtualSize                   17 Mb
    PageFaultCount                    829
    MemoryPriority                    BACKGROUND
    BasePriority                      8
    CommitCharge                      212

THREAD 85c25db0  Cid 53bc.5470  Teb: 7ffde000 Win32Thread: bd1a18a8 WAIT: (Unknown) UserMode Non-Alertable
    85bbf2a8  SynchronizationEvent
Not impersonating
DeviceMap                 e3743340
Owning Process            85c60020       Image:         application.exe
Wait Start TickCount      1121133        Ticks: 206877 (0:00:53:52.453)
Context Switch Count      19355  NoStackSwap    LargeStack
UserTime                  00:00:00.015
KernelTime                00:00:00.000
Win32 Start Address application (0x00402a38)
Start Address kernel32!BaseProcessStartThunk (0x7c8217f8)
Stack Init ad2b8000 Current ad2b7b1c Base ad2b8000 Limit ad2b4000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0
ChildEBP RetAddr 
ad2b7b34 80833ec5 nt!KiSwapContext+0x26
ad2b7b60 80829bc0 nt!KiSwapThread+0x2e5
ad2b7ba8 bf89aacc nt!KeWaitForSingleObject+0x346
ad2b7c04 bf8c4816 win32k!xxxSleepThread+0×1be
ad2b7ca0 bf8a134f win32k!xxxInterSendMsgEx+0×798
ad2b7cec bf85ae3c win32k!xxxSendMessageTimeout+0×1f3
ad2b7d10 bf8c13dc win32k!xxxWrapSendMessage+0×1b
ad2b7d40 8088ad3c win32k!NtUserMessageCall+0×9d

ad2b7d40 7c9485ec nt!KiFastCallEntry+0xfc (TrapFrame @ ad2b7d64)
0012f814 00000000 ntdll!KiFastSystemCallRet

We also see extremely high executive resource contention and various signs of a busy system like the fact that all processors are busy and very high number of ready threads at normal priority (about 1,000):

1: kd> !locks
**** DUMP OF ALL RESOURCE OBJECTS ****

Resource @ DriverA (0xbae016a0)    Exclusively owned
    Contention Count = 277088870
    NumberOfExclusiveWaiters = 3591
     Threads: 83b46db0-01<*> << Too many exclusive waiters to list>>

1: kd> !running

System Processors ff (affinity mask)
  Idle Processors 0

     Prcb      Current   Next   
  0  ffdff120  86300b40            …………….
  1  f772f120  f77320a0  852fadb0  …………….
  2  f7737120  f773a0a0  861528d0  …………….
  3  f773f120  f77420a0  877a4020  …………….
  4  f7747120  f774a0a0  865909a8  …………….
  5  f774f120  f77520a0  83d62cd0  …………….
  6  f7757120  f775a0a0  841aa020  …………….
  7  f775f120  f77620a0  ffb7b5e0  …………….

1: kd> !ready
Processor 0: No threads in READY state
Processor 1: Ready Threads at priority 10
    THREAD 861b1898  Cid 4860.4894  Teb: 7ffd8000 Win32Thread: bc1669a8 READY
Processor 1: Ready Threads at priority 9
    THREAD 83b46db0  Cid 44c8.a11c  Teb: 7f8f8000 Win32Thread: bcbabb38 READY
Processor 1: Ready Threads at priority 8
    THREAD 851408d0  Cid 6338.6398  Teb: 7ffdf000 Win32Thread: bc9bfbb8 READY
    THREAD 83eb1730  Cid 8f30.9568  Teb: 7ffdf000 Win32Thread: 00000000 READY
    THREAD fd310af8  Cid d53c.b4d8  Teb: 7ffdf000 Win32Thread: 00000000 READY
    THREAD 83bce8d0  Cid abec.6450  Teb: 7ffdd000 Win32Thread: 00000000 READY
    THREAD 83de2388  Cid a618.d79c  Teb: 7ffde000 Win32Thread: 00000000 READY
    THREAD 84197b40  Cid 44c8.6974  Teb: 7fe6a000 Win32Thread: bc662d48 READY
[…]

Processor 1: Ready Threads at priority 7
    THREAD 86d0c890  Cid 3524.365c  Teb: 7ff8e000 Win32Thread: bc403bb0 READY
Processor 2: No threads in READY state
Processor 3: No threads in READY state
Processor 4: No threads in READY state
Processor 5: No threads in READY state
Processor 6: No threads in READY state
Processor 7: No threads in READY state

There is AnotherApp.exe in the session process list that executes a VBS script:  

1: kd> .process /r /p 86083020
Implicit process is now 86083020
Loading User Symbols

1: kd> !process 86083020
[...]

        THREAD 860b0db0  Cid 4560.4e4c  Teb: 7ffdd000 Win32Thread: bc1bf4d0 WAIT: (Unknown) KernelMode Non-Alertable
            860b0e28  NotificationTimer

1: kd> .thread 860b0db0
Implicit thread is now 860b0db0

1: kd> kv 100
ChildEBP RetAddr  Args to Child             
ae7ec76c 80833ec5 860b0db0 860b0ea0 00000000 nt!KiSwapContext+0x26
ae7ec798 80829069 0000001e 00000000 bae016a0 nt!KiSwapThread+0x2e5
ae7ec7e0 badff394 00000000 00000000 ffdff5f0 nt!KeDelayExecutionThread+0x2ab
[...]
0012f6ac 7c8024d5 00000000 00000000 00a43280 kernel32!CreateProcessInternalA+0x28b
0012f6e4 00401b31 00000000 00a43280 00000000 kernel32!CreateProcessA+0×2c
[…]

1: kd> da /c 100 00a43280
00a43280  “wscript.exe C:\Scripts\script.vbs parameters”

The examination of that script showed that it contained a coding error resulted in an infinite loop.

- Dmitry Vostokov @ DumpAnalysis.org -

Crash Dump Analysis Patterns (Part 80)

Friday, February 13th, 2009

I remember in my old days of PDP-11 system programming I learnt about the system call to spawn processes and wrote a program in assembly language that was spawning itself. This recursive spawning resulted in geometrical progression of running tasks and brought RSX-11M system to halt very quickly. Recently I observed the similar but non-recursive Process Factory pattern in one of memory dumps: explorer was relentlessly creating application.exe processes and at the time some effect was noticed there were more than 5,000 of them:

1: kd> !vm
[...]
5d20 application.exe 212 ( 848 Kb)
5d08 application.exe 212 ( 848 Kb)
5d04 application.exe 212 ( 848 Kb)
5cf8 application.exe 212 ( 848 Kb)
5cf0 application.exe 212 ( 848 Kb)
5ce8 application.exe 212 ( 848 Kb)
5cdc application.exe 212 ( 848 Kb)
5ccc application.exe 212 ( 848 Kb)
5cc8 application.exe 212 ( 848 Kb)
5cc0 application.exe 212 ( 848 Kb)
5ca8 application.exe 212 ( 848 Kb)
5c9c application.exe 212 ( 848 Kb)
5c98 application.exe 212 ( 848 Kb)
5c90 application.exe 212 ( 848 Kb)
5c88 application.exe 212 ( 848 Kb)
5c7c application.exe 212 ( 848 Kb)
5c70 application.exe 212 ( 848 Kb)
5c68 application.exe 212 ( 848 Kb)
5c64 application.exe 212 ( 848 Kb)
5c60 application.exe 212 ( 848 Kb)
5c50 application.exe 212 ( 848 Kb)
5c4c application.exe 212 ( 848 Kb)
5c44 application.exe 212 ( 848 Kb)
5c3c application.exe 212 ( 848 Kb)
5c34 application.exe 212 ( 848 Kb)
5c2c application.exe 212 ( 848 Kb)
5c24 application.exe 212 ( 848 Kb)
5c1c application.exe 212 ( 848 Kb)
5bf8 application.exe 212 ( 848 Kb)
5be0 application.exe 212 ( 848 Kb)
5bd4 application.exe 212 ( 848 Kb)
5bd0 application.exe 212 ( 848 Kb)
5ba4 application.exe 212 ( 848 Kb)
5b58 application.exe 212 ( 848 Kb)
5b50 application.exe 212 ( 848 Kb)
5b44 application.exe 212 ( 848 Kb)
5b38 application.exe 212 ( 848 Kb)
5b30 application.exe 212 ( 848 Kb)
5b04 application.exe 212 ( 848 Kb)
5af4 application.exe 212 ( 848 Kb)
5ad8 application.exe 212 ( 848 Kb)
5ad4 application.exe 212 ( 848 Kb)
5ac8 application.exe 212 ( 848 Kb)
5ac4 application.exe 212 ( 848 Kb)
5ab4 application.exe 212 ( 848 Kb)
5aa4 application.exe 212 ( 848 Kb)
5a9c application.exe 212 ( 848 Kb)
5a94 application.exe 212 ( 848 Kb)
5a8c application.exe 212 ( 848 Kb)
5a88 application.exe 212 ( 848 Kb)
5a74 application.exe 212 ( 848 Kb)
[...]

1: kd> !process 0 0
**** NT ACTIVE PROCESS DUMP ****
PROCESS 8b57f020  SessionId: none  Cid: 0004    Peb: 00000000  ParentCid: 0000
    DirBase: cffb3020  ObjectTable: e1003da0  HandleCount: 3932.
    Image: System

PROCESS 8a9f8d88  SessionId: none  Cid: 01b8    Peb: 7ffdf000  ParentCid: 0004
    DirBase: cffb3040  ObjectTable: e13e3f68  HandleCount: 111.
    Image: smss.exe

PROCESS 89f0d508  SessionId: 0  Cid: 01f0    Peb: 7ffd8000  ParentCid: 01b8
    DirBase: cffb3060  ObjectTable: e16bc370  HandleCount: 1292.
    Image: csrss.exe

PROCESS 89eea7c8  SessionId: 0  Cid: 0208    Peb: 7ffde000  ParentCid: 01b8
    DirBase: cffb3080  ObjectTable: e14b4160  HandleCount: 564.
    Image: winlogon.exe

[...]

PROCESS 8607c020  SessionId: 1  Cid: 44c8    Peb: 7ffdc000  ParentCid: 4cf8
    DirBase: cffb7080  ObjectTable: e3c9fd38  HandleCount: 25407.
    Image: explorer.exe

[...]

PROCESS 85e1d020  SessionId: 1  Cid: 538c    Peb: 7ffda000  ParentCid: 44c8
    DirBase: cffb8980  ObjectTable: e8065b20  HandleCount:  39.
    Image: application.exe

PROCESS 85c74610  SessionId: 1  Cid: 5394    Peb: 7ffd9000  ParentCid: 44c8
    DirBase: cffb89a0  ObjectTable: e6951878  HandleCount:  39.
    Image: application.exe

PROCESS 85c81020  SessionId: 1  Cid: 53a4    Peb: 7ffd7000  ParentCid: 44c8
    DirBase: cffb89c0  ObjectTable: e6d2f600  HandleCount:  39.
    Image: application.exe

PROCESS 85c6fb18  SessionId: 1  Cid: 53a8    Peb: 7ffd7000  ParentCid: 44c8
    DirBase: cffb89e0  ObjectTable: e54df078  HandleCount:  39.
    Image: application.exe

PROCESS 85c60020  SessionId: 1  Cid: 53bc    Peb: 7ffdf000  ParentCid: 44c8
    DirBase: cffb8a40  ObjectTable: e1214e90  HandleCount:  39.
    Image: application.exe

PROCESS 85c5d380  SessionId: 1  Cid: 53c8    Peb: 7ffde000  ParentCid: 44c8
    DirBase: cffb8a60  ObjectTable: e7baf638  HandleCount:  39.
    Image: application.exe

PROCESS 85c648b8  SessionId: 1  Cid: 53dc    Peb: 7ffde000  ParentCid: 44c8
    DirBase: cffb8a80  ObjectTable: e759d060  HandleCount:  39.
    Image: application.exe

PROCESS 85c62528  SessionId: 1  Cid: 53e0    Peb: 7ffde000  ParentCid: 44c8
    DirBase: cffb8aa0  ObjectTable: e3b8fa00  HandleCount:  39.
    Image: application.exe

PROCESS 85c59d88  SessionId: 1  Cid: 53e8    Peb: 7ffdc000  ParentCid: 44c8
    DirBase: cffb8ac0  ObjectTable: e31751e0  HandleCount:  39.
    Image: application.exe

PROCESS 85c46d88  SessionId: 1  Cid: 542c    Peb: 7ffd5000  ParentCid: 4d9c
    DirBase: cffb8b00  ObjectTable: e6fbc500  HandleCount: 136.
    Image: nlapplication.exe

PROCESS 85c3c020  SessionId: 1  Cid: 5464    Peb: 7ffdc000  ParentCid: 44c8
    DirBase: cffb8b40  ObjectTable: e218b948  HandleCount:  39.
    Image: application.exe

PROCESS 85c2a020  SessionId: 1  Cid: 546c    Peb: 7ffdb000  ParentCid: 44c8
    DirBase: cffb8b60  ObjectTable: e639a8d0  HandleCount:  39.
    Image: application.exe

PROCESS 85c202c8  SessionId: 1  Cid: 5474    Peb: 7ffd7000  ParentCid: 44c8
    DirBase: cffb8b80  ObjectTable: e517caa8  HandleCount:  39.
    Image: application.exe

PROCESS 85c1b020  SessionId: 1  Cid: 547c    Peb: 7ffd6000  ParentCid: 44c8
    DirBase: cffb8ba0  ObjectTable: e6c0cbc0  HandleCount:  39.
    Image: application.exe

PROCESS 85c1dd88  SessionId: 1  Cid: 5484    Peb: 7ffd5000  ParentCid: 44c8
    DirBase: cffb8bc0  ObjectTable: e4a42f68  HandleCount:  39.
    Image: application.exe

PROCESS 85d3ed88  SessionId: 1  Cid: 5488    Peb: 7ffd5000  ParentCid: 44c8
    DirBase: cffb8be0  ObjectTable: e68558f0  HandleCount:  39.
    Image: application.exe

[...]

We see that all created processes have the same parent process with PID 44c8 and when we inspect it we see many threads inside creating application.exe process:

1: kd> .process /r /p 8607c020
Implicit process is now 8607c020
Loading User Symbols

1: kd> !process 8607c020
PROCESS 8607c020  SessionId: 1  Cid: 44c8    Peb: 7ffdc000  ParentCid: 4cf8
    DirBase: cffb7080  ObjectTable: e3c9fd38  HandleCount: 25407.
    Image: explorer.exe
    VadRoot 88efec98 Vads 3445 Clone 0 Private 30423. Modified 71292. Locked 0.
    DeviceMap e3743340
    Token                             e29be5e0
    ElapsedTime                       00:54:31.359
    UserTime                          00:00:19.234
    KernelTime                        00:04:04.828
    QuotaPoolUsage[PagedPool]         1075132
    QuotaPoolUsage[NonPagedPool]      137800
    Working Set Sizes (now,min,max)  (15457, 50, 345) (61828KB, 200KB, 1380KB)
    PeakWorkingSetSize                48919
    VirtualSize                       585 Mb
    PeakVirtualSize                   978 Mb
    PageFaultCount                    123488
    MemoryPriority                    BACKGROUND
    BasePriority                      8
    CommitCharge                      49919

[...]

THREAD 84f25300  Cid 44c8.6288  Teb: 7ff8e000 Win32Thread: bc486830 READY
IRP List:
    88699110: (0006,0220) Flags: 00000884  Mdl: 00000000
Not impersonating
DeviceMap                 e3743340
Owning Process            8607c020       Image:         explorer.exe
Wait Start TickCount      1327981        Ticks: 29 (0:00:00:00.453)
Context Switch Count      145332                 LargeStack
UserTime                  00:00:00.000
KernelTime                00:00:00.093
Win32 Start Address SHLWAPI!SHCreateThread (0x77ec3ea5)
Start Address kernel32!BaseThreadStartThunk (0x7c8217ec)
Stack Init a98e4000 Current a98e3700 Base a98e4000 Limit a98e0000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0
ChildEBP RetAddr 
a98e3718 80833ec5 nt!KiSwapContext+0x26
a98e3744 80829bc0 nt!KiSwapThread+0x2e5
a98e378c 8087e0d8 nt!KeWaitForSingleObject+0x346
a98e37c4 8087e397 nt!ExpWaitForResource+0x30
a98e37e4 badff32a nt!ExAcquireResourceExclusiveLite+0x8d
a98e3808 badffe35 driverA+0x132a
a98e3824 bae00208 driverA+0x1e35
a98e3868 bae0e45a driverA+0x2208
a98e38a0 8081e095 driverA+0x1045a
a98e38b4 b972c73b nt!IofCallDriver+0x45
[...]
a98e38e8 b9b194e1 nt!IofCallDriver+0x45
[...]
a98e3940 b85cbf08 nt!IofCallDriver+0x45
a98e3968 b85bcfcc driverB!LowerDevicePassThrough+0x48
a98e398c b85bd63d driverB+0x6fcc
a98e3a24 b85cb167 driverB+0x763d
a98e3a34 b85cb1b7 driverB+0x15167
a98e3a5c 8081e095 driverB!DispatchPassThrough+0x48
a98e3a70 808fb13b nt!IofCallDriver+0x45
a98e3b58 80939c6a nt!IopParseDevice+0xa35
a98e3bd8 80935d9e nt!ObpLookupObjectName+0x5b0
a98e3c2c 808ece57 nt!ObOpenObjectByName+0xea
a98e3ca8 808ee0f1 nt!IopCreateFile+0x447
a98e3d04 808f1e31 nt!IoCreateFile+0xa3
a98e3d44 8088ad3c nt!NtOpenFile+0x27
a98e3d44 7c9485ec nt!KiFastCallEntry+0xfc (TrapFrame @ a98e3d64)
03bbda04 7c82bdf6 ntdll!KiFastSystemCallRet
03bbda2c 7c82dd9a kernel32!BasepSxsCreateStreams+0xe2
03bbda9c 7c82d895 kernel32!BasepSxsCreateProcessCsrMessage+0x136
03bbe2c4 7c8024a0 kernel32!CreateProcessInternalW+0x1943
03bbe2fc 7ca36750 kernel32!CreateProcessW+0×2c
03bbed80 7ca36b45 SHELL32!_SHCreateProcess+0×387
03bbedd4 7ca3617b SHELL32!CShellExecute::_DoExecCommand+0xb4
03bbede0 7ca35a76 SHELL32!CShellExecute::_TryInvokeApplication+0×49
03bbedf4 7ca3599f SHELL32!CShellExecute::ExecuteNormal+0xb1
03bbee08 7ca35933 SHELL32!ShellExecuteNormal+0×30
03bbee24 7ca452ff SHELL32!ShellExecuteExW+0×8d

1: kd> .thread 84e6a600
Implicit thread is now 84e6a600

1: kd> kv 100
[...]
03bbda04 7c82bdf6 001200a9 03bbda8c 03bbdb20 ntdll!KiFastSystemCallRet
03bbda2c 7c82dd9a 00000000 00000003 001200a9 kernel32!BasepSxsCreateStreams+0xe2
03bbda9c 7c82d895 00000000 00000000 03bbdc38 kernel32!BasepSxsCreateProcessCsrMessage+0x136
03bbe2c4 7c8024a0 00000000 01dafb9c 01dad904 kernel32!CreateProcessInternalW+0x1943
03bbe2fc 7ca36750 01dafb9c 01dad904 00000000 kernel32!CreateProcessW+0×2c
03bbed80 7ca36b45 00010098 00000000 01daffac SHELL32!_SHCreateProcess+0×387
[…]

1: kd> du /c 100 01dafb9c
01dafb9c  “C:\Program Files\App Package\Application.exe”

The difference of this pattern and similar Handle Leak or Zombie Processes is the fact that leaks usually happen when a process forgets to close handles but Process Factory creates active processes which are full resource containers and consume system resources, for example, they all have full handle table or consume GDI resources if they are GUI processes.

- Dmitry Vostokov @ DumpAnalysis.org -

Stack trace collection, blocked thread and coupled processes: pattern cooperation

Wednesday, February 11th, 2009

This is a continuation of the story of a process hang simulation where I made all threads in IE7 instance frozen. I left that process frozen after my experiments and later tried to reply to one e-mail using PHP-based browser client running in another IE7 process. And I found that the mouse click on ”Reply” button didn’t bring out any GUI response. I tried to close IE7 instance: all tabs closed except the one that was hanging. So I dumped the process and found a blocking thread inside waiting for an RPC call. I made all threads in the first IE7 process unfrozen and the second hanging IE7 process immediately exited. Instead of digging into the dump further I decided to repeat the problem. First I launched the fresh instance of IE7 and opened my e-mail client. After clicking on “Reply” with success I dumped the process using Vista Task Manager and renamed the resulted memory dump as iexplore2.dmp. Then I launched another IE instance and made all threads frozen. Then I came back to the first instance of IE7 and tried to do ”Reply” again. After waiting for about 10 minutes for any response I dumped the process again and renamed the dump file as iexplore3.dmp. Comparing thread stack traces from both dump files showed one difference: the blocked OLE/RPC thread obviously processing some JavaScript code:

[Before hang]

0:000> ~[0n36]k 100
ChildEBP RetAddr 
161bfc00 76b60dde ntdll!KiFastSystemCallRet
161bfc04 705e41a1 user32!NtUserWaitMessage+0xc
161bfc68 76c24911 ieframe!CTabWindow::_TabWindowThreadProc+0x2d0
161bfc74 76fee4b6 kernel32!BaseThreadInitThunk+0xe
161bfcb4 76fee489 ntdll!__RtlUserThreadStart+0x23
161bfccc 00000000 ntdll!_RtlUserThreadStart+0x1b

[After hang]

0:000> ~[0n36]k 100
ChildEBP RetAddr 
WARNING: Stack unwind information not available. Following frames may be wrong.
161bc27c 76b60208 ntdll!KiFastSystemCallRet
161bc2d0 767fab28 user32!RealMsgWaitForMultipleObjectsEx+0x13c
161bc2f8 767fac88 ole32!CCliModalLoop::BlockFn+0×97
161bc320 76907b73 ole32!ModalLoop+0×5b
161bc33c 76908b68 ole32!ThreadSendReceive+0×12c
161bc364 769089d4 ole32!CRpcChannelBuffer::SwitchAptAndDispatchCall+0×194
161bc444 767fad2e ole32!CRpcChannelBuffer::SendReceive2+0xef
161bc460 767face0 ole32!CCliModalLoop::SendReceive+0×1e
161bc4d8 7681e688 ole32!CAptRpcChnl::SendReceive+0×73
161bc52c 7667264e ole32!CCtxComChnl::SendReceive+0×1c5
161bc544 766726af rpcrt4!NdrProxySendReceive+0×43
161bc9c8 76f3ad86 rpcrt4!NdrProxySendReceive+0xa4

161bc9e0 76f3ad58 oleaut32!IEnumVARIANT_RemoteNext_Proxy+0×19
161bc9fc 6c1f2a7b oleaut32!IEnumVARIANT_Next_Proxy+0×1c
161bca5c 6c1f2b9c mshtml!SearchBrowsersForWindow+0×1bd
161bca84 6c1a2932 mshtml!GetTargetWindow+0×53
161bcabc 6c1b1300 mshtml!CWindow::FindWindowByName+0xe1
161bcad4 706498d4 mshtml!CWindow::FindWindowByName+0×17
161bcaf4 70649e5a ieframe+0×1198d4
161bcb48 70649ff6 ieframe+0×119e5a
161bcbac 70649b82 ieframe+0×119ff6
161bcbe0 6c189f9b ieframe+0×119b82
161bcc10 6c119cba mshtml!COmWindowProxy::FindFrame+0×5c
161bcc44 6c18be8e mshtml!COmWindowProxy::AccessAllowedToFrame+0×7f
161bccb4 6c1c4a2e mshtml!COmWindowProxy::open+0×15b
161bcd1c 6c0371b6 mshtml!Method_IDispatchpp_oDoBSTR_oDoBSTR_oDoBSTR_oDoVARIANTBOOL+0xeb
161bcdb4 6c037493 mshtml!CBase::ContextInvokeEx+0×4ef
161bcde0 6c037607 mshtml!CBase::InvokeEx+0×25
161bce48 6c0374c2 mshtml!COmWindowProxy::InvokeEx+0×297
161bce70 6c5b348e mshtml!COmWindowProxy::subInvokeEx+0×26
161bcea8 6c5b33fe jscript!IDispatchExInvokeEx2+0xac
161bcee0 6c5b3e09 jscript!IDispatchExInvokeEx+0×56
161bcf50 6c5b30eb jscript!InvokeDispatchEx+0×78
161bcf98 6c5b18ab jscript!VAR::InvokeByName+0xba
161bcfd8 6c5b2109 jscript!VAR::InvokeDispName+0×43
161bcffc 6c5b28d8 jscript!VAR::InvokeByDispID+0xb9
161bd0b4 6c5b1019 jscript!CScriptRuntime::Run+0×167f
161bd0cc 6c5b2aa8 jscript!ScrFncObj::Call+0×8d
161bd158 6c5b00f2 jscript!NameTbl::InvokeInternal+0xe0
161bd184 6c5b28d8 jscript!VAR::InvokeByDispID+0xfd
161bd23c 6c5b1019 jscript!CScriptRuntime::Run+0×167f
161bd254 6c5b1b7f jscript!ScrFncObj::Call+0×8d
161bd2c4 6c59f9d2 jscript!CSession::Execute+0xa7
161bd314 6c59fdf7 jscript!COleScript::ExecutePendingScripts+0×147
161bd378 6c59fc46 jscript!COleScript::ParseScriptTextCore+0×243
161bd3a4 6bfcca36 jscript!COleScript::ParseScriptText+0×2b

161bd404 6c1b1931 mshtml!CScriptCollection::ParseScriptText+0×240
161bf48c 6c12adae mshtml!CWindow::ExecuteScriptUri+0×197
161bf4cc 6c1b2f77 mshtml!CWindow::NavigateEx+0×50
161bf530 6c1b3372 mshtml!CDoc::ExecuteScriptUri+0×1f7
161bf560 6c27b8ac mshtml!CDoc::ExecuteScriptURL+0×4b
161bf5a8 6c27a54c mshtml!CHyperlink::ClickAction+0×1a9
161bf5b8 6c121847 mshtml!CAnchorElement::ClickAction+0×10
161bf5e4 6c07a7ef mshtml!CElement::DoClick+0×121
161bf610 6c07a5bd mshtml!CAnchorElement::DoClick+0×4d
161bf69c 6c07f680 mshtml!CDoc::PumpMessage+0xcbd
161bf7e8 6c12a7e0 mshtml!CDoc::OnMouseMessage+0×3d7
161bf90c 6c039a11 mshtml!CDoc::OnWindowMessage+0×8f7
161bf938 76b5f8d2 mshtml!CServer::WndProc+0×78
161bf964 76b5f794 user32!InternalCallWinProc+0×23
161bf9dc 76b606f6 user32!UserCallWinProcCheckWow+0×14b
161bfa0c 76b6069c user32!CallWindowProcAorW+0×97
161bfa2c 6baad980 user32!CallWindowProcW+0×1b
161bfa98 6baa104a GoogleToolbarDynamic_F423308312A7B033+0×3d980
161bfabc 6bb67e57 GoogleToolbarDynamic_F423308312A7B033+0×3104a
161bfae8 76b5f8d2 GoogleToolbarDynamic_F423308312A7B033+0xf7e57
161bfb14 76b5f794 user32!InternalCallWinProc+0×23
161bfb8c 76b60008 user32!UserCallWinProcCheckWow+0×14b
161bfbf0 76b60060 user32!DispatchMessageWorker+0×322
161bfc00 705e42c1 user32!DispatchMessageW+0xf
161bfc68 76c24911 ieframe+0xb42c1
161bfc74 76fee4b6 kernel32!BaseThreadInitThunk+0xe

Upon seeing SendReceive2 on the latter stack trace I recalled that it is possible to know the target process PID: In Search of Lost CID. The same procedure applied here reveals PID = 0xdec:

0:000> ~[0n36]kv 9
ChildEBP RetAddr  Args to Child             
WARNING: Stack unwind information not available. Following frames may be wrong.
161bc27c 76b60208 161bc230 161bc2a4 00000000 ntdll!KiFastSystemCallRet
161bc2d0 767fab28 00000000 161bc318 00000000 user32!RealMsgWaitForMultipleObjectsEx+0x13c
161bc2f8 767fac88 161bc318 00000000 161bc328 ole32!CCliModalLoop::BlockFn+0x97
161bc320 76907b73 00000000 00000000 161bc42c ole32!ModalLoop+0x5b
161bc33c 76908b68 00000000 161bc440 00000000 ole32!ThreadSendReceive+0x12c
161bc364 769089d4 161bc42c 00000000 161bc488 ole32!CRpcChannelBuffer::SwitchAptAndDispatchCall+0x194
161bc444 767fad2e 14f75040 161bc56c 161bc550 ole32!CRpcChannelBuffer::SendReceive2+0xef
161bc460 767face0 161bc56c 161bc550 00000000 ole32!CCliModalLoop::SendReceive+0×1e
161bc4d8 7681e688 14f75040 161bc56c 161bc550 ole32!CAptRpcChnl::SendReceive+0×73

Note: 14f75040 is 00000000 in iexplore3.dmp from ftp because the dumps were stripped from almost all process data and contain only values necessary to reconstruct stack traces. So you won’t be able to extract correct raw stack data from them.

0:000> ddp 14f75040
14f75040  76828438 76907c77 ole32!CRpcChannelBuffer::QueryInterface
14f75044  7681c7e4 7689b57c ole32!CRpcChannelBuffer::QueryInterface
14f75048  00000003
14f7504c  00000002
14f75050  00000000
14f75054  00000000
14f75058  0046ccd0 0046ce50
14f7505c  0e8de858 00000000
14f75060  1acb7310 00000044
14f75064  1acb3130 76828510 ole32!CStdIdentity::`vftable’
14f75068  7682b098 767f8066 ole32!CDestObject::QueryInterface
14f7506c  00070005 ee0100ed
14f75070  00000000
14f75074  00000000
14f75078  00000d78
14f7507c  00000000
14f75080  76828438 76907c77 ole32!CRpcChannelBuffer::QueryInterface
14f75084  7681c7e4 7689b57c ole32!CRpcChannelBuffer::QueryInterface
14f75088  00000001
14f7508c  00000024
14f75090  00000000
14f75094  00000000
14f75098  07abd4a8 07aacab0
14f7509c  00000000
14f750a0  00000000
14f750a4  1ae12b10 76828510 ole32!CStdIdentity::`vftable’
14f750a8  7682b098 767f8066 ole32!CDestObject::QueryInterface
14f750ac  00070005 ee0100ed
14f750b0  ffffffff
14f750b4  00001134
14f750b8  00001134
14f750bc  00000000

0:000> dd 0046ccd0 l4
0046ccd0  0046ce50 0046cc50 00000dec 00000000

In Task Manager I found this to be ieuser.exe process so I suspect there is a high degree of process coupling between all launched IE7 processes and ieuser.exe including COM/OLE runtime.

The stripped versions of dumps are available for practice on ftp:

ftp://dumpanalysis.org/pub/ie7_pattern_cooperation2.zip

- Dmitry Vostokov @ DumpAnalysis.org -

Swarm of shared locks, blocked threads and waiting time: pattern cooperation

Monday, February 9th, 2009

Here is further analysis of a memory dump used to illustrate Swarm of Shared Locks pattern. In that dump there were also exclusively held locks with many blocked threads:

Resource @ 0x8a04c408    Exclusively owned
    Contention Count = 344875
    NumberOfExclusiveWaiters = 6
     Threads: 87eb3db0-01<*>
     Threads Waiting On Exclusive Access:
              88573db0       87b90378       86a49db0       891f4610      
              8662b020       87127db0
 

Resource @ 0x89678e80    Exclusively owned
    Contention Count = 10261
    NumberOfExclusiveWaiters = 2
     Threads: 87eb3db0-01<*>
     Threads Waiting On Exclusive Access:
              89131bf0       88d12db0 
     

Resource @ 0x88d099d8    Exclusively owned
    Contention Count = 562811
    NumberOfExclusiveWaiters = 4
     Threads: 873611d8-01<*>
     Threads Waiting On Exclusive Access:
              88b8bb88       88a72c50       89359af0       88d865e8      

Resource @ 0x86db9248    Exclusively owned
    Contention Count = 1382269
    NumberOfSharedWaiters = 2
    NumberOfExclusiveWaiters = 11
     Threads: 86ab2020-01<*> 8769cdb0-01    880c77b8-01   
     Threads Waiting On Exclusive Access:
              87bf4020       890dc020       874c01c0       884ef020      
              86913af8       875bab10       88e8a0d8       8923cdb0      
              894eca18       86aa6830       86f293a8     

Resource @ 0x873a88d0    Exclusively owned
    Contention Count = 719758
    NumberOfExclusiveWaiters = 8
     Threads: 88d5f990-01<*>
     Threads Waiting On Exclusive Access:
              8759ea88       871b6db0       88117710       87cb4718      
              883eb638       87239020       881ad020       891b9188      

Resource @ 0x88c379a0    Exclusively owned
    Contention Count = 126686
    NumberOfSharedWaiters = 1
    NumberOfExclusiveWaiters = 8
     Threads: 882b8020-01<*> 88951520-01   
     Threads Waiting On Exclusive Access:
              877d34a8       8939fdb0       87fc5668       8851fdb0      
              86fad850       87f1f450       8a1749f0       876a78d0      

Resource @ 0x88ca9250    Exclusively owned
    Contention Count = 319721
    NumberOfExclusiveWaiters = 4
     Threads: 88607908-01<*>
     Threads Waiting On Exclusive Access:
              86829370       892ae8e8       87205208       87b6d7e0      

Resource @ 0x86a90ef8    Exclusively owned
    Contention Count = 852830
    NumberOfExclusiveWaiters = 12
     Threads: 87571640-01<*>
     Threads Waiting On Exclusive Access:
              88a9c9b0       88a50db0       87117928       890e4c50      
              874ffb30       88b540f8       8705d020       8687edb0      
              87143188       8703e430       885b6aa0       8842bc50      

Resource @ 0x88954538    Exclusively owned
    Contention Count = 40708
    NumberOfExclusiveWaiters = 1
     Threads: 87571640-01<*>
     Threads Waiting On Exclusive Access:
              878ee980      

Resource @ 0x88617eb8    Exclusively owned
    Contention Count = 43531
    NumberOfExclusiveWaiters = 2
     Threads: 87571640-01<*>
     Threads Waiting On Exclusive Access:
              88851db0       87382c50      

Resource @ 0x87288bc8    Exclusively owned
    Contention Count = 644675
    NumberOfExclusiveWaiters = 2
     Threads: 874e4508-01<*>
     Threads Waiting On Exclusive Access:
              88863b08       89479650      

Resource @ 0x87c3d8b0    Exclusively owned
    Contention Count = 335064
    NumberOfExclusiveWaiters = 8
     Threads: 87f44520-01<*>
     Threads Waiting On Exclusive Access:
              88277190       88eceb48       87f0d308       8694d460      
              88461db0       876734a8       871721b0       88c2adb0      

All threads owning various locks exclusively are stuck in processing page fault code, for example:

0: kd> !thread 87eb3db0 1f
THREAD 87eb3db0  Cid 47ac.57c8  Teb: 7ffd7000 Win32Thread: bc151230 WAIT: (Unknown) KernelMode Non-Alertable
    8743e4e0  NotificationEvent
IRP List:
    8660c900: (0006,0094) Flags: 00000900  Mdl: 00000000
Not impersonating
DeviceMap                 e1003890
Owning Process            88e49918       Image:         csrss.exe
Wait Start TickCount      15420972       Ticks: 2527 (0:00:00:39.484)
Context Switch Count      1430991                 LargeStack
UserTime                  00:00:00.000
KernelTime                00:00:02.734
Start Address 0×75a8e96c
Stack Init a3cf7000 Current a3cf6430 Base a3cf7000 Limit a3cf4000 Call 0
Priority 14 BasePriority 13 PriorityDecrement 0
ChildEBP RetAddr 
a3cf6448 8083d5b1 nt!KiSwapContext+0×26
a3cf6474 8083df9e nt!KiSwapThread+0×2e5
a3cf64bc 8082629e nt!KeWaitForSingleObject+0×346
a3cf64e4 80826480 nt!MiWaitForInPageComplete+0×1f
a3cf656c 8084790e nt!MiDispatchFault+0xda3
a3cf65c8 80836c2a nt!MmAccessFault+0×64a
a3cf65c8 bfa38de0 nt!KiTrap0E+0xdc (TrapFrame @ a3cf65e0)

a3cf6a24 bf854a72 win32k!vSetPointer+0×36f
a3cf6a50 bf8b1b74 win32k!GreSetPointer+0×66
a3cf6a7c bf883183 win32k!zzzUpdateCursorImage+0×1cc
a3cf6a8c bf884b06 win32k!zzzSetFMouseMoved+0xd5
a3cf6ad4 bf81530a win32k!ProcessQueuedMouseEvents+0×1c4
a3cf6d30 bf86fd25 win32k!RawInputThread+0×5b4
a3cf6d40 bf898a52 win32k!xxxCreateSystemThreads+0×60
a3cf6d54 80833bef win32k!NtUserCallOneParam+0×23
a3cf6d54 7c8285ec nt!KiFastCallEntry+0xfc (TrapFrame @ a3cf6d64)

0: kd> !thread 87571640 1f
THREAD 87571640  Cid 49f4.65b4  Teb: 7ffdf000 Win32Thread: bc011680 WAIT: (Unknown) KernelMode Non-Alertable
    8870db90  NotificationEvent
Not impersonating
DeviceMap                 e24f6570
Owning Process            87be4a00       Image:         ApplicationC.EXE
Wait Start TickCount      15420974       Ticks: 2525 (0:00:00:39.453)
Context Switch Count      25640                 LargeStack
UserTime                  00:00:00.921
KernelTime                00:00:03.859
Win32 Start Address 0×30002658
Start Address 0×77e617f8
Stack Init 9a318600 Current 9a317b70 Base 9a319000 Limit 9a314000 Call 9a31860c
Priority 14 BasePriority 8 PriorityDecrement 0
ChildEBP RetAddr 
9a317b88 8083d5b1 nt!KiSwapContext+0×26
9a317bb4 8083df9e nt!KiSwapThread+0×2e5
9a317bfc 8082629e nt!KeWaitForSingleObject+0×346
9a317c24 80826480 nt!MiWaitForInPageComplete+0×1f
9a317cac 8084790e nt!MiDispatchFault+0xda3
9a317d08 80836c2a nt!MmAccessFault+0×64a
9a317d08 bf8b5485 nt!KiTrap0E+0xdc (TrapFrame @ 9a317d20)

9a317db4 bf8b526c win32k!vSolidFillRect1+0xb0
9a317f58 bf8ad7d2 win32k!vDIBSolidBlt+0×102
9a317fc4 bfa285d1 win32k!EngBitBlt+0xe1
9a3180c8 bf899b57 win32k!GrePatBltLockedDC+0×1ea
9a318160 bf8b32bb win32k!GrePolyPatBltInternal+0×17c
9a31819c bf8bd71c win32k!GrePolyPatBlt+0×45
9a31822c bf85e3d5 win32k!DrawEdge+0×23a
9a318274 bf8ae338 win32k!xxxDrawWindowFrame+0×170
9a3182d4 bf8847d1 win32k!xxxRealDefWindowProc+0×7a7
9a3182ec bf884801 win32k!xxxWrapRealDefWindowProc+0×16
9a318308 bf8c1769 win32k!NtUserfnDWORD+0×27
9a318340 80833bef win32k!NtUserMessageCall+0xc0
9a318340 7c8285ec nt!KiFastCallEntry+0xfc (TrapFrame @ 9a318364)

We also see that their waiting time is almost the same, 39 seconds. This means that the problem with paging probably started at that time before the crash dump was forced.

- Dmitry Vostokov @ DumpAnalysis.org -

Crash Dump Analysis Patterns (Part 79)

Monday, February 9th, 2009

Sometimes there are so many shared locks on the system that it might point to some problems in subsystems that own them. For example, there are two large swarms of them in this memory dump from a system running 90 user sessions:

0: kd> !session
Sessions on machine: 90

0: kd> !locks
**** DUMP OF ALL RESOURCE OBJECTS ****
KD: Scanning for held locks....

Resource @ nt!CmpRegistryLock (0x808ad4c0)    Shared 210 owning threads
    Contention Count = 1432
     Threads: 88bf1590-01<*> 8a78a660-01<*> 8a787660-01<*> 8825a3a8-01<*>
              89003358-01<*> 86723b90-01<*> 865bbb00-01<*> 89634638-01<*>
              888d9508-01<*> 88da6b48-01<*> 87db9db0-01<*> 86a9e610-01<*>
              89ff7410-01<*> 87450db0-01<*> 86bdedb0-01<*> 86d604c8-01<*>
              88d465d8-01<*> 86c3b6a0-01<*> 87c89020-01<*> 88e73db0-01<*>
              865fe5b0-01<*> 88450020-01<*> 86bd9db0-01<*> 8a73e838-01<*>
              88dc3db0-01<*> 88035708-01<*> 8833a2f0-01<*> 88608350-01<*>
              87aca020-01<*> 87e007c0-01<*> 86ec39b8-01<*> 893be1b8-01<*>
              8671ddb0-01<*> 8679a718-01<*> 89fe34c8-01<*> 86ccd720-01<*>
              881b1db0-01<*> 86771b20-01<*> 86d71db0-01<*> 89574db0-01<*>
              87dfac50-01<*> 86597020-01<*> 874b3488-01<*> 873b59b0-01<*>
              88e792f8-01<*> 878d2430-01<*> 8853d480-01<*> 889e2020-01<*>
              88c36db0-01<*> 8824f990-01<*> 8719b830-01<*> 884ba020-01<*>
              88e1d768-01<*> 89523db0-01<*> 896529f8-01<*> 887e2870-01<*>
              8a022db0-01<*> 867253a0-01<*> 865f0448-01<*> 87d35640-01<*>
              8715d968-01<*> 87ce0c50-01<*> 87d44730-01<*> 86d69aa8-01<*>
              88e5b020-01<*> 88734410-01<*> 898f2b40-01<*> 8a00a510-01<*>
              87e69db0-01<*> 8722b860-01<*> 86d8e308-01<*> 87263c50-01<*>
              8706ddb0-01<*> 892136e8-01<*> 8875b020-01<*> 8833ca48-01<*>
              8a100db0-01<*> 86b77590-01<*> 888bc020-01<*> 865c3db0-01<*>
              89fba910-01<*> 8a789660-01<*> 8670b2a8-01<*> 868737a8-01<*>
              868326d0-01<*> 871cdaf0-01<*> 8852edb0-01<*> 882b23b8-01<*>
              877e29e0-01<*> 8774f558-01<*> 876aa020-01<*> 89187518-01<*>
              8664b8e0-01<*> 865b4478-01<*> 88135020-01<*> 8686f020-01<*>
              866a0190-01<*> 87316758-01<*> 894dab18-01<*> 87938560-01<*>
              8658f5f0-01<*> 88e54020-01<*> 867f6350-01<*> 89246af8-01<*>
              86801430-01<*> 86db2af0-01<*> 865cf588-01<*> 86ab64f8-01<*>
              8a4a61e8-01<*> 885f3020-01<*> 86ea9af0-01<*> 8a4a7ba8-01<*>
              8a746b08-01<*> 89fc4790-01<*> 87093b10-01<*> 8659bc50-01<*>
              86681db0-01<*> 87102228-01<*> 866145a0-01<*> 866dddb0-01<*>
              86bda990-01<*> 88257db0-01<*> 8687d590-01<*> 867a9db0-01<*>
              89898848-01<*> 8a49b920-01<*> 86596db0-01<*> 8a0f7db0-01<*>
              866c1b40-01<*> 8754e020-01<*> 87fc1428-01<*> 8658c870-01<*>
              880d6a90-01<*> 88be6c50-01<*> 86bbcdb0-01<*> 8a37b8f8-01<*>
              866a13e0-01<*> 873e33d0-01<*> 87d43db0-01<*> 88a5adb0-01<*>
              884a5440-01<*> 883646f0-01<*> 87128020-01<*> 88e1d020-01<*>
              888e6418-01<*> 875c7c50-01<*> 871dd020-01<*> 890d5838-01<*>
              88d061f0-01<*> 88a09428-01<*> 8972f780-01<*> 87325b08-01<*>
              86deb020-01<*> 878b31b8-01<*> 891ac8a8-01<*> 86b234c0-01<*>
              86dd2190-01<*> 875f9db0-01<*> 87bbf200-01<*> 8a1a9c40-01<*>
              88628020-01<*> 87919020-01<*> 87c2a660-01<*> 877dc7c0-01<*>
              8a08adb0-01<*> 87c0f628-01<*> 87ca9a28-01<*> 8880a210-01<*>
              86ec0020-01<*> 88571020-01<*> 8a01edb0-01<*> 88115db0-01<*>
              87a9adb0-01<*> 879ecdb0-01<*> 8868ddb0-01<*> 872bcb58-01<*>
              884a0100-01<*> 8929f020-01<*> 87087020-01<*> 886e75a8-01<*>
              885a5908-01<*> 8762c020-01<*> 89550db0-01<*> 8a554768-01<*>
              89f10680-01<*> 87b322e8-01<*> 87cc74d0-01<*> 883ee2d0-01<*>
              8956caf8-01<*> 8788f330-01<*> 87d5c320-01<*> 86b99db0-01<*>
              876f42e0-01<*> 88e812d0-01<*> 8687cdb0-01<*> 8677a310-01<*>
              89711b40-01<*> 89b013a8-01<*> 86abcdb0-01<*> 89fd7bb0-01<*>
              877c22b0-01<*> 883fc850-01<*> 889e11f8-01<*> 892ff0e0-01<*>
              878ac490-01<*> 86de5c50-01<*> 87741db0-01<*> 8679f020-01<*>
              880ac6d0-01<*> 86d8fb00-01<*>
KD: Scanning for held locks….

Resource @ Ntfs!NtfsData (0xf71665b0)    Shared 1 owning threads
     Threads: 8a78d660-01<*>
KD: Scanning for held locks.

Resource @ 0x8a5c7734    Shared 1 owning threads
    Contention Count = 507565
    NumberOfSharedWaiters = 128
    NumberOfExclusiveWaiters = 1
     Threads: 894b4db0-01    87c773e0-01    88de7020-01    891c9db0-01   
              894d2020-01    865af5f8-01    87867340-01    88c964a0-01<*>
              88e57c98-01    87ae3020-01    86dbe730-01    88343790-01   
              871102e8-01    8855f020-01    87c99920-01    8796a318-01   
              88028db0-01    88ad6610-01    88b73db0-01    89fba3f0-01   
              87d8bc00-01    86f4c5c8-01    8a028608-01    88c783f0-01   
              88c138e0-01    89236910-01    896fbb78-01    88523600-01   
              8926f3b0-01    88a49a48-01    87c19750-01    86c88c50-01   
              88adfad8-01    872b0020-01    87ecab18-01    88b02020-01   
              875f9b10-01    8755e020-01    86f9fdb0-01    86a1cab8-01   
              86816858-01    881eedb0-01    894a99f0-01    87c97740-01   
              8a3bf4b0-01    867765a8-01    8a787660-01    86810330-01   
              876ad268-01    87af3320-01    865fedb0-01    88eb8230-01   
              86b0c438-01    881c0230-01    888b67c8-01    883e3210-01   
              87acbc50-01    873d6648-01    86ed0db0-01    88e2d020-01   
              89fdadb0-01    8934e830-01    870f89f0-01    8756c5e0-01   
              878c88d0-01    86fec608-01    88fdb420-01    87fa0628-01   
              87cad8d8-01    88ee3978-01    86fc49a0-01    875d5020-01   
              871a5020-01    89667a60-01    87170db0-01    88254ae0-01   
              8775e408-01    88204db0-01    87989890-01    873b89a8-01   
              888e6bf8-01    88cc3db0-01    88bf1590-01    879565a0-01   
              86773db0-01    8731a020-01    88aa7a78-01    8759cdb0-01   
              87e555f8-01    86de5678-01    86e28020-01    86ec9320-01   
              86871af0-01    8719cba0-01    8723f820-01    884dac20-01   
              89249020-01    889da168-01    8900b810-01    8a78d660-01   
              88cac758-01    892984c8-01    87d0c020-01    87ecec50-01   
              87ad8c90-01    88109aa8-01    86ef5bf0-01    8a78d3f0-01   
              88d2b020-01    88640db0-01    86fec878-01    895b12d8-01   
              86dd6708-01    87386930-01    888e34e0-01    86a56c50-01   
              8815f768-01    886c42a0-01    898f2020-01    87ca3610-01   
              886dd448-01    86ada210-01    8a37adb0-01    8896c940-01   
              8800e898-01    8733d4b8-01    865fa358-01    88ae1af0-01   
              868dd020-01   
     Threads Waiting On Exclusive Access:
              8a78b020
     

Both swarms are grouped around NTFS structures as can be seen from thread stack traces but also have another module in common: PGPsdk

0: kd> !thread 88bf1590 1f
THREAD 88bf1590  Cid 4354.2338  Teb: 7ffdf000 Win32Thread: bc3e88f8 WAIT: (Unknown) KernelMode Non-Alertable
    8a7a73d8  Semaphore Limit 0x7fffffff
    88bf1608  NotificationTimer
IRP List:
    86fb39d0: (0006,0268) Flags: 00000004  Mdl: 00000000
Not impersonating
DeviceMap                 e13c9ca0
Owning Process            869a6d88       Image:         ApplicationA.exe
Wait Start TickCount      15423469       Ticks: 30 (0:00:00:00.468)
Context Switch Count      6465                 LargeStack
UserTime                  00:00:00.343
KernelTime                00:00:01.062
Win32 Start Address 0x0056f122
Start Address 0x77e617f8
Stack Init 97e9d000 Current 97e9c788 Base 97e9d000 Limit 97e98000 Call 0
Priority 14 BasePriority 8 PriorityDecrement 6
ChildEBP RetAddr 
97e9c7a0 8083d5b1 nt!KiSwapContext+0x26
97e9c7cc 8083df9e nt!KiSwapThread+0x2e5
97e9c814 8081e05b nt!KeWaitForSingleObject+0x346
97e9c850 80824ba8 nt!ExpWaitForResource+0xd5
97e9c870 f718a07d nt!ExAcquireResourceSharedLite+0xf5
97e9c884 f717b2eb Ntfs!NtfsAcquireSharedVcb+0×23
97e9c8f0 f717a2e2 Ntfs!NtfsCommonFlushBuffers+0xf5
97e9c954 80840153 Ntfs!NtfsFsdFlushBuffers+0×92

97e9c968 f7272c45 nt!IofCallDriver+0×45
97e9c990 80840153 fltmgr!FltpDispatch+0×6f
97e9c9a4 f6fb1835 nt!IofCallDriver+0×45
WARNING: Stack unwind information not available. Following frames may be wrong.
97e9c9b8 f6fad69a PGPsdk+0×5835
97e9c9c4 80840153 PGPsdk+0×169a

86fb39d0 00000000 nt!IofCallDriver+0×45

0: kd> !thread 88c964a0 1f
THREAD 88c964a0  Cid 323c.43f0  Teb: 7ffad000 Win32Thread: bc2ceea8 WAIT: (Unknown) KernelMode Non-Alertable
    88268338  SynchronizationEvent
    88c96518  NotificationTimer
IRP List:
    86dad430: (0006,0268) Flags: 00000404  Mdl: 00000000
Not impersonating
DeviceMap                 e16c8eb0
Owning Process            8886ac88       Image:         ApplicationB.EXE
Wait Start TickCount      15423352       Ticks: 147 (0:00:00:02.296)
Context Switch Count      1660                 LargeStack
UserTime                  00:00:00.078
KernelTime                00:00:00.109
Win32 Start Address 0x14225c34
Start Address 0x77e617ec
Stack Init 96835000 Current 96834640 Base 96835000 Limit 96832000 Call 0
Priority 14 BasePriority 8 PriorityDecrement 6
ChildEBP RetAddr 
96834658 8083d5b1 nt!KiSwapContext+0x26
96834684 8083df9e nt!KiSwapThread+0x2e5
968346cc 8081e05b nt!KeWaitForSingleObject+0x346
96834708 8082e012 nt!ExpWaitForResource+0xd5
96834728 f714b89b nt!ExAcquireResourceExclusiveLite+0x8d
96834738 f718b194 Ntfs!NtfsAcquirePagingResourceExclusive+0×20
9683493c f718b8d9 Ntfs!NtfsCommonCleanup+0×193
96834aac 80840153 Ntfs!NtfsFsdCleanup+0xcf

96834ac0 f7272c45 nt!IofCallDriver+0×45
96834ae8 80840153 fltmgr!FltpDispatch+0×6f
96834afc f6fb196c nt!IofCallDriver+0×45
WARNING: Stack unwind information not available. Following frames may be wrong.
96834b10 f6fad69a PGPsdk+0×596c
96834b1c 80840153 PGPsdk+0×169a

86dad430 00000000 nt!IofCallDriver+0×45

Because no processors are busy except the one that processes crash dump request via NMI interrupt and there are no ready threads it would be natural to assume that the problem with paging started some time ago and some checks for 3rd-party volume encryption software are necessary as PGP name of the module suggests:

0: kd> lmv m PGPsdk
start    end        module name
f6fac000 f6fb7000   PGPsdk     (no symbols)          
    Loaded symbol image file: PGPsdk.sys
    Image path: \SystemRoot\System32\Drivers\PGPsdk.sys
    Image name: PGPsdk.sys
    Timestamp:        Wed Jun 09 11:44:04 2004 (40C6E9F4)
    CheckSum:         00010F72
    ImageSize:        0000B000
    Translations:     0000.04b0 0000.04e0 0409.04b0 0409.04e0

0: kd> !running

System Processors f (affinity mask)
  Idle Processors e

     Prcb      Current   Next   
  0  ffdff120  808a68c0  86841588  ................

0: kd> !thread 808a68c0 1f
THREAD 808a68c0  Cid 0000.0000  Teb: 00000000 Win32Thread: 00000000 RUNNING on processor 0
Not impersonating
Owning Process            808a6b40       Image:         Idle
Wait Start TickCount      0              Ticks: 15423499 (2:18:56:32.171)
Context Switch Count      100782385            
UserTime                  00:00:00.000
KernelTime                2 Days 12:18:49.343
Stack Init 808a38b0 Current 808a35fc Base 808a38b0 Limit 808a08b0 Call 0
Priority 0 BasePriority 0 PriorityDecrement 0
ChildEBP RetAddr 
808a07bc 80a84df7 nt!KeBugCheckEx+0x1b
808a080c 80834b83 hal!HalHandleNMI+0x1a5
808a080c 80a80853 nt!KiTrap02+0x136 (TrapFrame @ 808a0820)
808a3570 f7659ca2 hal!HalpClockInterrupt+0xff (TrapFrame @ 808a3570)
808a3600 80839b12 intelppm!AcpiC1Idle+0x12
808a3604 00000000 nt!KiIdleLoop+0xa

0: kd> !ready
Processor 0: No threads in READY state
Processor 1: No threads in READY state
Processor 2: No threads in READY state
Processor 3: No threads in READY state

- Dmitry Vostokov @ DumpAnalysis.org -

NULL code pointer, changed environment, hooked functions and execution residue: pattern cooperation

Wednesday, February 4th, 2009

After an upgrade to the new version of a productivity software package one unrelated application started to crash frequently. A crash dump was collected and the following stack trace pointed to a NULL code pointer:

0:000> r
eax=09680104 ebx=0013aefc ecx=0968a710 edx=0cdc0c0c esi=16a19058 edi=00000001
eip=00000000 esp=0013aea8 ebp=0013aeb8 iopl=0 nv up ei pl nz na po nc
cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00200202
00000000 ??              ???

0:000> k 100
ChildEBP RetAddr 
WARNING: Frame IP not in any known module. Following frames may be wrong.
0013aea4 096e28a0 0×0
0013aeb8 32e688bd dllC!Abort+0×10
0013aec8 32c82395 dllB+0×589e
0013aed8 32865718 dllB+0×18f1
[…]
0013b0c0 314de1ff dllB+0×4c6
0013b154 31293494 dllA!DllGetLCID+0×46d2d
0013b178 312af217 dllA!DllGetClassObject+0×4e896
[…]
0013f3d0 300e8721 dllA!DllGetClassObject+0×69e42
0013f578 300e7f5a application+0xcff5
[…]
0013ffc0 7c816ff7 application+0×51d5
0013fff0 00000000 kernel32!BaseProcessStart+0×23

To see if changed environment somehow affected this application the presence of any DLL hooks was checked. The following  hooked functions were found in user32.dll:

0:000> !chkimg -lo 50 -d !user32 -v
Searching for module with expression: !user32
Will apply relocation fixups to file used for comparison
Will ignore NOP/LOCK errors
Will ignore patched instructions
Image specific ignores will be applied
Comparison image path: c:\mss\USER32.dll\45F02D7C90000\USER32.dll
No range specified

Scanning section:    .text
Size: 389095
Range to scan: 7e411000-7e46ffe7
    7e4188a6-7e4188aa  5 bytes - USER32!GetWindowLongW
 [ 6a 08 68 e0 88:e9 55 77 a4 01 ]
    7e418f9c-7e418fa0  5 bytes - USER32!GetSystemMetrics (+0×6f6)
 [ 6a 10 68 00 90:e9 5f 70 b5 01 ]
    7e41945d-7e419461  5 bytes - USER32!GetWindowLongA (+0×4c1)
 [ 6a 10 68 78 9f:e9 f5 60 a2 01 ]
    7e41b6ae-7e41b6b2  5 bytes - USER32!GetClientRect (+0×17a8)
 [ 8b ff 55 8b ec:e9 4d 49 9f 01 ]
    7e41b6d4-7e41b6d8  5 bytes - USER32!GetWindowRect (+0×26)
 [ b8 74 11 00 00:e9 98 30 af 01 ]
    7e41d60d-7e41d611  5 bytes - USER32!SetWindowLongA (+0×6aa)
 [ 8b ff 55 8b ec:e9 ee 29 a5 01 ]
    7e41d62b-7e41d62f  5 bytes - USER32!SetWindowLongW (+0×1e)
 [ 6a 08 68 28 f5:e9 0e 0b b2 01 ]
    7e41fc25-7e41fc29  5 bytes - USER32!CreateWindowExW (+0×738)
 [ 8b ff 55 8b ec:e9 d6 03 b6 01 ]
    7e41ff33-7e41ff37  5 bytes - USER32!CreateWindowExA (+0×30e)
Total bytes compared: 389095(100%)
Number of errors: 52
52 errors : !user32 (7e4188a6-7e42e8d5)

The hooking DLL was found to be from that upgraded package:

0:000> u 7e4188a6
USER32!GetWindowLongW:
7e4188a6 e95577a401      jmp     7fe60000
7e4188ab 41              inc     ecx
7e4188ac 7ee8            jle     USER32!_GetWindowLong+0xda (7e418896)
7e4188ae 0e              push    cs
7e4188af fd              std
7e4188b0 ff              ???
7e4188b1 ff8b4d08e816    dec     dword ptr [ebx+16E8084Dh]
7e4188b7 fc              cld

0:000> u 7fe60000
7fe60000 e9bb62b080      jmp     hookA+0×62c0 (009662c0)
7fe60005 6a08            push    8
7fe60007 68e088417e      push    offset USER32!`string’+0×34 (7e4188e0)
7fe6000c e99c885bfe      jmp     USER32!GetWindowLongW+0×7 (7e4188ad)
7fe60011 0000            add     byte ptr [eax],al
7fe60013 0000            add     byte ptr [eax],al
7fe60015 0000            add     byte ptr [eax],al
7fe60017 0000            add     byte ptr [eax],al

0:000> lmv m hookA
start    end        module name
00960000 00976000   hookA     (no symbols)          
    Loaded symbol image file: hookA.dll
    Image path: C:\Program Files\CompanyA\hookA.dll
    Image name: hookA.dll
    […]
    ProductName:      ProductA
    […]

Execution residue from hookA module was also found on the problem thread raw stack and it looks like real code (not a coincidental symbolic information):

0:000> !teb
TEB at 7ffdf000
    ExceptionList:        0013f02c
    StackBase:            00140000
    StackLimit:           0010c000

    SubSystemTib:         00000000
    FiberData:            00001e00
    ArbitraryUserPointer: 00000000
    Self:                 7ffdf000
    EnvironmentPointer:   00000000
    ClientId:             00000c38 . 00000840
    RpcHandle:            00000000
    Tls Storage:          00163268
    PEB Address:          7ffdb000
    LastErrorValue:       0
    LastStatusValue:      0
    Count Owned Locks:    0
    HardErrorMode:        0

0:000> dds 0010c000 00140000
0010c000  00000000
0010c004  00000000
0010c008  00000000
[…]
00121f50  0096d7d1*** ERROR: Module load completed but symbols could not be loaded for hookA.dll
 hookA+0xd7d1

00121f54  00009924
00121f58  00121fb4
00121f5c  00000000
00121f60  00121f9c
00121f64  0096d895 hookA+0xd895
00121f68  00121f78
00121f6c  00000000
00121f70  00122008
00121f74  00000000
00121f78  00000000
00121f7c  00000000
00121f80  00000000
00121f84  00121f6c
00121f88  000001fe
00121f8c  001220fc
00121f90  0096ec98 hookA+0xec98
00121f94  00970e48 hookA+0×10e48
00121f98  00121fb4
00121f9c  7e41b6a3 USER32!_GetClientRect+0×6e
00121fa0  00122008
00121fa4  fffffa01
[…]

0:000> u 0096d895
hookA+0xd895:
0096d895 8bc6            mov     eax,esi
0096d897 8b4df0          mov     ecx,dword ptr [ebp-10h]
0096d89a 64890d00000000  mov     dword ptr fs:[0],ecx
0096d8a1 5f              pop     edi
0096d8a2 5e              pop     esi
0096d8a3 5b              pop     ebx
0096d8a4 8be5            mov     esp,ebp
0096d8a6 5d              pop     ebp

0:000> ub 0096d895
hookA+0xd876:
0096d876 8b65e8          mov     esp,dword ptr [ebp-18h]
0096d879 be0d000000      mov     esi,0Dh
0096d87e c745fcffffffff  mov     dword ptr [ebp-4],0FFFFFFFFh
0096d885 eb05            jmp     hookA+0xd88c (0096d88c)
0096d887 be72000000      mov     esi,72h
0096d88c 8d55dc          lea     edx,[ebp-24h]
0096d88f 52              push    edx
0096d890 e8fbfeffff      call    hookA+0xd790 (0096d790)

As was found the upgraded application had special DLL hooks to improve productivity and ease of use of GUI applications. Fortunately it was possible to disable that hook on a per-application basis and application crashes disappeared.

- Dmitry Vostokov @ DumpAnalysis.org -

Memory leak, spiking threads, wait chain, high critical section contention and module variety: pattern cooperation

Monday, January 26th, 2009

I noticed yesterday that my home Vista computer suddenly became slower than usual so I brought Task Manager, sorted processes by CPU usage and discovered an instance of IE7 with 50% - 60% of CPU consumption. Dumping processes in Vista is easier than ever, so I did the right click on that process and selected Create Dump File menu option. The dump was saved and I killed the process. The size of the dump file was 1.2Gb and that definitely indicated a memory leak. Examining process heap showed large heap segments amounting to 800Mb and therefore pointing to the possible heap leak:

0:000> !heap 0 0
Index   Address  Name      Debugging options enabled
  1:   00370000
    Segment at 00370000 to 00470000 (00100000 bytes committed)
    Segment at 04990000 to 04a90000 (00100000 bytes committed)
    Segment at 063e0000 to 065e0000 (00200000 bytes committed)
    Segment at 08440000 to 08840000 (00400000 bytes committed)
    Segment at 0ce80000 to 0d680000 (00800000 bytes committed)
    Segment at 160b0000 to 17080000 (00fd0000 bytes committed)
    Segment at 19b00000 to 1aad0000 (00fd0000 bytes committed)
    Segment at 1c8c0000 to 1d890000 (00fd0000 bytes committed)
    Segment at 27870000 to 28840000 (00fd0000 bytes committed)
    Segment at 29870000 to 2a840000 (00fd0000 bytes committed)
    Segment at 2d1f0000 to 2e1c0000 (00fd0000 bytes committed)
    Segment at 31fb0000 to 32f80000 (00fd0000 bytes committed)
    Segment at 384c0000 to 39490000 (00fd0000 bytes committed)
    Segment at 3c040000 to 3d010000 (00fd0000 bytes committed)
    Segment at 41cf0000 to 42cc0000 (00fd0000 bytes committed)
    Segment at 43c90000 to 44c60000 (00fd0000 bytes committed)
    Segment at 44c60000 to 45c30000 (00fd0000 bytes committed)
    Segment at 473f0000 to 483c0000 (00fd0000 bytes committed)
    Segment at 4a390000 to 4b360000 (00fd0000 bytes committed)
    Segment at 4b360000 to 4c330000 (00fd0000 bytes committed)
    Segment at 4d300000 to 4e2d0000 (00fd0000 bytes committed)
    Segment at 4e2d0000 to 4f2a0000 (00fd0000 bytes committed)
    Segment at 50480000 to 51450000 (00fd0000 bytes committed)
    Segment at 51450000 to 52420000 (00fd0000 bytes committed)
    Segment at 533f0000 to 543c0000 (00fd0000 bytes committed)
    Segment at 54810000 to 557e0000 (00fd0000 bytes committed)
    Segment at 567b0000 to 57780000 (00fd0000 bytes committed)
    Segment at 57c80000 to 58c50000 (00fc1000 bytes committed)
    Segment at 59c20000 to 5abf0000 (00fc6000 bytes committed)
    Segment at 5b0f0000 to 5c0c0000 (00fc1000 bytes committed)
    Segment at 5c0c0000 to 5d090000 (00fc1000 bytes committed)
    Segment at 5d090000 to 5e060000 (00fc1000 bytes committed)
    Segment at 5f030000 to 60000000 (00fc1000 bytes committed)
    Segment at 60000000 to 60fd0000 (00fc1000 bytes committed)
    Segment at 60fd0000 to 61fa0000 (00fd0000 bytes committed)
    Segment at 61fa0000 to 62f70000 (00e26000 bytes committed)

  2:   00010000
    Segment at 00010000 to 00020000 (00003000 bytes committed)
  3:   00d80000
    Segment at 00d80000 to 00d90000 (00010000 bytes committed)
    Segment at 00050000 to 00150000 (00014000 bytes committed)
  4:   00190000
    Segment at 00190000 to 001a0000 (00010000 bytes committed)
    Segment at 00d90000 to 00e90000 (00100000 bytes committed)
    Segment at 0a430000 to 0a630000 (00200000 bytes committed)
    Segment at 0d8d0000 to 0dcd0000 (00400000 bytes committed)
    Segment at 0ecc0000 to 0f4c0000 (00800000 bytes committed)
    Segment at 18690000 to 19660000 (00fd0000 bytes committed)
    Segment at 24fe0000 to 25fb0000 (00fd0000 bytes committed)
    Segment at 2bf40000 to 2cf10000 (00fd0000 bytes committed)
    Segment at 303b0000 to 31380000 (00fd0000 bytes committed)
    Segment at 33370000 to 34340000 (00fd0000 bytes committed)
    Segment at 39490000 to 3a460000 (00fd0000 bytes committed)
    Segment at 40d20000 to 41cf0000 (00fd0000 bytes committed)
    Segment at 483c0000 to 49390000 (00fd0000 bytes committed)
    Segment at 557e0000 to 567b0000 (00452000 bytes committed)
  5:   00330000
    Segment at 00330000 to 00340000 (00010000 bytes committed)
    Segment at 00c10000 to 00d10000 (00100000 bytes committed)
    Segment at 0c910000 to 0cb10000 (00200000 bytes committed)
    Segment at 18280000 to 18680000 (00400000 bytes committed)
    Segment at 2ec20000 to 2f420000 (00800000 bytes committed)
    Segment at 42cc0000 to 43c90000 (00fc7000 bytes committed)
    Segment at 4c330000 to 4d300000 (00d45000 bytes committed)
    Segment at 52420000 to 533f0000 (00d39000 bytes committed)
    Segment at 58c50000 to 59c20000 (00ddc000 bytes committed)
    Segment at 5e060000 to 5f030000 (00dd1000 bytes committed)
  6:   00e90000
    Segment at 00e90000 to 00ea0000 (00010000 bytes committed)
    Segment at 06780000 to 06880000 (00026000 bytes committed)
  7:   00170000
    Segment at 00170000 to 00180000 (00010000 bytes committed)
    Segment at 06880000 to 06980000 (00026000 bytes committed)
  8:   01bf0000
    Segment at 01bf0000 to 01c00000 (00010000 bytes committed)
    Segment at 03bb0000 to 03cb0000 (00100000 bytes committed)
    Segment at 0e610000 to 0e810000 (00200000 bytes committed)
  9:   00bf0000
    Segment at 00bf0000 to 00c00000 (00001000 bytes committed)
 10:   00b70000
    Segment at 00b70000 to 00b80000 (00003000 bytes committed)
 11:   01b60000
    Segment at 01b60000 to 01ba0000 (00040000 bytes committed)
 12:   03650000
    Segment at 03650000 to 03690000 (00009000 bytes committed)
 13:   039c0000
    Segment at 039c0000 to 039d0000 (00008000 bytes committed)
    Segment at 07e30000 to 07f30000 (00012000 bytes committed)
 14:   00b20000
    Segment at 00b20000 to 00b30000 (00003000 bytes committed)
 15:   01b00000
    Segment at 01b00000 to 01b40000 (00040000 bytes committed)
    Segment at 22b80000 to 22c80000 (00032000 bytes committed)
 16:   00b30000
    Segment at 00b30000 to 00b70000 (00040000 bytes committed)
    Segment at 08f00000 to 09000000 (00100000 bytes committed)
    Segment at 376f0000 to 378f0000 (000e3000 bytes committed)
 17:   03700000
    Segment at 03700000 to 03740000 (00040000 bytes committed)
 18:   03a70000
    Segment at 03a70000 to 03ab0000 (00040000 bytes committed)
 19:   00be0000
    Segment at 00be0000 to 00bf0000 (00010000 bytes committed)
    Segment at 0a630000 to 0a730000 (000a8000 bytes committed)
 20:   04df0000
    Segment at 04df0000 to 04ef0000 (00100000 bytes committed)
 21:   044d0000
    Segment at 044d0000 to 044e0000 (00010000 bytes committed)
    Segment at 04390000 to 04490000 (00028000 bytes committed)
 22:   04730000
    Segment at 04730000 to 04740000 (00010000 bytes committed)
    Segment at 04620000 to 04720000 (00100000 bytes committed)
    Segment at 23fb0000 to 241b0000 (001f6000 bytes committed)
 23:   055e0000
    Segment at 055e0000 to 056e0000 (00100000 bytes committed)
 24:   05ce0000
    Segment at 05ce0000 to 05cf0000 (00010000 bytes committed)
    Segment at 06bb0000 to 06cb0000 (00012000 bytes committed)
 25:   05e20000
    Segment at 05e20000 to 05e60000 (00020000 bytes committed)
 26:   04860000
    Segment at 04860000 to 04870000 (00010000 bytes committed)
    Segment at 0df60000 to 0e060000 (00024000 bytes committed)
 27:   04dc0000
    Segment at 04dc0000 to 04dd0000 (00010000 bytes committed)
    Segment at 062e0000 to 063e0000 (00100000 bytes committed)
    Segment at 26d70000 to 26f70000 (001eb000 bytes committed)
 28:   06aa0000
    Segment at 06aa0000 to 06ab0000 (00010000 bytes committed)
    Segment at 06980000 to 06a80000 (00100000 bytes committed)
    Segment at 1ede0000 to 1efe0000 (00200000 bytes committed)
    Segment at 1efe0000 to 1f3e0000 (00322000 bytes committed)
    Segment at 1f3e0000 to 1fbe0000 (00800000 bytes committed)
    Segment at 205e0000 to 215b0000 (001c7000 bytes committed)
 29:   05420000
    Segment at 05420000 to 05430000 (00010000 bytes committed)
    Segment at 06ab0000 to 06bb0000 (00053000 bytes committed)
 30:   05980000
    Segment at 05980000 to 05990000 (00010000 bytes committed)
    Segment at 17d90000 to 17e90000 (00012000 bytes committed)
 31:   07c20000
    Segment at 07c20000 to 07c60000 (00040000 bytes committed)
    Segment at 08cc0000 to 08dc0000 (00100000 bytes committed)
    Segment at 1fbe0000 to 1fde0000 (001fd000 bytes committed)
    Segment at 241b0000 to 245b0000 (003fa000 bytes committed)
    Segment at 2a840000 to 2b040000 (0007c000 bytes committed)
 32:   07be0000
    Segment at 07be0000 to 07c20000 (0003a000 bytes committed)
    Segment at 17900000 to 17a00000 (000fd000 bytes committed)
    Segment at 3b2b0000 to 3b4b0000 (001fe000 bytes committed)
    Segment at 45c30000 to 46030000 (00289000 bytes committed)
 33:   07df0000
    Segment at 07df0000 to 07e30000 (0003a000 bytes committed)
    Segment at 22810000 to 22910000 (0001c000 bytes committed)
 34:   08000000
    Segment at 08000000 to 08040000 (00001000 bytes committed)
 35:   07da0000
    Segment at 07da0000 to 07de0000 (00001000 bytes committed)
 36:   04b60000
    Segment at 04b60000 to 04b70000 (00002000 bytes committed)
 37:   08990000
    Segment at 08990000 to 089a0000 (00010000 bytes committed)
    Segment at 06cb0000 to 06db0000 (00024000 bytes committed)
 38:   051f0000
    Segment at 051f0000 to 05200000 (00010000 bytes committed)
    Segment at 050c0000 to 051c0000 (00100000 bytes committed)
    Segment at 0c110000 to 0c310000 (00200000 bytes committed)
    Segment at 0c310000 to 0c710000 (003f6000 bytes committed)
    Segment at 1bd00000 to 1c500000 (00529000 bytes committed)
    Segment at 216c0000 to 22690000 (00376000 bytes committed)
 39:   0ac10000
    Segment at 0ac10000 to 0ac20000 (00010000 bytes committed)
    Segment at 0aa80000 to 0ab80000 (000c4000 bytes committed)
 40:   12ed0000
    Segment at 12ed0000 to 12ee0000 (00010000 bytes committed)
    Segment at 199e0000 to 19ae0000 (00022000 bytes committed)
 41:   15450000
    Segment at 15450000 to 15490000 (00001000 bytes committed)
 42:   17ad0000
    Segment at 17ad0000 to 17b10000 (00001000 bytes committed)
 43:   1b2f0000
    Segment at 1b2f0000 to 1b300000 (00010000 bytes committed)
    Segment at 1ad30000 to 1ae30000 (0002c000 bytes committed)
 44:   232b0000
    Segment at 232b0000 to 232f0000 (00015000 bytes committed)
 45:   21680000
    Segment at 21680000 to 216c0000 (00001000 bytes committed)
 46:   23490000
    Segment at 23490000 to 234d0000 (00001000 bytes committed)
 47:   23670000
    Segment at 23670000 to 236b0000 (00001000 bytes committed)
 48:   17ed0000
    Segment at 17ed0000 to 17f10000 (00001000 bytes committed)
 49:   247f0000
    Segment at 247f0000 to 24830000 (00040000 bytes committed)
 50:   28c40000
    Segment at 28c40000 to 28c80000 (00040000 bytes committed)
 51:   2ffd0000
    Segment at 2ffd0000 to 2ffe0000 (00006000 bytes committed)
 52:   376b0000
    Segment at 376b0000 to 376f0000 (00040000 bytes committed)
 53:   2ff90000
    Segment at 2ff90000 to 2ffd0000 (00040000 bytes committed)
 54:   26260000
    Segment at 26260000 to 262a0000 (00040000 bytes committed)
 55:   3a530000
    Segment at 3a530000 to 3a570000 (00040000 bytes committed)

However I concentrated on CPU spike and !runaway WinDbg command showed the following distribution of thread user mode times:

0:000> !runaway
 User Mode Time
  Thread       Time
 117:10a0      0 days 3:09:13.643
  13:ca4       0 days 2:18:41.311

  61:16c4      0 days 0:25:46.515
  33:1690      0 days 0:25:25.954
   4:fb0       0 days 0:22:20.797
  29:840       0 days 0:21:25.385
  23:1614      0 days 0:21:08.194
  77:3e0       0 days 0:18:57.434
  45:11f4      0 days 0:17:13.647
  71:1314      0 days 0:17:10.667
  31:1198      0 days 0:16:48.374
  39:156c      0 days 0:16:40.980
  59:d1c       0 days 0:16:37.610
 115:3e8       0 days 0:16:32.384
  57:170c      0 days 0:16:30.746
  47:1364      0 days 0:16:18.360
  84:12a8      0 days 0:15:56.145
 112:a10       0 days 0:15:52.089
 106:1374      0 days 0:15:51.652
  89:b58       0 days 0:15:47.768
 125:115c      0 days 0:15:41.122
 101:1100      0 days 0:15:30.748
 104:1294      0 days 0:15:16.147
  99:d00       0 days 0:15:15.008
  96:9b4       0 days 0:15:13.604
 123:1624      0 days 0:15:12.247
  86:1444      0 days 0:15:11.654
 131:1728      0 days 0:14:35.914
 135:100c      0 days 0:14:16.414
 133:1530      0 days 0:14:04.963
 137:a30       0 days 0:13:41.360
 139:dd8       0 days 0:13:40.674
 142:1098      0 days 0:12:51.284
   0:efc       0 days 0:02:43.005
   1:f44       0 days 0:01:34.536
  19:8d0       0 days 0:00:42.557
  98:54c       0 days 0:00:28.282
 114:138c      0 days 0:00:26.598
  83:1060      0 days 0:00:22.354
  88:17ec      0 days 0:00:22.027
 103:da8       0 days 0:00:20.404
 141:15c8      0 days 0:00:19.843
  10:b14       0 days 0:00:12.526
   8:5b8       0 days 0:00:02.246
  21:cfc       0 days 0:00:00.795
  12:10c       0 days 0:00:00.561
  11:8d4       0 days 0:00:00.312
  65:b0c       0 days 0:00:00.202
  22:ae8       0 days 0:00:00.187
  17:744       0 days 0:00:00.124
  28:168c      0 days 0:00:00.093
   6:5a8       0 days 0:00:00.046
   2:f90       0 days 0:00:00.031
 130:fa4       0 days 0:00:00.015
 113:17c4      0 days 0:00:00.015
  76:1a4       0 days 0:00:00.015
  70:10a8      0 days 0:00:00.015
  32:df0       0 days 0:00:00.015
  18:ee0       0 days 0:00:00.015
   7:3f4       0 days 0:00:00.015
 148:11cc      0 days 0:00:00.000
 147:132c      0 days 0:00:00.000
 146:1458      0 days 0:00:00.000
 145:133c      0 days 0:00:00.000
 144:1268      0 days 0:00:00.000
 143:838       0 days 0:00:00.000
 140:1168      0 days 0:00:00.000
 138:f48       0 days 0:00:00.000
 136:1f0       0 days 0:00:00.000
 134:17ac      0 days 0:00:00.000
 132:119c      0 days 0:00:00.000
 129:fc4       0 days 0:00:00.000
 128:bd8       0 days 0:00:00.000
 127:1528      0 days 0:00:00.000
 126:1058      0 days 0:00:00.000
 124:16a4      0 days 0:00:00.000
 122:1518      0 days 0:00:00.000
 121:7c        0 days 0:00:00.000
 120:103c      0 days 0:00:00.000
 119:a2c       0 days 0:00:00.000
 118:1524      0 days 0:00:00.000
 116:1240      0 days 0:00:00.000
 111:1248      0 days 0:00:00.000
 110:de8       0 days 0:00:00.000
 109:dc8       0 days 0:00:00.000
 108:17e8      0 days 0:00:00.000
 107:994       0 days 0:00:00.000
 105:162c      0 days 0:00:00.000
 102:112c      0 days 0:00:00.000
 100:1764      0 days 0:00:00.000
  97:1548      0 days 0:00:00.000
  95:1334      0 days 0:00:00.000
  94:1024      0 days 0:00:00.000
  93:1170      0 days 0:00:00.000
  92:12f0      0 days 0:00:00.000
  91:12d4      0 days 0:00:00.000
  90:1264      0 days 0:00:00.000
  87:12d8      0 days 0:00:00.000
  85:153c      0 days 0:00:00.000
  82:14c4      0 days 0:00:00.000
  81:834       0 days 0:00:00.000
  80:17f4      0 days 0:00:00.000
  79:1784      0 days 0:00:00.000
  78:530       0 days 0:00:00.000
  75:1320      0 days 0:00:00.000
  74:15fc      0 days 0:00:00.000
  73:16e4      0 days 0:00:00.000
  72:17b0      0 days 0:00:00.000
  69:af0       0 days 0:00:00.000
  68:83c       0 days 0:00:00.000
  67:b78       0 days 0:00:00.000
  66:cc4       0 days 0:00:00.000
  64:14fc      0 days 0:00:00.000
  63:14dc      0 days 0:00:00.000
  62:16b0      0 days 0:00:00.000
  60:1130      0 days 0:00:00.000
  58:1504      0 days 0:00:00.000
  56:1160      0 days 0:00:00.000
  55:16c0      0 days 0:00:00.000
  54:bfc       0 days 0:00:00.000
  53:f70       0 days 0:00:00.000
  52:1178      0 days 0:00:00.000
  51:1448      0 days 0:00:00.000
  50:15e8      0 days 0:00:00.000
  49:1410      0 days 0:00:00.000
  48:10c0      0 days 0:00:00.000
  46:14e4      0 days 0:00:00.000
  44:1150      0 days 0:00:00.000
  43:1454      0 days 0:00:00.000
  42:131c      0 days 0:00:00.000
  41:8cc       0 days 0:00:00.000
  40:17bc      0 days 0:00:00.000
  38:17c0      0 days 0:00:00.000
  37:15a4      0 days 0:00:00.000
  36:1048      0 days 0:00:00.000
  35:143c      0 days 0:00:00.000
  34:1384      0 days 0:00:00.000
  30:fa0       0 days 0:00:00.000
  27:1688      0 days 0:00:00.000
  26:1684      0 days 0:00:00.000
  25:1680      0 days 0:00:00.000
  24:161c      0 days 0:00:00.000
  20:500       0 days 0:00:00.000
  16:1a0       0 days 0:00:00.000
  15:a18       0 days 0:00:00.000
  14:c44       0 days 0:00:00.000
   9:6c4       0 days 0:00:00.000
   5:ec8       0 days 0:00:00.000
   3:fa8       0 days 0:00:00.000

Threads 117 and 13 were waiting for a critical section 6e1876c4:

0:000> ~117kv
ChildEBP RetAddr  Args to Child             
35f0e468 77009254 76ff33b4 00000520 00000000 ntdll!KiFastSystemCallRet
35f0e46c 76ff33b4 00000520 00000000 00000000 ntdll!ZwWaitForSingleObject+0xc
35f0e4d0 76ff323c 00000000 00000000 00000000 ntdll!RtlpWaitOnCriticalSection+0x155
35f0e4f8 6e16ac32 6e1876c4 00071370 35f0e59c ntdll!RtlEnterCriticalSection+0x152
35f0e510 6e16b4cc 6e16e2f1 00000000 35f0e59c AcRedir!NS_RedirectRegistry::RedirectorRegistry::LookupKOECache+0×22
35f0e524 6e16bb90 00071370 00000000 00000000 AcRedir!NS_RedirectRegistry::RedirectorRegistry::PreChecks+0xd3
35f0e544 6e16bbce 00071370 00000000 00000008 AcRedir!NS_RedirectRegistry::RedirectorRegistry::InitializeMergeW+0×1a
35f0e574 6e16e327 00071370 00000002 00000002 AcRedir!NS_RedirectRegistry::RedirectorRegistry::InitializeEnumeration+0×26

*** ERROR: Symbol file could not be found.  Defaulted to export symbols for PDFCreator_Toolbar.dll -
35f0e620 05729772 00071370 00000002 35f0e690 AcRedir!NS_RedirectRegistry::APIHook_RegEnumValueA+0×36
WARNING: Stack unwind information not available. Following frames may be wrong.
35f0e6a4 76b60528 c02193db 00000128 00000000 PDFCreator_Toolbar!DllUnregisterServer+0×3b7ce
35f0e6dc 73207be1 000319f8 00000128 00030001 user32!DefWindowProcW+0×86
76b60528 90909090 fffffffe 00000000 ffffffd0 comctl32!ToolbarWndProc+0×14f7
76b60528 00000000 fffffffe 00000000 ffffffd0 0×90909090

0:000> ~13kv
ChildEBP RetAddr  Args to Child             
0c90e5ec 77009254 76ff33b4 00000520 00000000 ntdll!KiFastSystemCallRet
0c90e5f0 76ff33b4 00000520 00000000 00000000 ntdll!ZwWaitForSingleObject+0xc
0c90e654 76ff323c 00000000 00000000 00000000 ntdll!RtlpWaitOnCriticalSection+0x155
0c90e67c 6e16ac32 6e1876c4 00071348 0c90e720 ntdll!RtlEnterCriticalSection+0x152
0c90e694 6e16b4cc 6e16e2f1 00000000 0c90e720 AcRedir!NS_RedirectRegistry::RedirectorRegistry::LookupKOECache+0×22
0c90e6a8 6e16bb90 00071348 00000000 00000000 AcRedir!NS_RedirectRegistry::RedirectorRegistry::PreChecks+0xd3
0c90e6c8 6e16bbce 00071348 00000000 00000008 AcRedir!NS_RedirectRegistry::RedirectorRegistry::InitializeMergeW+0×1a
0c90e6f8 6e16e327 00071348 0000000c 00000002 AcRedir!NS_RedirectRegistry::RedirectorRegistry::InitializeEnumeration+0×26
0c90e7a4 05729772 00071348 0000000c 0c90e814 AcRedir!NS_RedirectRegistry::APIHook_RegEnumValueA+0×36

WARNING: Stack unwind information not available. Following frames may be wrong.
0c90e858 76b60528 73207be1 000205e2 00000128 PDFCreator_Toolbar!DllUnregisterServer+0×3b7ce
0c90e8d4 76b5f8d2 626f6441 44502065 00200046 user32!DefWindowProcW+0×86
0c90e978 76b60817 0041fecc 73207ae0 000205e2 user32!InternalCallWinProc+0×23
00030ad4 0031002e 00300038 00350036 006e005f user32!DispatchClientMessage+0xda
00030ad4 00000000 00300038 00350036 006e005f 0×31002e

Examining critical section locks showed this section to be the only one locked and having high contention:

0:000> !locks

CritSec AcRedir!NS_RedirectRegistry::RedirectorRegistry::ClassLock+0 at 6e1876c4
WaiterWoken        No
LockCount          32
RecursionCount     1
OwningThread       d1c
EntryCount         0
ContentionCount    c74ad4
*** Locked

Scanned 22054 critical sections

There were 32 threads waiting on it. Examining its owning thread d1c showed similar stack trace pattern:

0:000> ~~[d1c]kv
ChildEBP RetAddr  Args to Child             
269ae72c 6e16f1da 269ae808 31f4a7e8 269ae75c AcRedir!NS_RedirectRegistry::OwnedRegistryKeyPair::Match+0×14
269ae73c 6e16f40c 269ae7ec 269ae808 269ae808 AcRedir!NS_RedirectRegistry::MergedRegistryKey::Match+0×22
269ae75c 6e16bc11 269ae7ec 269ae808 269ae784 AcRedir!NS_RedirectRegistry::MergedRegistryKeyList::FindItem+0×25
269ae790 6e16e327 00c211b0 00000008 00000002 AcRedir!NS_RedirectRegistry::RedirectorRegistry::InitializeEnumeration+0×69
269ae83c 05729772 000714a4 00000008 269ae8ac AcRedir!NS_RedirectRegistry::APIHook_RegEnumValueA+0×36

WARNING: Stack unwind information not available. Following frames may be wrong.
269ae8f0 76b60528 73207be1 00050cf8 00000128 PDFCreator_Toolbar!DllUnregisterServer+0×3b7ce
269ae96c 76b5f8d2 00000001 00070598 00040582 user32!DefWindowProcW+0×86
269aea10 76b60817 0041fecc 73207ae0 00050cf8 user32!InternalCallWinProc+0×23
00030ad4 0031002e 00300038 00350036 006e005f user32!DispatchClientMessage+0xda
00030ad4 00000000 00300038 00350036 006e005f 0×31002e

Two components immediately came to suspicion, AcRedir.dll and PDFCreator_Toolbar.dll:

0:000> lmv m AcRedir
start    end        module name
6e150000 6e18e000   AcRedir    (pdb symbols)          c:\mss\AcRedir.pdb\923AF38F594246C99580DC1CFB4B3AE02\AcRedir.pdb
    Loaded symbol image file: AcRedir.dll
    Image path: C:\Windows\AppPatch\AcRedir.dll
    Image name: AcRedir.dll
    Timestamp:        Sat Jan 19 07:26:39 2008 (4791A62F)
    CheckSum:         0003F278
    ImageSize:        0003E000
    File version:     6.0.6001.18000
    Product version:  6.0.6001.18000
    File flags:       0 (Mask 3F)
    File OS:          40004 NT Win32
    File type:        2.0 Dll
    File date:        00000000.00000000
    Translations:     0409.04b0
    CompanyName:      Microsoft Corporation
    ProductName:      Microsoft® Windows® Operating System
    InternalName:     Microsoft® Windows® Operating System
    OriginalFilename: Microsoft® Windows® Operating System
    ProductVersion:   6.0.6001.18000
    FileVersion:      6.0.6001.18000 (longhorn_rtm.080118-1840)
    FileDescription:  Windows Compatibility DLL
    LegalCopyright:   © Microsoft Corporation. All rights reserved.

0:000> lmv m PDFCreator_Toolbar
start    end        module name
056e0000 057bb000   PDFCreator_Toolbar   (export symbols)       PDFCreator_Toolbar.dll
    Loaded symbol image file: PDFCreator_Toolbar.dll
    Image path: C:\Program Files\PDFCreator Toolbar\v3.3.0.1\PDFCreator_Toolbar.dll
    Image name: PDFCreator_Toolbar.dll
    Timestamp:        Sat Aug 09 08:53:38 2008 (489D4D02)
    CheckSum:         000AA334
    ImageSize:        000DB000
    File version:     3.3.0.1
    Product version:  3.3.0.1
    File flags:       0 (Mask 3F)
    File OS:          4 Unknown Win32
    File type:        2.0 Dll
    File date:        00000000.00000000
    Translations:     0409.04b0
    ProductName:      PDFCreator Toolbar
    InternalName:     PDFCreator Toolbar
    OriginalFilename: Toolbar.dll
    ProductVersion:   3,3,0,1
    FileVersion:      3,3,0,1
    FileDescription:  PDFCreator Toolbar
    LegalCopyright:   Copyright 2006

Then I decided to examine some heap blocks from leaked segments and found the prolifiration of UNICODE string fragments containing “PDFCreator Toolbar”:

0:000> dc 567b0000 l3000
[...]
567b21a0  00000001 00000008 00000040 00650054  ............T.e.
567b21b0  0070006d 00610044 00610074 00730000  m.p.D.a.t.a...s.
567b21c0  00740069 006f0069 0000006e 00000072  i.t.i.o.n...r...
567b21d0  00000068 005c0067 00440050 00430046  h…g.\.P.D.F.C.
567b21e0  00650072 00740061 0072006f 00540020  r.e.a.t.o.r. .T.
567b21f0  006f006f 0062006c 00720061 002d0000  o.o.l.b.a.r…-.

567b2200  00300031 00300030 00300000 00420025  1.0.0.0…0.%.B.
567b2210  00250030 00310044 00380025 00250031  0.%.D.1.%.8.1.%.
567b2220  00310044 00380025 00000031 00000000  D.1.%.8.1…….
567b2230  52332e04 88000000 00000001 00000013  ..3R…………
567b2240  00000040 00690044 00450064 0061006e  @…D.i.d.E.n.a.
567b2250  006c0062 00410065 00740075 0053006f  b.l.e.A.u.t.o.S.
567b2260  00610065 00630072 00000068 005c0067  e.a.r.c.h…g.\.
567b2270  00440050 00430046 00650072 00740061  P.D.F.C.r.e.a.t.
567b2280  0072006f 00540020 006f006f 0062006c  o.r. .T.o.o.l.b.
567b2290  00720061 002d0000 00300031 00300030  a.r…-.1.0.0.0.

567b22a0  00300000 00420025 00250030 00310044  ..0.%.B.0.%.D.1.
567b22b0  00380025 00250031 00310044 00380025  %.8.1.%.D.1.%.8.
567b22c0  00000031 00000000 52332e1b 88000000  1………3R….
567b22d0  00000001 00000005 00000040 004c0053  …………S.L.
567b22e0  00730069 00000074 00450052 0070005c  i.s.t…R.E.\.p.
567b22f0  00660064 006f0066 00670072 002e0065  d.f.f.o.r.g.e…
567b2300  0072006f 005c0067 00440050 00430046  o.r.g.\.P.D.F.C.
567b2310  00650072 00740061 0072006f 00540020  r.e.a.t.o.r. .T.
567b2320  006f006f 0062006c 00720061 00300000  o.o.l.b.a.r…0.

567b2330  00420025 00250042 00300044 00420025  %.B.B.%.D.0.%.B.
567b2340  00250030 00310044 00380025 00250031  0.%.D.1.%.8.1.%.
567b2350  00310044 00380025 00000031 00000000  D.1.%.8.1…….
567b2360  52332e2e 88000000 00000001 00000005  ..3R…………

Because AcRedir code was called from PDFCreator Toolbar component the final decision was to uninstall PDFCreator Toolbar. Before I quit the debugger I dumped the list of modules and was astonished at the module variety:

0:000> lm
start    end        module name
00850000 008eb000   iexplore   (pdb symbols)         
05430000 054ab000   ssv        (deferred)            
056e0000 057bb000   PDFCreator_Toolbar   (export symbols)
0a7f0000 0aa73000   igdumd32   (deferred)            
10000000 100a4000   swg        (deferred)            
16080000 160a5000   mdnsNSP    (deferred)            
28f90000 28f9a000   icalogon   (deferred)            
29330000 29337000   PScript    (deferred)            
29440000 29462000   ctxmui     (deferred)            
29470000 29476000   TcpPServ   (deferred)            
29480000 29492000   CgpCore    (deferred)            
295a0000 295b0000   confmgr    (deferred)            
295b0000 295b7000   logging    (deferred)            
296c0000 296c7000   icafile    (deferred)            
296d0000 296d6000   cgpcfg     (deferred)            
296e0000 296e5000   ctxmuiUI   (deferred)            
2bd20000 2bd8e000   Wfica      (deferred)            
30000000 303ae000   Flash9e    (export symbols)
63f00000 63f0c000   mscorie    (deferred)            
655e0000 65639000   rpbrowserrecordplugin   (deferred)            
692a0000 69a66000   wmploc     (deferred)            
69a70000 6a4a0000   wmp        (deferred)            
6b220000 6b2e3000   VGX        (deferred)            
6b2f0000 6b3bc000   d3dim700   (deferred)            
6b450000 6b4d3000   AdobeUpdater   (deferred)            
6b4e0000 6b7de000   agcore     (deferred)            
6b7e0000 6ba63000   fastsearch_219B3E1547538286   (deferred)            
6ba70000 6be17000   GoogleToolbarDynamic_F423308312A7B033   (export symbols)   
6be20000 6be89000   vbscript   (deferred)            
6bf90000 6c302000   mshtml     (export symbols)   
6c320000 6c36a000   ntshrui    (deferred)            
6c3d0000 6c447000   mshtmled   (deferred)            
6c4d0000 6c527000   dxtmsft    (deferred)            
6c590000 6c60d000   jscript    (pdb symbols)         
6c610000 6c649000   dxtrans    (pdb symbols)         
6c770000 6c7e0000   dsound     (deferred)            
6c810000 6c839000   msls31     (deferred)            
6ca50000 6ca6b000   cryptnet   (deferred)            
6ca90000 6cada000   rasapi32   (deferred)            
6cca0000 6ccb4000   rasman     (deferred)            
6cd40000 6cd71000   tapi32     (deferred)            
6d0b0000 6d0fc000   Wpc        (deferred)            
6d350000 6d410000   npctrl     (deferred)            
6d450000 6d482000   iepeers    (deferred)            
6d4d0000 6d530000   ieapfltr   (deferred)            
6d5b0000 6d603000   AcroIEFavClient   (deferred)            
6d6b0000 6d795000   ddraw      (deferred)            
6d7a0000 6d818000   AcSpecfc   (deferred)            
6d820000 6d82e000   pngfilt    (deferred)            
6d830000 6d892000   mscms      (deferred)            
6dbc0000 6dc5b000   msvcr80    (deferred)            
6dc60000 6dce7000   msvcp80    (deferred)            
6dd70000 6ddf8000   AcLayers   (deferred)            
6de00000 6de0a000   ddrawex    (deferred)            
6de60000 6de83000   msvfw32    (deferred)            
6dfb0000 6dfc1000   AcroIEHelperShim   (deferred)            
6dff0000 6e036000   GoogleToolbar   (deferred)            
6e060000 6e086000   dssenh     (deferred)            
6e090000 6e0f0000   tiptsf     (deferred)            
6e0f0000 6e11f000   ieui       (pdb symbols)         
6e130000 6e140000   AcroIEHelper   (deferred)            
6e150000 6e18e000   AcRedir    (pdb symbols)         
6e570000 6e57b000   msimtf     (deferred)            
6e580000 6e58f000   davclnt    (deferred)            
6e590000 6e5a3000   ntlanman   (deferred)            
6e610000 6e618000   drprov     (deferred)            
6e620000 6e630000   iebrshim   (deferred)            
6e650000 6e680000   mlang      (deferred)            
6f7b0000 6f7b8000   dispex     (deferred)            
6f8a0000 6f8ab000   cscapi     (deferred)            
6fa70000 6fb4c000   dbghelp    (deferred)            
6fe40000 6fe73000   msrating   (deferred)            
6ff00000 6ff3a000   sqlite     (deferred)            
70530000 70afe000   ieframe    (pdb symbols)      
71260000 71462000   msi        (deferred)            
717c0000 717d2000   pnrpnsp    (deferred)            
71870000 71877000   wsock32    (deferred)            
718a0000 718a7000   msiltcfg   (pdb symbols)      
71920000 71973000   actxprxy   (deferred)            
71980000 7198c000   wshbth     (deferred)            
71990000 71998000   winrnr     (deferred)            
719e0000 71b06000   msxml3     (deferred)            
71b10000 71b1f000   NapiNSP    (deferred)            
71b20000 71b29000   linkinfo   (deferred)            
71c70000 71c76000   SensApi    (deferred)            
71d10000 71e56000   browseui   (deferred)            
71ee0000 71fe7000   shdocvw    (deferred)            
72100000 72109000   snmpapi    (deferred)            
72580000 725c2000   winspool   (deferred)            
725d0000 725d6000   rasadhlp   (deferred)            
72610000 72615000   sfc        (deferred)            
72620000 7262c000   dwmapi     (deferred)            
72640000 72676000   mfplat     (deferred)            
72850000 72857000   midimap    (deferred)            
72860000 72874000   msacm32_72860000   (deferred)            
72880000 72933000   WindowsCodecs   (deferred)            
72940000 729a6000   AudioEng   (deferred)            
729b0000 729d1000   AudioSes   (deferred)            
729e0000 72a0f000   wdmaud     (pdb symbols)      
72a50000 72a59000   msacm32    (deferred)            
72a60000 72a64000   ksuser     (deferred)            
72a70000 72aa2000   winmm      (pdb symbols)      
72b60000 72b6c000   imgutil    (deferred)            
72b80000 72b8d000   sfc_os     (deferred)            
72b90000 72bae000   shimeng    (deferred)            
72bb0000 72bb6000   dciman32   (deferred)            
72c60000 72c8f000   xmllite    (deferred)            
72c90000 72c9c000   rtutils    (deferred)            
72ed0000 72f66000   FWPUCLNT   (deferred)            
73080000 731ca000   msxml6     (deferred)            
731d0000 731d5000   msimg32    (deferred)            
73200000 73285000   comctl32   (pdb symbols)      
73290000 732ef000   winhttp    (deferred)            
73380000 733b9000   oleacc     (deferred)            
733c0000 733ff000   uxtheme    (deferred)            
73400000 73430000   duser      (deferred)            
73430000 735db000   GdiPlus    (deferred)            
738d0000 7398b000   propsys    (deferred)            
74460000 74474000   atl        (deferred)            
74580000 7471e000   comctl32_74580000   (pdb symbols)
74890000 748b7000   MMDevAPI   (deferred)            
74960000 74975000   cabinet    (deferred)            
74980000 749ad000   wintrust   (deferred)            
74a40000 74a4f000   nlaapi     (deferred)            
74a50000 74a5a000   wtsapi32   (deferred)            
74b10000 74b15000   WSHTCPIP   (deferred)            
74b20000 74b27000   avrt       (deferred)            
74b30000 74b4a000   powrprof   (deferred)            
74b50000 74b71000   ntmarta    (deferred)            
74bb0000 74beb000   rsaenh     (deferred)            
74c20000 74c64000   schannel   (deferred)            
74dd0000 74de5000   gpapi      (deferred)            
74ed0000 74f0b000   mswsock    (pdb symbols)         
74f10000 74f55000   bcrypt     (deferred)            
74f60000 74f95000   ncrypt     (deferred)            
74fb0000 74fd1000   dhcpcsvc6   (deferred)            
74fe0000 74fe7000   winnsi     (deferred)            
74ff0000 75025000   dhcpcsvc   (deferred)            
75030000 75049000   IPHLPAPI   (deferred)            
75050000 75090000   wevtapi    (deferred)            
75090000 750ca000   SLC        (deferred)            
750d0000 751c1000   crypt32    (deferred)            
75200000 75214000   mpr        (deferred)            
75260000 75265000   wship6     (deferred)            
75270000 75278000   version    (deferred)            
75280000 75287000   credssp    (deferred)            
752c0000 752d2000   msasn1     (deferred)            
752e0000 752f1000   samlib     (deferred)            
75300000 7532c000   dnsapi     (deferred)            
75360000 753d5000   netapi32   (deferred)            
755a0000 755ff000   sxs        (deferred)            
75660000 7568c000   apphelp    (deferred)            
756c0000 756d4000   secur32    (deferred)            
756e0000 756fe000   userenv    (deferred)            
75820000 75865000   iertutil   (deferred)            
75870000 76380000   shell32    (deferred)            
76380000 763ca000   Wldap32    (deferred)            
763d0000 76428000   shlwapi    (deferred)            
76430000 764b4000   clbcatq    (deferred)            
764c0000 76588000   msctf      (deferred)            
76590000 765b9000   imagehlp   (deferred)            
765c0000 76682000   rpcrt4     (pdb symbols)        
76690000 76760000   wininet    (pdb symbols)        
76760000 767ab000   gdi32      (deferred)            
767b0000 767dd000   ws2_32     (pdb symbols)        
767e0000 76924000   ole32      (pdb symbols)        
76930000 76aba000   setupapi   (deferred)            
76ac0000 76b33000   comdlg32   (deferred)            
76b40000 76bdd000   user32     (pdb symbols)        
76be0000 76cbb000   kernel32   (pdb symbols)    
76cc0000 76d3d000   usp10      (deferred)            
76d40000 76dea000   msvcrt     (pdb symbols)    
76df0000 76f19000   urlmon     (deferred)            
76f20000 76fad000   oleaut32   (deferred)            
76fb0000 770d7000   ntdll      (pdb symbols)    
770e0000 770e7000   psapi      (deferred)            
770f0000 770f9000   lpk        (deferred)            
77100000 7711e000   imm32      (deferred)            
77120000 77126000   nsi        (deferred)            
77130000 77133000   normaliz   (deferred)            
77140000 77206000   advapi32   (deferred)            
79000000 79046000   mscoree    (deferred)            
7c340000 7c396000   msvcr71    (deferred)            
7c3a0000 7c41b000   msvcp71    (deferred)

Actually, before I quit the debugger, I saved a secured stripped version of the dump file using this command: 

0:000> .dump /mrRFt c:\UserDumps\ie7_pattern_cooperation.dmp

The dump file is available on ftp:

ftp://dumpanalysis.org/pub/ie7_pattern_cooperation.zip

Thread times and stack traces are available in it together with module information. However heap data and critical section list was not included in it.

- Dmitry Vostokov @ DumpAnalysis.org -

Crash Dump Analysis Patterns (Part 13f)

Monday, January 5th, 2009

Sometimes there is not enough physical memory and the system experiences the so called disk or page file thrashing trying to resolve page faults. This can be seen in some memory dumps coming from frozen environments showing signs of double traps in running threads, the first one is a normal memory access fault (blue) and the other is forced NMI bugcheck to save a memory dump (red):

1: kd> .bugcheck
Bugcheck code 00000080
Arguments 004f4454 00000000 00000000 00000000

1: kd> !thread
THREAD 88939b20  Cid 360.378  Teb: 7ffdb000  Win32Thread: a20a7ac8 RUNNING
IRP List:
    86be9e68: (0006,0100) Flags: 00000070  Mdl: 00000000
    88939e68: (0006,0100) Flags: 00000070  Mdl: 00000000
    88939128: (0006,0100) Flags: 00000070  Mdl: 00000000
Not impersonating
Owning Process 889456e0
Wait Start TickCount    2357431       Elapsed Ticks: 9
Context Switch Count    18267                   LargeStack
UserTime                  0:00:08.0218
KernelTime                0:12:28.0109
Start Address KERNEL32!BaseThreadStartThunk (0x7c57b740)
Win32 Start Address msafd!SockAsyncThread (0x74fd3113)
Stack Init bef9e000 Current bef9db60 Base bef9e000 Limit bef9b000 Call 0
Priority 11 BasePriority 11 PriorityDecrement 0 DecrementCount 0

ChildEBP RetAddr
8904aff0 80469211 hal!HalHandleNMI+0×193
8904aff0 80438621 nt!KiTrap02+0×41

bef9dc10 8043799a nt!MiTrimWorkingSet+0xa7
bef9dc38 804378ec nt!MiDoReplacement+0×2e
bef9dc50 804453cf nt!MiLocateAndReserveWsle+0×1e
bef9dc68 804444e0 nt!MiAddValidPageToWorkingSet+0×89
bef9dc8c 804443a2 nt!MiCompleteProtoPteFault+0xf6
bef9dcb8 804436e8 nt!MiResolveProtoPteFault+0×160
bef9dcfc 8044ccd0 nt!MiDispatchFault+0xfc
bef9dd4c 8046b063 nt!MmAccessFault+0xd1c
bef9dd4c 74fd31e0 nt!KiTrap0E+0xc7

016effb4 7c57b3bc msafd!SockAsyncThread+0xcd
016effec 00000000 KERNEL32!BaseThreadStart+0×52

If we check virtual memory stats we see the low number of available pages:

1: kd> !vm

*** Virtual Memory Usage ***
 Physical Memory:   524165   ( 2096660 Kb)
 Page File: \??\C:\pagefile.sys
    Current:   4190208Kb Free Space:   3298704Kb
    Minimum:   4190208Kb Maximum:      4190208Kb
 Page File: \??\E:\pagefile.sys
    Current:   4190208Kb Free Space:   3339860Kb
    Minimum:   4190208Kb Maximum:      4190208Kb
 Available Pages:     1098   (    4392 Kb)
 ResAvail Pages:    410646   ( 1642584 Kb)
 Modified Pages:    282384   ( 1129536 Kb)
 NonPagedPool Usage: 10046   (   40184 Kb)
 NonPagedPool Max:   68609   (  274436 Kb)
 PagedPool 0 Usage:  15391   (   61564 Kb)
 PagedPool 1 Usage:   1906   (    7624 Kb)
 PagedPool 2 Usage:   1925   (    7700 Kb)
 PagedPool 3 Usage:   1937   (    7748 Kb)
 PagedPool 4 Usage:   1892   (    7568 Kb)
 PagedPool Usage:    23051   (   92204 Kb)
 PagedPool Maximum:  87040   (  348160 Kb)
 Shared Commit:      16867   (   67468 Kb)
 Special Pool:           0   (       0 Kb)
 Free System PTEs:   65288   (  261152 Kb)
 Shared Process:     38655   (  154620 Kb)
 PagedPool Commit:   23051   (   92204 Kb)
 Driver Commit:       1060   (    4240 Kb)
 Committed pages:  1049592   ( 4198368 Kb)
 Commit limit:     2580155   (10320620 Kb)
[…]

In W2K dumps we can also see locking on a working set resource (I guess the name from Ws shortcut here):

 1: kd> !locks
**** DUMP OF ALL RESOURCE OBJECTS ****

Resource @ nt!MmSystemWsLock (0×804869c0)    Exclusively owned
    Contention Count = 33083
    NumberOfExclusiveWaiters = 237
[…]

and huge number of threads in Ready state for every thread priority.

Looking at the current process owning the running thread shows the large number of page faults and increased kernel CPU time compared to time spent in user mode:

1: kd> !process 889456e0
PROCESS 889456e0  SessionId: 0  Cid: 0360    Peb: 7ffdf000  ParentCid: 01a8
    DirBase: 102af000  ObjectTable: 88945c08  TableSize: 622.
    Image: Application.EXE
    VadRoot 88944468 Clone 0 Private 838. Modified 30691412. Locked 188.
    DeviceMap 89049288
    Token                             e28db550
    ElapsedTime                       10:13:30.0684
    UserTime                          0:00:12.0578
    KernelTime                        0:12:38.0625
    QuotaPoolUsage[PagedPool]         31568
    QuotaPoolUsage[NonPagedPool]      68266
    Working Set Sizes (now,min,max)  (49, 50, 345) (196KB, 200KB, 1380KB)
    PeakWorkingSetSize                1956
    VirtualSize                       131 Mb
    PeakVirtualSize                   131 Mb
    PageFaultCount                    46180598
    MemoryPriority                    BACKGROUND
    BasePriority                      10
    CommitCharge                      1247

- Dmitry Vostokov @ DumpAnalysis.org -

Insufficient memory, handle leak, wait chain, deadlock, inconsistent dump and overaged system: pattern cooperation

Wednesday, December 24th, 2008

In one complete memory dump taken from the system refusing user connections but not hung completely we can see the signs of past pool allocation failures (see Insufficient Memory):

0: kd> !vm
[...]
       PagedPool Usage:       47391 (    189564 Kb)
       PagedPool Maximum:     67584 (    270336 Kb)

       ********** 981 pool allocations have failed **********
[…]

We check paged pool usage but the output is inconsistent (shown in magenta color):

0: kd> !poolused 4
   Sorting by  Paged Pool Consumed

  Pool Used:
            NonPaged            Paged
 Tag    Allocs     Used    Allocs     Used
 LSmi        0        0        -1 4294967240 BlockTypeMisc
 PpEE        0        0        -1 4294967040 PNP_DEVICE_EVENT_ENTRY_TAG , Binary: nt!pnp
 CM         58     2320        -1 4294967000 Configuration Manager (registry) , Binary: nt!cm
 SeSc        0        0       -65 4294966112 Captured Security Descriptor , Binary: nt!se
 RxMs        1     1096       -99 4294947312 misc.
 CM38        0        0        -2 4294942720 Internal Configuration manager allocations , Binary: nt!cm
 RxFc        0        0        -8 4294879664 FCB
 Lfs         0        0      -907 4294872976 Lfs allocations
 xSMB        0        0      -179 4293500928 IFSKIT sample SMB mini-redirector , Binary: smbmrx.sys

 AAAA        4      224       581 51639048 UNKNOWN pooltag ‘AAAA’, please update pooltag.txt
 BBBB        2    65664      2582 16362984 UNKNOWN pooltag ‘BBBB’, please update pooltag.txt

 MmSt        0        0     10718 14944776 Mm section object prototype ptes , Binary: nt!mm
[…]

However we see that drivers using AAAA and BBBB consumed almost 65Mb and we can search for them as described here.

Dumping processes we notice signs of possible handle leak:

0: kd> !process 0 0
[...]
PROCESS 89ac09c0  SessionId: 0  Cid: 04b0    Peb: 7ffd5000  ParentCid: 0480
    DirBase: cc210000  ObjectTable: e13991a0  HandleCount: 3329.
    Image: csrss.exe

PROCESS 89ae4508  SessionId: 0  Cid: 07a8    Peb: 7ffdf000  ParentCid: 04f4
    DirBase: cb330000  ObjectTable: e115c220  HandleCount: 4476.
    Image: svchost.exe

PROCESS 868d1d88  SessionId: 0  Cid: 4120    Peb: 7ffd8000  ParentCid: 04f4
    DirBase: 95558000  ObjectTable: e1135428  HandleCount: 2255.
    Image: AppC.exe
[…]

We see lots of threads in the process 89ae4508 waiting for LPC reply:

0: kd> !thread 86b64388 1f
THREAD 86b64388  Cid 07a8.0fbc  Teb: 7ff73000 Win32Thread: bc173ac0 WAIT: (Unknown) UserMode Non-Alertable
    86b64574  Semaphore Limit 0x1
Waiting for reply to LPC MessageId 06345018:
Current LPC port e169dd90
Impersonation token:  e492a6c0 (Level Impersonation)
DeviceMap                 e1603ce8
Owning Process            89ae4508       Image:         svchost.exe
Wait Start TickCount      148053822      Ticks: 23982406 (4:08:05:25.093)
Context Switch Count      11                 LargeStack
UserTime                  00:00:00.000
KernelTime                00:00:00.000
Win32 Start Address DllA!ThreadEntry (0×752e27fe)
Start Address kernel32!BaseThreadStartThunk (0×77e6b5f3)
Stack Init 901e5000 Current 901e4c08 Base 901e5000 Limit 901e2000 Call 0
Priority 10 BasePriority 8 PriorityDecrement 0
Kernel stack not resident.

Now we follow LPC wait chain:

0: kd> !lpc message 06345018
Searching message 6345018 in threads ...
Client thread 86b64388 waiting a reply from 6345018                         
    Server thread 87f0d790 is working on message 6345018
[…]

0: kd> !thread 87f0d790 1f
THREAD 87f0d790  Cid 0de4.5b2c  Teb: 7ff8f000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable
    87f0d97c  Semaphore Limit 0x1
Waiting for reply to LPC MessageId 0634501d:
Current LPC port eb2e6450
Impersonation token:  e93ff870 (Level Impersonation)
DeviceMap                 e1603ce8
Owning Process            89c36690       Image:         AppA.exe
Wait Start TickCount      113650910      Ticks: 58385318 (10:13:24:30.593)
Context Switch Count      373            
UserTime                  00:00:00.015
KernelTime                00:00:00.000
Win32 Start Address 0×06345018
LPC Server thread working on message Id 6345018
Start Address kernel32!BaseThreadStartThunk (0×77e6b5f3)
Stack Init 8b0e6000 Current 8b0e5c08 Base 8b0e6000 Limit 8b0e3000 Call 0
Priority 11 BasePriority 8 PriorityDecrement 0
Kernel stack not resident.

0: kd> !lpc message 0634501d
Searching message 634501d in threads ...
Client thread 87f0d790 waiting a reply from 634501d                         
    Server thread 89137780 is working on message 634501d
[…]

0: kd> !thread 89137780 1f
THREAD 89137780  Cid 1884.41f8  Teb: 7ff90000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable
    8913796c  Semaphore Limit 0x1
Waiting for reply to LPC MessageId 064aa11b:
Current LPC port ea3fc860
Impersonation token:  e93ff870 (Level Impersonation)
DeviceMap                 e1603ce8
Owning Process            8a608020       Image:         AppB.exe
Wait Start TickCount      148002015      Ticks: 24034213 (4:08:18:54.578)
Context Switch Count      700            
UserTime                  00:00:00.015
KernelTime                00:00:00.000
Win32 Start Address 0×0634501d
LPC Server thread working on message Id 634501d
Start Address kernel32!BaseThreadStartThunk (0×77e6b5f3)
Stack Init 8b749000 Current 8b748c08 Base 8b749000 Limit 8b746000 Call 0
Priority 10 BasePriority 8 PriorityDecrement 0
Kernel stack not resident.

0: kd> !lpc message 064aa11b
Searching message 64aa11b in threads ...
Client thread 89137780 waiting a reply from 64aa11b                         
    Server thread 87acb728 is working on message 64aa11b
[…]

0: kd> !thread 87acb728 1f
THREAD 87acb728  Cid 4120.4078  Teb: 7ff3f000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable
    87acb914  Semaphore Limit 0x1
Waiting for reply to LPC MessageId 064aa127:
Current LPC port e7ec63f0
Not impersonating
DeviceMap                 e1003910
Owning Process            868d1d88       Image:         AppC.exe
Wait Start TickCount      147996856      Ticks: 24039372 (4:08:20:15.187)
Context Switch Count      440            
UserTime                  00:00:00.812
KernelTime                00:00:00.015
Win32 Start Address 0×064aa11b
LPC Server thread working on message Id 64aa11b
Start Address kernel32!BaseThreadStartThunk (0×77e6b5f3)
Stack Init 8ba35000 Current 8ba34c08 Base 8ba35000 Limit 8ba32000 Call 0
Priority 13 BasePriority 8 PriorityDecrement 0
Kernel stack not resident.

0: kd> !lpc message 064aa127
Searching message 64aa127 in threads ...
    Server thread 899e1750 is working on message 64aa127
Client thread 87acb728 waiting a reply from 64aa127                         
[…]

0: kd> !thread 899e1750 1f
THREAD 899e1750  Cid 0a0c.6cfc  Teb: 7ff16000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable
    89293390  Mutant - owning thread 89a9dc38
Not impersonating
DeviceMap                 e1003910
Owning Process            892b8a38       Image:         svchost.exe
Wait Start TickCount      148115996      Ticks: 23920232 (4:07:49:13.625)
Context Switch Count      166            
UserTime                  00:00:00.000
KernelTime                00:00:00.000
Win32 Start Address 0×064aa127
LPC Server thread working on message Id 64aa127
Start Address kernel32!BaseThreadStartThunk (0×77e6b5f3)
Stack Init 8c7b1000 Current 8c7b0c60 Base 8c7b1000 Limit 8c7ae000 Call 0
Priority 13 BasePriority 8 PriorityDecrement 0
Kernel stack not resident.

We finally come to a thread waiting for a mutant and we inspect its owner:

0: kd> !thread 89a9dc38 1f
THREAD 89a9dc38  Cid 0a0c.185c  Teb: 7ff8d000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable
    89a9de24  Semaphore Limit 0x1
Waiting for reply to LPC MessageId 064a90f1:
Current LPC port e15992a8
Not impersonating
DeviceMap                 e1003910
Owning Process            892b8a38       Image:         svchost.exe
Wait Start TickCount      148115996      Ticks: 23920232 (4:07:49:13.625)
Context Switch Count      29043            
UserTime                  00:00:01.046
KernelTime                00:00:00.968
Win32 Start Address 0×064a8fb6
LPC Server thread working on message Id 64a8fb6
Start Address kernel32!BaseThreadStartThunk (0×77e6b5f3)
Stack Init 92201000 Current 92200c08 Base 92201000 Limit 921fe000 Call 0
Priority 10 BasePriority 8 PriorityDecrement 0
Kernel stack not resident.

We see it is waiting for an LPC reply from the thread waiting for the mutant we already saw:

0: kd> !lpc message 064a90f1
Searching message 64a90f1 in threads ...
Client thread 89a9dc38 waiting a reply from 64a90f1                      
    Server thread 88806a28 is working on message 64a90f1
[…]

0: kd> !thread 88806a28 1f
THREAD 88806a28  Cid 0a0c.10b8  Teb: 7ff82000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable
    89293390  Mutant - owning thread 89a9dc38
Not impersonating
DeviceMap                 e1003910
Owning Process            892b8a38       Image:         svchost.exe
Wait Start TickCount      148115996      Ticks: 23920232 (4:07:49:13.625)
Context Switch Count      532            
UserTime                  00:00:00.000
KernelTime                00:00:00.015
Win32 Start Address 0×064a90f1
LPC Server thread working on message Id 64a90f1
Start Address kernel32!BaseThreadStartThunk (0×77e6b5f3)
Stack Init 94ef3000 Current 94ef2c60 Base 94ef3000 Limit 94ef0000 Call 0
Priority 10 BasePriority 8 PriorityDecrement 0
Kernel stack not resident.

We have

… -> Thread(899e1750) -> Mutant(89293390) Thread(89a9dc38) -> LPC(064a90f1) Thread(88806a28) -> Mutant(89293390) Thread(89a9dc38)

This looks like a deadlock although we cannot examine stack traces which are not resident (stack data resides in a page file).

We also notice the system uptime which might suggest that all these abnormalities had been gradually accumulated (see Overaged System):

0: kd> version
[…]
System Uptime: 61 days 3:40:01.122
[…]

- Dmitry Vostokov @ DumpAnalysis.org -

WinDbg In Use: Debugging Exercises

Wednesday, December 24th, 2008

The analogy between learning a complex tool with its own language and a foreign natural language has been developed further after the release of WinDbg Learning Cards and finally culminated in “WinDbg In Use” book series with the first book to be published during the 1st quarter of 2009:

  • Title: WinDbg In Use: Debugging Exercises (Elementary and Intermediate Level)
  • Author: Dmitry Vostokov
  • Publisher: Opentask (15 March 2009)
  • Language: English
  • Product Dimensions: 23.5 x 19.1
  • ISBN-13: 978-1-906717-50-6
  • Paperback: 200 pages
  • Book Annotation: Includes 60 programmed exercises from real life debugging and crash dump analysis scenarios and multiple-choice questions with full answers, comments and suggestions for further reading.

Some example exercises will be published on this blog from time to time. I also plan a corresponding column in the forthcoming Debugged! magazine. 

- Dmitry Vostokov @ DumpAnalysis.org -

Visual Learning Guide to Stack Traces

Tuesday, December 23rd, 2008

The following book is planned for publication during the 1st quarter of 2009:

Title: Reference Stack Traces: Windows Server® 2008 and Windows Vista™
ISBN-13: 978-1-906717-23-0

It features visual separation between kernel and user space in thread stack traces and useful footnotes for IRP and modules. Its publishing was delayed by a few months but fortunately my editing just got new breath by introducing thread stackprint images for kernel stacks (12Kb bitmaps):

Sample pages 13 and 96

Thread stackprints were generated from a complete memory dump using WinDbg scripts and Dump2Picture.

- Dmitry Vostokov @ DumpAnalysis.org -

Blocked GUI thread, wait chain and virtualized process: pattern cooperation

Friday, December 19th, 2008

In one system even Task Manager was hanging and forced complete memory dump reveals a blocked GUI dialog thread waiting for an LPC reply:

THREAD fffffade69e36310  Cid 4b30.4f34  Teb: 000007fffffde000 Win32Thread: fffff97ff3f97620 WAIT: (Unknown) UserMode Non-Alertable
    fffffade69e36678  Semaphore Limit 0x1
Waiting for reply to LPC MessageId a7531ec4:
Current LPC port fffffa8007118190
Not impersonating
DeviceMap                 fffffa80021c6240
Owning Process            fffffadee0332040       Image:         taskmgr.exe
Wait Start TickCount      80209499       Ticks: 5596 (0:00:01:27.437)
Context Switch Count      173                 LargeStack
UserTime                  00:00:00.000
KernelTime                00:00:00.031
Win32 Start Address taskmgr!wWinMainCRTStartup (0×000000010001bfe0)
Start Address kernel32!BaseProcessStart (0×0000000077d59620)
Stack Init fffffad7c6e5ae00 Current fffffad7c6e5a8e0
Base fffffad7c6e5b000 Limit fffffad7c6e52000 Call 0
Priority 14 BasePriority 13 PriorityDecrement 0
Child-SP          RetAddr           Call Site
fffffad7`c6e5a920 fffff800`01027752 nt!KiSwapContext+0×85
fffffad7`c6e5aaa0 fffff800`0102835e nt!KiSwapThread+0×3c9
fffffad7`c6e5ab00 fffff800`01283ebb nt!KeWaitForSingleObject+0×5a6
fffffad7`c6e5ab80 fffff800`0102e3fd nt!NtRequestWaitReplyPort+0xa60
fffffad7`c6e5ac70 00000000`77ef0c0a nt!KiSystemServiceCopyEnd+0×3 (TrapFrame @ fffffad7`c6e5ac70)
00000000`000adef8 000007ff`7fd6df46 ntdll!ZwRequestWaitReplyPort+0xa
00000000`000adf00 000007ff`7fd6e17f RPCRT4!LRPC_CCALL::SendReceive+0×447
00000000`000adfe0 000007ff`7fe974c8 RPCRT4!NdrSendReceive+0xf6
00000000`000ae010 000007ff`7fe975bd RPCRT4!NdrpClientCall2+0×7e2
00000000`000ae5f0 000007ff`7d4d8a0d RPCRT4!NdrClientCall2+0×1d
00000000`000ae620 00000001`00011029 WINSTA!WinStationGetProcessSid+0xfd
00000000`000ae6a0 00000001`00010e3b taskmgr!CProcInfo::SetProcessUsername+0×189
00000000`000ae930 00000001`000118e9 taskmgr!CProcInfo::SetData+0×53b
00000000`000aebb0 00000001`000122f4 taskmgr!CProcPage::UpdateProcInfoArray+0×449
00000000`000aee70 00000001`00013eab taskmgr!CProcPage::TimerEvent+0×14
00000000`000aeea0 00000001`00004e8f taskmgr!CProcPage::Initialize+0×29b
00000000`000af320 00000001`000070e8 taskmgr!MainWnd_OnInitDialog+0×2ff
00000000`000af620 00000000`77c34582 taskmgr!MainWindowProc+0×3f8
00000000`000af680 00000000`77c34bf2 USER32!UserCallDlgProcCheckWow+0×210
00000000`000af760 00000000`77c2ff5f USER32!DefDlgProcWorker+0xf6
00000000`000af7f0 00000000`77c29beb USER32!InternalCreateDialog+0×16a7
00000000`000af980 00000001`00007c97 USER32!CreateDialogParamW+0xab
00000000`000afa00 00000001`0001c24b taskmgr!wWinMain+0×5f7
00000000`000afed0 00000000`77d5964c taskmgr!wWinMainCRTStartup+0×26b
00000000`000aff80 00000000`00000000 kernel32!BaseProcessStart+0×29

We search for that LPC message:

6: kd> !lpc message a7531ec4
Searching message a7531ec4 in threads ...
    Server thread fffffade6b8cf7a0 is working on message a7531ec4
Client thread fffffade69e36310 waiting a reply from a7531ec4                         
[…]

and then examine the corresponding server thread (for visual clarity only 1 argument is shown for each function call):

6: kd> !thread fffffade6b8cf7a0 16
THREAD fffffade6b8cf7a0  Cid 0238.8ff4  Teb: 000007fffff48000 Win32Thread: 0000000000000000 WAIT: (Unknown) UserMode Non-Alertable
    fffffade6f2e93c0  SynchronizationEvent
Impersonation token:  fffffa8013a17700 (Level Impersonation)
DeviceMap                 fffffa80021c6240
Owning Process            fffffade6f337040       Image:         svchost.exe
Wait Start TickCount      80209499       Ticks: 5596 (0:00:01:27.437)
Context Switch Count      40138            
UserTime                  00:00:00.140
KernelTime                00:00:00.312
Win32 Start Address 0×00000000a7531ec4
LPC Server thread working on message Id a7531ec4
Start Address kernel32!BaseThreadStart (0×0000000077d6b6a0)
Stack Init fffffad867f5ae00 Current fffffad867f5a950
Base fffffad867f5b000 Limit fffffad867f55000 Call 0
Priority 13 BasePriority 8 PriorityDecrement 0
Child-SP          RetAddr           : Args to Child     : Call Site
fffffad8`67f5a990 fffff800`01027752 : fffffa80`071181f0 : nt!KiSwapContext+0×85
fffffad8`67f5ab10 fffff800`0102835e : 00000000`00000000 : nt!KiSwapThread+0×3c9
fffffad8`67f5ab70 fffff800`0127f03f : 00000000`00000000 : nt!KeWaitForSingleObject+0×5a6
fffffad8`67f5abf0 fffff800`0102e3fd : fffffade`6b8cf7a0 : nt!NtWaitForSingleObject+0xc1
fffffad8`67f5ac70 00000000`77ef0a2a : 00000000`77efb9a6 : nt!KiSystemServiceCopyEnd+0×3 (TrapFrame @ fffffad8`67f5ac70)
00000000`04d0f098 00000000`77efb9a6 : 00000000`00000000 : ntdll!NtWaitForSingleObject+0xa
00000000`04d0f0a0 00000000`77efba10 : 000007ff`7b8c3500 : ntdll!RtlpWaitOnCriticalSection+0×240
00000000`04d0f120 000007ff`7b887042 : 00000000`04d0f300 : ntdll!RtlEnterCriticalSection+0xa9
[…]
00000000`04d0f190 000007ff`7fe96cc9 : 00000000`00000048 : RPCRT4!Invoke+0×65
00000000`04d0f210 000007ff`7fe9758d : 00000000`04d0f8f0 : RPCRT4!NdrStubCall2+0×54d
00000000`04d0f7d0 000007ff`7fd697b4 : 00000000`0450a8fd : RPCRT4!NdrServerCall2+0×1d
00000000`04d0f800 000007ff`7fd6990d : 00000000`00377aa0 : RPCRT4!DispatchToStubInCNoAvrf+0×14
00000000`04d0f830 000007ff`7fd69766 : 00000000`00000001 : RPCRT4!RPC_INTERFACE::DispatchToStubWorker+0×50d
00000000`04d0f9a0 000007ff`7fd6b214 : 00000000`06c18ba0 : RPCRT4!RPC_INTERFACE::DispatchToStub+0×2ec
00000000`04d0fa20 000007ff`7fd6b9e3 : 00000000`06c18ba0 : RPCRT4!LRPC_SCALL::DealWithRequestMessage+0×63b
00000000`04d0fae0 000007ff`7fd7007c : 00000000`048348a0 : RPCRT4!LRPC_ADDRESS::DealWithLRPCRequest+0×3bf
00000000`04d0fba0 000007ff`7fd45369 : 00000000`0525fd30 : RPCRT4!LRPC_ADDRESS::ReceiveLotsaCalls+0×710
00000000`04d0feb0 000007ff`7fd65996 : 00000000`00000000 : RPCRT4!RecvLotsaCallsWrapper+0×9
00000000`04d0fee0 000007ff`7fd65d51 : 00000000`0492de90 : RPCRT4!BaseCachedThreadRoutine+0xde
00000000`04d0ff50 00000000`77d6b6da : 00000000`77d6b6a0 : RPCRT4!ThreadStartRoutine+0×21
00000000`04d0ff80 00000000`00000000 : 00000000`00000000 : kernel32!BaseThreadStart+0×3a 

We see the thread above is waiting for a critical section and we examine it using !cs WinDbg extension command after switching to the process context of that thread:

6: kd> .process /r /p fffffade6f337040
Implicit process is now fffffade`6f337040
Loading User Symbols

6: kd> !cs 000007ff`7b8c3500
Critical section   = 0×000007ff7b8c3500 (DllA!Lock+0×0)
DebugInfo          = 0×00000000000ffea0
LOCKED
LockCount          = 0×8
WaiterWoken        = No
OwningThread       = 0×0000000000004100
RecursionCount     = 0×1
LockSemaphore      = 0×8E0
SpinCount          = 0×0000000000000000 

From the output we know the critical section owner thread and examine it too (function call arguments are not shown for visual clarity):

6: kd> !thread -t 4100 16
Looking for thread Cid = 4100 …
THREAD fffffade6b9df4f0  Cid 0238.4100  Teb: 000007fffff58000 Win32Thread: 0000000000000000 WAIT: (Unknown) UserMode Non-Alertable
    fffffadff5edadc0  Mutant - owning thread fffffadfe2486bf0
Impersonation token:  fffffa8010197250 (Level Impersonation)
Owning Process            fffffade6f337040       Image:         svchost.exe
Wait Start TickCount      79672315       Ticks: 542780 (0:02:21:20.937)
Context Switch Count      174            
UserTime                  00:00:00.000
KernelTime                00:00:00.000
Win32 Start Address 0×00000000a75007ac
LPC Server thread working on message Id a75007ac
Start Address kernel32!BaseThreadStart (0×0000000077d6b6a0)
Stack Init fffffad83a94ee00 Current fffffad83a94e950
Base fffffad83a94f000 Limit fffffad83a949000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0
Kernel stack not resident.
Child-SP          RetAddr           : Call Site
fffffad8`3a94e990 fffff800`01027752 : nt!KiSwapContext+0×85
fffffad8`3a94eb10 fffff800`0102835e : nt!KiSwapThread+0×3c9
fffffad8`3a94eb70 fffff800`0127f03f : nt!KeWaitForSingleObject+0×5a6
fffffad8`3a94ebf0 fffff800`0102e3fd : nt!NtWaitForSingleObject+0xc1
fffffad8`3a94ec70 00000000`77ef0a2a : nt!KiSystemServiceCopyEnd+0×3 (TrapFrame @ fffffad8`3a94ec70)
00000000`03c8efa8 000007ff`7b880427 : ntdll!NtWaitForSingleObject+0xa
[…]
00000000`03c8f1a0 000007ff`7fe96cc9 : RPCRT4!Invoke+0×65
00000000`03c8f210 000007ff`7fe9758d : RPCRT4!NdrStubCall2+0×54d
00000000`03c8f7d0 000007ff`7fd697b4 : RPCRT4!NdrServerCall2+0×1d
00000000`03c8f800 000007ff`7fd6990d : RPCRT4!DispatchToStubInCNoAvrf+0×14
00000000`03c8f830 000007ff`7fd69766 : RPCRT4!RPC_INTERFACE::DispatchToStubWorker+0×50d
00000000`03c8f9a0 000007ff`7fd6b214 : RPCRT4!RPC_INTERFACE::DispatchToStub+0×2ec
00000000`03c8fa20 000007ff`7fd6b9e3 : RPCRT4!LRPC_SCALL::DealWithRequestMessage+0×63b
00000000`03c8fae0 000007ff`7fd7007c : RPCRT4!LRPC_ADDRESS::DealWithLRPCRequest+0×3bf
00000000`03c8fba0 000007ff`7fd45369 : RPCRT4!LRPC_ADDRESS::ReceiveLotsaCalls+0×710
00000000`03c8feb0 000007ff`7fd65996 : RPCRT4!RecvLotsaCallsWrapper+0×9
00000000`03c8fee0 000007ff`7fd65d51 : RPCRT4!BaseCachedThreadRoutine+0xde
00000000`03c8ff50 00000000`77d6b6da : RPCRT4!ThreadStartRoutine+0×21
00000000`03c8ff80 00000000`00000000 : kernel32!BaseThreadStart+0×3a

We see that it is waiting for a mutant and examine its owner thread:

6: kd> !thread fffffadfe2486bf0 16
THREAD fffffadfe2486bf0  Cid 0238.7010  Teb: 000007fffff5e000 Win32Thread: 0000000000000000 WAIT: (Unknown) UserMode Non-Alertable
    fffffadfe2486f58  Semaphore Limit 0x1
Waiting for reply to LPC MessageId a7507485:
Current LPC port fffffa8006822c80
Not impersonating
DeviceMap                 fffffa8000003790
Owning Process            fffffade6f337040       Image:         svchost.exe
Wait Start TickCount      79744596       Ticks: 470499 (0:02:02:31.546)
Context Switch Count      29636            
UserTime                  00:00:00.062
KernelTime                00:00:00.156
Win32 Start Address 0×00000000a74ff6e4
LPC Server thread working on message Id a74ff6e4
Start Address kernel32!BaseThreadStart (0×0000000077d6b6a0)
Stack Init fffffad7d98a0e00 Current fffffad7d98a08e0
Base fffffad7d98a1000 Limit fffffad7d989b000 Call 0
Priority 13 BasePriority 8 PriorityDecrement 0
Kernel stack not resident.
Child-SP          RetAddr           : Call Site
fffffad7`d98a0920 fffff800`01027752 : nt!KiSwapContext+0×85
fffffad7`d98a0aa0 fffff800`0102835e : nt!KiSwapThread+0×3c9
fffffad7`d98a0b00 fffff800`01283ebb : nt!KeWaitForSingleObject+0×5a6
fffffad7`d98a0b80 fffff800`0102e3fd : nt!NtRequestWaitReplyPort+0xa60
fffffad7`d98a0c70 00000000`77ef0c0a : nt!KiSystemServiceCopyEnd+0×3 (TrapFrame @ fffffad7`d98a0c70)
00000000`0430dc18 000007ff`7fd6df46 : ntdll!ZwRequestWaitReplyPort+0xa
00000000`0430dc20 000007ff`7fd6e17f : RPCRT4!LRPC_CCALL::SendReceive+0×447
00000000`0430dd10 000007ff`7fe974c8 : RPCRT4!NdrSendReceive+0xf6
00000000`0430dd40 000007ff`7fe975bd : RPCRT4!NdrpClientCall2+0×7e2
00000000`0430e320 00000000`676b1dd7 : RPCRT4!NdrClientCall2+0×1d
[…]

The thread above is waiting for an LPC message and we examine its corresponding server thread:

6: kd> !lpc message a7507485
Searching message a7507485 in threads ...
Client thread fffffadfe2486bf0 waiting a reply from a7507485                         
    Server thread fffffade6f3c9720 is working on message a7507485                        
[...]

6: kd> !thread fffffade6f3c9720 16
THREAD fffffade6f3c9720  Cid 6308.a1c8  Teb: 000000007ef24000 Win32Thread: 0000000000000000 WAIT: (Unknown) UserMode Non-Alertable
    fffffade68d31a40  SynchronizationEvent
Not impersonating
DeviceMap                 fffffa80016ce1b0
Owning Process            fffffade69c29430       Image:         AppA.exe
Wait Start TickCount      79744596       Ticks: 470499 (0:02:02:31.546)
Context Switch Count      7230            
UserTime                  00:00:00.218
KernelTime                00:00:00.109
Win32 Start Address 0×00000000a7507485
LPC Server thread working on message Id a7507485
Start Address kernel32!BaseThreadStartThunk (0×000000007d4d1504)
Stack Init fffffad83f7e4e00 Current fffffad83f7e4950
Base fffffad83f7e5000 Limit fffffad83f7df000 Call 0
Priority 9 BasePriority 8 PriorityDecrement 0
Kernel stack not resident.
Child-SP          RetAddr           : Call Site
fffffad8`3f7e4990 fffff800`01027752 : nt!KiSwapContext+0×85
fffffad8`3f7e4b10 fffff800`0102835e : nt!KiSwapThread+0×3c9
fffffad8`3f7e4b70 fffff800`0127f03f : nt!KeWaitForSingleObject+0×5a6
fffffad8`3f7e4bf0 fffff800`0102e3fd : nt!NtWaitForSingleObject+0xc1
fffffad8`3f7e4c70 00000000`78b842d9 : nt!KiSystemServiceCopyEnd+0×3 (TrapFrame @ fffffad8`3f7e4c70)
00000000`0257f108 00000000`78b840e5 : wow64cpu!CpupSyscallStub+0×9
00000000`0257f110 00000000`6b006a5a : wow64cpu!Thunk0ArgReloadState+0×1a
00000000`0257f180 00000000`6b005e0d : wow64!RunCpuSimulation+0xa
00000000`0257f1b0 00000000`77f109f0 : wow64!Wow64LdrpInitialize+0×2ed

00000000`0257f6f0 00000000`77ef30a5 : ntdll!LdrpInitialize+0×2aa
00000000`0257f7d0 00000000`7d4d1504 : ntdll!KiUserApcDispatcher+0×15 (TrapFrame @ 00000000`0257fb38)
00000000`0257fcc8 00000000`00000000 : kernel32!BaseThreadStartThunk

We see the thread belongs to a virtualized WOW64 process and presently I’m not aware of how to get its 32-bit stacks from complete memory dumps. WOW64 extensions seems only working in process user dumps. Therefore I recommended to get a userdump of AppA process using 32-bit version of userdump.exe as soon as the same condition starts surfacing again.

- Dmitry Vostokov @ DumpAnalysis.org -

Crash Dump Analysis Patterns (Part 42e)

Wednesday, December 17th, 2008

Now its time to write about wait chains involving LPC calls. These chains are easily identified by searching for “Waiting for reply to LPC MessageId” in the output of !process 0 ff command or if we know that some specific process is hanging and see that message in its thread information output. For example, in one kernel memory dump taken when AppA was hanging we see this example of Blocked Thread pattern:

7: kd> !process 88556778  ff
PROCESS 88556778  SessionId: 0  Cid: 1f88    Peb: 7ffdc000  ParentCid: 0f74
DirBase: 96460000  ObjectTable: e65a5348  HandleCount:  80.
Image: AppA.exe
VadRoot 870d2208 Vads 54 Clone 0 Private 234. Modified 0. Locked 0.
DeviceMap e22ba7c0
Token                             e5e47cf0
ElapsedTime                       00:04:44.017
UserTime                          00:00:00.000
KernelTime                        00:00:00.000
QuotaPoolUsage[PagedPool]         20092
QuotaPoolUsage[NonPagedPool]      2160
Working Set Sizes (now,min,max)  (748, 50, 345) (2992KB, 200KB, 1380KB)
PeakWorkingSetSize                748
VirtualSize                       16 Mb
PeakVirtualSize                   16 Mb
PageFaultCount                    810
MemoryPriority                    BACKGROUND
BasePriority                      8
CommitCharge                      252

    PEB NULL...                       

THREAD 8861aab8  Cid 1f88.1bd4  Teb: 7ffdf000 Win32Thread: bc161ea8 WAIT: (Unknown) UserMode Non-Alertable
    8861aca4  Semaphore Limit 0x1
Waiting for reply to LPC MessageId 00037bb2:
Current LPC port e625bbd0
Not impersonating
DeviceMap                 e22ba7c0
Owning Process            88556778       Image:         AppA.exe
Wait Start TickCount      426549         Ticks: 18176 (0:00:04:44.000)
Context Switch Count      76                 LargeStack
UserTime                  00:00:00.000
KernelTime                00:00:00.000
Win32 Start Address 0×010043ab
Start Address 0×77e617f8
Stack Init bab4b000 Current bab4ac08 Base bab4b000 Limit bab47000 Call 0
Priority 11 BasePriority 8 PriorityDecrement 2
Kernel stack not resident.
ChildEBP RetAddr 
bab4ac20 8083d5b1 nt!KiSwapContext+0×26
bab4ac4c 8083df9e nt!KiSwapThread+0×2e5
bab4ac94 8093eda1 nt!KeWaitForSingleObject+0×346
bab4ad50 80833bef nt!NtRequestWaitReplyPort+0×776
bab4ad50 7c8285ec nt!KiFastCallEntry+0xfc

Now we look for a server thread processing the message 00037bb2:

7: kd> !lpc message 00037bb2
Searching message 37bb2 in threads ...
    Server thread 89815db0 is working on message 37bb2
Client thread 8861aab8 waiting a reply from 37bb2                         
Searching thread 8861aab8 in port rundown queues …

Server communication port 0xe1216be8
    Handles: 1   References: 1
    The LpcDataInfoChainHead queue is empty
        Connected port: 0xe625bbd0      Server connection port: 0xe1323f68

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

Server connection port e1323f68  Name: ApiABC
    Handles: 1   References: 43
    Server process  : 887d32d0 (svchost.exe)
    Queue semaphore : 884df210
    Semaphore state 0 (0x0)
    The message queue is empty

    Messages in LpcDataInfoChainHead:
        0000 e6067418 - Busy  Id=00020695  From: 0224.134c  Context=80050003  [e1323fe8 . e65fa5a8]
                   Length=0044002c  Type=00380001 (LPC_REQUEST)
                   Data: 00000001 00050242 00000000 00000000 00000000 00000000
        0000 e65fa5a8 - Busy  Id=0002e1dd  From: 0fd8.0fe0  Context=80110002  [e6067418 . e5f6a360]
                   Length=0044002c  Type=00380001 (LPC_REQUEST)
                   Data: 00000001 00050242 c03007fc c01fff7c 00000000 80a84456
        0000 e5f6a360 - Busy  Id=00037bb2  From: 1f88.1bd4  Context=8017000f  [e65fa5a8 . e1323fe8]
                   Length=0044002c  Type=00380001 (LPC_REQUEST)
                   Data: 00000001 00050242 88572278 88572290 8a386990 000015e7
    The LpcDataInfoChainHead queue contains 3 messages
    Threads in RunDown queue :     0xe6067258    0xe65fa3e8    0xe5f6a1a0
Done.           

7: kd> !thread  89815db0
THREAD 89815db0  Cid 1218.0c00  Teb: 7ff8f000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable
    88603e40  Mutant - owning thread 884d7db0
Not impersonating
DeviceMap                 e10018b8
Owning Process            887d32d0       Image:         svchost.exe
Wait Start TickCount      426549         Ticks: 18176 (0:00:04:44.000)
Context Switch Count      42            
UserTime                  00:00:00.000
KernelTime                00:00:00.000
Win32 Start Address 0×00037bb2
LPC Server thread working on message Id 37bb2
Start Address 0×77e617ec
Stack Init f60e0000 Current f60dfc60 Base f60e0000 Limit f60dd000 Call 0
Priority 9 BasePriority 8 PriorityDecrement 0
Kernel stack not resident.
ChildEBP RetAddr  Args to Child             
f60dfc78 8083d5b1 89815db0 89815e58 00000006 nt!KiSwapContext+0×26
f60dfca4 8083df9e 00000000 00000000 00000000 nt!KiSwapThread+0×2e5
f60dfcec 8092ae57 88603e40 00000006 00000001 nt!KeWaitForSingleObject+0×346
f60dfd50 80833bef 000004fc 00000000 00000000 nt!NtWaitForSingleObject+0×9a
f60dfd50 7c8285ec 000004fc 00000000 00000000 nt!KiFastCallEntry+0xfc

We see that it is blocked waiting for a synchronization object (mutant, shown in magenta above) and we check the thread 884d7db0 that owns it:

7: kd> !thread 884d7db0
THREAD 884d7db0  Cid 1218.12ec  Teb: 7ffdd000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable
    884d7f9c  Semaphore Limit 0x1
Waiting for reply to LPC MessageId 0000fa9e:
Current LPC port e121fdb8
Not impersonating
DeviceMap                 e10018b8
Owning Process            887d32d0       Image:         svchost.exe
Wait Start TickCount      11800          Ticks: 432925 (0:01:52:44.453)
Context Switch Count      111            
UserTime                  00:00:00.000
KernelTime                00:00:00.000
Win32 Start Address 0×0000fa9b
LPC Server thread working on message Id fa9b
Start Address 0×77e617ec
Stack Init f4598000 Current f4597c08 Base f4598000 Limit f4595000 Call 0
Priority 9 BasePriority 8 PriorityDecrement 0
Kernel stack not resident.
ChildEBP RetAddr  Args to Child             
f4597c20 8083d5b1 884d7db0 884d7e58 00000007 nt!KiSwapContext+0×26
f4597c4c 8083df9e 884d7f9c 884d7f70 884d7db0 nt!KiSwapThread+0×2e5
f4597c94 8093eda1 884d7f9c 00000011 80930901 nt!KeWaitForSingleObject+0×346
f4597d50 80833bef 00000560 000ebfe0 000ebfe0 nt!NtRequestWaitReplyPort+0×776
f4597d50 7c8285ec 00000560 000ebfe0 000ebfe0 nt!KiFastCallEntry+0xfc

The thread is waiting for the LPC message 0000fa9e and we look for a server thread processing it:

7: kd> !thread 898c6db0
THREAD 898c6db0  Cid 0b38.188c  Teb: 7ff4d000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable
    884362c8  SynchronizationEvent
Not impersonating
DeviceMap                 e11399e8
Owning Process            88340758       Image:         AppB.exe
Wait Start TickCount      11801          Ticks: 432924 (0:01:52:44.437)
Context Switch Count      7            
UserTime                  00:00:00.000
KernelTime                00:00:00.000
Win32 Start Address 0x0000fa9e
LPC Server thread working on message Id fa9e
Start Address 0x77e617ec
Stack Init f5138000 Current f5137c60 Base f5138000 Limit f5135000 Call 0
Priority 9 BasePriority 8 PriorityDecrement 0
Kernel stack not resident.
ChildEBP RetAddr  Args to Child             
f5137c78 8083d5b1 898c6db0 898c6e58 00000006 nt!KiSwapContext+0x26
f5137ca4 8083df9e 00000000 00000000 00000000 nt!KiSwapThread+0x2e5
f5137cec 8092ae57 884362c8 00000006 00000001 nt!KeWaitForSingleObject+0x346
f5137d50 80833bef 0000056c 00000000 00000000 nt!NtWaitForSingleObject+0x9a
f5137d50 7c8285ec 0000056c 00000000 00000000 nt!KiFastCallEntry+0xfc

We also see that the thread 884d7db0 was working on message fa9b (shown in blue above) and therefore we can find its client thread:

7: kd> !lpc message fa9b
Searching message fa9b in threads ...
    Server thread 884d7db0 is working on message fa9b                        
Client thread 871ab9a0 waiting a reply from fa9b                         
Searching thread 871ab9a0 in port rundown queues …

Server communication port 0xe23f68b8
    Handles: 1   References: 1
    The LpcDataInfoChainHead queue is empty
        Connected port: 0xe1325c10      Server connection port: 0xe1323f68

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

Server connection port e1323f68  Name: ApiABC
    Handles: 1   References: 43
    Server process  : 887d32d0 (svchost.exe)
    Queue semaphore : 884df210
    Semaphore state 0 (0x0)
    The message queue is empty

    Messages in LpcDataInfoChainHead:
        0000 e6067418 - Busy  Id=00020695  From: 0224.134c  Context=80050003  [e1323fe8 . e65fa5a8]
                   Length=0044002c  Type=00380001 (LPC_REQUEST)
                   Data: 00000001 00050242 00000000 00000000 00000000 00000000
        0000 e65fa5a8 - Busy  Id=0002e1dd  From: 0fd8.0fe0  Context=80110002  [e6067418 . e5f6a360]
                   Length=0044002c  Type=00380001 (LPC_REQUEST)
                   Data: 00000001 00050242 c03007fc c01fff7c 00000000 80a84456
        0000 e5f6a360 - Busy  Id=00037bb2  From: 1f88.1bd4  Context=8017000f  [e65fa5a8 . e1323fe8]
                   Length=0044002c  Type=00380001 (LPC_REQUEST)
                   Data: 00000001 00050242 88572278 88572290 8a386990 000015e7
    The LpcDataInfoChainHead queue contains 3 messages
    Threads in RunDown queue :     0xe6067258    0xe65fa3e8    0xe5f6a1a0
Done.

7: kd> !thread 871ab9a0
THREAD 871ab9a0  Cid 180c.1810  Teb: 7ffdf000 Win32Thread: bc011008 WAIT: (Unknown) UserMode Non-Alertable
    871abb8c  Semaphore Limit 0x1
Waiting for reply to LPC MessageId 0000fa9b:
Current LPC port e1325c10
Not impersonating
DeviceMap                 e10018b8
Owning Process            8963c388       Image:         AppC.exe
Wait Start TickCount      11796          Ticks: 432929 (0:01:52:44.515)
Context Switch Count      540                 LargeStack
UserTime                  00:00:00.046
KernelTime                00:00:00.062
Start Address 0x0103e1b0
Stack Init f68a4000 Current f68a3c08 Base f68a4000 Limit f689f000 Call 0
Priority 15 BasePriority 15 PriorityDecrement 0
Kernel stack not resident.
ChildEBP RetAddr  Args to Child             
f68a3c20 8083d5b1 871ab9a0 871aba48 00000004 nt!KiSwapContext+0x26
f68a3c4c 8083df9e 871abb8c 871abb60 871ab9a0 nt!KiSwapThread+0x2e5
f68a3c94 8093eda1 871abb8c 00000011 e24f0401 nt!KeWaitForSingleObject+0x346
f68a3d50 80833bef 00000150 0007fc70 0007fc70 nt!NtRequestWaitReplyPort+0x776
f68a3d50 7c8285ec 00000150 0007fc70 0007fc70 nt!KiFastCallEntry+0xfc

Finally we can draw this wait chain diagram where LPC calls are shown as red arrows:

 

- Dmitry Vostokov @ DumpAnalysis.org -

Crash Dump Analysis AntiPatterns (Part 12)

Tuesday, December 16th, 2008

Sometimes a memory dump is not useful because of missing memory space, hence the name of this anti-pattern: Missing Space. This usually happens for non-bugcheck type issues like CPU spikes, application or session hangs where user space analysis is needed. Here is an example of Spiking Thread pattern in a kernel memory dump where analysis cannot be done because threads were spiking mostly in user space not included in kernel memory dumps:

Loading Dump File [MEMORY.DMP]
Kernel Summary Dump File: Only kernel address space is available

1: kd> !running

System Processors 3 (affinity mask)
  Idle Processors 0

     Prcb      Current   Next   
  0  ffdff120  88d14b40            ................
  1  f7737120  891dddb0            ................

1: kd> !thread 88d14b40
THREAD 88d14b40  Cid 02b0.5298  Teb: 7ff7b000 Win32Thread: 00000000 RUNNING on processor 0
IRP List:
    87e3ad50: (0006,0094) Flags: 00000900  Mdl: 00000000
    8a8485f8: (0006,0094) Flags: 00000900  Mdl: 00000000
Not impersonating
DeviceMap                 e1001878
Owning Process            8a9831a8       Image:         ApplicationA.exe
Wait Start TickCount      1282379        Ticks: 0
Context Switch Count      2950            
UserTime                  00:00:15.109
KernelTime                00:00:00.125
Win32 Start Address 0×77c7b0f5
Start Address 0×77e617ec
Stack Init ae302000 Current ae301c38 Base ae302000 Limit ae2ff000 Call 0
Priority 11 BasePriority 10 PriorityDecrement 0
ChildEBP RetAddr  Args to Child             
0269fd6c 00000000 00000000 00000000 00000000 0×77e61684

1: kd> !thread 891dddb0
THREAD 891dddb0  Cid 2de4.3f58  Teb: 7ffd8000 Win32Thread: bc487c18 RUNNING on processor 1
Not impersonating
DeviceMap                 e6aba8b0
Owning Process            88b50d88       Image:         ApplicationB.exe
Wait Start TickCount      1282379        Ticks: 0
Context Switch Count      46241                 LargeStack
UserTime                  00:00:35.296
KernelTime                00:00:06.656
Win32 Start Address 0×0b80e53c
Start Address 0×77e617ec
Stack Init b234c000 Current b234bd00 Base b234c000 Limit b2346000 Call 0
Priority 10 BasePriority 10 PriorityDecrement 0
ChildEBP RetAddr  Args to Child             
b234bcc8 f65c0532 000000e2 00000000 00000000 nt!KeBugCheckEx+0×1b
b234bcf8 f65bfd2c 00866d40 bbf000c6 00000000 i8042prt!I8xProcessCrashDump+0×256
b234bd40 808395a5 8a107c28 8a866c88 0101000a i8042prt!I8042KeyboardInterruptService+0×225
b234bd40 432de484 8a107c28 8a866c88 0101000a nt!KiInterruptDispatch+0×49
WARNING: Frame IP not in any known module. Following frames may be wrong.
01bbf150 00000000 00000000 00000000 00000000 0×432de484

The solution here is to request either a complete memory dump or user dumps of identified processes. The former was requested already but the crash dump type in Control Panel was not checked before forcing the dump of the system via standard keyboard method. Therefore this is also an instance of Wrong Dump anti-pattern.

- Dmitry Vostokov @ DumpAnalysis.org -

Pattern Cooperation Collection Page

Monday, December 15th, 2008

I’ve written 10 pattern-driven crash dump analysis case studies so far and now put them on one page:

Pattern Cooperation

More case studies will be added in the future.

- Dmitry Vostokov @ DumpAnalysis.org -

Wait chain and spiking thread: pattern cooperation

Friday, December 12th, 2008

Here is the simplified example of executive resource wait chain:

0: kd> !locks
**** DUMP OF ALL RESOURCE OBJECTS ****
KD: Scanning for held locks...

Resource @ 0x88094118    Exclusively owned
    Contention Count = 1461106
    NumberOfExclusiveWaiters = 172
     Threads: 87571600-01<*>
     Threads Waiting On Exclusive Access:
              87a0cd70       86e478b0       86d73270       87463908      
              86ed5020       872d3a08       87a0b228       87985020      
              870e4430       870adb00       88197500       86e06db0      
              87030db0       86d86db0       88a22288       86db07a0      
              86815c50       87524628       899d2020       86da03f0      
              86fc8db0       86e43b40       86d86ac8       87320690      
              86da2020       879c0108       86d8f7a8       86876370      
              87565150       87142020       879ddd30       86ff8990      
              86e5c770       867a7200       87a97c50       86e21020      
              86dac6e8       876d6db0       876fadb0       86e36408      
              86e621c8       8770adb0       86fd7c50       86db6ba8      
              86b87020       867ea2f8       870b60e8       889dc6d8      
              877ebae0       86e267a8       88a8a9f0       8737e5e8      
              86fc0780       87993c98       88aead28       872bedb0      
              899e5628       87523770       870aaaf0       8717b3b0      
              86e19db0       86e11db0       86e5a7a0       87038448      
              8743adb0       8816b9a0       880955f8       867f3db0      
              875c3430       8714a4f8       879b6020       87642598      
              86ec2b40       884a7c50       87200020       86880db0      
              86e2f988       866fb020       86ddfdb0       867c1bd8      
              86645020       868c0db0       87613db0       872b0020      
              88a56898       8770d9e0       8680b418       87014db0      
              865e0720       868c7af0       8733aaf0       86929508      
              8798f928       879cd378       8822ec50       8721adb0      
              876b25a0       87b5b598       8684baf0       86e48db0      
              86eb5b90       86d969a8       87039db0       87486020      
              86d8f3c0       8680edb0       86fddb88       885c2cb0      
              870ba890       86e2e4f8       8695b948       86e6fa28      
              88a42b88       86e58af0       86ddd2e0       8695b540      
              86817520       86975800       86817020       88b40b50      
              87271620       8695b2d0       867b44c8       880b6af8      
              870e1898       87c711e0       87a77210       8676bdb0      
              86734630       86878db0       86fd0c50       872a81f8      
              86e09020       880cf4f8       87178970       868a1508      
              870a9db0       8692c020       867a4020       868c9c50      
              890c74e0       8687c9a8       8692c4f8       880cf238      
              8708cac0       86ef5db0       86fa9db0       87158330      
              87979868       87a4f510       879a3510       87a1cdb0      
              87094020       87095db0       8705d2a8       87b0d5b0      
              870c0020       879eb660       8737e2e0       86ea7918      
              86e46a28       87a49198       87d61db0       87067db0      
              8730e598       86f97db0       8668d020       89d671b8      
              8732a5c8       89a00bb8       867fa020       86e2a020

KD: Scanning for held locks..

Resource @ 0x88aaabe8    Exclusively owned
    Contention Count = 97373
     Threads: 87178598-01<*>
KD: Scanning for held locks.

Resource @ 0x87712650    Exclusively owned
    Contention Count = 41716
    NumberOfExclusiveWaiters = 2
     Threads: 87178598-01<*>
     Threads Waiting On Exclusive Access:
              87571600       879f5648

KD: Scanning for held locks...

Resource @ 0x87736048    Exclusively owned
    Contention Count = 29109
    NumberOfExclusiveWaiters = 1
     Threads: 87ab30d0-01<*>
     Threads Waiting On Exclusive Access:
              87178598

KD: Scanning for held locks...

21056 total locks, 4 locks currently held

This is straight forward single wait chain (172 threads -> 87571600 -> 87178598 -> 87ab30d0) culminating in thread 87ab30d0 which loops in kernel mode (Spiking Thread):

0: kd> !thread 87ab30d0
THREAD 87ab30d0  Cid 3814.322c  Teb: 00000000 Win32Thread: 00000000 RUNNING on processor 3
Not impersonating
DeviceMap                 e1006e10
Owning Process            889d6d88       Image:         Application.exe
Wait Start TickCount      2518917        Ticks: 0
Context Switch Count      4057707            
UserTime                  00:00:00.000
KernelTime                01:26:13.906
*** WARNING: Unable to verify timestamp for driverA.sys
*** ERROR: Module load completed but symbols could not be loaded for driverA.dll
Start Address driverA (0xbfa1c930)
Stack Init ae8ec000 Current ae8eae7c Base ae8ec000 Limit ae8e9000 Call 0
Priority 13 BasePriority 13 PriorityDecrement 0
ChildEBP RetAddr  Args to Child             
WARNING: Stack unwind information not available. Following frames may be wrong.
f773d3b0 ae8eaf40 00000010 00000000 00000000 driverA+0×25880

- Dmitry Vostokov @ DumpAnalysis.org -

Invalid handle, stack trace collection, multiple exceptions, invalid pointer, data alignment on page boundary, dynamic memory corruption and not my version: pattern cooperation

Tuesday, December 9th, 2008

Here we can look at one process dump with many patterns seen inside. Default WinDbg analysis command !analyze -v points to invalid handle exception perhaps at DLL initialization time during thread attach to DllA module:

STACK_TEXT: 
0296fa68 7c90eb93 ntdll!KiRaiseUserExceptionDispatcher+0x37
0296fa7c 10001252 ntdll!KiFastSystemCallRet+0x4
WARNING: Stack unwind information not available. Following frames may be wrong.
0296faa8 771215f8 DllA!DllMain+0×202
0296fbec 100014b0 OLEAUT32!DllMain+0×2c
0296fc0c 7c9011a7 DllA!DllMain+0×460
0296fc2c 7c918f65 ntdll!LdrpCallInitRoutine+0×14
0296fca0 7c918dde ntdll!LdrpInitializeThread+0xc0
0296fd18 7c90eac7 ntdll!_LdrpInitialize+0×219
00000000 00000000 ntdll!KiUserApcDispatcher+0×7

EXCEPTION_RECORD:  ffffffff -- (.exr 0xffffffffffffffff)
ExceptionAddress: 7c90eb74 (ntdll!KiRaiseUserExceptionDispatcher+0x00000037)
   ExceptionCode: c0000008 (Invalid handle)
  ExceptionFlags: 00000000
NumberParameters: 0
Thread tried to close a handle that was invalid or illegal to close

We may stop here after applying lmv command to DllA and recommending to upgrade / remove that component. But let’s look a bit deeper inside that crash dump. If we list all thread stacks (stack trace collection) we would see another thread with unhandled exception processing stack:

0:000> ~*kL

.  0  Id: a1c.e78 Suspend: 1 Teb: 7ffdf000 Unfrozen
ChildEBP RetAddr 
0012da34 7c90e9ab ntdll!KiFastSystemCallRet
0012da38 7c86372c ntdll!ZwWaitForMultipleObjects+0xc
0012e1a8 77c32f0f kernel32!UnhandledExceptionFilter+0×8e4
0012e1c4 0041808b msvcrt!_XcptFilter+0×161

0012ffc0 7c816fd7 Application!WinMainCRTStartup+0×14f
0012fff0 00000000 kernel32!BaseProcessStart+0×23

   1  Id: a1c.2ec Suspend: 1 Teb: 7ffdc000 Unfrozen
ChildEBP RetAddr 
02faff84 7c90e9ab ntdll!KiFastSystemCallRet
02faff88 5b890f8c ntdll!ZwWaitForMultipleObjects+0xc
02faffb4 7c80b683 NETAPI32!NetbiosWaiter+0x73
02faffec 00000000 kernel32!BaseThreadStart+0x37

   2  Id: a1c.c14 Suspend: 1 Teb: 7ffdb000 Unfrozen
ChildEBP RetAddr 
036afe1c 7c90e9ab ntdll!KiFastSystemCallRet
036afe20 7c8094e2 ntdll!ZwWaitForMultipleObjects+0xc
036afebc 7e4195f9 kernel32!WaitForMultipleObjectsEx+0x12c
036aff18 7e4196a8 USER32!RealMsgWaitForMultipleObjectsEx+0x13e
036aff34 00450d91 USER32!MsgWaitForMultipleObjects+0x1f
036aff80 77c3a3b0 Application!ThreadProc+0x61
036affb4 7c80b683 msvcrt!_endthreadex+0xa9
036affec 00000000 kernel32!BaseThreadStart+0x37

   3  Id: a1c.15c Suspend: 1 Teb: 7ffda000 Unfrozen
ChildEBP RetAddr 
0417ff78 7c90e31b ntdll!KiFastSystemCallRet
0417ff7c 71a5d320 ntdll!ZwRemoveIoCompletion+0xc
0417ffb4 7c80b683 mswsock!SockAsyncThread+0x5a
0417ffec 00000000 kernel32!BaseThreadStart+0x37

#  4  Id: a1c.96c Suspend: 1 Teb: 7ffde000 Unfrozen
ChildEBP RetAddr 
0296fa68 7c90eb93 ntdll!KiRaiseUserExceptionDispatcher+0x37
0296fa7c 10001252 ntdll!KiFastSystemCallRet+0x4
WARNING: Stack unwind information not available. Following frames may be wrong.
0296faa8 771215f8 DllA!DllMain+0x202
0296fbec 100014b0 OLEAUT32!DllMain+0x2c
0296fc0c 7c9011a7 DllA!DllMain+0x460
0296fc2c 7c918f65 ntdll!LdrpCallInitRoutine+0x14
0296fca0 7c918dde ntdll!LdrpInitializeThread+0xc0
0296fd18 7c90eac7 ntdll!_LdrpInitialize+0x219
00000000 00000000 ntdll!KiUserApcDispatcher+0x7

Seems we have multiple exceptions here. Let’s extract thread 0 exception:

0:000> kv
ChildEBP RetAddr  Args to Child             
0012da34 7c90e9ab 7c86372c 00000002 0012dbac ntdll!KiFastSystemCallRet
0012da38 7c86372c 00000002 0012dbac 00000001 ntdll!ZwWaitForMultipleObjects+0xc
0012e1a8 77c32f0f 0012e1f0 00000000 00000000 kernel32!UnhandledExceptionFilter+0×8e4
0012e1c4 0041808b 00000000 0012e1f0 77c35cf5 msvcrt!_XcptFilter+0×161
0012ffc0 7c816fd7 00160000 001ae3c6 7ffdd000 Application!WinMainCRTStartup+0×14f
0012fff0 00000000 00417f3c 00000000 78746341 kernel32!BaseProcessStart+0×23

0:000> .exptr 0012e1f0

----- Exception record at 0012e2e4:
ExceptionAddress: 77c47fd4 (msvcrt!wcslen+0x00000008)
   ExceptionCode: c0000005 (Access violation)
  ExceptionFlags: 00000000
NumberParameters: 2
   Parameter[0]: 00000000
   Parameter[1]: 04649000
Attempt to read from address 04649000

----- Context record at 0012e300:
eax=04649000 ebx=00000000 ecx=0464006c edx=04648fb4 esi=04648fd0 edi=00000000
eip=77c47fd4 esp=0012e5cc ebp=0012e5cc iopl=0  nv up ei pl nz na pe nc
cs=001b  ss=0023  ds=0023  es=0023  fs=003b  gs=0000  efl=00010206
msvcrt!wcslen+0x8:
77c47fd4 668b08          mov     cx,word ptr [eax]        ds:0023:04649000=????

0:000> kv
  *** Stack trace for last set context - .thread/.cxr resets it
ChildEBP RetAddr  Args to Child             
0012e5cc 7301561a 04648fd0 00000030 00000018 msvcrt!wcslen+0×8
0012e5f0 73016c32 04648fd0 04afefe8 00000000 DllB!UnicodeToAnsiString+0×105
[…]

We see invalid pointer access violation while calculating string length. If we look at invalid address we see that UNICODE string crosses page boundary into a reserved page:

0:000> dd 04648fd0
04648fd0  0060004d 00620066 00680072 0020006f
04648fe0  00200034 00630022 007100ea 00710060
04648ff0  00200073 0060006e 0076006f 006d0066

04649000  ???????? ???????? ???????? ????????
04649010  ???????? ???????? ???????? ????????
04649020  ???????? ???????? ???????? ????????
04649030  ???????? ???????? ???????? ????????
04649040  ???????? ???????? ???????? ????????

0:000> !address 04648fd0
    04648000 : 04648000 - 00001000
                    Type     00020000 MEM_PRIVATE
                    Protect  00000004 PAGE_READWRITE
                    State    00001000 MEM_COMMIT
                    Usage    RegionUsageIsVAD

0:000> !address 04649000
    045e0000 : 04649000 - 00001000
                    Type     00040000 MEM_MAPPED
                    State    00002000 MEM_RESERVE
                    Usage    RegionUsageIsVAD

And we also notice full page heap enabled to catch possible heap corruption (dynamic memory corruption):

0:000> !gflag
Current NtGlobalFlag contents: 0x02000000
    hpa - Place heap allocations at ends of pages

This explains why we see invalid handle exception which is normally ignored by runtime unless we enable Application Verifier. Looking at DllB version data we see that it is the old component that needs to be upgraded.

- Dmitry Vostokov @ DumpAnalysis.org -