Software Diagnostics Library

Windows shutdown couldn’t progress and a complete memory dump was saved for later postmortem analysis. !stacks command showed reduced number of waiting threads in one important system service:

0: kd> !stacks
[...]
                            [89d6d8e8 ServiceA.exe]
1454.0014b0  89d36b60 0000163 Blocked    DriverA!Check+0x177
[...]

Normally this service had at least a dozen waiting threads. If we switch to the process we see many threads missing and the process itself is in the process of exiting (three “process” nouns in one sentence):

0: kd> !process 89d6d8e8
PROCESS 89d6d8e8  SessionId: 0  Cid: 1454    Peb: 7ffd8000  ParentCid: 0234
    DirBase: afa06000  ObjectTable: e5491278  HandleCount: 444.
    Image: ServiceA.exe
    VadRoot 89db18d8 Vads 213 Clone 0 Private 827. Modified 15. Locked 0.
    DeviceMap e10028c8
    Token                             e5556710
    ElapsedTime                       2 Days 02:59:39.285
    UserTime                          00:00:08.375
    KernelTime                        00:00:20.046
    QuotaPoolUsage[PagedPool]         50660
    QuotaPoolUsage[NonPagedPool]      9704
    Working Set Sizes (now,min,max)  (2523, 50, 345) (10092KB, 200KB, 1380KB)
    PeakWorkingSetSize                2953
    VirtualSize                       76 Mb
    PeakVirtualSize                   78 Mb
    PageFaultCount                    19259
    MemoryPriority                    BACKGROUND
    BasePriority                      8
    CommitCharge                      1522

THREAD 89d36b60  Cid 1454.14b0  Teb: 00000000 Win32Thread: 00000000 WAIT: (Unknown) KernelMode Alertable
    8a8d7438  NotificationEvent
    89d36bd8  NotificationTimer
Not impersonating
DeviceMap                 e10028c8
Owning Process            89d6d8e8       Image:         ServiceA.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      11760358       Ticks: 355 (0:00:00:05.546)
Context Switch Count      4591            
UserTime                  00:00:00.000
KernelTime                00:00:00.000
Start Address DriverA!CheckProtocolStackThread (0xf762cfa0)
Stack Init f3e7b000 Current f3e7acc0 Base f3e7b000 Limit f3e78000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0
ChildEBP RetAddr 
f3e7acd8 8083d5b1 nt!KiSwapContext+0x26
f3e7ad04 8083df9e nt!KiSwapThread+0x2e5
f3e7ad4c f762cf8d nt!KeWaitForSingleObject+0x346
[...]
f3e7adac 8092083b DriverA!CheckProtocolStackThread+0x5
f3e7addc 8083fe9f nt!PspSystemThreadStartup+0x2e
00000000 00000000 nt!KiThreadStartup+0x16

THREAD 89ce9580  Cid 1454.1630  Teb: 7ff9e000 Win32Thread: bc1e71f8 WAIT: (Unknown) UserMode Non-Alertable
     893fae40  SynchronizationEvent
Not impersonating
DeviceMap                 e10028c8
Owning Process            89d6d8e8       Image:         ServiceA.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      11048203       Ticks: 712510 (0:03:05:32.968)
Context Switch Count      1103                 LargeStack
UserTime                  00:00:00.281
KernelTime                00:00:01.484
Win32 Start Address DllA!OperationThread (0x1003b37e)
Start Address kernel32!BaseThreadStartThunk (0x77e617ec)
Stack Init f65a3000 Current f65a2c60 Base f65a3000 Limit f65a0000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0
Kernel stack not resident.
ChildEBP RetAddr 
f65a2c78 8083d5b1 nt!KiSwapContext+0x26
f65a2ca4 8083df9e nt!KiSwapThread+0x2e5
f65a2cec 8092ae67 nt!KeWaitForSingleObject+0x346
f65a2d50 80833bef nt!NtWaitForSingleObject+0x9a
f65a2d50 7c82860c nt!KiFastCallEntry+0xfc (TrapFrame @ f65a2d64)
0293fd18 7c827d29 ntdll!KiFastSystemCallRet
0293fd1c 77e61d1e ntdll!ZwWaitForSingleObject+0xc
0293fd8c 77e61c8d kernel32!WaitForSingleObjectEx+0xac
0293fda0 724c705b kernel32!WaitForSingleObject+0x12
0293fdb4 724c6745 DllB!Cleanup+0x3b
[...]
0293fde0 7c81a352 DllB!DLLEntry+0x62
0293fe00 7c830e90 ntdll!LdrpCallInitRoutine+0x14
0293feb8 77e668ab ntdll!LdrShutdownProcess+0x182
0293ffa4 77e6690d kernel32!_ExitProcess+0×43
0293ffb8 77e792c1 kernel32!ExitProcess+0×14
0293ffec 00000000 kernel32!BaseThreadStart+0×5f

