Archive for December, 2011

Crash Dump Analysis Patterns (Part 160)

Sunday, December 11th, 2011

When doing software behavior artifact collection, live debugging or postmortem memory dump analysis we must also take into consideration the possibility of Debugger Bugs. I classify them into hard and soft bugs. The former are those software defects and behavioral problems that result in further abnormal software behavior incidents like crashes and hangs. One example is this Microsoft KB article about DebugDiag. Soft debugger bugs usually manifest themselves as glitches in data output, nonsense or false positive diagnostics, for example, this excessive non-paged pool usage message in the output from !vm WinDbg command (see the corresponding MS KB article):

1: kd> !vm

*** Virtual Memory Usage ***
Physical Memory:     1031581 (   4126324 Kb)
Page File: \??\C:\pagefile.sys
Current:   4433524 Kb  Free Space:   4433520 Kb
Minimum:   4433524 Kb  Maximum:     12378972 Kb
Unimplemented error for MiSystemVaTypeCount
Available Pages:      817652 (   3270608 Kb)
ResAvail Pages:       965229 (   3860916 Kb)
Locked IO Pages:           0 (         0 Kb)
Free System PTEs:   33555714 ( 134222856 Kb)
Modified Pages:        15794 (     63176 Kb)
Modified PF Pages:     15793 (     63172 Kb)
NonPagedPool Usage: 88079121 ( 352316484 Kb)
NonPagedPoolNx Usage:  12885 (     51540 Kb)
NonPagedPool Max:     764094 (   3056376 Kb)
********** Excessive NonPaged Pool Usage *****
PagedPool 0 Usage:     35435 (    141740 Kb)
PagedPool 1 Usage:      3620 (     14480 Kb)
PagedPool 2 Usage:       573 (      2292 Kb)
PagedPool 3 Usage:       535 (      2140 Kb)
PagedPool 4 Usage:       538 (      2152 Kb)
PagedPool Usage:       40701 (    162804 Kb)
PagedPool Maximum:  33554432 ( 134217728 Kb)
Session Commit:         9309 (     37236 Kb)
Shared Commit:          6460 (     25840 Kb)
Special Pool:              0 (         0 Kb)
Shared Process:         5760 (     23040 Kb)
PagedPool Commit:      40765 (    163060 Kb)
Driver Commit:          2805 (     11220 Kb)
Committed pages:      212472 (    849888 Kb)
Commit limit:        2139487 (   8557948 Kb)

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

My Vision of TaaS

Monday, December 5th, 2011

On the portal I published my vision of software tools as a service in the context of post-construction software problem solving. The main part is software problem description language (SPDL) which was previously introduced as Riemann programming language. I have decided to keep the name.

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

Crash Dump Analysis Patterns (Part 159)

Monday, December 5th, 2011

Sometimes we have a value or a pointer or a handle and would like to know all memory addresses that reference it. This can be done by virtual memory search (s WinDbg command). If you look for references in code (for example, or pool tags please see this case study) you can combine search with !for_each_module WinDbg extension command. There is also !search command for physical pages. We cover this Value References pattern in the forthcoming Advanced Windows Memory Dump Analysis training with a step-by-step complete memory dump analysis exercise. For object references there is also recently added !obtrace command with good examples in WinDbg help.

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

Crash Dump Analysis Patterns (Part 69c)

Sunday, December 4th, 2011

This is a variant of Self-Diagnosis (kernel mode) pattern for system configuration database (registry). Sometimes it is possible to see which part of it (hive) caused the problem. Here’s an example involving possibly corrupt user profiles:

REGISTRY_ERROR (51)
Something has gone badly wrong with the registry.  If a kernel debugger is available, get a stack trace. It can also indicate that the registry got an I/O error while trying to read one of its files, so it can be caused by hardware problems or filesystem corruption. It may occur due to a failure in a refresh operation, which is used only in by the security system, and then only when resource limits are encountered.
Arguments:
Arg1: 00000003, (reserved)
Arg2: 00000004, (reserved)
Arg3: e82372f8, depends on where Windows bugchecked, may be pointer to hive
Arg4: 00000000, depends on where Windows bugchecked, may be return code of HvCheckHive if the hive is corrupt.

0: kd> !reg hivelist

