Archive for September, 2012

Event Owners

Sunday, September 30th, 2012

When we dump a stack trace collection from a complete or kernel memory dump we see lots of synchronization and notification events, for example:

THREAD fffffa8003d33120  Cid 0734.0868  Teb: 000007fffffd4000 Win32Thread: fffff900c07182e0 WAIT: (UserRequest) UserMode Alertable
fffffa8003413d20  NotificationEvent
fffffa80020b5170  NotificationEvent
fffffa80017f31e0  NotificationEvent
fffffa80013f8cf0  NotificationEvent
fffffa8002547ee0  NotificationEvent
fffffa8002547e80  NotificationEvent
fffffa8004186100  NotificationEvent
fffffa8003dcfa80  NotificationEvent
fffffa8003df6870  NotificationEvent
fffffa8003bbd5e0  NotificationEvent
fffffa8003b5d4e0  NotificationEvent
fffffa800390c690  NotificationEvent
fffffa8003dbc410  NotificationEvent
fffffa8003dbc3b0  NotificationEvent
fffffa8004041040  NotificationEvent
fffffa8003dde8a0  NotificationEvent
fffffa80038f4530  NotificationEvent
fffffa800401fa50  NotificationEvent
fffffa800398a550  NotificationEvent
fffffa8003b587e0  NotificationEvent
fffffa800398d200  SynchronizationEvent
IRP List:
fffffa800150b010: (0006,0358) Flags: 00060000  Mdl: 00000000
fffffa80015c1010: (0006,0358) Flags: 00060000  Mdl: 00000000
fffffa80017f53a0: (0006,0358) Flags: 00060000  Mdl: 00000000
fffffa80014ccca0: (0006,0358) Flags: 00060000  Mdl: 00000000
fffffa80011fa710: (0006,03a0) Flags: 00060000  Mdl: 00000000
fffffa80011d6070: (0006,0358) Flags: 00060000  Mdl: 00000000
fffffa80030b5450: (0006,0358) Flags: 00060000  Mdl: 00000000
fffffa8004149810: (0006,0358) Flags: 00060000  Mdl: 00000000
fffffa800419b500: (0006,0358) Flags: 00060000  Mdl: 00000000
fffffa80040c2520: (0006,0358) Flags: 00060000  Mdl: 00000000
fffffa8003b75520: (0006,0358) Flags: 00060000  Mdl: 00000000
fffffa8004082ca0: (0006,0358) Flags: 00060000  Mdl: 00000000
fffffa8004082010: (0006,0358) Flags: 00060000  Mdl: 00000000
fffffa800403aa40: (0006,0358) Flags: 00060000  Mdl: 00000000
fffffa800403a010: (0006,0358) Flags: 00060000  Mdl: 00000000
fffffa8003dbc9d0: (0006,0358) Flags: 00060000  Mdl: 00000000
fffffa8003dbc010: (0006,0358) Flags: 00060000  Mdl: 00000000
Not impersonating
DeviceMap                 fffff88001697690
Owning Process            fffffa80039bac10       Image:         explorer.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      41897          Ticks: 561 (0:00:00:08.765)
Context Switch Count      4744                 LargeStack
UserTime                  00:00:00.187
KernelTime                00:00:01.218
Win32 Start Address SHLWAPI!WrapperThreadProc (0×000007fefe854f20)
Stack Init fffff9800ef2fdb0 Current fffff9800ef2f260
Base fffff9800ef30000 Limit fffff9800ef27000 Call 0
Priority 12 BasePriority 8 PriorityDecrement 2 IoPriority 2 PagePriority 5
Child-SP          RetAddr           Call Site
fffff980`0ef2f2a0 fffff800`0185d695 nt!KiSwapContext+0×84
fffff980`0ef2f3e0 fffff800`0185ad2f nt!KiSwapThread+0×125
fffff980`0ef2f440 fffff800`01ac1813 nt!KeWaitForMultipleObjects+0×703
fffff980`0ef2f4b0 fffff800`01ac1a03 nt!ObpWaitForMultipleObjects+0×216
fffff980`0ef2f960 fffff800`0184dcf3 nt!NtWaitForMultipleObjects+0xe2
fffff980`0ef2fbb0 00000000`776f082a nt!KiSystemServiceCopyEnd+0×13 (TrapFrame @ fffff980`0ef2fc20)
00000000`03acf718 00000000`774ced73 ntdll!NtWaitForMultipleObjects+0xa
00000000`03acf720 00000000`775ee97d kernel32!WaitForMultipleObjectsEx+0×10b
00000000`03acf830 00000000`775ee86e USER32!RealMsgWaitForMultipleObjectsEx+0×129
00000000`03acf8d0 000007fe`fed47a9a USER32!MsgWaitForMultipleObjectsEx+0×46
00000000`03acf910 000007fe`fe854d48 SHELL32!CChangeNotify::ThreadProc+0xba
00000000`03acfb90 00000000`774ccdcd SHLWAPI!WrapperThreadProc+0xfc
00000000`03acfc70 00000000`776ec6e1 kernel32!BaseThreadInitThunk+0xd
00000000`03acfca0 00000000`00000000 ntdll!RtlUserThreadStart+0×1d

The problem with such synchronization objects as events is that they don’t have an owner field as in other structures:

1: kd> dt -r _KEVENT
ntdll!_KEVENT
+0x000 Header           : _DISPATCHER_HEADER
+0x000 Type             : UChar
+0x001 Abandoned        : UChar
+0x001 Absolute         : UChar
+0x001 NpxIrql          : UChar
+0x001 Signalling       : UChar
+0x002 Size             : UChar
+0x002 Hand             : UChar
+0x003 Inserted         : UChar
+0x003 DebugActive      : UChar
+0x003 DpcActive        : UChar
+0x000 Lock             : Int4B
+0x004 SignalState      : Int4B
+0x008 WaitListHead     : _LIST_ENTRY
+0x000 Flink            : Ptr64 _LIST_ENTRY
+0x008 Blink            : Ptr64 _LIST_ENTRY

1: kd> dt _KMUTANT
nt!_KMUTANT
+0x000 Header           : _DISPATCHER_HEADER
+0x018 MutantListEntry  : _LIST_ENTRY
+0×028 OwnerThread      : Ptr64 _KTHREAD
+0×030 Abandoned        : UChar
+0×031 ApcDisable       : UChar

Fortunately many of such events are created to wait for asynchronous I/O and their addresses are stored in IRP structures that also have an associated thread. For example, in the thread above we find one of notification events, fffffa80020b5170, in an IRP fffffa800150b010:

1: kd> !irp fffffa800150b010 -v
Irp is active with 9 stacks 9 is current (= 0xfffffa800150b320)
No Mdl: No System Buffer: Thread fffffa8003d33120:  Irp stack trace.
Flags = 00060000
ThreadListEntry.Flink = fffffa80015c1030
ThreadListEntry.Blink = fffffa8003d334d8
IoStatus.Status = 00000000
IoStatus.Information = fffff88002ac09c0
RequestorMode = 00000001
Cancel = 00
CancelIrql = 0
ApcEnvironment = 00
UserIosb = 04127ca0
UserEvent = fffffa80020b5170
Overlay.AsynchronousParameters.UserApcRoutine = 00000000
Overlay.AsynchronousParameters.UserApcContext = 04127ca0
Overlay.AllocationSize = 00000000 - 00000000
CancelRoutine = fffff80001912fc0   nt!FsRtlCancelNotify
UserBuffer = 04127498
&Tail.Overlay.DeviceQueueEntry = fffffa800150b088
Tail.Overlay.Thread = fffffa8003d33120
Tail.Overlay.AuxiliaryBuffer = 00000000
Tail.Overlay.ListEntry.Flink = fffff88002ac0a00
Tail.Overlay.ListEntry.Blink = fffff88002ac0a00
Tail.Overlay.CurrentStackLocation = fffffa800150b320
Tail.Overlay.OriginalFileObject = fffffa8002390770
Tail.Apc = 00000000
Tail.CompletionKey = 00000000
cmd  flg cl Device   File     Completion-Context
[  0, 0]   0  0 00000000 00000000 00000000-00000000
Args: 00000000 00000000 00000000 00000000
[  0, 0]   0  0 00000000 00000000 00000000-00000000
Args: 00000000 00000000 00000000 00000000
[  0, 0]   0  0 00000000 00000000 00000000-00000000
Args: 00000000 00000000 00000000 00000000
[  0, 0]   0  0 00000000 00000000 00000000-00000000
Args: 00000000 00000000 00000000 00000000
[  0, 0]   0  0 00000000 00000000 00000000-00000000
Args: 00000000 00000000 00000000 00000000
[  0, 0]   0  0 00000000 00000000 00000000-00000000
Args: 00000000 00000000 00000000 00000000
[  0, 0]   0  0 00000000 00000000 00000000-00000000
Args: 00000000 00000000 00000000 00000000
[  0, 0]   0  0 00000000 00000000 00000000-00000000
Args: 00000000 00000000 00000000 00000000
>[  c, 2]   0  1 fffffa8001bcb030 fffffa8002390770 00000000-00000000    pending
\FileSystem\Ntfs
Args: 00000800 00000015 00000000 00000000

Another example when IRP fffffa80022d4410 was created by one thread fffffa8002119700 but another thread fffffa8001fda450 is waiting for its associated event fffffa8002093190:

1: kd> !irpfind
Irp    [ Thread ] irpStack: (Mj,Mn)   DevObj  [Driver]         MDL Process
fffffa8002f2d980 [00000000] irpStack: ( f, 0)  fffffa8002f6f050 [ \Driver\usbehci]
fffffa800200dc40 [fffffa80030a0710] irpStack: ( d, 0)  fffffa8001f192d0 [ \FileSystem\Npfs]
fffffa800203d280 [fffffa80035b1b10] irpStack: ( e, 0)  fffffa8001c09b50 [ \Driver\netbt] 0xfffffa8002f10970
fffffa800228e4e0 [00000000] irpStack: ( e, 0)  fffffa8002be1840 [ \Driver\CmBatt]
fffffa800229c6a0 [00000000] irpStack: ( f, 0)  fffffa8002f2c050 [ \Driver\usbuhci]
fffffa800229a6a0 [00000000] irpStack: ( f, 0)  fffffa8002f2c050 [ \Driver\usbuhci]
fffffa80022946a0 [00000000] irpStack: ( f, 0)  fffffa8002f2c050 [ \Driver\usbuhci]
fffffa80022a28a0 [00000000] irpStack: ( f, 0)  fffffa80022d04c0 [ \Driver\usbhub]
fffffa80022a6230 [00000000] irpStack: ( f, 0)  fffffa8002f2c050 [ \Driver\usbuhci]
fffffa80022d4410 [fffffa8002119700] irpStack: ( e,2d)  fffffa80022ee720 [ \Driver\AFD]
[…]

1: kd> !irp fffffa80022d4410 -v
Irp is active with 4 stacks 4 is current (= 0xfffffa80022d45b8)
No Mdl: System buffer=fffffa8001fda150: Thread fffffa8002119700:  Irp stack trace.
Flags = 00060030
ThreadListEntry.Flink = fffffa8002396c80
ThreadListEntry.Blink = fffffa8002119ab8
IoStatus.Status = 00000000
IoStatus.Information = 00000000
RequestorMode = 00000001
Cancel = 00
CancelIrql = 0
ApcEnvironment = 00
UserIosb = 7fefc914858
UserEvent = fffffa8002093190
Overlay.AsynchronousParameters.UserApcRoutine = 00000000
Overlay.AsynchronousParameters.UserApcContext = 7fefc914858
Overlay.AllocationSize = 00000000 - 00000000
CancelRoutine = fffff980044ad250   afd!AfdCancelAddressListChange
UserBuffer = 00000000
&Tail.Overlay.DeviceQueueEntry = fffffa80022d4488
Tail.Overlay.Thread = fffffa8002119700
Tail.Overlay.AuxiliaryBuffer = 00000000
Tail.Overlay.ListEntry.Flink = 00000000
Tail.Overlay.ListEntry.Blink = 00000000
Tail.Overlay.CurrentStackLocation = fffffa80022d45b8
Tail.Overlay.OriginalFileObject = fffffa8002bbe050
Tail.Apc = 00000000
Tail.CompletionKey = 00000000
cmd  flg cl Device   File     Completion-Context
[  0, 0]   0  0 00000000 00000000 00000000-00000000
Args: 00000000 00000000 00000000 00000000
[  0, 0]   0  0 00000000 00000000 00000000-00000000
Args: 00000000 00000000 00000000 00000000
[  0, 0]   0  0 00000000 00000000 00000000-00000000
Args: 00000000 00000000 00000000 00000000
>[  e,2d]   5  1 fffffa80022ee720 fffffa8002bbe050 00000000-00000000    pending
\Driver\AFD
Args: fffffa8002bbef50 fffffa8002bbef50 fffff9800446cf00 fffffa800250d220

THREAD fffffa8002119700  Cid 0310.0318  Teb: 000007fffffdc000 Win32Thread: fffff900c07b6d60 WAIT: (DelayExecution) UserMode Non-Alertable
fffffa80021197b8  NotificationTimer
IRP List:
fffffa80022d4410: (0006,03a0) Flags: 00060030  Mdl: 00000000
fffffa8002396c60: (0006,03a0) Flags: 00060030  Mdl: 00000000
Not impersonating
DeviceMap                 fffff880017b4c70
Owning Process            fffffa800209f880       Image:         svchost.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      42336          Ticks: 122 (0:00:00:01.906)
Context Switch Count      159                 LargeStack
UserTime                  00:00:00.031
KernelTime                00:00:00.140
Win32 Start Address ADVAPI32!ScSvcctrlThreadW (0×000007fefe2b4bd0)
Stack Init fffff9800ccabdb0 Current fffff9800ccab990
Base fffff9800ccac000 Limit fffff9800cca6000 Call 0
Priority 9 BasePriority 8 PriorityDecrement 0 IoPriority 2 PagePriority 5
Child-SP          RetAddr           Call Site
fffff980`0ccab9d0 fffff800`0185d695 nt!KiSwapContext+0×84
fffff980`0ccabb10 fffff800`0185bbe9 nt!KiSwapThread+0×125
fffff980`0ccabb70 fffff800`01a8b1cd nt!KeDelayExecutionThread+0×339
fffff980`0ccabbf0 fffff800`0184dcf3 nt!NtDelayExecution+0×5c
fffff980`0ccabc20 00000000`776f05ba nt!KiSystemServiceCopyEnd+0×13 (TrapFrame @ fffff980`0ccabc20)
00000000`000ff9d8 00000000`774cd908 ntdll!NtDelayExecution+0xa
00000000`000ff9e0 000007fe`fc8ba8c0 kernel32!SleepEx+0×84
00000000`000ffa60 000007fe`fc8b17bd rpcss!ObjectExporterWorkerThread+0×50b
00000000`000ffb30 000007fe`fc8b27f2 rpcss!ScmServiceMain+0xe4
00000000`000ffb60 00000000`ffaa1771 rpcss!ServiceMain+0×251
00000000`000ffe20 000007fe`fe2b4bf5 svchost!ServiceStarter+0×1ea
00000000`000ffeb0 00000000`774ccdcd ADVAPI32!ScSvcctrlThreadW+0×25
00000000`000ffee0 00000000`776ec6e1 kernel32!BaseThreadInitThunk+0xd
00000000`000fff10 00000000`00000000 ntdll!RtlUserThreadStart+0×1d