However, the brief scan of all other processes and threads from !process 0 ff command output shows that another important service ServiceB has critical section wait chains:

THREAD 89e1f890  Cid 09f4.1018  Teb: 7ff96000 Win32Thread: bc279160 WAIT: (Unknown) UserMode Non-Alertable
    89d96c30  SynchronizationEvent
Not impersonating
DeviceMap                 e10028c8
Owning Process            8a453b18       Image:         ServiceB.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      11750950       Ticks: 9763 (0:00:02:32.546)
Context Switch Count      327                 LargeStack
UserTime                  00:00:00.000
KernelTime                00:00:00.000
Win32 Start Address msvcrt!_endthreadex (0×77bcb4bc)
Start Address kernel32!BaseThreadStartThunk (0×77e617ec)
Stack Init f6113000 Current f6112c60 Base f6113000 Limit f6110000 Call 0
Priority 9 BasePriority 8 PriorityDecrement 1
Kernel stack not resident.
ChildEBP RetAddr 
f6112c78 8083d5b1 nt!KiSwapContext+0×26
f6112ca4 8083df9e nt!KiSwapThread+0×2e5
f6112cec 8092ae67 nt!KeWaitForSingleObject+0×346
f6112d50 80833bef nt!NtWaitForSingleObject+0×9a
f6112d50 7c82860c nt!KiFastCallEntry+0xfc
09eafd98 7c827d29 ntdll!KiFastSystemCallRet
09eafd9c 7c83d266 ntdll!ZwWaitForSingleObject+0xc
09eafdd8 7c83d2b1 ntdll!RtlpWaitOnCriticalSection+0×1a3
09eafdf8 6738d489 ntdll!RtlEnterCriticalSection+0xa8
[…]
09eaffb8 77e6482f msvcrt!_endthreadex+0xa3
09eaffec 00000000 kernel32!BaseThreadStart+0×34

We switch to this process and find the owner of a critical section that blocks other threads:

0: kd> .process /r /p 8a453b18
Implicit process is now 8a453b18

0: kd> !cs -l -o -s
[...]
DebugInfo          = 0x0a199ea0
Critical section   = 0x0998ac80 (+0x998AC80)
LOCKED
LockCount          = 0x5
WaiterWoken        = No
OwningThread       = 0x00001680
RecursionCount     = 0x1
LockSemaphore      = 0xE08
SpinCount          = 0x00000000
OwningThread       = .thread 89bfc4d8
[…]

0: kd> !thread 89bfc4d8 1f
THREAD 89bfc4d8  Cid 09f4.1680  Teb: 7ff70000 Win32Thread: bc1e79d8 WAIT: (Unknown) UserMode Non-Alertable
    89bfc6c4  Semaphore Limit 0x1