-------------------------------------------------------------------------------------------------------------
| HiveAddr |Stable Length|Stable Map|Volatile Length|Volatile Map|MappedViews|PinnedViews|U(Cnt)| BaseBlock | FileName
-------------------------------------------------------------------------------------------------------------
| e1008a68 |      13000  | e1008ac8 |       1000    |  e1008c04  |        0  |        0  |     0| e1015000  | <NONAME>
| e101a4e0 |     901000  | e1023000 |      40000    |  e101a67c  |      202  |        0  |     0| e101e000  | SYSTEM
| e1938188 |       d000  | e19381e8 |       4000    |  e1938324  |        0  |        0  |     0| e193a000  | <NONAME>
| e1968290 |       8000  | e19682f0 |          0    |  00000000  |        3  |        0  |     0| e1d39000  | \SystemRoot\System32\Config\SAM
| e1cab270 |      3d000  | e1cab2d0 |       1000    |  e1cab40c  |       16  |        0  |     0| e1d32000  | emRoot\System32\Config\SECURITY
| e1c9f448 |    3f70000  | e1e37000 |       1000    |  e1c9f5e4  |      256  |        0  |     0| e1d71000  | temRoot\System32\Config\DEFAULT
| e1d75a80 |    7d5d000  | e1ee3000 |      23000    |  e1d75c1c  |      254  |       12  |     0| e1d37000  | emRoot\System32\Config\SOFTWARE
| e1ba30d0 |      37000  | e1ba3130 |       1000    |  e1ba326c  |       17  |        0  |     0| e1b9e000  | tings\NetworkService\ntuser.dat
| e1ba8060 |       1000  | e1ba80c0 |          0    |  00000000  |        1  |        0  |     0| e1b8e000  | \Microsoft\Windows\UsrClass.dat
| e1afc068 |      3b000  | e1afc0c8 |       1000    |  e1afc204  |       17  |        0  |     0| e1b3d000  | ettings\LocalService\ntuser.dat
| e1d6e2a0 |       1000  | e1d6e300 |          0    |  00000000  |        1  |        0  |     0| e1b39000  | \Microsoft\Windows\UsrClass.dat
[...]
| e82372f8 |     106000  | e8237358 |          0    |  00000000  |       55  |        4  |     0| e514c000  | ings\User123\NTUSER.DAT
[…]
————————————————————————————————————-

0: kd> dt _CMHIVE e82372f8
nt!_CMHIVE
   +0x000 Hive             : _HHIVE
   +0x2d0 FileHandles      : [3] 0x80002234 Void
   +0x2dc NotifyList       : _LIST_ENTRY [ 0x0 - 0x0 ]
   +0x2e4 HiveList         : _LIST_ENTRY [ 0xe7a38d64 - 0xe4d9fc9c ]
   +0x2ec HiveLock         : _EX_PUSH_LOCK
   +0x2f0 ViewLock         : 0x877b0120 _KGUARDED_MUTEX
   +0x2f4 WriterLock       : _EX_PUSH_LOCK
   +0x2f8 FlusherLock      : _EX_PUSH_LOCK
   +0x2fc SecurityLock     : _EX_PUSH_LOCK
   +0x300 LRUViewListHead  : _LIST_ENTRY [ 0xe6160170 - 0xe3d71978 ]
   +0x308 PinViewListHead  : _LIST_ENTRY [ 0xe2714fe0 - 0xe108d9e0 ]
   +0x310 FileObject       : 0x89ecf310 _FILE_OBJECT
   +0x314 FileFullPath     : _UNICODE_STRING "\Device\HarddiskVolumeX\Documents and Settings\User123\NTUSER.DAT"
   +0×31c FileUserName     : _UNICODE_STRING “\??\E:\Documents and Settings\User123\NTUSER.DAT”
   +0×324 MappedViews      : 0×37
   +0×326 PinnedViews      : 4
   +0×328 UseCount         : 0
   +0×32c SecurityCount    : 9
   +0×330 SecurityCacheSize : 9
   +0×334 SecurityHitHint  : 0n0
   +0×338 SecurityCache    : 0xe74d5008 _CM_KEY_SECURITY_CACHE_ENTRY
   +0×33c SecurityHash     : [64] _LIST_ENTRY [ 0xe3f80228 - 0xe5901ef0 ]
   +0×53c UnloadEvent      : (null)
   +0×540 RootKcb          : (null)
   +0×544 Frozen           : 0 ”
   +0×548 UnloadWorkItem   : (null)
   +0×54c GrowOnlyMode     : 0 ”
   +0×550 GrowOffset       : 0
   +0×554 KcbConvertListHead : _LIST_ENTRY [ 0xe823784c - 0xe823784c ]
   +0×55c KnodeConvertListHead : _LIST_ENTRY [ 0xe8237854 - 0xe8237854 ]
   +0×564 CellRemapArray   : (null)
   +0×568 Flags            : 1
   +0×56c TrustClassEntry  : _LIST_ENTRY [ 0xe8237864 - 0xe8237864 ]
   +0×574 FlushCount       : 0
   +0×578 CreatorOwner     : (null)

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

Crash Dump Analysis Patterns (Part 158)

Sunday, December 4th, 2011

Certain System Objects can be found in object directory and can be useful to see additional system and other product activity. For example, in a complete memory dump from Accelerated .NET Memory Dump Analysis training we see that LowCommitCondition event is signalled:

1: kd> !object \KernelObjects
Object: 85a08030  Type: (82b38ed0) Directory
    ObjectHeader: 85a08018 (old version)
    HandleCount: 0  PointerCount: 19
    Directory Object: 85a074c0  Name: KernelObjects

    Hash Address  Type          Name
    ---- -------  ----          ----
     02  82b7b0b8 Event         HighCommitCondition
     04  82b7b780 Event         HighMemoryCondition
     10  82b7b178 Event         LowNonPagedPoolCondition
     11  82b7b138 Event         HighNonPagedPoolCondition
     17  82b7b0f8 Event         LowCommitCondition
     20  82b78d08 Event         SuperfetchParametersChanged
         82b6eb58 Event         BootLoaderTraceReady
     23  84bfdd58 Session       Session0
         82b78c88 Event         PrefetchTracesReady
     24  84b7d1f8 Session       Session1
     25  82b78cc8 Event         SuperfetchScenarioNotify
         82b7b740 Event         LowPagedPoolCondition
     26  82b7b1b8 Event         HighPagedPoolCondition
         82b7a030 Event         MemoryErrors
     28  82b78c48 Event         SuperfetchTracesReady
     32  82b7b7c0 Event         LowMemoryCondition
         85a09d00 KeyedEvent    CritSecOutOfMemoryEvent
     34  82b7b078 Event         MaximumCommitCondition

1: kd> dt _DISPATCHER_HEADER 82b7b0f8
ntdll!_DISPATCHER_HEADER
   +0x000 Type             : 0 ''
   +0x001 Abandoned        : 0 ''
   +0x001 Absolute         : 0 ''
   +0x001 NpxIrql          : 0 ''
   +0x001 Signalling       : 0 ''
   +0x002 Size             : 0x4 ''
   +0x002 Hand             : 0x4 ''
   +0x003 Inserted         : 0 ''
   +0x003 DebugActive      : 0 ''
   +0x003 DpcActive        : 0 ''
   +0x000 Lock             : 0n262144
   +0×004 SignalState      : 0n1
   +0×008 WaitListHead     : _LIST_ENTRY [ 0×82b7b100 - 0×82b7b100 ]

If we check virtual memory statistics we see lots of free space for the currrent physical memory and pagefile: 

1: kd> !vm

*** Virtual Memory Usage ***
 Physical Memory:      261872 (   1047488 Kb)
 Page File: \??\C:\pagefile.sys
   Current:   1354688 Kb  Free Space:     53120 Kb
   Minimum:   1354688 Kb  Maximum:      4194304 Kb
 Available Pages:      180984 (    723936 Kb)
 ResAvail Pages:       216475 (    865900 Kb)
 Locked IO Pages:           0 (         0 Kb)
 Free System PTEs:     352925 (   1411700 Kb)
 Modified Pages:          129 (       516 Kb)
 Modified PF Pages:        94 (       376 Kb)
 NonPagedPool Usage:        0 (         0 Kb)
 NonPagedPoolNx Usage:  16894 (     67576 Kb)
 NonPagedPool Max:     192350 (    769400 Kb)
 PagedPool 0 Usage:      5957 (     23828 Kb)
 PagedPool 1 Usage:      3218 (     12872 Kb)
 PagedPool 2 Usage:       965 (      3860 Kb)
 PagedPool 3 Usage:      1311 (      5244 Kb)
 PagedPool 4 Usage:      1064 (      4256 Kb)
 PagedPool Usage:       12515 (     50060 Kb)
 PagedPool Maximum:    523264 (   2093056 Kb)
 Session Commit:         5021 (     20084 Kb)
 Shared Commit:         15023 (     60092 Kb)
 Special Pool:              0 (         0 Kb)
 Shared Process:         1938 (      7752 Kb)
 PagedPool Commit:      12523 (     50092 Kb)
 Driver Commit:          2592 (     10368 Kb)
 Committed pages:      402494 (   1609976 Kb)
 Commit limit:         589254 (   2357016 Kb)
[...]

Another example is from Windows 7 memory dump I used for Fundamentals of Complete Crash and Hang Memory Dump Analysis presentation. Here we can find WER reporting mutant in session 1 object directory and get problem PID from its name:

0: kd> !object \Sessions\1\BaseNamedObjects\
Object: fffff8a0016eb290  Type: (fffffa800426df30) Directory
    ObjectHeader: fffff8a0016eb260 (new version)
    HandleCount: 57  PointerCount: 217
    Directory Object: fffff8a0016e9220  Name: BaseNamedObjects

    Hash Address          Type          Name
    ---- -------          ----          ----
     00  fffffa8008437670 Event         STOP_HOOKING64
[...]
    08  fffffa80044baa40 Mutant        WERReportingForProcess1788
[…]

