A page to reference all different kinds of optimization patterns 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 -
Finally, the new version of WinDbg: A Reference Poster and Learning Cards is under development. This time every page is published online for comments, suggestions and corrections which are very welcome. The format of every page follows colored memory space diagram where red cards are for native kernel space commands, blue cards are for unmanaged user space, and green cards are for managed .NET space (click on a picture to open a PDF file):
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
Most of the time it is not possible to trace from the beginning. Obviously, internal application tracing cannot trace anything before that application start and its early initialization. The same is for system wide tracing which cannot trace before the tracing subsystem or service starts. Therefore, each log has its Visibility Limit in addition to possible truncation or missing components:
One of solutions would be to use different tracing tools and inter-correlation to glue activities, for example, Process Monitor and CDFControl.
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
Not all processes are linked into a list that some commands traverse such as !process 0 0. A processes may unlink itself or be in an initialization stage. However, a process structure is allocated from nonpaged pool and such pool can be searched for ”Proc” pool tag (unless a process changes that in memory). We call such pattern Hidden Process. For example:
0: kd> !poolfind Proc
Searching NonPaged pool (83c3c000 : 8bc00000) for Tag: Proc
*87b15000 size: 298 previous size: 0 (Free) Pro.
*87b18370 size: 298 previous size: 98 (Allocated) Proc (Protected)
[...]
*8a35e900 size: 298 previous size: 30 (Allocated) Proc (Protected)
*8a484000 size: 298 previous size: 0 (Allocated) Proc (Protected)
*8a4a2d68 size: 298 previous size: 28 (Allocated) Proc (Protected)
[…]
One such structure is missing from active process linked list (note that it has a parent PID):
0: kd> !process 8a484000+20
PROCESS 8a484020 SessionId: 0 Cid: 05a0 Peb: 00000000 ParentCid: 0244
DirBase: bffc2200 ObjectTable: e17e6a78 HandleCount: 0.
Image: AppChild.exe
VadRoot 8a574f80 Vads 4 Clone 0 Private 3. Modified 0. Locked 0.
DeviceMap e1002898
Token e1a36030
ElapsedTime 00:00:00.000
UserTime 00:00:00.000
KernelTime 419 Days 13:24:16.625
QuotaPoolUsage[PagedPool] 7580
QuotaPoolUsage[NonPagedPool] 160
Working Set Sizes (now,min,max) (12, 50, 345) (48KB, 200KB, 1380KB)
PeakWorkingSetSize 12
VirtualSize 1 Mb
PeakVirtualSize 1 Mb
PageFaultCount 5
MemoryPriority BACKGROUND
BasePriority 8
CommitCharge 156
No active threads
We may think that this process is zombie (note that unlike terminated processes it has a non-zero data such as VAD and object table and zero PEB and elapsed time) but inspection of its parent process thread stacks reveals that it was in the process of creation (note an attached process field):
THREAD 8a35dad8 Cid 0244.0248 Teb: 7ffdd000 Win32Thread: bc3aa688 WAIT: (Unknown) KernelMode Non-Alertable
ba971608 NotificationEvent
Impersonation token: e2285030 (Level Impersonation)
DeviceMap e1a31a58
Owning Process 8a35e920 Image: AppParent.exe
Attached Process 8a484020 Image: AppChild.exe
Wait Start TickCount 2099 Ticks: 1 (0:00:00:00.015)
Context Switch Count 279 LargeStack
UserTime 00:00:00.046
KernelTime 00:00:00.046
Win32 Start Address AppParent!mainCRTStartup (0×0100d303)
Start Address kernel32!BaseProcessStartThunk (0×77e617f8)
Stack Init ba972000 Current ba971364 Base ba972000 Limit ba96e000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0
ChildEBP RetAddr
ba97137c 80833f2d nt!KiSwapContext+0×26
ba9713a8 80829c72 nt!KiSwapThread+0×2e5
ba9713f0 bad3c9db nt!KeWaitForSingleObject+0×346
[…]
ba971b94 8094cfc3 nt!MmCreatePeb+0×2cc
ba971ce4 8094d42d nt!PspCreateProcess+0×5a9
ba971d38 8088b4ac nt!NtCreateProcessEx+0×77
ba971d38 7c82845c nt!KiFastCallEntry+0xfc (TrapFrame @ ba971d64)
0006f498 7c826d09 ntdll!KiFastSystemCallRet
0006f49c 77e6cf95 ntdll!ZwCreateProcessEx+0xc
0006fcc0 7d1ec670 kernel32!CreateProcessInternalW+0×15e5
0006fd0c 01008bcf ADVAPI32!CreateProcessAsUserW+0×108
[…]
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
Computation is short. Debugging is long. Problem is fleeting. Troubleshooting is risky. Diagnosis is difficult.
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
Similar to Network Packet Buildup pattern we also have Disk Packet Buildup. This can be detectable either through SCSI WinDbg extension or using IRP Distribution Anomaly pattern:
0: kd> .load scsikd
0: kd> !scsikd.classext
Storage class devices:
* !classext fffffa80026395b0 [1,2] SAMSUNG HS082HB Paging Disk
Usage: !classext <class device> <level [0-2]>
0: kd> !scsikd.classext fffffa80026395b0
Storage class device fffffa80026395b0 with extension at fffffa8002639700
Classpnp Internal Information at fffffa8002648010
-- dt classpnp!_CLASS_PRIVATE_FDO_DATA fffffa8002648010 --
Classpnp External Information at fffffa8002639700
SAMSUNG HS082HB NL100-01 S140JR0SA00025
Minidriver information at fffffa8002639bc0
Attached device object at fffffa80017ecda0
Physical device object at fffffa80024ab060
Media Geometry:
Bytes in a Sector = 512
Sectors per Track = 63
Tracks / Cylinder = 255
Media Length = 80026361856 bytes = ~74 GB
-- dt classpnp!_FUNCTIONAL_DEVICE_EXTENSION fffffa8002639700 --
This is a normal case:
0: kd> !scsikd.classext fffffa80026395b0 2
Storage class device fffffa80026395b0 with extension at fffffa8002639700
Classpnp Internal Information at fffffa8002648010
Transfer Packet Engine:
Packet Status DL Irp Opcode Sector/ListId UL Irp
-------- ------ -------- ------ --------------- --------
fffffa8002648e80 Free fffffa800249eac0
fffffa8002644220 Free fffffa80024aa4f0
fffffa80026898a0 Free fffffa80019d2b30
fffffa800267ad40 Free fffffa8001801b90
fffffa800267aa60 Free fffffa8001835e10
fffffa8002679010 Free fffffa80019fac40
fffffa8002679770 Free fffffa8002679500
fffffa80027659a0 Free fffffa8002764e10
fffffa8002790e80 Free fffffa800267a6a0
fffffa800278f5e0 Free fffffa80019d53c0
fffffa8002599410 Free fffffa8002785600
fffffa80027f7490 Free fffffa800278ea00
fffffa80027f6e80 Free fffffa80027f6c80
fffffa80027f69a0 Free fffffa80027f67a0
fffffa80027f64c0 Free fffffa80027f62c0
fffffa8002dd4440 Free fffffa80027fc600
fffffa8002dced30 Free fffffa8002dceb30
fffffa8002dce850 Free fffffa8002ddc010
fffffa8002ddc530 Free fffffa8002ddc330
fffffa8002de2d30 Free fffffa8002de2b30
fffffa8002de2850 Free fffffa8002de2650
fffffa8002de2370 Free fffffa8002de2170
fffffa8002ddbe80 Free fffffa8002ddbc80
fffffa8002ddb9a0 Free fffffa8002ddb7a0
fffffa8002dda010 Free fffffa8002ddae10
[...]
This is not:
0: kd> !scsikd.classext fffffa80026395b0 2
Storage class device fffffa80026395b0 with extension at fffffa8002639700
Classpnp Internal Information at fffffa8002648010
Transfer Packet Engine:
Packet Status DL Irp Opcode Sector UL Irp
-------- ------ -------- ------ -------- --------
fffffa80c71d9560 Queued fffffa80c71d9360 2a 03cbb948 fffffa80c4f269d0 \FileName
fffffa80c77a3360 Queued fffffa80c77a3160 2a 0400f0a8 fffffa80c59c1010 \FileName
fffffa80c6cefe60 Queued fffffa80c6cefc60 2a 0400f128 fffffa80c59c1010 \FileName
fffffa80c6e92260 Queued fffffa80c4f80010 2a 0400f1e8 fffffa80c59c1010 \FileName
fffffa80c79dbca0 Queued fffffa80c79dbaa0 2a 0400c4e8 fffffa80c59c1010 \FileName
fffffa80c83f2d90 Queued fffffa80c3b23bc0 2a 0400f168 fffffa80c59c1010 \FileName
fffffa80c4a94640 Queued fffffa80c4a94440 2a 0400d5e8 fffffa80c59c1010 \FileName
fffffa80c7984010 Queued fffffa80c7984210 2a 0400d328 fffffa80c59c1010 \FileName
fffffa80c6e52be0 Queued fffffa80c6e529e0 2a 0400f1a8 fffffa80c59c1010 \FileName
fffffa80c7afada0 Queued fffffa80c7afaba0 2a 04010268 fffffa80c59c1010 \FileName
fffffa80c7c19d90 Queued fffffa80ca2c5e10 2a 0400c628 fffffa80c59c1010 \FileName
fffffa80c6182d60 Queued fffffa80c6182b60 2a 0400f9a8 fffffa80c59c1010 \FileName
fffffa80c8695ba0 Queued fffffa80c86959a0 2a 0400d128 fffffa80c59c1010 \FileName
fffffa80c6b42b40 Queued fffffa80c6b42940 2a 0400ed28 fffffa80c59c1010 \FileName
fffffa80c5e1ab00 Queued fffffa80c5e1a900 2a 0400eee8 fffffa80c59c1010 \FileName
fffffa80c5d80a30 Queued fffffa80c4841e10 2a 0400fba8 fffffa80c59c1010 \FileName
fffffa80c48255d0 Queued fffffa80c48253d0 2a 040119e8 fffffa80c59c1010 \FileName
fffffa80c718a270 Queued fffffa80c47d0010 2a 0400d1e8 fffffa80c59c1010 \FileName
fffffa80c51a94b0 Queued fffffa80c51a92b0 2a 0400bd28 fffffa80c59c1010 \FileName
fffffa80ca280990 Queued fffffa80c52b2930 2a 0400d268 fffffa80c59c1010 \FileName
fffffa80c586f280 Queued fffffa80c551fe10 2a 0400f068 fffffa80c59c1010 \FileName
fffffa80c8413540 Queued fffffa80c544ae10 2a 04011a68 fffffa80c59c1010 \FileName
fffffa80c544ac60 Queued fffffa80c535ba90 2a 0400e7e8 fffffa80c59c1010 \FileName
fffffa80c4678010 Queued fffffa80c4678230 2a 04011168 fffffa80c59c1010 \FileName
fffffa80c9d94be0 Queued fffffa80c59205e0 2a 0400d4a8 fffffa80c59c1010 \FileName
fffffa80c5920430 Queued fffffa80c59248f0 2a 0400ea68 fffffa80c59c1010 \FileName
fffffa80c737e8f0 Queued fffffa80c737e6f0 2a 0400fee8 fffffa80c59c1010 \FileName
fffffa80c4797c60 Queued fffffa80c5d31800 2a 0400f328 fffffa80c59c1010 \FileName
fffffa80c711d270 Queued fffffa80c76ee390 2a 0400eaa8 fffffa80c59c1010 \FileName
fffffa80c872dba0 Queued fffffa80c872d9a0 2a 0400eb28 fffffa80c59c1010 \FileName
fffffa80c9e67d10 Queued fffffa80c9e67b10 2a 04012168 fffffa80c59c1010 \FileName
fffffa80ca3bb350 Queued fffffa80c66e4370 2a 0400c928 fffffa80c59c1010 \FileName
fffffa80c5894ab0 Queued fffffa80c58948b0 2a 0400c368 fffffa80c59c1010 \FileName
fffffa80c305fe60 Queued fffffa80c305fc60 2a 04013168 fffffa80c59c1010 \FileName
fffffa80c496cce0 Queued fffffa80c496cae0 2a 0400d168 fffffa80c59c1010 \FileName
fffffa80c5e78c60 Queued fffffa80c905c7f0 2a 0400f8a8 fffffa80c59c1010 \FileName
fffffa80c905c640 Queued fffffa80c5c1c410 2a 0400f428 fffffa80c59c1010 \FileName
fffffa80c68ffc40 Queued fffffa80c68ffa40 2a 0400f468 fffffa80c59c1010 \FileName
fffffa80c3aa3e60 Queued fffffa80c3aa3c60 2a 0400c7a8 fffffa80c59c1010 \FileName
fffffa80c5e8dc60 Queued fffffa80c8852cf0 2a 0400f4a8 fffffa80c59c1010 \FileName
fffffa80c90082b0 Queued fffffa80c7907440 2a 04013428 fffffa80c59c1010 \FileName
fffffa80c7907290 Queued fffffa80c67aea80 2a 0400fe68 fffffa80c59c1010 \FileName
fffffa80c67ae8d0 Queued fffffa80c9383cf0 2a 0400f3a8 fffffa80c59c1010 \FileName
fffffa80c8497010 Queued fffffa80c8497270 2a 0400c5e8 fffffa80c59c1010 \FileName
fffffa80c78c7480 Queued fffffa80c78c7280 2a 0400c3e8 fffffa80c59c1010 \FileName
fffffa80c7f37d90 Queued fffffa80c618b480 2a 0400cce8 fffffa80c59c1010 \FileName
fffffa80c618b2d0 Queued fffffa80ca2e9e10 2a 0400ee28 fffffa80c59c1010 \FileName
fffffa80ca2e9c60 Queued fffffa80c5e783f0 2a 0400d8e8 fffffa80c59c1010 \FileName
fffffa80c64e1650 Queued fffffa80c64e1450 2a 0400d0e8 fffffa80c59c1010 \FileName
fffffa80c684dd60 Queued fffffa80c684db60 2a 0400c6a8 fffffa80c59c1010 \FileName
fffffa80c3b2bac0 Queued fffffa80c3b2b8c0 2a 040127a8 fffffa80c59c1010 \FileName
fffffa80c5ff64d0 Queued fffffa80c5ff62d0 2a 0400de68 fffffa80c59c1010 \FileName
fffffa80c99a84b0 Queued fffffa80c99a82b0 2a 0400cfe8 fffffa80c59c1010 \FileName
fffffa80ca300510 Queued fffffa80ca300310 2a 0400c168 fffffa80c59c1010 \FileName
[...]
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
Doing memory dump analysis training for more than 2 years I found that students are divided into 2 types: those who prefer to see source code first and those who want to see a memory dump first. We actually prefer to show a memory dump first and then explore it to find certain patterns of abnormal structure and behavior. Software Diagnostics Services used this approach to design its Accelerated Windows Memory Dump Analysis and Accelerated .NET Memory Dump Analysis courses. Students explore memory dumps and debugger logs to find memory dump analysis patterns which are introduced when necessary. After that they can check source code of modeling applications if they have development experience. Accelerated Windows Software Trace Analysis course uses a different approach. It introduces all software trace analysis patterns at once because they are patterns from software narratology independent from programming languages and software platforms. After that they explore and analyze software traces and logs. We can summarize these 2 approaches on this diagram:
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
Relative Density pattern describes anomalies related to the semantically related pairs of trace messages, for example, “data arrival” and “data display”. Their statement densities can be put in a ratio (also called specific gravity) and compared between working and non-working scenarios. Because the total number of trace messages cancel each other we have just mutual ratio of two message types. In our hypothetical “data” example the increased ratio of “data arrival” to “data display” messages accounts for reported visual data loss and sluggish GUI.
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
Looks like Windows 8 reuses the debugging concept of a frozen thread for the so called a “deeply frozen” process:
0: kd> !sprocess 2
Dumping Session 2
[...]
PROCESS fffffa8002cb2940
SessionId: 2 Cid: 0c80 Peb: 7f6c41dd000 ParentCid: 0288
DeepFreeze
DirBase: 2ef45000 ObjectTable: fffff8a002f215c0 HandleCount: <Data Not Accessible>
Image: iexplore.exe
[…]
0: kd> dt nt!_KPROCESS fffffa8002cb2940
+0x000 Header : _DISPATCHER_HEADER
+0x018 ProfileListHead : _LIST_ENTRY [ 0xfffffa80`02cb2958 - 0xfffffa80`02cb2958 ]
+0x028 DirectoryTableBase : 0x2ef45000
+0x030 ThreadListHead : _LIST_ENTRY [ 0xfffffa80`01e4edf8 - 0xfffffa80`01f5bbf8 ]
+0x040 ProcessLock : 0
+0x044 Spare0 : 0
+0x048 Affinity : _KAFFINITY_EX
+0x0f0 ReadyListHead : _LIST_ENTRY [ 0xfffffa80`02cb2a30 - 0xfffffa80`02cb2a30 ]
+0x100 SwapListEntry : _SINGLE_LIST_ENTRY
+0x108 ActiveProcessors : _KAFFINITY_EX
+0x1b0 AutoAlignment : 0y0
+0x1b0 DisableBoost : 0y0
+0x1b0 DisableQuantum : 0y0
+0x1b0 AffinitySet : 0y0
+0×1b0 DeepFreeze : 0y1
+0×1b0 TimerVirtualization : 0y1
+0×1b0 ActiveGroupsMask : 0y00000000000000000001 (0×1)
+0×1b0 ReservedFlags : 0y000000 (0)
+0×1b0 ProcessFlags : 0n112
+0×1b4 BasePriority : 8 ”
+0×1b5 QuantumReset : 6 ”
+0×1b6 Visited : 0 ”
+0×1b7 Flags : _KEXECUTE_OPTIONS
+0×1b8 ThreadSeed : [20] 0
+0×208 IdealNode : [20] 0
+0×230 IdealGlobalNode : 0
+0×232 Spare1 : 0
+0×234 StackCount : _KSTACK_COUNT
+0×238 ProcessListEntry : _LIST_ENTRY [ 0xfffffa80`03816b78 - 0xfffffa80`02cc2b78 ]
+0×248 CycleTime : 0×225078
+0×250 ContextSwitches : 0×22
+0×258 SchedulingGroup : (null)
+0×260 FreezeCount : 0
+0×264 KernelTime : 0
+0×268 UserTime : 0
+0×26c LdtFreeSelectorHint : 0
+0×26e LdtTableLength : 0
+0×270 LdtSystemDescriptor : _KGDTENTRY64
+0×280 LdtBaseAddress : (null)
+0×288 LdtProcessLock : _FAST_MUTEX
+0×2c0 InstrumentationCallback : (null)
We also see that all its threads have a freeze count 1:
0: kd> !process fffffa8002cb2940 2
[...]
THREAD fffffa8001e4eb00 Cid 0c80.0514 Teb: 000007f6c41de000 Win32Thread: fffff901000e5b90 WAIT: (Suspended) KernelMode Non-Alertable
FreezeCount 1
fffffa8001e4ede0 NotificationEvent
THREAD fffffa800219c080 Cid 0c80.0d88 Teb: 000007f6c41db000 Win32Thread: fffff90103f206e0 WAIT: (Suspended) KernelMode Non-Alertable
FreezeCount 1
fffffa800219c360 NotificationEvent
[…]
0: kd> dt _KTHREAD fffffa800219c080
nt!_KTHREAD
+0x000 Header : _DISPATCHER_HEADER
+0x018 SListFaultAddress : (null)
+0x020 QuantumTarget : 0x18c26200
+0x028 InitialStack : 0xfffff880`1548ddd0 Void
+0x030 StackLimit : 0xfffff880`15488000 Void
+0x038 StackBase : 0xfffff880`1548e000 Void
+0x040 ThreadLock : 0
+0x048 CycleTime : 0x15ca97c8
+0x050 CurrentRunTime : 0
+0x054 ExpectedRunTime : 0xd77e
+0x058 KernelStack : 0xfffff880`1548d430 Void
+0x060 StateSaveArea : 0xfffff880`1548de00 _XSAVE_FORMAT
+0x068 SchedulingGroup : (null)
+0x070 WaitRegister : _KWAIT_STATUS_REGISTER
+0x071 Running : 0 ''
+0x072 Alerted : [2] ""
+0x074 KernelStackResident : 0y1
+0x074 ReadyTransition : 0y0
+0x074 ProcessReadyQueue : 0y0
+0x074 WaitNext : 0y0
+0x074 SystemAffinityActive : 0y0
+0x074 Alertable : 0y0
+0x074 CodePatchInProgress : 0y0
+0x074 UserStackWalkActive : 0y0
+0x074 ApcInterruptRequest : 0y0
+0x074 QuantumEndMigrate : 0y0
+0x074 UmsDirectedSwitchEnable : 0y0
+0x074 TimerActive : 0y0
+0x074 SystemThread : 0y0
+0x074 ProcessDetachActive : 0y0
+0x074 CalloutActive : 0y0
+0x074 ScbReadyQueue : 0y0
+0x074 ApcQueueable : 0y1
+0x074 ReservedStackInUse : 0y0
+0x074 UmsPerformingSyscall : 0y0
+0x074 Reserved : 0y0000000000000 (0)
+0x074 MiscFlags : 0n65537
+0x078 AutoAlignment : 0y0
+0x078 DisableBoost : 0y0
+0x078 UserAffinitySet : 0y0
+0x078 AlertedByThreadId : 0y0
+0x078 QuantumDonation : 0y0
+0x078 EnableStackSwap : 0y1
+0x078 GuiThread : 0y1
+0x078 DisableQuantum : 0y0
+0x078 ChargeOnlyGroup : 0y0
+0x078 DeferPreemption : 0y0
+0x078 QueueDeferPreemption : 0y0
+0x078 ForceDeferSchedule : 0y0
+0x078 ExplicitIdealProcessor : 0y0
+0×078 FreezeCount : 0y1
+0×078 EtwStackTraceApcInserted : 0y00000000 (0)
+0×078 ReservedFlags : 0y0000000000 (0)
+0×078 ThreadFlags : 0n8288
+0×07c Spare0 : 0
+0×080 SystemCallNumber : 0×87
+0×084 Spare1 : 0
+0×088 FirstArgument : 0×00000000`0000017c Void
+0×090 TrapFrame : (null)
+0×098 ApcState : _KAPC_STATE
+0×098 ApcStateFill : [43] “???”
+0×0c3 Priority : 8 ”
+0×0c4 UserIdealProcessor : 1
+0×0c8 WaitStatus : 0n256
+0×0d0 WaitBlockList : 0xfffffa80`0219c1c0 _KWAIT_BLOCK
+0×0d8 WaitListEntry : _LIST_ENTRY [ 0xfffffa80`0418a458 - 0xfffff880`009eb300 ]
+0×0d8 SwapListEntry : _SINGLE_LIST_ENTRY
+0×0e8 Queue : 0xfffffa80`03da4bc0 _KQUEUE
+0×0f0 Teb : 0×000007f6`c41db000 Void
+0×0f8 RelativeTimerBias : 0×00000001`8b165f54
+0×100 Timer : _KTIMER
+0×140 WaitBlock : [4] _KWAIT_BLOCK
+0×140 WaitBlockFill4 : [20] “h???”
+0×154 ContextSwitches : 0×1817
+0×140 WaitBlockFill5 : [68] “h???”
+0×184 State : 0×5 ”
+0×185 NpxState : 1 ”
+0×186 WaitIrql : 0 ”
+0×187 WaitMode : 0 ”
+0×140 WaitBlockFill6 : [116] “h???”
+0×1b4 WaitTime : 0xf0172e
+0×140 WaitBlockFill7 : [164] “h???”
+0×1e4 KernelApcDisable : 0n0
+0×1e6 SpecialApcDisable : 0n0
+0×1e4 CombinedApcDisable : 0
+0×140 WaitBlockFill8 : [40] “h???”
+0×168 ThreadCounters : (null)
+0×140 WaitBlockFill9 : [88] “h???”
+0×198 XStateSave : (null)
+0×140 WaitBlockFill10 : [136] “h???”
+0×1c8 Win32Thread : 0xfffff901`03f206e0 Void
+0×140 WaitBlockFill11 : [176] “h???”
+0×1f0 Ucb : (null)
+0×1f8 Uch : (null)
+0×200 TebMappedLowVa : (null)
+0×208 QueueListEntry : _LIST_ENTRY [ 0xfffffa80`02ccf408 - 0xfffffa80`03da4bf0 ]
+0×218 NextProcessor : 0
+0×21c DeferredProcessor : 1
+0×220 Process : 0xfffffa80`02cb2940 _KPROCESS
+0×228 UserAffinity : _GROUP_AFFINITY
+0×228 UserAffinityFill : [10] “???”
+0×232 PreviousMode : 1 ”
+0×233 BasePriority : 8 ”
+0×234 PriorityDecrement : 0 ”
+0×234 ForegroundBoost : 0y0000
+0×234 UnusualBoost : 0y0000
+0×235 Preempted : 0 ”
+0×236 AdjustReason : 0 ”
+0×237 AdjustIncrement : 0 ”
+0×238 Affinity : _GROUP_AFFINITY
+0×238 AffinityFill : [10] “???”
+0×242 ApcStateIndex : 0 ”
+0×243 WaitBlockCount : 0×1 ”
+0×244 IdealProcessor : 1
+0×248 ApcStatePointer : [2] 0xfffffa80`0219c118 _KAPC_STATE
+0×258 SavedApcState : _KAPC_STATE
+0×258 SavedApcStateFill : [43] “???”
+0×283 WaitReason : 0×5 ”
+0×284 SuspendCount : 0 ”
+0×285 Saturation : 0 ”
+0×286 SListFaultCount : 0
+0×288 SchedulerApc : _KAPC
+0×288 SchedulerApcFill0 : [1] “??????”
+0×289 ResourceIndex : 0×1 ”
+0×288 SchedulerApcFill1 : [3] “???”
+0×28b QuantumReset : 0×6 ”
+0×288 SchedulerApcFill2 : [4] “???”
+0×28c KernelTime : 7
+0×288 SchedulerApcFill3 : [64] “???”
+0×2c8 WaitPrcb : (null)
+0×288 SchedulerApcFill4 : [72] “???”
+0×2d0 LegoData : (null)
+0×288 SchedulerApcFill5 : [83] “???”
+0×2db CallbackNestingLevel : 0 ”
+0×2dc UserTime : 0xa
+0×2e0 SuspendEvent : _KEVENT
+0×2f8 ThreadListEntry : _LIST_ENTRY [ 0xfffffa80`01c41378 - 0xfffffa80`01e4edf8 ]
+0×308 MutantListHead : _LIST_ENTRY [ 0xfffffa80`0219c388 - 0xfffffa80`0219c388 ]
+0×318 ReadOperationCount : 0n392
+0×320 WriteOperationCount : 0n321
+0×328 OtherOperationCount : 0n240
+0×330 ReadTransferCount : 0n1849338
+0×338 WriteTransferCount : 0n1197496
+0×340 OtherTransferCount : 0n4972
This is different when a process is under a debugger and all its threads are frozen except the one that communicates to the debugger like in this case study. In Windows 8 this happens, for example, when we switch to a desktop from IE launched from the start page. Then we would see shortly that iexplore.exe process changes from Running to Suspended in Task Manager Details page. We call this pattern Frozen Process to cover both the new feature and a debugged process case.
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
Found in Matthew 1:2-16 (KJV):
0:000> k
RetAddr Call Site
Jacob Joseph
Matthan Jacob
Eleazar Matthan
Eliud Eleazar
Achim Eliud
Sadoc Achim
Azor Sadoc
Eliakim Azor
Abiud Eliakim
Zorobabel Abiud
Salathiel Zorobabel
Jechonias Salathiel
Josias Jechonias
Amon Josias
Manasses Amon
Ezekias Manasses
Achaz Ezekias
Joatham Achaz
Ozias Joatham
Joram Ozias
Josaphat Joram
Asa Josaphat
Abia Asa
Roboam Abia
Solomon Roboam
David Solomon
Jesse David
Obed Jesse
Booz Obed
Salmon Booz
Naasson Salmon
Aminadab Naasson
Aram Aminadab
Esrom Aram
Phares Esrom
Judas Phares
Jacob Judas
Isaac Jacob
Abraham Isaac
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
I was analyzing a raw thread stack when came upon this symbolic address which I thought was coincidental:
363b0030 77777777 advapi32!LsaEnumerateAccountRights+0×56
Forward disasssembly makes sense, isn’t it? And every instruction seems have a purpose 
0:000> u 77777777
advapi32!LsaEnumerateAccountRights+0×56:
77777777 a4 movs byte ptr es:[edi],byte ptr [esi]
77777778 fc cld
77777779 ffc3 inc ebx
7777777b 8b65e8 mov esp,dword ptr [ebp-18h]
7777777e ff75e0 push dword ptr [ebp-20h]
77777781 ff15e4187377 call dword ptr [advapi32!_imp__I_RpcMapWin32Status (777318e4)]
77777787 50 push eax
77777788 e8c6f6fbff call advapi32!LsapApiReturnResult (77736e53)
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
If trace messages contain some character or formatted data that is passed from module to module or between threads and processes it is possible to trace that data and form a Data Flow thread similar to an adjoint thread we have when we filter by a specific message. However, in the former case we have different message types.
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
We resume our case studies involving multiple patterns. It was reported that a user couldn’t start a session. A complete memory dump was generated and we found 3 sessions there. Looking at the last one we found it incomplete with only 3 processes (a normal running user session after initialization was expected to have more than 3 processes):
0: kd> !session
Sessions on machine: 3
Valid Sessions: 0 1 2
0: kd> !sprocess 2
Dumping Session 2
_MM_SESSION_SPACE fffffa600a3e1000
_MMSESSION fffffa600a3e1b40
PROCESS fffffa8007f6c040
SessionId: 2 Cid: 242c Peb: 7fffffd8000 ParentCid: 2374
DirBase: 58350000 ObjectTable: fffff8800f485630 HandleCount: 192.
Image: csrss.exe
PROCESS fffffa8007de8130
SessionId: 2 Cid: 1a48 Peb: 7fffffde000 ParentCid: 2374
DirBase: 15755000 ObjectTable: fffff8800c742010 HandleCount: 240.
Image: winlogon.exe
PROCESS fffffa8004c2e4a0
SessionId: 2 Cid: 17b8 Peb: 7efdf000 ParentCid: 144c
DirBase: a3b80000 ObjectTable: fffff8800bf1d350 HandleCount: 168.
Image: AppA.exe
Looking at AppA process we find its main thread blocked in ALPC request directed to ServiceA process:
0: kd> !process fffffa8004c2e4a0 ff
PROCESS fffffa8004c2e4a0
SessionId: 2 Cid: 17b8 Peb: 7efdf000 ParentCid: 144c
DirBase: a3b80000 ObjectTable: fffff8800bf1d350 HandleCount: 168.
Image: AppA.exe
VadRoot fffffa8006d7f310 Vads 192 Clone 0 Private 572. Modified 2. Locked 0.
DeviceMap fffff88015685f30
Token fffff8800a245050
ElapsedTime 01:58:00.200
UserTime 00:00:00.000
KernelTime 00:00:00.015
QuotaPoolUsage[PagedPool] 140256
QuotaPoolUsage[NonPagedPool] 18368
Working Set Sizes (now,min,max) (2025, 50, 345) (8100KB, 200KB, 1380KB)
PeakWorkingSetSize 2087
VirtualSize 74 Mb
PeakVirtualSize 79 Mb
PageFaultCount 2351
MemoryPriority BACKGROUND
BasePriority 8
CommitCharge 741
Job fffffa80063de710
THREAD fffffa8006db8440 Cid 17b8.20e0 Teb: 000000007efdb000 Win32Thread: fffff900c0b0c4f0 WAIT: (WrLpcReply) UserMode Non-Alertable
fffffa8006db87d0 Semaphore Limit 0x1
Waiting for reply to ALPC Message fffff8800f487cf0 : queued at port fffffa8004b37d90 : owned by process fffffa8004b11c10
Not impersonating
DeviceMap fffff88015685f30
Owning Process fffffa8004c2e4a0 Image: AppA.exe
Attached Process N/A Image: N/A
Wait Start TickCount 4244174 Ticks: 453096 (0:01:57:59.625)
Context Switch Count 132 LargeStack
UserTime 00:00:00.031
KernelTime 00:00:00.109
Win32 Start Address AppA!WinMainCRTStartup (0×00000000658c9866)
Stack Init fffffa6008832db0 Current fffffa6008832670
Base fffffa6008833000 Limit fffffa600882a000 Call 0
Priority 10 BasePriority 8 PriorityDecrement 0 IoPriority 2 PagePriority 5
Kernel stack not resident.
Child-SP RetAddr Call Site
fffffa60`088326b0 fffff800`01e5ccfa nt!KiSwapContext+0×7f
fffffa60`088327f0 fffff800`01e519bb nt!KiSwapThread+0×13a
fffffa60`08832860 fffff800`01e86b12 nt!KeWaitForSingleObject+0×2cb
fffffa60`088328f0 fffff800`020d40b4 nt!AlpcpSignalAndWait+0×92
fffffa60`08832980 fffff800`020d0b46 nt!AlpcpReceiveSynchronousReply+0×44
fffffa60`088329e0 fffff800`020c06ef nt!AlpcpProcessSynchronousRequest+0×24f
fffffa60`08832b00 fffff800`01e5a573 nt!NtAlpcSendWaitReceivePort+0×19f
fffffa60`08832bb0 00000000`77cb76ca nt!KiSystemServiceCopyEnd+0×13 (TrapFrame @ fffffa60`08832c20)
00000000`000be3f8 00000000`7578993f ntdll!ZwAlpcSendWaitReceivePort+0xa
00000000`000be400 00000000`7577a996 wow64!whNtAlpcSendWaitReceivePort+0×5f
00000000`000be450 00000000`75813688 wow64!Wow64SystemServiceEx+0xca
00000000`000bed00 00000000`7577ab46 wow64cpu!ServiceNoTurbo+0×28
00000000`000bed90 00000000`7577a14c wow64!RunCpuSimulation+0xa
00000000`000bedc0 00000000`77cabbb3 wow64!Wow64LdrpInitialize+0×4b4
00000000`000bf320 00000000`77cab83c ntdll!LdrpInitializeProcess+0×13eb
00000000`000bf5c0 00000000`77c9660e ntdll! ?? ::FNODOBFM::`string’+0×1fbc9
00000000`000bf670 00000000`00000000 ntdll!LdrInitializeThunk+0xe
0: kd> !alpc /m fffff8800f487cf0
Message @ fffff8800f487cf0
MessageID : 0x0640 (1600)
CallbackID : 0x36C184 (3588484)
SequenceNumber : 0x00000002 (2)
Type : LPC_REQUEST
DataLength : 0x0048 (72)
TotalLength : 0x0070 (112)
Canceled : No
Release : No
ReplyWaitReply : No
Continuation : Yes
OwnerPort : fffffa80061946c0 [ALPC_CLIENT_COMMUNICATION_PORT]
WaitingThread : fffffa8006db8440
QueueType : ALPC_MSGQUEUE_PENDING
QueuePort : fffffa8004b37d90 [ALPC_CONNECTION_PORT]
QueuePortOwnerProcess : fffffa8004b11c10 (ServiceA.exe)
ServerThread : fffffa80066d44b0
QuotaCharged : No
CancelQueuePort : 0000000000000000
CancelSequencePort : 0000000000000000
CancelSequenceNumber : 0×00000000 (0)
ClientContext : 00000000007a5630
ServerContext : 0000000000000000
PortContext : 0000000005aa3ef0
CancelPortContext : 0000000000000000
SecurityData : 0000000000000000
View : 0000000000000000
0: kd> !thread fffffa80066d44b0 ff
THREAD fffffa80066d44b0 Cid 07d0.1bec Teb: 000007fffffa2000 Win32Thread: 0000000000000000 WAIT: (UserRequest) UserMode Non-Alertable
fffffa800728e420 SynchronizationEvent
Impersonation token: fffff8800a245050 (Level Impersonation)
DeviceMap fffff88015685f30
Owning Process fffffa8004b11c10 Image: ServiceA.exe
Attached Process N/A Image: N/A
Wait Start TickCount 4244188 Ticks: 453082 (0:01:57:59.406)
Context Switch Count 43
UserTime 00:00:00.015
KernelTime 00:00:00.000
Win32 Start Address RPCRT4!ThreadStartRoutine (0×000007feff787780)
Stack Init fffffa6009abbdb0 Current fffffa6009abb940
Base fffffa6009abc000 Limit fffffa6009ab6000 Call 0
Priority 10 BasePriority 8 PriorityDecrement 0 IoPriority 2 PagePriority 5
Kernel stack not resident.
Child-SP RetAddr Call Site
fffffa60`09abb980 fffff800`01e5ccfa nt!KiSwapContext+0×7f
fffffa60`09abbac0 fffff800`01e519bb nt!KiSwapThread+0×13a
fffffa60`09abbb30 fffff800`020be7c8 nt!KeWaitForSingleObject+0×2cb
fffffa60`09abbbc0 fffff800`01e5a573 nt!NtWaitForSingleObject+0×98
fffffa60`09abbc20 00000000`77cb6eba nt!KiSystemServiceCopyEnd+0×13 (TrapFrame @ fffffa60`09abbc20)
00000000`096eedb8 00000000`77c9577a ntdll!ZwWaitForSingleObject+0xa
00000000`096eedc0 00000000`77c95671 ntdll!RtlpWaitOnCriticalSection+0xea
00000000`096eee70 00000000`667dfe24 ntdll!RtlEnterCriticalSection+0xf4
[…]
If we examine ServiceA process we fined a critical section wait chain where a endpoint is blocked in a dialog box:
0: kd> .process /r /p fffffa8004b11c10
Implicit process is now fffffa80`04b11c10
Loading User Symbols
0: kd> !cs -l -o -s
-----------------------------------------
DebugInfo = 0x00000000003a4880
Critical section = 0x000000006684d4c0
LOCKED
LockCount = 0×3
WaiterWoken = No
OwningThread = 0×00000000000023f0
RecursionCount = 0×1
LockSemaphore = 0×608
SpinCount = 0×0000000000000000
OwningThread = .thread fffffa8006948650
ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled.
—————————————–
DebugInfo = 0×00000000003b7140
Critical section = 0×000000000023f188 (+0×23F188)
LOCKED
LockCount = 0×2
WaiterWoken = No
OwningThread = 0×0000000000000a38
RecursionCount = 0×1
LockSemaphore = 0×344
SpinCount = 0×0000000000000000
OwningThread = .thread fffffa8005d3ebb0
ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled.
0: kd> .thread /r /p fffffa8006948650
Implicit thread is now fffffa80`06948650
Implicit process is now fffffa80`04b11c10
Loading User Symbols
0: kd> k
*** Stack trace for last set context - .thread/.cxr resets it
Child-SP RetAddr Call Site
fffffa60`0b5ed980 fffff800`01e5ccfa nt!KiSwapContext+0x7f
fffffa60`0b5edac0 fffff800`01e519bb nt!KiSwapThread+0x13a
fffffa60`0b5edb30 fffff800`020be7c8 nt!KeWaitForSingleObject+0x2cb
fffffa60`0b5edbc0 fffff800`01e5a573 nt!NtWaitForSingleObject+0x98
fffffa60`0b5edc20 00000000`77cb6eba nt!KiSystemServiceCopyEnd+0x13
00000000`089cef08 00000000`77c9577a ntdll!ZwWaitForSingleObject+0xa
00000000`089cef10 00000000`77c95671 ntdll!RtlpWaitOnCriticalSection+0xea
00000000`089cefc0 00000000`667e0ad7 ntdll!RtlEnterCriticalSection+0xf4
[…]
0: kd> .thread /r /p fffffa8005d3ebb0
Implicit thread is now fffffa80`05d3ebb0
Implicit process is now fffffa80`04b11c10
Loading User Symbols
0: kd> k
*** Stack trace for last set context - .thread/.cxr resets it
Child-SP RetAddr Call Site
fffffa60`02ed4c50 fffff800`01e5ccfa nt!KiSwapContext+0x7f
fffffa60`02ed4d90 fffff800`01e625eb nt!KiSwapThread+0x13a
fffffa60`02ed4e00 fffff800`020bfc2e nt!KeWaitForMultipleObjects+0x2eb
fffffa60`02ed4e80 fffff800`020c0273 nt!ObpWaitForMultipleObjects+0x26e
fffffa60`02ed5340 fffff800`01e5a573 nt!NtWaitForMultipleObjects+0xe2
fffffa60`02ed5590 00000000`77cb742a nt!KiSystemServiceCopyEnd+0x13
00000000`034de248 00000000`77a8aff3 ntdll!NtWaitForMultipleObjects+0xa
00000000`034de250 00000000`77bbe2b5 kernel32!WaitForMultipleObjectsEx+0x10b
00000000`034de360 000007fe`fc3d14f2 USER32!RealMsgWaitForMultipleObjectsEx+0x129
00000000`034de400 000007fe`fc3d190f DUser!CoreSC::Wait+0x62
00000000`034de450 000007fe`fc3d188a DUser!CoreSC::WaitMessage+0x6f
00000000`034de490 00000000`77bc538e DUser!MphWaitMessageEx+0x36
00000000`034de4c0 00000000`77cb6db6 USER32!_ClientWaitMessageExMPH+0x1a
00000000`034de510 00000000`77bbd2ba ntdll!KiUserCallbackDispatcherContinue
00000000`034de578 00000000`77bc5118 USER32!NtUserWaitMessage+0xa
00000000`034de580 00000000`77bc5770 USER32!DialogBox2+0×261
00000000`034de600 00000000`77bc57e6 USER32!InternalDialogBox+0×134
00000000`034de660 00000000`77bc5e18 USER32!DialogBoxIndirectParamAorW+0×58
00000000`034de6a0 000007fe`fcf349a6 USER32!DialogBoxIndirectParamW+0×18
[…]
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
Pattern-driven software post-construction problem solving involves using preexisting pattern languages and pattern catalogs for software diagnostics, troubleshooting and debugging. Pattern-based software post-construction problem solving addresses PLS (Pattern Life Cycle) - from the discovery of a new pattern through its integration into an existing catalog and language, testing, packaging and delivering to pattern consumers with subsequent usage, refactoring and writing case studies:
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
Empty Trace is another trivial missing pattern that we need to add to make software log analysis pattern system complete. It ranges from a totally empty trace message list where only a meta-trace header (if any) describing overall trace structure is present to a few messages where we expect thousands. This is also an extreme case of Truncated Trace, No Activity and Missing Component patterns for a trace taken as a whole. Note, that an empty trace file doesn’t necessarily have a zero file size because a tracing architecture may preallocate some file space for block data writing.
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
While working on Accelerated Windows Software Trace Analysis training I discovered some missing patterns needed for completeness despite their triviality. One of them is called Error Message. Here an error is reported either explicitly (”operation failed”) or implicitly as an operation status result such as 0xC00000XX. Sometimes, a trace message designer specifies that the number value was supplied for information only and should be ignored. Some error messages may contain information that is not relevant for the current software incident, the so called false positive errors. Some tracing architectures and tools include message information category for errors, such as Citrix CDF (ETW-based) where you filter by error category to get an adjoint thread. Note, that the association of a trace statement with an error category is left at the discretion of an engineer writing code and information category messages may contain implicit errors such as last error and return status reports.
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