Waiting for reply to LPC MessageId 00fbbc86:
Current LPC port e544f108
Not impersonating
DeviceMap                 e10028c8
Owning Process            8a453b18       Image:         ServiceB.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      11049035       Ticks: 711678 (0:03:05:19.968)
Context Switch Count      455269                 LargeStack
UserTime                  00:00:45.312
KernelTime                00:00:10.531
Win32 Start Address msvcrt!_endthreadex (0×77bcb4bc)
Start Address kernel32!BaseThreadStartThunk (0×77e617ec)
Stack Init f3b8b000 Current f3b8ac08 Base f3b8b000 Limit f3b88000 Call 0
Priority 13 BasePriority 8 PriorityDecrement 0
Kernel stack not resident.
ChildEBP RetAddr 
f3b8ac20 8083d5b1 nt!KiSwapContext+0×26
f3b8ac4c 8083df9e nt!KiSwapThread+0×2e5
f3b8ac94 8093edb1 nt!KeWaitForSingleObject+0×346
f3b8ad50 80833bef nt!NtRequestWaitReplyPort+0×776
f3b8ad50 7c82860c nt!KiFastCallEntry+0xfc (TrapFrame @ f3b8ad64)
0f13ebe8 7c827899 ntdll!KiFastSystemCallRet
0f13ebec 77c80a6e ntdll!ZwRequestWaitReplyPort+0xc
0f13ec38 77c7fcf0 RPCRT4!LRPC_CCALL::SendReceive+0×230
0f13ec44 77c80673 RPCRT4!I_RpcSendReceive+0×24
0f13ec58 77ce315a RPCRT4!NdrSendReceive+0×2b
0f13f040 771f40c4 RPCRT4!NdrClientCall2+0×22e
[…]
0f13ffb8 77e6482f msvcrt!_endthreadex+0xa3
0f13ffec 00000000 kernel32!BaseThreadStart+0×34

Following LPC chain we find that the blocking thread in ServiceB was waiting for a response from ServiceA:

0: kd> !lpc message 00fbbc86
[...]
    Server process  : 89d6d8e8 (ServiceA.exe)
[…]

Now the question arises: who was freezing first, ServiceA or ServiceB? We can compare waiting times to answer. We see that waiting time for ServiceB request thread is 3:05:19 and for ServiceA shutdown thread is 03:05:32 (from !thread and !process output above):

Owning Process            8a453b18       Image:         ServiceB.exe
[...]
Wait Start TickCount      11049035       Ticks: 711678 (0:03:05:19.968)

Owning Process            89d6d8e8       Image:         ServiceA.exe
[...]
Wait Start TickCount      11048203       Ticks: 712510 (0:03:05:32.968)

Therefore, we conclude that ServiceB was blocked after ServiceA was blocked. Such questions often arise in multivendor troubleshooting scenarious.

- Dmitry Vostokov @ DumpAnalysis.org -

A few days ago I noticed that one euro became 10 times more than its usual conversion value to Russian rouble (ruble). As shown on the picture below it was 1:430.96 instead of expected 1:43.096. At first, I thought of a sudden devaluation and rushed to financial websites for confirmation but they didn’t show any signs of it. I then wanted to announce my findings and cause panic on Wall Street (computers crash there too) but other battles with bugs set this problem aside. 

This evening I noticed that it was fixed (remotely, I suppose, on a distant server):

- Dmitry Vostokov @ DumpAnalysis.org -

When looking at lengthy traces with thousands and millions of messages (trace statements) we can see regions of activity where statement current (J_m, msg/s) is much higher than in surrounding temporal regions. Hence the name of this pattern, Activity Region. Here is an illustration for a typical ETW/CDF trace where a middle region of activity (J_m2) signifies a system performing some response function like a user session initialization and application launch:

- Dmitry Vostokov @ TraceAnalysis.org -

Here is the reading system I devised to read all books that I review on this blog:

Mod N Reading System

- Dmitry Vostokov @ LiterateScientist.com -

This is a hardware counterpart of Not My Version pattern. Some problems manifest themselves on different hardware not used at the time of the product testing. In such cases we can look at kernel and complete memory dumps, extract hardware information using !sysinfo command and compare differences. This is similar to Virtualized System pattern and might provide troubleshooting hints. One example, I have seen in the past, involved a graphics intensive application that relied heavily upon hardware acceleration features. It was tested with certain processors and chipsets but after a few years failed to work on one computer despite the same OS image and drivers. !sysinfo command revealed significant hardware differences: the failing client computer was newer faster multiprocessor machine.

- Dmitry Vostokov @ DumpAnalysis.org -

This weekend noticed that it is in stock and this means that I soon get it in the post:

Advanced .NET Debugging (Addison-Wesley Microsoft Technology Series)