0: kd> !process 0n1788 1
Searching for Process with Cid == 6fc
Cid handle table at fffff8a00180b000 with 21248 entries in use

PROCESS fffffa8004364060
    SessionId: 1  Cid: 06fc    Peb: 7fffffd4000  ParentCid: 0840
    DirBase: 5fbc2000  ObjectTable: fffff8a004c8e930  HandleCount:  16.
    Image: ApplicationD.exe
    VadRoot fffffa8009d85170 Vads 34 Clone 0 Private 206. Modified 0. Locked 0.
    DeviceMap fffff8a001ce6b90
    Token                             fffff8a003eab060
    ElapsedTime                       00:01:51.543
    UserTime                          00:00:00.000
    KernelTime                        00:00:00.000
    QuotaPoolUsage[PagedPool]         0
    QuotaPoolUsage[NonPagedPool]      0
    Working Set Sizes (now,min,max)  (483, 50, 345) (1932KB, 200KB, 1380KB)
    PeakWorkingSetSize                483
    VirtualSize                       13 Mb
    PeakVirtualSize                   13 Mb
    PageFaultCount                    481
    MemoryPriority                    BACKGROUND
    BasePriority                      8
    CommitCharge                      231

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

Crash Dump Analysis Patterns (Part 157)

Saturday, December 3rd, 2011

In addition to functions we also have module variables like nt!MmPagedPoolCommit in Windows 7:

0: kd> x nt!MmPagedPool*
fffff800`031148d0 nt!MmPagedPoolInfo = <no type information>
fffff800`03092d20 nt!MmPagedPoolCommit = <no type information>
fffff800`031141a0 nt!MmPagedPoolEnd = <no type information>
fffff800`031175c0 nt!MmPagedPoolWs = <no type information>

If we are not sure whether we have a function or Module Variable we can try to disassemble:

0: kd> u nt!MmPagedPoolCommit
nt!MmPagedPoolCommit:
fffff800`03092d20 e3b2            jrcxz   nt!MmTotalNonPagedPoolQuota+0x4 (fffff800`03092cd4)
fffff800`03092d22 0000            add     byte ptr [rax],al
fffff800`03092d24 0000            add     byte ptr [rax],al
fffff800`03092d26 0000            add     byte ptr [rax],al
fffff800`03092d28 0000            add     byte ptr [rax],al
fffff800`03092d2a 0000            add     byte ptr [rax],al
fffff800`03092d2c 0000            add     byte ptr [rax],al
fffff800`03092d2e 0000            add     byte ptr [rax],al

Here the value is probably in pages so we multiply by 4 to get Kb value and compare to the output of !vm command:

0: kd> dp nt!MmPagedPoolCommit
fffff800`03092d20  00000000`0000b2e3 00000000`00000000
fffff800`03092d30  00000000`00000000 00000000`00000000
fffff800`03092d40  00000000`00000001 00000000`00000000
fffff800`03092d50  00000000`00000000 00000000`00060107
fffff800`03092d60  fffff800`03092d60 fffff800`03092d60
fffff800`03092d70  00000000`00000000 00000000`0001e972
fffff800`03092d80  fffff900`c0000000 00000000`00000002
fffff800`03092d90  fffff880`071dc0a8 fffff880`057340a8

0: kd> ? b2e3 * 4
Evaluate expression: 183180 = 00000000`0002cb8c

0: kd> !vm

*** Virtual Memory Usage ***
 Physical Memory:     1035228 (   4140912 Kb)
 Page File: \??\C:\pagefile.sys
   Current:   4448112 Kb  Free Space:   4448108 Kb
   Minimum:   4448112 Kb  Maximum:     12422736 Kb
Unimplemented error for MiSystemVaTypeCount
 Available Pages:      594029 (   2376116 Kb)
 ResAvail Pages:       889795 (   3559180 Kb)
 Locked IO Pages:           0 (         0 Kb)
 Free System PTEs:   33556870 ( 134227480 Kb)
 Modified Pages:        20079 (     80316 Kb)
 Modified PF Pages:     19441 (     77764 Kb)
 NonPagedPool Usage: 50865104 ( 203460416 Kb)
 NonPagedPoolNx Usage:  28163 (    112652 Kb)
 NonPagedPool Max:     763396 (   3053584 Kb)
 ********** Excessive NonPaged Pool Usage *****
 PagedPool 0 Usage:     39420 (    157680 Kb)
 PagedPool 1 Usage:      5194 (     20776 Kb)
 PagedPool 2 Usage:       367 (      1468 Kb)
 PagedPool 3 Usage:       338 (      1352 Kb)
 PagedPool 4 Usage:       440 (      1760 Kb)
 PagedPool Usage:       45759 (    183036 Kb)
 PagedPool Maximum:  33554432 ( 134217728 Kb)
 Session Commit:         8112 (     32448 Kb)
 Shared Commit:         31802 (    127208 Kb)
 Special Pool:              0 (         0 Kb)
 Shared Process:        10765 (     43060 Kb)
 PagedPool Commit:      45795 (    183180 Kb)
 Driver Commit:         13773 (     55092 Kb)
 Committed pages:      540998 (   2163992 Kb)
 Commit limit:        2146794 (   8587176 Kb)