THREAD fffffa8001fda450  Cid 0310.031c  Teb: 000007fffffda000 Win32Thread: 0000000000000000 WAIT: (UserRequest) UserMode Alertable
fffffa8002012ef0  SynchronizationTimer
fffffa800208d7a0  SynchronizationEvent
fffffa80023bb820  SynchronizationEvent
fffffa80023bb740  SynchronizationEvent
fffffa8001fd9730  SynchronizationEvent
fffffa8002093190  SynchronizationEvent
fffffa8001a0eee0  SynchronizationEvent
Not impersonating
DeviceMap                 fffff880017b4c70
Owning Process            fffffa800209f880       Image:         svchost.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      5767           Ticks: 36691 (0:00:09:33.296)
Context Switch Count      8
UserTime                  00:00:00.000
KernelTime                00:00:00.000
Win32 Start Address ntdll!TppWaiterpThread (0×00000000776c6930)
Stack Init fffff9800d2c0db0 Current fffff9800d2c0260
Base fffff9800d2c1000 Limit fffff9800d2bb000 Call 0
Priority 10 BasePriority 8 PriorityDecrement 0 IoPriority 2 PagePriority 5
Kernel stack not resident.
Child-SP          RetAddr           Call Site
fffff980`0d2c02a0 fffff800`0185d695 nt!KiSwapContext+0×84
fffff980`0d2c03e0 fffff800`0185ad2f nt!KiSwapThread+0×125
fffff980`0d2c0440 fffff800`01ac1813 nt!KeWaitForMultipleObjects+0×703
fffff980`0d2c04b0 fffff800`01ac1a03 nt!ObpWaitForMultipleObjects+0×216
fffff980`0d2c0960 fffff800`0184dcf3 nt!NtWaitForMultipleObjects+0xe2
fffff980`0d2c0bb0 00000000`776f082a nt!KiSystemServiceCopyEnd+0×13 (TrapFrame @ fffff980`0d2c0c20)
00000000`00d1fb08 00000000`776c6b07 ntdll!NtWaitForMultipleObjects+0xa
00000000`00d1fb10 00000000`774ccdcd ntdll!TppWaiterpThread+0×14d
00000000`00d1fdb0 00000000`776ec6e1 kernel32!BaseThreadInitThunk+0xd
00000000`00d1fde0 00000000`00000000 ntdll!RtlUserThreadStart+0×1d

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

Analytic Memory Dump - A Mathematical Definition

Friday, September 28th, 2012

The previous mathematical definition of memory dump is for raw memory dumps. They are not really useful because they require symbol files. Each symbol file entry conceptually is a correspondence between a memory address and a direct sum or product of letters from some alphabet:

00000000`76e82c40: kernel32!WaitForMultipleObjectsExImplementation

So we propose an analytical definition of a memory dump as a direct sum of disjoint memory areas Mt taken during some time interval (t0, …, tn) where we replace stk having values from Z2 with Stq having values from Zp and cardinality of Zp depending on a platform (32, 64, etc) plus a symbolic description Di for each Stq with cardinality of ”i” set sufficient enough to accommodate the largest symbolic name:

M = Mt where Mt = ∑(Stq+Di)

or simply

M = (Stq+Di)

This can be visualized as a linear memory space such as a virtual memory space when symbol files are applied to modules one after another. However, all this is not necessary, as a symbol from a virtual address can also be mapped to a physical address if necessary. Di, in fact, refers to any symbolic description.

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

Trace Analysis Patterns (Part 52)

Wednesday, September 26th, 2012

The modern software trace recording, visualization and analysis tools such as Process Monitor, Xperf, WPR and WPA provide stack traces associated with trace messages. Consider stack traces as software traces we have, in a more general case, traces (fibers) bundled together on (attached to) a base software trace. For example, a trace message, that mentions an IRP can have its I/O stack attached together with thread stack trace with function calls leading to a function that emitted the trace message. Another example is association of different types of traces with trace messages such as managed and unmanaged ones. This general trace analysis pattern needs a name so we opted for Fiber Bundle as analogy with a fiber bundle from mathematics. Here’s a graphical representation of stack traces recorded for each trace message where one message also has an associated I/O stack trace:

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

Bugtation No.159

Tuesday, September 25th, 2012

Software diagnosis requires intelligence.

Dmitry Vostokov

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

Crash Dump Analysis Patterns (Part 29d)

Monday, September 24th, 2012

This is a high contention pattern variant where the contention is around a monitor object. For example, we have a distributed CPU spike for some threads:

0:000> !runaway
 User Mode Time
  Thread       Time
   9:6ff4      0 days 0:07:39.019
  12:6b88      0 days 0:06:19.786
  11:6bf0      0 days 0:06:13.889
  10:6930      0 days 0:06:09.240
  16:3964      0 days 0:05:44.483
  17:6854      0 days 0:05:35.326
  13:668c      0 days 0:05:35.123
  14:5594      0 days 0:05:34.858
  15:7248      0 days 0:05:23.111
   2:c54       0 days 0:00:41.215
   4:1080      0 days 0:00:00.349
   7:10f0      0 days 0:00:00.302
   0:c3c       0 days 0:00:00.271
[...]

If we look at their stack traces we find them all blocked trying to enter a monitor, for example:

0:000> ~*k

[...]

  12  Id: d50.6b88 Suspend: 0 Teb: 000007ff`fffd8000 Unfrozen
Child-SP          RetAddr           Call Site
00000000`1a98e798 000007fe`fd0c1420 ntdll!ZwWaitForMultipleObjects+0xa
00000000`1a98e7a0 00000000`76e82cf3 KERNELBASE!WaitForMultipleObjectsEx+0xe8
00000000`1a98e8a0 000007fe`f82e0669 kernel32!WaitForMultipleObjectsExImplementation+0xb3
00000000`1a98e930 000007fe`f82dbec9 mscorwks!WaitForMultipleObjectsEx_SO_TOLERANT+0xc1
00000000`1a98e9d0 000007fe`f82a0569 mscorwks!Thread::DoAppropriateAptStateWait+0x41
00000000`1a98ea30 000007fe`f82beaec mscorwks!Thread::DoAppropriateWaitWorker+0x191
00000000`1a98eb30 000007fe`f81f1b9a mscorwks!Thread::DoAppropriateWait+0x5c
00000000`1a98eba0 000007fe`f82fd3c9 mscorwks!CLREvent::WaitEx+0xbe
00000000`1a98ec50 000007fe`f81ac6be mscorwks!AwareLock::EnterEpilog+0xc9
00000000`1a98ed20 000007fe`f81c7b2b mscorwks!AwareLock::Enter+0x72
00000000`1a98ed50 000007fe`f87946af mscorwks!AwareLock::Contention+0x1fb
00000000`1a98ee20 000007ff`00161528 mscorwks!JITutil_MonContention+0xdf
00000000`1a98efd0 000007ff`0016140e 0×7ff`00161528
00000000`1a98f040 000007ff`00167271 0×7ff`0016140e
00000000`1a98f0a0 000007fe`f74e2bbb 0×7ff`00167271
00000000`1a98f130 000007fe`f753ed76 mscorlib_ni+0×2f2bbb
00000000`1a98f180 000007fe`f8390282 mscorlib_ni+0×34ed76
00000000`1a98f1d0 000007fe`f8274363 mscorwks!CallDescrWorker+0×82
00000000`1a98f220 000007fe`f8274216 mscorwks!CallDescrWorkerWithHandler+0xd3
00000000`1a98f2c0 000007fe`f81c96a7 mscorwks!DispatchCallDebuggerWrapper+0×3e
00000000`1a98f320 000007fe`f830ae42 mscorwks!DispatchCallNoEH+0×5f
00000000`1a98f3a0 000007fe`f81bdc00 mscorwks!AddTimerCallback_Worker+0×92
00000000`1a98f430 000007fe`f82a41a5 mscorwks!ManagedThreadCallState::IsAppDomainEqual+0×4c
00000000`1a98f480 000007fe`f82df199 mscorwks!SVR::gc_heap::make_heap_segment+0×155
00000000`1a98f550 000007fe`f82ececa mscorwks!DoOpenIAssemblyStress::DoOpenIAssemblyStress+0×99
00000000`1a98f590 000007fe`f830c0db mscorwks!AddTimerCallbackEx+0xba
00000000`1a98f650 000007fe`f81ebb37 mscorwks!ThreadpoolMgr::AsyncTimerCallbackCompletion+0×53
00000000`1a98f6b0 000007fe`f81fe92a mscorwks!UnManagedPerAppDomainTPCount::DispatchWorkItem+0×157
00000000`1a98f750 000007fe`f81bb1fc mscorwks!ThreadpoolMgr::WorkerThreadStart+0×1ba
00000000`1a98f7f0 00000000`76e7652d mscorwks!Thread::intermediateThreadProc+0×78
00000000`1a98fcc0 00000000`76fac521 kernel32!BaseThreadInitThunk+0xd
00000000`1a98fcf0 00000000`00000000 ntdll!RtlUserThreadStart+0×1d

[...]

  15  Id: d50.7248 Suspend: 0 Teb: 000007ff`ffee6000 Unfrozen
Child-SP          RetAddr           Call Site
00000000`1c16e6f0 000007fe`f87946af mscorwks!AwareLock::Contention+0×13b
00000000`1c16e7c0 000007ff`0016135e mscorwks!JITutil_MonContention+0xdf

00000000`1c16e970 000007ff`0016726b 0×7ff`0016135e
00000000`1c16e9c0 000007fe`f74e2bbb 0×7ff`0016726b
00000000`1c16ea50 000007fe`f753ed76 mscorlib_ni+0×2f2bbb
00000000`1c16eaa0 000007fe`f8390282 mscorlib_ni+0×34ed76
00000000`1c16eaf0 000007fe`f8274363 mscorwks!CallDescrWorker+0×82
00000000`1c16eb40 000007fe`f8274216 mscorwks!CallDescrWorkerWithHandler+0xd3
00000000`1c16ebe0 000007fe`f81c96a7 mscorwks!DispatchCallDebuggerWrapper+0×3e
00000000`1c16ec40 000007fe`f830ae42 mscorwks!DispatchCallNoEH+0×5f
00000000`1c16ecc0 000007fe`f81bdc00 mscorwks!AddTimerCallback_Worker+0×92
00000000`1c16ed50 000007fe`f82a41a5 mscorwks!ManagedThreadCallState::IsAppDomainEqual+0×4c
00000000`1c16eda0 000007fe`f82df199 mscorwks!SVR::gc_heap::make_heap_segment+0×155
00000000`1c16ee70 000007fe`f82ececa mscorwks!DoOpenIAssemblyStress::DoOpenIAssemblyStress+0×99
00000000`1c16eeb0 000007fe`f830c0db mscorwks!AddTimerCallbackEx+0xba
00000000`1c16ef70 000007fe`f81ebb37 mscorwks!ThreadpoolMgr::AsyncTimerCallbackCompletion+0×53
00000000`1c16efd0 000007fe`f81fe92a mscorwks!UnManagedPerAppDomainTPCount::DispatchWorkItem+0×157
00000000`1c16f070 000007fe`f81bb1fc mscorwks!ThreadpoolMgr::WorkerThreadStart+0×1ba
00000000`1c16f110 00000000`76e7652d mscorwks!Thread::intermediateThreadProc+0×78
00000000`1c16f9e0 00000000`76fac521 kernel32!BaseThreadInitThunk+0xd
00000000`1c16fa10 00000000`00000000 ntdll!RtlUserThreadStart+0×1d

[...]

Thread #15 seems was caught at the time it was trying to enter and not waiting yet. If we check a monitor object the thread #12 tries to enter we see it has an address 01af0be8:

0:000> !u 000007ff`00161528
Normal JIT generated code
[…]
000007ff`00161505 90              nop
000007ff`00161506 48b8f089ae1100000000 mov rax,11AE89F0h
000007ff`00161510 488b00          mov     rax,qword ptr [rax]
000007ff`00161513 48894528        mov     qword ptr [rbp+28h],rax
000007ff`00161517 488b4528        mov     rax,qword ptr [rbp+28h]
000007ff`0016151b 48894518        mov     qword ptr [rbp+18h],rax
000007ff`0016151f 488b4d28        mov     rcx,qword ptr [rbp+28h]
000007ff`00161523 e8b8d422f8      call    mscorwks!JIT_MonEnter (000007fe`f838e9e0)
>>> 000007ff`00161528 90              nop
000007ff`00161529 90              nop
000007ff`0016152a 90              nop
[…]
000007ff`001615d2 4883c430        add     rsp,30h
000007ff`001615d6 5d              pop     rbp
000007ff`001615d7 f3c3            rep ret

0:000> dps 11AE89F0h l1
00000000`11ae89f0  00000000`01af0be8

This object seems to be owned by the thread #17:

0:000> !syncblk
Index         SyncBlock MonitorHeld Recursion Owning Thread Info          SyncBlock Owner
 1362 000000001ba7b6c0           15         1 000000001c0173b0  6854  17   0000000001af0be8 System.Object
[…]

This thread seems to be blocked in ALPC:

0:017> k
Child-SP          RetAddr           Call Site
00000000`1d55c9e8 000007fe`fee1a776 ntdll!NtAlpcSendWaitReceivePort+0xa
00000000`1d55c9f0 000007fe`fee14e42 rpcrt4!LRPC_CCALL::SendReceive+0x156
00000000`1d55cab0 000007fe`ff0828c0 rpcrt4!I_RpcSendReceive+0x42
00000000`1d55cae0 000007fe`ff08282f ole32!ThreadSendReceive+0x40
00000000`1d55cb30 000007fe`ff08265b ole32!CRpcChannelBuffer::SwitchAptAndDispatchCall+0xa3
00000000`1d55cbd0 000007fe`fef3daaa ole32!CRpcChannelBuffer::SendReceive2+0x11b
00000000`1d55cd90 000007fe`fef3da0c ole32!CAptRpcChnl::SendReceive+0x52
00000000`1d55ce60 000007fe`ff08205d ole32!CCtxComChnl::SendReceive+0x68
00000000`1d55cf10 000007fe`feebfd61 ole32!NdrExtpProxySendReceive+0x45
00000000`1d55cf40 000007fe`ff07f82f rpcrt4!NdrpClientCall2+0x9ea
00000000`1d55d6b0 000007fe`fef3d8a2 ole32!ObjectStublessClient+0x1ad
00000000`1d55da40 000007fe`fa511ba8 ole32!ObjectStubless+0x42
[...]
 

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

Webinar: Introduction to Philosophy of Software Diagnostics

Sunday, September 23rd, 2012

Learn from this Webinar about phenomenological, hermeneutical and analytical approaches to software diagnostics and its knowledge, foundations, norms, theories, logic, methodology, language, ontology, nature and truth. This seminar is hosted by Software Diagnostics Services.

 Introduction to Philosophy of Software Diagnostics Logo

Title: Introduction to Philosophy of Software Diagnostics
Date: 17th of December, 2012
Time: 19:00 GMT
Duration: 60 minutes

Space is limited.
Reserve your Webinar seat now at:
https://www3.gotomeeting.com/register/872846486

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

WinDbg as a Practical Reversing Tool

Thursday, September 20th, 2012

I was very pleased to find out this book that uses WinDbg as OS reversing tool. Not only you learn a very important aspect of Windows internals related to crash and hang memory dump analysis (all crash processing starts from memory manager) but you also learn many WinDbg commands from practical reversing experiments. I was even more pleased to find the output of WinDbg command on the page 0, before even the table of contents.

What Makes It Page?: The Windows 7 (x64) Virtual Memory Manager

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

Facets of Systems Science

Monday, September 17th, 2012

If you liked An Introduction to General Systems Thinking book then you really need this comprehensive introduction which is more formal. Don’t be overwhelmed by the number of pages, you only need to read part 1, the first 218 pages as the rest is a collection of articles you can read selectively later on. For me one of the great features was the coverage of systems literature including some mathematical treatment books (including category theory in addition to famous Rosen’s books such as Anticipatory Systems). I also liked the discussion of critics of general systems theory that points to the fact that it should be called general systems-theory not general-systems theory. Highly recommended.

Facets of Systems Science (IFSR International Series on Systems Science and Engineering)

- Dmitry Vostokov @ LiterateScientist.com -

Insane Amazon Review System

Friday, September 14th, 2012

We tried to post this positive review on Amazon 3 times and each time it was rejected despite being an Amazon verified purchase:

Mathematical Physics

We decided that we never post a review on Amazon again due to such censoring of an opinion about mathematical physics and category theory textbook.

- Dmitry Vostokov @ LiterateScientist.com -

Mathematical Physics

Friday, September 14th, 2012

This book came to my attention because it starts with category theory in the first chapters and then moves to traditional contemporary mathematical physics topics such as topology and operators. It also covers groups, vector spaces, their duals, tensors, associative and Lie algebras, representation theory, spectral theorem, distributions, homotopy and homology. The author also provides physical examples along the way such as Fock vector spaces, dynamical systems, Minkowski space and algebra of observables. The flow of this mathematical text is very smooth (proofs can be omitted from reading) and explanations are very intuitive. The latter seems to be the main goal of this text. It is also structured into 56 chapters so it can be possible to casually read this book in 2 months during commuting like I did. One strange thing I noticed though is the avoidance of the manifold terminology: the author only uses the word “manifold” only once and without an explanation what it is about so you may even not notice that.

Mathematical Physics (Chicago Lectures in Physics)

- Dmitry Vostokov @ LiterateScientist.com -

User Interface Problem Analysis Patterns (Part 2)

Sunday, September 9th, 2012

We continue with such problem pattern category and discuss Unresponsive Window pattern. The previous one was Error Message Box. We all see hang windows from time to time. This can happen, for example, from a main thread blocked in a wait chain. Some windows become unresponsive only temporary, for example, when a window message loop results in a CPU intensive window procedure code path. When I open large WinDbg logs generated by WinDbg scripts running on a complete memory dump in Notepad it opens up a frozen window for some seconds and sometimes for a minute or two. To get an unresponsive window for a longer time I opened a PDF file with a size of a few MB and I attached WinDbg. I got this stack trace:

0:000> k
Child-SP          RetAddr           Call Site
00000000`001ecce0 000007fe`ff9fdf89 USP10!otlCacheManager::GetNextLookup+0x12a
00000000`001ecd40 000007fe`ff9fa134 USP10!ApplyFeatures+0x489
00000000`001ed000 000007fe`ff9e1600 USP10!SubstituteOtlGlyphs+0x224
00000000`001ed0b0 000007fe`ff9d4b60 USP10!GenericEngineGetGlyphs+0x1000
00000000`001ed450 000007fe`ff9989c5 USP10!ShlShape+0x7a0
00000000`001ed670 000007fe`ff9a7363 USP10!ScriptShape+0x205
00000000`001ed710 000007fe`ff9a8ac9 USP10!RenderItemNoFallback+0x433
00000000`001ed7d0 000007fe`ff9a8d86 USP10!RenderItemWithFallback+0x129
00000000`001ed820 000007fe`ff9aa5f7 USP10!RenderItem+0x36
00000000`001ed870 000007fe`ff99b2c9 USP10!ScriptStringAnalyzeGlyphs+0x277
00000000`001ed910 000007fe`ff30285c USP10!ScriptStringAnalyse+0x399
00000000`001ed990 000007fe`ff3031c1 LPK!EditStringAnalyse+0x1d4
00000000`001eda70 000007fe`fc876c05 LPK!EditCchInWidth+0x4e
00000000`001edad0 000007fe`fc85862e COMCTL32!EditML_BuildchLines+0x221
00000000`001edba0 000007fe`fc878f56 COMCTL32!Edit_ResetTextInfo+0x82
00000000`001edbe0 000007fe`fc85a566 COMCTL32!EditML_WndProc+0x456
00000000`001edcd0 00000000`77a19bd1 COMCTL32!Edit_WndProc+0xe0a
00000000`001edd70 00000000`77a16aa8 USER32!UserCallWinProcCheckWow+0x1ad
00000000`001ede30 00000000`77a16bad USER32!SendMessageWorker+0x682
00000000`001edec0 00000000`ff7f4256 USER32!SendMessageW+0x5c
00000000`001edf10 00000000`ff7f43d6 NOTEPAD!LoadFile+0x7cb
00000000`001ee260 00000000`ff7f1018 NOTEPAD!NPInit+0x802
00000000`001efbb0 00000000`ff7f133c NOTEPAD!WinMain+0xc7
00000000`001efc30 00000000`7764652d NOTEPAD!DisplayNonGenuineDlgWorker+0x2da
00000000`001efcf0 00000000`77b2c521 kernel32!BaseThreadInitThunk+0xd
00000000`001efd20 00000000`00000000 ntdll!RtlUserThreadStart+0x1d

Another notepad.exe instance had this similar stack trace:

0:000> k
Child-SP          RetAddr           Call Site
00000000`0015ca60 000007fe`ff9e2152 USP10!ShapingLibraryInternal::RestoreCharMap+0x12
00000000`0015cab0 000007fe`ff9d80b8 USP10!GenericEngineGetGlyphPositions+0x2a2
00000000`0015ce60 000007fe`ff9d548e USP10!ShapingGetGlyphPositions+0x8c8
00000000`0015d030 000007fe`ff998c72 USP10!ShlPlace+0x2de
00000000`0015d1e0 000007fe`ff9a742d USP10!ScriptPlace+0x1f2
00000000`0015d270 000007fe`ff9a8ac9 USP10!RenderItemNoFallback+0x4fd
00000000`0015d330 000007fe`ff9a8d86 USP10!RenderItemWithFallback+0x129
00000000`0015d380 000007fe`ff9aa5f7 USP10!RenderItem+0x36
00000000`0015d3d0 000007fe`ff99b2c9 USP10!ScriptStringAnalyzeGlyphs+0x277
00000000`0015d470 000007fe`ff30285c USP10!ScriptStringAnalyse+0x399
00000000`0015d4f0 000007fe`ff3031c1 LPK!EditStringAnalyse+0x1d4
00000000`0015d5d0 000007fe`fc876c05 LPK!EditCchInWidth+0x4e
00000000`0015d630 000007fe`fc85862e COMCTL32!EditML_BuildchLines+0x221
00000000`0015d700 000007fe`fc878f56 COMCTL32!Edit_ResetTextInfo+0x82
00000000`0015d740 000007fe`fc85a566 COMCTL32!EditML_WndProc+0x456
00000000`0015d830 00000000`77a19bd1 COMCTL32!Edit_WndProc+0xe0a
00000000`0015d8d0 00000000`77a16aa8 USER32!UserCallWinProcCheckWow+0x1ad
00000000`0015d990 00000000`77a16bad USER32!SendMessageWorker+0x682
00000000`0015da20 00000000`ff7f4256 USER32!SendMessageW+0x5c
00000000`0015da70 00000000`ff7f43d6 NOTEPAD!LoadFile+0×7cb
00000000`0015ddc0 00000000`ff7f1018 NOTEPAD!NPInit+0×802
00000000`0015f710 00000000`ff7f133c NOTEPAD!WinMain+0xc7
00000000`0015f790 00000000`7764652d NOTEPAD!DisplayNonGenuineDlgWorker+0×2da
00000000`0015f850 00000000`77b2c521 kernel32!BaseThreadInitThunk+0xd
00000000`0015f880 00000000`00000000 ntdll!RtlUserThreadStart+0×1d

This thread is also spiking and all work was done in a Unicode script processor as the PDF file was obviously not an ASCII text file:

0:000> !runaway f
User Mode Time
Thread       Time
0:fa0       0 days 0:00:12.402
Kernel Mode Time
Thread       Time
0:fa0       0 days 0:00:10.826
Elapsed Time
Thread       Time
0:fa0       0 days 0:00:34.654

0:000> lmv m USP10
start             end                 module name
000007fe`ff990000 000007fe`ffa59000   USP10      (pdb symbols)          c:\mss\usp10.pdb\DB4EC1196F91457FBB0A462D9D0AFEC31\usp10.pdb
Loaded symbol image file: C:\Windows\system32\USP10.dll
Image path: C:\Windows\system32\USP10.dll
Image name: USP10.dll
Timestamp:        Sat Nov 20 13:15:33 2010 (4CE7C9F5)
CheckSum:         000C4B61
ImageSize:        000C9000
File version:     1.626.7601.17514
Product version:  1.626.7601.17514
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(R) Uniscribe Unicode script processor
InternalName:     Uniscribe
OriginalFilename: Uniscribe
ProductVersion:   1.0626.7601.17514
FileVersion:      1.0626.7601.17514 (win7sp1_rtm.101119-1850)
FileDescription:  Uniscribe Unicode script processor
LegalCopyright:   © Microsoft Corporation. All rights reserved.

We see LoadFile function and find a file name from execution residue on the raw stack:

0:000> dpu 00000000`0015da70
00000000`0015da70  00000000`00000000
00000000`0015da78  00000000`00000000
00000000`0015da80  00000000`00000000
00000000`0015da88  00000000`00000000
00000000`0015da90  00000000`02b40040 "%PDF-1.4..%µµµµ..1 0 obj..<</Type/Catalog/Pages 2 0 R/L"
00000000`0015da98  00000000`00576a62
00000000`0015daa0  00000000`00000000
00000000`0015daa8  00000000`00000000
00000000`0015dab0  00000000`025c0000
00000000`0015dab8  00000000`00000000
00000000`0015dac0  00000000`00000000
00000000`0015dac8  00000000`00000100
00000000`0015dad0  00000000`00000000
00000000`0015dad8  00000000`025c0000
00000000`0015dae0  00000000`00000265
00000000`0015dae8  00000000`ff800b40 "C:\DL\History-Russian-Literature-VIII-Volume2.pdf"
[...]

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