I plan to start reading it as soon as it arrives and put notes on my Software Generalist blog.

- Dmitry Vostokov @ DumpAnalysis.org -

I have created Book Errata page at this address:

http://www.dumpanalysis.org/MDAA-Volume2-Errata

The link to it has also been added to the main book ad page:

Memory Dump Analysis Anthology, Volume 2

- Dmitry Vostokov @ DumpAnalysis.org -

Sometimes we can observe rare events when abnormal conditions that usually result in a system crash result in a milder problem, for example, a service is unavailable and not affecting other services and users. It was reported that an application was freezing during user session logoff. A complete memory dump was saved at that time and its stack trace collection (!stacks command) shows the following suspicious thread in a user process (all other threads were normally waiting):

0: kd> !stacks
Proc.Thread  .Thread  Ticks   ThreadState Blocker
[...]
                                    [89cfa960 Application.exe]
ea0.001c4c  89a11db0 0499cd1 Blocked    DriverA+0×69db
[…]

0: kd> !thread 89a11db0 16
THREAD 89a11db0  Cid 0ea0.1c4c  Teb: 7ffdf000 Win32Thread: bc347a48 WAIT: (Unknown) KernelMode Non-Alertable
    89b87770  Unknown
    b97004ac  NotificationEvent
IRP List:
    899e2668: (0006,0244) Flags: 00000884  Mdl: 00000000
Not impersonating
DeviceMap                 daf62b28
Owning Process            89cfa960       Image:         Application.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      909331         Ticks: 4824273 (0:20:56:19.265)
Context Switch Count      186                 LargeStack
UserTime                  00:00:00.015
KernelTime                00:00:00.093
*** ERROR: Module load completed but symbols could not be loaded for Application.exe
Win32 Start Address Application (0×00406b2a)
Start Address kernel32!BaseProcessStartThunk (0×77e617f8)
Stack Init b60ceb30 Current b60cdf10 Base b60cf000 Limit b60cb000 Call b60ceb34
Priority 10 BasePriority 10 PriorityDecrement 0
ChildEBP RetAddr  Args to Child             
b60cdf28 80833485 89a11db0 00000002 00000000 nt!KiSwapContext+0×26
b60cdf54 808294b9 dc399008 89b87748 b60ce01c nt!KiSwapThread+0×2e5
b60cdf88 b96d69db 00000002 b60cdfbc 00000001 nt!KeWaitForMultipleObjects+0×3d7
WARNING: Stack unwind information not available. Following frames may be wrong.
b60cdfe8 b96d719e 89b87748 dc399008 b60ce01c DriverA+0×69db
[…]

We notice “89b87770  Unknown” and double check what object the thread is waiting for:

0: kd> dp b60cdfbc L00000002
b60cdfbc  89b87770 b97004ac

These are exactly the same objects that are listed in !thread command output. We see that the second one is normal and resides in a nonpaged area:

0: kd> dt _DISPATCHER_HEADER b97004ac
ntdll!_DISPATCHER_HEADER
   +0x000 Type             : 0 ''
   +0x001 Absolute         : 0 ''
   +0x001 NpxIrql          : 0 ''
   +0x002 Size             : 0x4 ''
   +0x002 Hand             : 0x4 ''
   +0x003 Inserted         : 0 ''
   +0x003 DebugActive      : 0 ''
   +0x000 Lock             : 262144
   +0x004 SignalState      : 0
   +0x008 WaitListHead     : _LIST_ENTRY [ 0x89a11e70 - 0x89a11e70 ]

0: kd> !address b97004ac
  a71e3000 - 13e1d000                          
          Usage       KernelSpaceUsageNonPagedSystem

The other looks like an invalid Random Object from the free nonpaged pool entry (it even says about itself that it is bad) that used to belong in the past to Configuration Manager:

0: kd> !pool 89b87770
Pool page 89b87770 region is Nonpaged pool
[...]
 89b87540 size:   98 previous size:   40  (Allocated)  File (Protected)
*89b875d8 size:  260 previous size:   98  (Free)      *CMpa
  Pooltag CMpa : registry post apcs, Binary : nt!cm
 89b87838 size:   28 previous size:  260  (Allocated)  FSfm