[…]

Knowledge of available module variables is useful because some of them are not included in WinDbg extension command output. For their list please consult Windows Internals book. Also useful variables can be found in other modules as well, for example, srv!srvcomputername:

0: kd> dS srv!srvcomputername
fffff8a0`0344b090  "MYNOTEBOOK"

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

Crash Dump Analysis Patterns (Part 27c)

Saturday, December 3rd, 2011

Sometimes we need to narrow general stack trace collection to a few threads that satisfy some predicate, for example, all threads with kernel time spent greater than some value or all suspended threads or all threads that wait for a specific synchronization object type. We call this pattern variant Stack Trace Collection (predicate). This can be implemented using WinDbg scripts and / or debugger extensions.

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

2 WinDbg Scripts That Changed The World

Saturday, December 3rd, 2011

If not for you then definitely for me because I now diagnose Spiking Thread pattern much faster. One of the readers if this blog asked me whether there is !runaway command equivalent for kernel and complete memory dumps. So, after some thinking I gave it a try especially in the context of WinDbg scripting exercises designed for Advanced Windows Memory Dump Analysis training. As a result I wrote 2 scripts initially that you can try yourself. Their output here is taken from a complete memory dump I used for Fundamentals of Complete Crash and Hang Memory Dump Analysis presentation.

The first one dumps the most CPU consuming threads for user and kernel mode:

$$
$$ krunawaymost.wds
$$ Copyright (c) 2011 Memory Dump Analysis Services
$$ GNU GENERAL PUBLIC LICENSE
$$ http://www.gnu.org/licenses/gpl-3.0.txt
$$
r $t0 = 0
!for_each_thread “r $t1 = dwo( @#Thread + @@c++(#FIELD_OFFSET(nt!_KTHREAD, UserTime)) ); .if (@$t1 > @$t0) {r $t0 = @$t1; r $t2 = @#Thread}”
.echo “The largest UserTime value: ”
? @$t0
!thread @$t2 ff
r $t0 = 0
!for_each_thread “r $t1 = dwo( @#Thread + @@c++(#FIELD_OFFSET(nt!_KTHREAD, KernelTime)) ); .if (@$t1 > @$t0) {r $t0 = @$t1; r $t2 = @#Thread}”
.echo “The largest KernelTime value: ”
? @$t0
!thread @$t2 ff

0: kd> $$><c:\Scripts\krunawaymost.wds
The largest UserTime value:
Evaluate expression: 5470 = 00000000`0000155e

THREAD fffffa800451d720  Cid 1418.17fc  Teb: 000007fffffdc000 Win32Thread: 0000000000000000 RUNNING on processor 2
Not impersonating
DeviceMap                 fffff8a001ce6b90
Owning Process            fffffa800442ab30       Image:         ApplicationE.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      22295          Ticks: 0
Context Switch Count      27960            
UserTime                  00:01:25.332
KernelTime                00:00:00.015
*** ERROR: Module load completed but symbols could not be loaded for ApplicationE.exe
Win32 Start Address ApplicationE (0×000000013f0f1578)
Stack Init fffff8800723cc70 Current fffff8800723c960
Base fffff8800723d000 Limit fffff88007237000 Call 0
Priority 8 BasePriority 8 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5
Child-SP          RetAddr           Call Site
00000000`0021f9e0 00000000`00000000 ApplicationE+0×6cd3