[…]

0: kd> dd 89b87770
89b87770  bad0b0b0 00000000 00000000 00000000
89b87780  8a04be01 00000000 89b87788 89b87788
89b87790  00150006 e56c6946 8993e208 89ab96b8
89b877a0  00000000 00000000 bad0b0b0 c0000800
89b877b0  02110004 63426343 88ebbf80 00001000
89b877c0  00199000 00000000 8993e238 88d0d248
89b877d0  0019a000 00000000 00000000 00000000
89b877e0  00000000 00000000 00000000 00000000

0: kd> dt _DISPATCHER_HEADER 89b87770
ntdll!_DISPATCHER_HEADER
   +0×000 Type             : 0xb0 ”
   +0×001 Absolute         : 0xb0 ”
   +0×001 NpxIrql          : 0xb0 ”
   +0×002 Size             : 0xd0 ”
   +0×002 Hand             : 0xd0 ”
   +0×003 Inserted         : 0xba ”
   +0×003 DebugActive      : 0xba ”
   +0×000 Lock             : -1160728400
   +0×004 SignalState      : 0
   +0×008 WaitListHead     : _LIST_ENTRY [ 0×0 - 0×0 ]

Now some counterfactual thinking. One possible scenario after KeWaitForMultipleObjects was called to wait for both objects to become signalled (3rd WAIT_TYPE parameter) the free pool slot was allocated or coalesced with SignalState becoming nonzero by coincidence and other members becoming random values and then the second normal object becomes signalled when another thread sets the notification event…

- Dmitry Vostokov @ DumpAnalysis.org -

a bobo address - an address a system will definitely crash at, given an opportunity

Examples: bad0b0b0, 00000000

- Dmitry Vostokov @ DumpAnalysis.org -

The system crashes at it (Google search shows 164,000 hits). Notice the second part “b0b0″ after “bad”. For my eyes (I wear glasses) it is “bobo” – that was my mother telling me when I was a child and I was about to touch a hot or sharp object.

Bad! Bo-bo!

Was the address value designed intentionally or it is just a coincidence?

- Dmitry Vostokov @ DumpAnalysis.org -

The CRC Encyclopedia of Mathematics, Third Edition - 3 Volume Set

I spotted this book on Amazon US and was thrilled to have the new edition in 3 volumes for easy handling when reading. I also have the previous edition that is even featured on my own book cover (the picture of my previous library book arrangement, the book is highlighted in white rectangle in the lower right corner):

This is a unique volume that sits between The Princeton Companion to Mathematics (that I’m also reading now) and Encyclopedic Dictionary of Mathematics: The Mathematical Society of Japan (that I also own). In fact after reading 3 volumes from cover to cover I can start with 2 volumes of EDM. There is also Springer Encyclopaedia of Mathematics in 11 volumes with various additional supplement volumes that I plan to own as well and it looks to me on the same level as EDM.

After searching for the best price I ordered a copy from Amazon DE and after my purchase in just a few days the price was up by 50%! I can only explain this that more people tried to purchase after I used twitter to announce this encyclopedia (there were 5 copies available on Amazon DE and in just 2 days only 1 left) or there was a mistake in price.

3 volumes arrived and I immediately started reading them, a few pages from each volume every day using mod 3 reading technique, for example, Wed - Vol I, Thu - Vol II, Fri - Vol III, Mon - Vol I, an so on. I prefer paper books for bulk reading instead of electronic version (in this case corresponding website) although if I’m interested in a specific article or a keyword I go to Wolfram MathWorld website to get the latest update and citations. These paperback volumes are just for day-to-day scheduled reading to get ideas and general mathematical education. This is why I don’t need an Index. For example, just after reading the first pages I got the idea of cubic (qubic) memory representation.

I usually put reviews on Amazon after I finish a book from cover to cover but in this case the review would be waiting for at least a year so I write it now based on my first impressions. After some time I plan to update it.

- Dmitry Vostokov @ LiterateScientist.com -

Inspired by qubic memory.

- Dmitry Vostokov @ DumpAnalysis.org -