The largest KernelTime value:
Evaluate expression: 187 = 00000000`000000bb

THREAD fffffa80098d7b60  Cid 07bc.0a14  Teb: 000007fffffd7000 Win32Thread: fffff900c2ca0c20 WAIT: (UserRequest) KernelMode Non-Alertable
    fffffa8008a4a030  NotificationEvent
Not impersonating
DeviceMap                 fffff8a001ce6b90
Owning Process            fffffa80096beb30       Image:         dwm.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      22294          Ticks: 1 (0:00:00:00.015)
Context Switch Count      15473                 LargeStack
UserTime                  00:00:06.801
KernelTime                00:00:02.917
Win32 Start Address dwmcore!CPartitionThread::ThreadMain (0×000007fef8a1f0d8)
Stack Init fffff8800d3d5c70 Current fffff8800d3d5740
Base fffff8800d3d6000 Limit fffff8800d3cf000 Call 0
Priority 15 BasePriority 15 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5
Child-SP          RetAddr           Call Site
fffff880`0d3d5780 fffff800`02ee6f32 nt!KiSwapContext+0×7a
fffff880`0d3d58c0 fffff800`02ee974f nt!KiCommitThreadWait+0×1d2
fffff880`0d3d5950 fffff880`0fef65b3 nt!KeWaitForSingleObject+0×19f
fffff880`0d3d59f0 fffff960`001fedea dxgkrnl!DxgkWaitForVerticalBlankEvent+0×53f
fffff880`0d3d5ab0 fffff800`02ee0ed3 win32k!NtGdiDdDDIWaitForVerticalBlankEvent+0×12
fffff880`0d3d5ae0 000007fe`ff1d143a nt!KiSystemServiceCopyEnd+0×13 (TrapFrame @ fffff880`0d3d5ae0)
00000000`0287f778 000007fe`f8791da1 GDI32!NtGdiDdDDIWaitForVerticalBlankEvent+0xa
00000000`0287f780 000007fe`f89e1b6e dxgi!CDXGIOutput::WaitForVBlank+0×51
00000000`0287f7c0 000007fe`f89e1ae9 dwmcore!CD3DDeviceLevel1::WaitForVBlank+0×1f9
00000000`0287f810 000007fe`f89e1a9d dwmcore!CHwDisplayRenderTarget::WaitForVBlank+0×39
00000000`0287f850 000007fe`f89e1a4c dwmcore!CDesktopRenderTarget::WaitForVBlank+0×40
00000000`0287f880 000007fe`f89d3513 dwmcore!CSlaveHWndRenderTarget::WaitForVBlank+0×2c
00000000`0287f8c0 000007fe`f89d3584 dwmcore!CRenderTargetManager::WaitForVBlank+0×7d
00000000`0287f900 000007fe`f89d2661 dwmcore!CPartitionVerticalBlankScheduler::WaitForVBlank+0×7c
00000000`0287f950 000007fe`f8a1f0f4 dwmcore!CPartitionVerticalBlankScheduler::Run+0xe5
00000000`0287f9b0 00000000`7719652d dwmcore!CPartitionThread::ThreadMain+0×1c
00000000`0287f9e0 00000000`772cc521 kernel32!BaseThreadInitThunk+0xd
00000000`0287fa10 00000000`00000000 ntdll!RtlUserThreadStart+0×1d

The second script takes two arguments and shows all threads that have UserTime and KernelTime ticks value greater than (you can have the idea of the maximum from the previous script):