A nibble is a (0,1)-matrix, a byte is a cubic 0,1-lattice and the next cubic byte-boundary 0,1-lattice represents a 64-bit qword:

This is what I call a natural memory representation as memory building blocks or qubic memory (do not mistaken it with qubit memory). This elevates bytes and 64-bit quadruple words as natural addresses and shows that 32-bit addresses are unnatural.

This also allows to us to visualize certain overlapped memory patterns in dump files (same vertice, edge or side).

- Dmitry Vostokov @ DumpAnalysis.org -

- Dmitry Vostokov @ DumpAnalysis.org -

Some differences with Anaxagoras philosophy where Mind is a partial substance to distinguish animate and inanimate and is a source of Motion. In memoidealism Memory is a substance that is always present in things including itself and is a source of Process.

- Dmitry Vostokov @ DumpAnalysis.org - 

Birds eye view of software traces makes it easier to see their coarse blocked structure:

where further finer structure is discernible and even nested blocks:

Some blocks of output can be seen when scrolling trace viewer output but if a viewer support zooming it is possible to get an overview and jump directly into a Characteristic Message Block, for example, debug messages of repeated attempts to query a database. If a viewer supports message coloring it also helps. Sometimes this technique is useful to ignore bulk messages and start the analysis around block boundaries.

- Dmitry Vostokov @ TraceAnalysis.org -

Here is a fragment of a condensed view of a CDF (ETW-based) trace imported into MS Word:

- Dmitry Vostokov @ TraceAnalysis.org -

Suppose we want to write a support tool to troubleshoot a frequent software problem. Would we start with GUI? Most tools are command line tools and we therefore choose Tool Façade pattern to decouple GUI from CLI:

By making our GUI optional we postpone its development until later implementation phase when we want to beautify or simplify the tool user interface. The troubleshooting of software problem we want to automate is quite complex, scattered across several knowledge base articles, with many troubleshooting steps and various checks. We therefore treat different steps as TUWs, Troubleshooting Units of Work (aggregating related ones if necessary) and choose Checklist pattern to coordinate them:

Initially we think that just one checklist is suffice but while studying the domain of troubleshooting we find that the problem usually spans client and server computers, where servers sometimes have client roles as well and different troubleshooting steps and checks are needed. In order to simplify the tool we apply Span Differentiator pattern and our architectural UML component diagram becomes more refined:

We also see that different TUW use similar operations like querying registry values or checking whether certain processes are running and factor them out into separate SMs, Supporting Modules:

Deployment methods are important in troubleshooting where it is not always desirable to change configuration on production servers and we plan for optional Self Extractor pattern:

In diagrams we liberally mixed component and static UML diagramming elements. We also need to design a uniform interface that each TUW module exposes to the main tool coordinator module but we leave it for the part 2.

- Dmitry Vostokov @ DumpAnalysis.org -

As a dual to my previous Resume and CV: As a Book (it actually has a “bug” on the cover, try to spot it) I plan to publish the long time memories in the following book next year:

My Failed Job Interviews: Reflections on 50 Percent (ISBN: 978-1906717889)

The recollections of my pre-memory dump analysis era span East and West, small and giant software companies, full time and part time, office and remote job positions, direct and recruitment company hiring, phone and on-site, technical and business interviews.

- Dmitry Vostokov @ DumpAnalysis.org -

Support tools can be packaged for delivery as (not counting optional separate readme and EULA files):

• - A raw collection of modules
• - A single installation package
• - A single archived file
• - A single self-extractable component

The latter common packaging choice is a pattern itself that I call Self Extractor. Typical examples include sysinternals tools like Process Monitor. Here is a simple unorthodox UML diagram for a single platform tool combining elements from static and component diagrams to illustrate component embedding (not sharing):

SM is a supporting module, for example, a driver, to carry out some task or receive notifications.

Some tools even extract different components depending on the processor architecture, for example, x86 and x64. This is illustrated on a more elaborate UML diagram:

The typical example would be a backward compatible x86 Extractor that extracts an x64 driver (Extractee) for an x64 OS kernel that doesn’t load x86 drivers.

- Dmitry Vostokov @ DumpAnalysis.org -