$$
$$ krunawaygt.wds
$$ Copyright (c) 2011 Memory Dump Analysis Services
$$ GNU GENERAL PUBLIC LICENSE
$$ http://www.gnu.org/licenses/gpl-3.0.txt
$$
!for_each_thread “r $t1 = dwo( @#Thread + @@c++(#FIELD_OFFSET(nt!_KTHREAD, UserTime)) ); r $t0 = $arg1; .if (@$t1 > @$t0) {!thread @#Thread ff}”
!for_each_thread “r $t1 = dwo( @#Thread + @@c++(#FIELD_OFFSET(nt!_KTHREAD, KernelTime)) ); r $t0 = $arg2; .if (@$t1 > @$t0) {!thread @#Thread ff}”

Using hints from the previous script run (the largest UserTime ticks value is 0×155e) we now get threads that spent more than 0×100 ticks in user mode:

0: kd> $$>a<c:\Scripts\krunawaygt.wds 100 100
THREAD fffffa800843e060  Cid 03f4.0658  Teb: 000007fffff90000 Win32Thread: 0000000000000000 WAIT: (WrQueue) UserMode Non-Alertable
    fffffa800843c2c0  QueueObject
Not impersonating
DeviceMap                 fffff8a000008aa0
Owning Process            fffffa800916b060       Image:         MsMpEng.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      21211          Ticks: 1084 (0:00:00:16.910)
Context Switch Count      6028            
UserTime                  00:00:10.140
KernelTime                00:00:00.296
Win32 Start Address msvcrt!endthreadex (0×000007feff5173fc)
Stack Init fffff88009d4bc70 Current fffff88009d4b660
Base fffff88009d4c000 Limit fffff88009d46000 Call 0
Priority 9 BasePriority 8 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5
*** ERROR: Symbol file could not be found.  Defaulted to export symbols for mprtp.dll -
Child-SP          RetAddr           Call Site
fffff880`09d4b6a0 fffff800`02ee6f32 nt!KiSwapContext+0×7a
fffff880`09d4b7e0 fffff800`02ee9f93 nt!KiCommitThreadWait+0×1d2
fffff880`09d4b870 fffff800`031ca647 nt!KeRemoveQueueEx+0×323
fffff880`09d4b930 fffff800`0319cae5 nt!IoRemoveIoCompletion+0×47
fffff880`09d4b9c0 fffff800`02ee0ed3 nt!NtRemoveIoCompletion+0×145
fffff880`09d4ba70 00000000`772f13aa nt!KiSystemServiceCopyEnd+0×13 (TrapFrame @ fffff880`09d4bae0)
00000000`0209fb08 000007fe`fd9e169d ntdll!ZwRemoveIoCompletion+0xa
00000000`0209fb10 00000000`7718a4e1 KERNELBASE!GetQueuedCompletionStatus+0×39
00000000`0209fb70 00000000`748f2c74 kernel32!GetQueuedCompletionStatusStub+0×11
00000000`0209fbb0 00000000`0045cbc0 mprtp!MpPluginSignatureChange+0×3e170
00000000`0209fbb8 000007fe`fbac25ff 0×45cbc0
00000000`0209fbc0 00000000`00466610 FLTLIB!FilterGetMessage+0×2b
00000000`0209fc20 00000000`00000000 0×466610

THREAD fffffa800845c060  Cid 03f4.065c  Teb: 000007fffff8e000 Win32Thread: 0000000000000000 WAIT: (WrQueue) UserMode Non-Alertable
    fffffa800843c2c0  QueueObject
Not impersonating
DeviceMap                 fffff8a000008aa0
Owning Process            fffffa800916b060       Image:         MsMpEng.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      21520          Ticks: 775 (0:00:00:12.090)
Context Switch Count      4979            
UserTime                  00:00:04.149
KernelTime                00:00:00.156
Win32 Start Address msvcrt!endthreadex (0×000007feff5173fc)
Stack Init fffff88009d52c70 Current fffff88009d52660
Base fffff88009d53000 Limit fffff88009d4d000 Call 0
Priority 8 BasePriority 8 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5
*** ERROR: Symbol file could not be found.  Defaulted to export symbols for mprtp.dll -
Child-SP          RetAddr           Call Site
fffff880`09d526a0 fffff800`02ee6f32 nt!KiSwapContext+0×7a
fffff880`09d527e0 fffff800`02ee9f93 nt!KiCommitThreadWait+0×1d2
fffff880`09d52870 fffff800`031ca647 nt!KeRemoveQueueEx+0×323
fffff880`09d52930 fffff800`0319cae5 nt!IoRemoveIoCompletion+0×47
fffff880`09d529c0 fffff800`02ee0ed3 nt!NtRemoveIoCompletion+0×145
fffff880`09d52a70 00000000`772f13aa nt!KiSystemServiceCopyEnd+0×13 (TrapFrame @ fffff880`09d52ae0)
00000000`01ccf498 000007fe`fd9e169d ntdll!ZwRemoveIoCompletion+0xa
00000000`01ccf4a0 00000000`7718a4e1 KERNELBASE!GetQueuedCompletionStatus+0×39
00000000`01ccf500 00000000`748f2c74 kernel32!GetQueuedCompletionStatusStub+0×11
00000000`01ccf540 00000000`0045d030 mprtp!MpPluginSignatureChange+0×3e170
00000000`01ccf548 000007fe`fbac25ff 0×45d030
00000000`01ccf550 00000000`004666b0 FLTLIB!FilterGetMessage+0×2b
00000000`01ccf5b0 00000000`00000000 0×4666b0

THREAD fffffa80092b7060  Cid 03f4.1268  Teb: 000007fffff6a000 Win32Thread: 0000000000000000 WAIT: (WrQueue) UserMode Alertable
    fffffa8009299140  QueueObject
Not impersonating
DeviceMap                 fffff8a000008aa0
Owning Process            fffffa800916b060       Image:         MsMpEng.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      7762           Ticks: 14533 (0:00:03:46.716)
Context Switch Count      3297            
UserTime                  00:00:06.489
KernelTime                00:00:00.499
Win32 Start Address ntdll!TppWorkerThread (0×00000000772bfbc0)
Stack Init fffff8800e620c70 Current fffff8800e620680
Base fffff8800e621000 Limit fffff8800e61b000 Call 0
Priority 8 BasePriority 8 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5
Child-SP          RetAddr           Call Site
fffff880`0e6206c0 fffff800`02ee6f32 nt!KiSwapContext+0×7a
fffff880`0e620800 fffff800`02ee9f93 nt!KiCommitThreadWait+0×1d2
fffff880`0e620890 fffff800`031ca647 nt!KeRemoveQueueEx+0×323
fffff880`0e620950 fffff800`02ecdb36 nt!IoRemoveIoCompletion+0×47
fffff880`0e6209e0 fffff800`02ee0ed3 nt!NtWaitForWorkViaWorkerFactory+0×285
fffff880`0e620ae0 00000000`772f2c1a nt!KiSystemServiceCopyEnd+0×13 (TrapFrame @ fffff880`0e620ae0)
00000000`0540f998 00000000`772bfe0b ntdll!ZwWaitForWorkViaWorkerFactory+0xa
00000000`0540f9a0 00000000`7719652d ntdll!TppWorkerThread+0×2c9
00000000`0540fca0 00000000`772cc521 kernel32!BaseThreadInitThunk+0xd
00000000`0540fcd0 00000000`00000000 ntdll!RtlUserThreadStart+0×1d

THREAD fffffa80098d7b60  Cid 07bc.0a14  Teb: 000007fffffd7000 Win32Thread: fffff900c2ca0c20 WAIT: (UserRequest) KernelMode Non-Alertable
    fffffa8008a4a030  NotificationEvent
Not impersonating
DeviceMap                 fffff8a001ce6b90
Owning Process            fffffa80096beb30       Image:         dwm.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      22294          Ticks: 1 (0:00:00:00.015)
Context Switch Count      15473                 LargeStack
UserTime                  00:00:06.801
KernelTime                00:00:02.917
Win32 Start Address dwmcore!CPartitionThread::ThreadMain (0×000007fef8a1f0d8)
Stack Init fffff8800d3d5c70 Current fffff8800d3d5740
Base fffff8800d3d6000 Limit fffff8800d3cf000 Call 0
Priority 15 BasePriority 15 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5
Child-SP          RetAddr           Call Site
fffff880`0d3d5780 fffff800`02ee6f32 nt!KiSwapContext+0×7a
fffff880`0d3d58c0 fffff800`02ee974f nt!KiCommitThreadWait+0×1d2
fffff880`0d3d5950 fffff880`0fef65b3 nt!KeWaitForSingleObject+0×19f
fffff880`0d3d59f0 fffff960`001fedea dxgkrnl!DxgkWaitForVerticalBlankEvent+0×53f
fffff880`0d3d5ab0 fffff800`02ee0ed3 win32k!NtGdiDdDDIWaitForVerticalBlankEvent+0×12
fffff880`0d3d5ae0 000007fe`ff1d143a nt!KiSystemServiceCopyEnd+0×13 (TrapFrame @ fffff880`0d3d5ae0)
00000000`0287f778 000007fe`f8791da1 GDI32!NtGdiDdDDIWaitForVerticalBlankEvent+0xa
00000000`0287f780 000007fe`f89e1b6e dxgi!CDXGIOutput::WaitForVBlank+0×51
00000000`0287f7c0 000007fe`f89e1ae9 dwmcore!CD3DDeviceLevel1::WaitForVBlank+0×1f9
00000000`0287f810 000007fe`f89e1a9d dwmcore!CHwDisplayRenderTarget::WaitForVBlank+0×39
00000000`0287f850 000007fe`f89e1a4c dwmcore!CDesktopRenderTarget::WaitForVBlank+0×40
00000000`0287f880 000007fe`f89d3513 dwmcore!CSlaveHWndRenderTarget::WaitForVBlank+0×2c
00000000`0287f8c0 000007fe`f89d3584 dwmcore!CRenderTargetManager::WaitForVBlank+0×7d
00000000`0287f900 000007fe`f89d2661 dwmcore!CPartitionVerticalBlankScheduler::WaitForVBlank+0×7c
00000000`0287f950 000007fe`f8a1f0f4 dwmcore!CPartitionVerticalBlankScheduler::Run+0xe5
00000000`0287f9b0 00000000`7719652d dwmcore!CPartitionThread::ThreadMain+0×1c
00000000`0287f9e0 00000000`772cc521 kernel32!BaseThreadInitThunk+0xd
00000000`0287fa10 00000000`00000000 ntdll!RtlUserThreadStart+0×1d

THREAD fffffa800451d720  Cid 1418.17fc  Teb: 000007fffffdc000 Win32Thread: 0000000000000000 RUNNING on processor 2
Not impersonating
DeviceMap                 fffff8a001ce6b90
Owning Process            fffffa800442ab30       Image:         ApplicationE.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      22295          Ticks: 0
Context Switch Count      27960            
UserTime                  00:01:25.332
KernelTime                00:00:00.015
*** ERROR: Module load completed but symbols could not be loaded for ApplicationE.exe
Win32 Start Address ApplicationE (0×000000013f0f1578)
Stack Init fffff8800723cc70 Current fffff8800723c960
Base fffff8800723d000 Limit fffff88007237000 Call 0
Priority 8 BasePriority 8 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5
Child-SP          RetAddr           Call Site
00000000`0021f9e0 00000000`00000000 ApplicationE+0×6cd3

Memory Dump Analysis Services is now working to incorporate client-side WinDbg scripting into their CARE2 architecture. 

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org

Bugtation No.148

Thursday, December 1st, 2011

Does God play keyboard?

Dmitry Vostokov, Memoriarch, Founder of Memory Religion (Memorianity)

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