Software Diagnostics Library

Typical software trace may contain several Error Messages with different error codes and different exception names with Exception Stack Traces. Searching for individual codes or exceptions in problem databases may show many matches. Searching for all of them may show nothing. Therefore, we can construct the set of all subsets from the set of codes and exceptions (a power set) and perform analytic reasoning (and a search) based on certain subsets based on the problem description, Trace Viewpoints such as Use Case Trails, Motifs, Focus of Tracing, Foreground Components, (Adjoint) Threads of Activity, and simply some Activity Regions and Message Sets.

The following picture illustrates Error Powerset analysis pattern with a trace that has 4 error messages where 2 messages have the same error code.

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

Sometimes we need to know about client-server interaction between components, threads, or processes in order to find out where the problem started. For example, if we have Error Message or Discontinuity in one PID Adjoint Thread of Activity, and we know that that process uses API from another PID, we can look at the latter PID Adjoint Thread to see if there are any Error Messages or other problems. The failure in the server can propagate to the client as illustrated in the following diagram:

We call this pattern Coupled Activities similar to Coupled Processes memory analysis pattern. It can help in Intra- and Inter-Correlation analysis, for example in choosing adjoint threads from Sheaf of Activities.

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

Sometimes, a stack trace from Stack Trace Collection may look well-formed at the first sight like having an expected start frames, for example:

0:000> ~*k

[...]

# 19 Id: 16a4.21f4 Suspend: 0 Teb: 7e95b000 Unfrozen
ChildEBP RetAddr
0c2de6b0 74eb112f ntdll!NtWaitForMultipleObjects+0xc
0c2de83c 76ca7b89 KERNELBASE!WaitForMultipleObjectsEx+0xcc
0c2de858 76d007bf kernel32!WaitForMultipleObjects+0x19
0c2dec98 76d00295 kernel32!WerpReportFaultInternal+0x50b
0c2deca8 76ce1709 kernel32!WerpReportFault+0x74
0c2decb0 74f5f705 kernel32!BasepReportFault+0x19
0c2ded3c 76fb4f84 KERNELBASE!UnhandledExceptionFilter+0x1f4
0c2ded54 76fb5728 ntdll!TppExceptionFilter+0x30
0c2ded64 76f5c95a ntdll!TppWorkerpInnerExceptionFilter+0xe
0c2df914 76ca7c04 ntdll!TppWorkerThread+0×87f5a
0c2df928 76f1ad1f kernel32!BaseThreadInitThunk+0×24
0c2df970 76f1acea ntdll!__RtlUserThreadStart+0×2f
0c2df980 00000000 ntdll!_RtlUserThreadStart+0×1b

[...]

So, we may think something wrong happened in ntdll!TppWorkerThread code (although 0×87f5a offset looks suspicious). However, in reality, in this case due to exception filter logic (or some other reason in different cases) we have Hidden Stack Trace. When looking at UnhandledExceptionFilter parameters (or raw stack as in the case of Hidden Exceptions) we find an exception context:

0:019> kv
ChildEBP RetAddr Args to Child
0c2de6b0 74eb112f 00000003 0c2de880 00000001 ntdll!NtWaitForMultipleObjects+0xc
0c2de83c 76ca7b89 00000003 0c2de880 00000000 KERNELBASE!WaitForMultipleObjectsEx+0xcc
0c2de858 76d007bf 00000003 0c2de880 00000000 kernel32!WaitForMultipleObjects+0x19
0c2dec98 76d00295 00000000 00000001 00000000 kernel32!WerpReportFaultInternal+0x50b
0c2deca8 76ce1709 0c2ded3c 74f5f705 0c2ded94 kernel32!WerpReportFault+0x74
0c2decb0 74f5f705 0c2ded94 00000001 a79b7895 kernel32!BasepReportFault+0x19
0c2ded3c 76fb4f84 0c2ded94 0c2ded94 00000000 KERNELBASE!UnhandledExceptionFilter+0×1f4
0c2ded54 76fb5728 00000000 00000000 0c2df914 ntdll!TppExceptionFilter+0×30
0c2ded64 76f5c95a 0c2df8d0 76f00a70 0c2df914 ntdll!TppWorkerpInnerExceptionFilter+0xe
0c2df914 76ca7c04 0f79e380 76ca7be0 a5b45024 ntdll!TppWorkerThread+0×87f5a
0c2df928 76f1ad1f 0f79e380 a59141d7 00000000 kernel32!BaseThreadInitThunk+0×24
0c2df970 76f1acea ffffffff 76f00233 00000000 ntdll!__RtlUserThreadStart+0×2f
0c2df980 00000000 76ed4a00 0f79e380 00000000 ntdll!_RtlUserThreadStart+0×1b

0:019> dd 0c2ded94 L2
0c2ded94 0c2deef8 0c2def48

0:019> .cxr 0c2def48
eax=15f237e5 ebx=15f235e9 ecx=15f237e1 edx=7e95b000 esi=15f237e1 edi=09724b10
eip=76f00fb2 esp=0c2df3ac ebp=0c2df3ac iopl=0 nv up ei pl nz na po nc
cs=0023 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00010202
ntdll!RtlEnterCriticalSection+0×12:
76f00fb2 f00fba3000 lock btr dword ptr [eax],0 ds:002b:15f237e5=????????

0:019> k
*** Stack trace for last set context - .thread/.cxr resets it
ChildEBP RetAddr
0c2df3ac 7407999c ntdll!RtlEnterCriticalSection+0x12
0c2df3cc 7407acd6 ModuleA!DoWork+0x1b
[...]
0c2df73c 76ee3aa7 ModuleA!ThreadPoolWorkCallback+0xa9
0c2df77c 76ee1291 ntdll!TppWorkpExecuteCallback+0x137
0c2df914 76ca7c04 ntdll!TppWorkerThread+0x48e
0c2df928 76f1ad1f kernel32!BaseThreadInitThunk+0x24
0c2df970 76f1acea ntdll!__RtlUserThreadStart+0x2f
0c2df980 00000000 ntdll!_RtlUserThreadStart+0x1b

We consider this a different pattern than Hidden Call because an entire stack (sub)trace is missing between UnhandledExceptionFilter and thread start frames:

ntdll!NtWaitForMultipleObjects
KERNELBASE!WaitForMultipleObjectsEx
kernel32!WaitForMultipleObjects
kernel32!WerpReportFaultInternal
kernel32!WerpReportFault
kernel32!BasepReportFault
KERNELBASE!UnhandledExceptionFilter
[...]
ntdll!TppWorkerThread
kernel32!BaseThreadInitThunk
ntdll!__RtlUserThreadStart
ntdll!_RtlUserThreadStart

This pattern is also different from Past Stack Trace pattern because Hidden Stack Trace belongs to PRESENT time zone. Our example is also different from Hidden Exception analysis pattern and its recovered stack trace because exception processing is not hidden and shows Exception Stack Trace albeit with a hidden part.

We were also fortunate to have Stored Exception (accessible by !analyze -v command):

0:019> .exr -1
ExceptionAddress: 76f00fb2 (ntdll!RtlEnterCriticalSection+0x00000012)
ExceptionCode: c0000005 (Access violation)
ExceptionFlags: 00000000
NumberParameters: 2
Parameter[0]: 00000001
Parameter[1]: 15f237e5
Attempt to write to address 15f237e5

0:019> .ecxr
eax=15f237e5 ebx=15f235e9 ecx=15f237e1 edx=7e95b000 esi=15f237e1 edi=09724b10
eip=76f00fb2 esp=0c2df3ac ebp=0c2df3ac iopl=0 nv up ei pl nz na po nc
cs=0023 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00010202
ntdll!RtlEnterCriticalSection+0x12:
76f00fb2 f00fba3000 lock btr dword ptr [eax],0 ds:002b:15f237e5=????????

So this Hidden Stack Trace is detected straightforwardly. But in other cases, such as when we have Multiple Exceptions in a process dump or Stack Trace Collection from a complete memory dump, we need to pay attention to such a possibility.

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

By analogy with Adjoint Thread of Activity we introduce Adjoint Message analysis pattern. Most if not all analysis patterns focus on log message text and consider TID, PID, Module, source file and function as its attributes. However, we can choose one of attributes and consider it as a message in its own right with the original message text consigned now as another attribute. Then we can analyze the structure of the trace from the perspective of that newly selected message:

Since the number of different message values now is smaller (for example, module names) compared to normal trace messages we can use them in protein-like encoding and structure analysis schemes (see Software Trace and Logs as Proteins). We metaphorically name Adjoint Messages as Amino-acid-Messages (A-Messages). We can also compress same message sequences into one message which may be useful for pattern matching (and even use different color intensities to represent message cardinalities):

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

Sometimes we have Periodic Message Blocks of a few adjacent messages, for example, when flags are translated into separate messages per bit. Then we may have a pattern of Sequence Repeat Anomaly when one of several message blocks have missing or added messages compared to the more numerous number of expected identical message blocks. Then Missing Message Message Context may be explored further. The following diagram illustrates the pattern:

The name of the pattern comes from the notion of repeated DNA sequences.

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

We resume our workaround patterns for common reusable solutions to common software execution problems. In the past we proposed a general pattern of Axed Code for removing problem software behavior. The Shadow File blog post about fixing free() crashes by introducing heap metadata header with a data length set to zero led me to generalize and introduce a complementary Axed Data pattern. Such a pattern suggests cutting the data size specified in metadata memory plane (which may be separate from the data plane). In some cases, it may avoid buffer overwrites including Local and Shared in addition to Dynamic Memory Corruption (process heap and kernel pool). The following picture illustrates this general pattern approach.

Sometimes, it may even be possible to provide a workaround by cutting real file data, for example, by changing its file or database record size. But this is also done conceptually by changing file or database system metadata.

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

The advent of virtual machines, the possibility of saving complete memory snapshots without interruption, and the ability to quickly convert such snapshots into a debugger readable memory dump format such as in the case of VMware allows to study how Stack Trace Collections and Wait Chains change over time in complex problem scenarios. Such Stack Trace Surface may also show service restarts if PID changes for processes of interest. We call this pattern by analogy with a memory dump surface where each line corresponds to an individual memory snapshot with coordinates from 0 to the highest address:

In case of orbifold memory space we have a case of a 3D volume (we may call 3D orbifold).

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

Recently we analyzed a few logs which ended with a specialized Activity Region from a subsystem that sets operational parameters. The problem description stated that the system became unresponsive after changing parameters in a certain sequence. Usually, for that system, when we stop logging (even after setting parameters) we end up with messages from some Background Components since some time passes between the end of setting parameters activity and the time the operator sends stop logging request:

However, in the problem case we see message flow stops right in the middle of parameter setting activity:

So we advised to check for any crashes or hangs, and, indeed, it was found that the system was actually experiencing system crashes, and we got memory dumps for analysis where we found Top Module from a 3rd-party vendor related to parameter setting activity.

Please also note an analogy here between normal thread stack traces from threads that are waiting most of the time and Spiking Thread stack trace caught up in the middle of some function.

We call this pattern Ruptured Trace after a ruptured computation.

Note, that if it is possible to restart the system and resume the same tracing we may get an instance of Blackout analysis pattern.

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

Sometimes we notice the anomalies in object distribution in heaps and pools. Memory consumption may be high in case of big objects. Such anomalies may point to possible memory, handle, and object leaks. But it may also be a temporary condition (Memory Fluctuation) due to the large amount of queued or postponed work that can be solved by proper software configuration. Diagnosed anomalies may also direction troubleshooting efforts if they cluster around certain component(s) or specific functionality. The distribution can be assessed by both the total memory consumption and the total number of objects of a particular class.

Here’s an example of Object Distribution Anomaly analysis pattern from .NET heap. The output of !DumpHeap -stat WinDbg SOS extension command shows the abnormal distribution of objects related to SQL data queries:

Count TotalSize
[…]
2342 281040 System.Reflection.RuntimeParameterInfo
3868 309440 System.Data.Metadata.Edm.TypeUsage
13218 317232 System.Object
3484 390208 System.Reflection.RuntimeMethodInfo
6092 508044 System.Int32[]
2756 617344 System.Data.SqlClient._SqlMetaData
2770 822870 System.Char[]
24560 1375360 System.RuntimeType
18 4195296 System.Int64[]
449691 10792584 System.Data.SqlClient.SqlGen.SqlBuilder
449961 10799064 System.Int64
449691 14390112 System.Data.Query.InternalTrees.ComparisonOp
449695 14390240 System.Data.Query.InternalTrees.ConditionalOp
6360 15509435 System.Byte[]
449690 17987600 System.Data.Query.InternalTrees.ConstantOp
449938 17997520 System.Data.Query.InternalTrees.VarRefOp
450898 21643104 System.Data.Common.CommandTrees.DbPropertyExpression
[…]

The anomalous character of the distribution is also illustrated in the following diagrams:

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

This is another variant of Stack Trace Collection pattern that shows stack traces from threads currently execution on all CPUs. Although we can see the non-idle running threads from the stack traces corresponding to all processes and their threads we may also want to see idle thread stack traces too. Also, the corresponding WinDbg command (!running -t -i) is faster if we want to double check the output of !analyze -v command in case of BSOD. The latter command may show the stack trace from the current CPU instead of the stack trace from the thread running on a different CPU that caused a bugcheck. Here’s an example from one of the memory dumps for which !analyze -v command shows an incorrect stack trace in the output when we open the dump file. It reports the stack trace from CPU 0 but the bugcheck  happened on CPU 1:

0: kd> !running -t -i

System Processors:  (00000000000000ff)
Idle Processors:  (00000000000000fd)

Prcbs             Current         (pri) Next            (pri) Idle
0    fffff801e5d85180  fffff801e5ddea00 ( 0)                       fffff801e5ddea00  ................

Child-SP          RetAddr           Call Site
fffff801`e8c9eb60 fffff801`e5c69b74 hal!KeQueryPerformanceCounter+0x75
fffff801`e8c9eba0 fffff801`e5c69e01 nt!KiCheckStall+0x2c
fffff801`e8c9ebd0 fffff801`e5c6aa8f nt!KiFreezeTargetExecution+0x231
fffff801`e8c9ece0 fffff801`e5bdbec2 nt!KiProcessNMI+0x3b
fffff801`e8c9ed30 fffff801`e5bdbd36 nt!KxNmiInterrupt+0x82
fffff801`e8c9ee70 fffff801`e5a2d82f nt!KiNmiInterrupt+0x176
fffff801`e8c8c8e8 fffff801`e5bb91a2 hal!HalProcessorIdle+0xf
fffff801`e8c8c8f0 fffff801`e5ad7848 nt!PpmIdleDefaultExecute+0xa
fffff801`e8c8c920 fffff801`e5ad72a6 nt!PpmIdleExecuteTransition+0x3e8
fffff801`e8c8cb10 fffff801`e5bd64bc nt!PoIdle+0x2f6
fffff801`e8c8cc60 00000000`00000000 nt!KiIdleLoop+0x2c

1    ffffd000f0975180  ffffe0000d726880 (12)                       ffffd000f09813c0  …………….

Child-SP          RetAddr           Call Site
ffffd000`202cb618 fffff801`e5a1cc3c hal!HalpAcpiPmRegisterReadPort+0x1b
ffffd000`202cb620 fffff801`e5a417e7 hal!HalpAcpiPmRegisterRead+0x30
ffffd000`202cb650 fffff801`e5c66af5 hal!HaliHaltSystem+0x53
ffffd000`202cb690 fffff801`e5c66741 nt!KiBugCheckDebugBreak+0×99
ffffd000`202cb6f0 fffff801`e5bd2aa4 nt!KeBugCheck2+0xc6d
ffffd000`202cbe00 fffff801`e5bde4e9 nt!KeBugCheckEx+0×104
ffffd000`202cbe40 fffff801`e5bdcd3a nt!KiBugCheckDispatch+0×69
ffffd000`202cbf80 fffff800`913601da nt!KiPageFault+0×23a
ffffd000`202cc118 fffff800`91363710 DriverA!memcpy+0×21a
[…]

2    ffffd000f09ee180  ffffd000f09fa3c0 ( 0)                       ffffd000f09fa3c0  ................

Child-SP          RetAddr           Call Site
ffffd000`f09f9f88 fffff801`e5c69e01 nt!KiCheckStall+0xa
ffffd000`f09f9f90 fffff801`e5c6aa8f nt!KiFreezeTargetExecution+0x231
ffffd000`f09fa0a0 fffff801`e5bdbec2 nt!KiProcessNMI+0x3b
ffffd000`f09fa0f0 fffff801`e5bdbd36 nt!KxNmiInterrupt+0x82
ffffd000`f09fa230 fffff801`e5a2d82f nt!KiNmiInterrupt+0x176
ffffd000`eb5938e8 fffff801`e5bb91a2 hal!HalProcessorIdle+0xf
ffffd000`eb5938f0 fffff801`e5ad7848 nt!PpmIdleDefaultExecute+0xa
ffffd000`eb593920 fffff801`e5ad72a6 nt!PpmIdleExecuteTransition+0x3e8
ffffd000`eb593b10 fffff801`e5bd64bc nt!PoIdle+0x2f6
ffffd000`eb593c60 00000000`00000000 nt!KiIdleLoop+0x2c

3    ffffd000eb5e5180  ffffd000eb5f13c0 ( 0)                       ffffd000eb5f13c0  ................

Child-SP          RetAddr           Call Site
ffffd000`eb5f0f60 fffff801`e5c69e01 nt!KiCheckStall+0x5f
ffffd000`eb5f0f90 fffff801`e5c6aa8f nt!KiFreezeTargetExecution+0x231
ffffd000`eb5f10a0 fffff801`e5bdbec2 nt!KiProcessNMI+0x3b
ffffd000`eb5f10f0 fffff801`e5bdbd36 nt!KxNmiInterrupt+0x82
ffffd000`eb5f1230 fffff801`e5a2d82f nt!KiNmiInterrupt+0x176
ffffd000`eb5fa8e8 fffff801`e5bb91a2 hal!HalProcessorIdle+0xf
ffffd000`eb5fa8f0 fffff801`e5ad7848 nt!PpmIdleDefaultExecute+0xa
ffffd000`eb5fa920 fffff801`e5ad72a6 nt!PpmIdleExecuteTransition+0x3e8
ffffd000`eb5fab10 fffff801`e5bd64bc nt!PoIdle+0x2f6
ffffd000`eb5fac60 00000000`00000000 nt!KiIdleLoop+0x2c

4    ffffd000f08d1180  ffffd000f08dd3c0 ( 0)                       ffffd000f08dd3c0  ................

Child-SP          RetAddr           Call Site
ffffd000`f08dcf90 fffff801`e5c6aa8f nt!KiFreezeTargetExecution+0x227
ffffd000`f08dd0a0 fffff801`e5bdbec2 nt!KiProcessNMI+0x3b
ffffd000`f08dd0f0 fffff801`e5bdbd36 nt!KxNmiInterrupt+0x82
ffffd000`f08dd230 fffff801`e5a2d82f nt!KiNmiInterrupt+0x176
ffffd000`eb85b8e8 fffff801`e5bb91a2 hal!HalProcessorIdle+0xf
ffffd000`eb85b8f0 fffff801`e5ad7848 nt!PpmIdleDefaultExecute+0xa
ffffd000`eb85b920 fffff801`e5ad72a6 nt!PpmIdleExecuteTransition+0x3e8
ffffd000`eb85bb10 fffff801`e5bd64bc nt!PoIdle+0x2f6
ffffd000`eb85bc60 00000000`00000000 nt!KiIdleLoop+0x2c

5    ffffd000eb8ad180  ffffd000eb8b93c0 ( 0)                       ffffd000eb8b93c0  ................

Child-SP          RetAddr           Call Site
ffffd000`eb8b8f60 fffff801`e5c69e01 nt!KiCheckStall+0x75
ffffd000`eb8b8f90 fffff801`e5c6aa8f nt!KiFreezeTargetExecution+0x231
ffffd000`eb8b90a0 fffff801`e5bdbec2 nt!KiProcessNMI+0x3b
ffffd000`eb8b90f0 fffff801`e5bdbd36 nt!KxNmiInterrupt+0x82
ffffd000`eb8b9230 fffff801`e5a2d82f nt!KiNmiInterrupt+0x176
ffffd000`eb8db8e8 fffff801`e5bb91a2 hal!HalProcessorIdle+0xf
ffffd000`eb8db8f0 fffff801`e5ad7848 nt!PpmIdleDefaultExecute+0xa
ffffd000`eb8db920 fffff801`e5ad72a6 nt!PpmIdleExecuteTransition+0x3e8
ffffd000`eb8dbb10 fffff801`e5bd64bc nt!PoIdle+0x2f6
ffffd000`eb8dbc60 00000000`00000000 nt!KiIdleLoop+0x2c

6    ffffd000eb92a180  ffffd000eb9363c0 ( 0)                       ffffd000eb9363c0  ................

Child-SP          RetAddr           Call Site
ffffd000`eb935f60 fffff801`e5c69e01 nt!KiCheckStall+0x75
ffffd000`eb935f90 fffff801`e5c6aa8f nt!KiFreezeTargetExecution+0x231
ffffd000`eb9360a0 fffff801`e5bdbec2 nt!KiProcessNMI+0x3b
ffffd000`eb9360f0 fffff801`e5bdbd36 nt!KxNmiInterrupt+0x82
ffffd000`eb936230 fffff801`e5a2d82f nt!KiNmiInterrupt+0x176
ffffd000`eb93f8e8 fffff801`e5bb91a2 hal!HalProcessorIdle+0xf
ffffd000`eb93f8f0 fffff801`e5ad7848 nt!PpmIdleDefaultExecute+0xa
ffffd000`eb93f920 fffff801`e5ad72a6 nt!PpmIdleExecuteTransition+0x3e8
ffffd000`eb93fb10 fffff801`e5bd64bc nt!PoIdle+0x2f6
ffffd000`eb93fc60 00000000`00000000 nt!KiIdleLoop+0x2c

7    ffffd000eb967180  ffffd000eb9733c0 ( 0)                       ffffd000eb9733c0  ................

Child-SP          RetAddr           Call Site
ffffd000`eb972f60 fffff801`e5c69e01 nt!KiCheckStall+0x75
ffffd000`eb972f90 fffff801`e5c6aa8f nt!KiFreezeTargetExecution+0x231
ffffd000`eb9730a0 fffff801`e5bdbec2 nt!KiProcessNMI+0x3b
ffffd000`eb9730f0 fffff801`e5bdbd36 nt!KxNmiInterrupt+0x82
ffffd000`eb973230 fffff801`e5a2d82f nt!KiNmiInterrupt+0x176
ffffd000`eb97c8e8 fffff801`e5bb91a2 hal!HalProcessorIdle+0xf
ffffd000`eb97c8f0 fffff801`e5ad7848 nt!PpmIdleDefaultExecute+0xa
ffffd000`eb97c920 fffff801`e5ad72a6 nt!PpmIdleExecuteTransition+0x3e8
ffffd000`eb97cb10 fffff801`e5bd64bc nt!PoIdle+0x2f6
ffffd000`eb97cc60 00000000`00000000 nt!KiIdleLoop+0x2c

This command is obviously faster than repeatedly switching to subsequent CPUs using ~s command and then checking the corresponding stack trace (k). It also helps in diagnosing Spiking Threads in kernel and complete memory dumps.

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

Sometimes a few Error Messages or Periodic Errors with low Statement Density for specific Activity Regions or Adjoint Threads of Activity (for specific component, file or function) may constitute Activity Disruption. If the particular functionality was no longer available at the logging time then its unavailability may not be explained by such disruptions, and such messages may be considered False Positive Errors in relation to the reported problem:

But, if we have Periodic Message Blocks containing only Periodic Errors, Activity Region or Adjoint Thread Discontinuity, or simply No Activity, then we may have the complete cease of activity that may correlate with the unavailable functionality:

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

Sometimes we have messages that report about error but do not give exact details. For example, “Communication error. Problem at the server side” or “Access denied error”. This may be the case of Translated Messages. Such messages are plain language descriptions or reinterpretations of flags, error and status codes contained in another log message. These descriptions may be coming from system API, for example, FormatMessage from Windows API, or may be from custom formatting code. Since the code translating the message is in close proximity to the original message both messages usually follow each other with zero or very small Time Delta, come from the same component, file, function, and belong to the same Thread of Activity:

This pattern is different from Gossip because the latter messages come from different modules, and, although they reflect some underlying event, they are independent from each.

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

General traces and logs may have Message Space regions “surrounded” by the so-called Interspace. Such Interspace regions may link individual Message Space regions like in this diagram generalizing WinDbg !process 0 3f command output:

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

Message stream can be considered as a union of Message Spaces. A message space is an ordered set of messages preserving the structure of the overall trace. Such messages may be selected based on a memory space they came from or can be selected by some other general attribute, or a combination of attributes and facts. The differences from Message Set is that Message Space is usually much larger (with large scale structure) with various Message Sets extracted from it later for fine grained analysis. This pattern also fits nicely with Adjoint Spaces. Here’s an example of kernel and managed spaces in the same CDF / ETW trace from Windows platform where we see that kernel space messages came not only from System process but also from other process contexts:

In the context of general traces and logs such as debugger logs separate Message Space regions may be linked (or “surrounded”) by Interspace.

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

Predicate Stack Trace Collections allow you to get a subset of stack traces, for example, by showing only stack traces where a specific module is used (for example, !stacks 2 module WinDbg command). From diagnostic analysis perspective, the order in which threads from the subset appear is also important, especially when the output is sorted by thread creation time or simply the order is given by a global thread linked list. We call this analysis pattern Thread Poset by analogy with a mathematical concept of poset (partially ordered set):

Such an analysis pattern is mostly useful when we compare stack traces for differences or when we don’t have symbols for some problem version and want to map threads to some other previous normal run where symbol files are available. Any discrepancies may point in the direction of further diagnostic analysis. For example, we got this fragment of Stack Trace Collection:

4.000188 fffffa800d3d3b50 ffd0780f Blocked ModuleA+0x1ac1
4.00018c fffffa800d3f9950 ffd07b53 Blocked ModuleA+0xd802
4.000190 fffffa800d4161b0 fffffda6 Blocked ModuleA+0x9ce4
4.000194 fffffa800d418b50 fffffda6 Blocked ModuleA+0x9ce4
4.000198 fffffa800d418660 fffffda6 Blocked ModuleA+0x9ce4
4.0001ac fffffa800d41eb50 ffd078d2 Blocked ModuleA+0xa7cf
4.0001b0 fffffa800d41e660 ffd0780f Blocked ModuleA+0x9ce4
4.0001c0 fffffa800d48f300 ffd0e5c0 Blocked ModuleA+0x7ee5

We didn’t have symbols, and, therefore, didn’t know whether there was anything wrong with those threads. Fortunately, we had Thread Poset from an earlier 32-bit version with available symbol files:

4.0000ec 85d8dc58 000068c Blocked ModuleA!FuncA+0x9b
4.0000f0 85d9fc78 001375a Blocked ModuleA!FuncB+0x67
4.0000fc 85db8a58 000068c Blocked ModuleA!WorkerThread+0xa2
4.000104 85cdbd48 000ff44 Blocked ModuleA!WorkerThread+0xa2
4.000108 85da2788 000ff47 Blocked ModuleA!WorkerThread+0xa2
4.000110 857862e0 0013758 Blocked ModuleA!FuncC+0xe4
4.000114 85dda250 000ff44 Blocked ModuleA!FuncD+0xf2

If we map worker threads to the middle section of x64 version we see just one more worker thread but the overall order is the same:

4.000188 fffffa800d3d3b50 ffd0780f Blocked ModuleA+0x1ac1
4.00018c fffffa800d3f9950 ffd07b53 Blocked ModuleA+0xd802
4.000190 fffffa800d4161b0 fffffda6 Blocked ModuleA+0×9ce4
4.000194 fffffa800d418b50 fffffda6 Blocked ModuleA+0×9ce4
4.000198 fffffa800d418660 fffffda6 Blocked ModuleA+0×9ce4
4.0001ac fffffa800d41eb50 ffd078d2 Blocked ModuleA+0xa7cf
4.0001b0 fffffa800d41e660 ffd0780f Blocked ModuleA+0×9ce4
4.0001c0 fffffa800d48f300 ffd0e5c0 Blocked ModuleA+0×7ee5

So we may think of x64 Thread Poset as normal if x86 Thread Poset is normal too. Of course, only initially, then to continue looking for other patterns of abnormal behavior. If necessary, we may need to inspect stack traces deeper, because individual threads from two Thread Posets may differ in their stack trace depth, subtraces, and in usage of other components. Despite the same order, some threads may actually be abnormal.

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

Managed code Nested Exceptions give us process virtual space bound stack traces. However, exception objects may be marshaled across processes and even computers. The remote stack trace return addresses don’t have the same validity in different process contexts. Fortunately, there is _remoteStackTraceString field in exception objects that contains the original stack trace. Default analysis command sometimes uses it:

0:013> !analyze -v

[...]

EXCEPTION_OBJECT: !pe 25203b0
Exception object: 00000000025203b0
Exception type: System.Reflection.TargetInvocationException
Message: Exception has been thrown by the target of an invocation.
InnerException: System.Management.Instrumentation.WmiProviderInstallationException, Use !PrintException 0000000002522cf0 to see more.
StackTrace (generated):
SP IP Function
000000001D39E720 0000000000000001 Component!Proxy.Start()+0x20
000000001D39E720 000007FEF503D0B6 mscorlib_ni!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)+0x286
000000001D39E880 000007FEF503CE1A mscorlib_ni!System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)+0xa
000000001D39E8B0 000007FEF503CDD8 mscorlib_ni!System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)+0x58
000000001D39E900 000007FEF4FB0302 mscorlib_ni!System.Threading.ThreadHelper.ThreadStart()+0x52

[...]

MANAGED_STACK_COMMAND: ** Check field _remoteStackTraceString **;!do 2522cf0;!do 2521900

[...]

0:013> !DumpObj 2522cf0
[...]
000007fef51b77f0 4000054 2c System.String 0 instance 2521900 _remoteStackTraceString
[…]

0:013> !DumpObj 2521900
Name: System.String
[…]
String: at System.Management.Instrumentation.InstrumentationManager.RegisterType(Type managementType)
at Component.Provider..ctor()
at Component.Start()

Checking this field may also be necessary for exceptions of interest from managed space Execution Residue. We call this pattern Distributed Exception. The basic idea is illustrated in the following diagram using the borrowed UML notation (not limited to just two computers):

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

Palimpsest Messages are messages where some part or all of their content was erased or overwritten.

The name of this pattern comes from palimpsest manuscript scrolls. Such messages may be a part of malnarratives or result from Circular Tracing or trace buffer corruption. Sometimes, not all relevant data is erased and by using Intra- and Inter-Correlation, and via the analysis of Message Invariants it is possible to recover the original data. Also, as in Recovered Messages pattern it may be possible to use Message Context to infer some partial content.

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

Occasionally, we look at Stack Trace Collection and notice Internal Stack Trace. This is a stack trace that is shouldn’t be seen in a normal crash dump because statistically it is rare (we planned to name this pattern Rare Stack Trace initially). This stack trace is also not Special Stack Trace because it is not associated with the special system events or problems. It is also not a stack trace that belongs to various Wait Chains or Spiking Threads. This is also a real stack trace and not a reconstructed or hypothetical stack trace such as Rough Stack Trace or Past Stack Trace. This is simply a thread stack trace that shows some internal operation, for example, where it suggests that message hooking was involved:

THREAD fffffa8123702b00 Cid 11cc.0448 Teb: 000007fffffda000 Win32Thread: fffff900c1e6ec20 WAIT: (WrUserRequest) UserMode Non-Alertable
fffffa81230cf4e0 SynchronizationEvent
Not impersonating
DeviceMap fffff8a0058745e0
Owning Process fffffa81237a8b30 Image: ProcessA.exe
Attached Process N/A Image: N/A
Wait Start TickCount 1258266 Ticks: 18 (0:00:00:00.280)
Context Switch Count 13752 IdealProcessor: 1 NoStackSwap LargeStack
UserTime 00:00:00.468
KernelTime 00:00:00.187
Win32 Start Address ProcessA!ThreadProc (0×000007feff17c608)
Stack Init fffff8800878c700 Current fffff8800878ba10
Base fffff8800878d000 Limit fffff88008781000 Call fffff8800878c750
Priority 12 BasePriority 8 UnusualBoost 0 ForegroundBoost 2 IoPriority 2 PagePriority 5
Child-SP RetAddr Call Site
fffff880`0878ba50 fffff800`01a6c8f2 nt!KiSwapContext+0×7a
fffff880`0878bb90 fffff800`01a7dc9f nt!KiCommitThreadWait+0×1d2
fffff880`0878bc20 fffff960`0010dbd7 nt!KeWaitForSingleObject+0×19f
fffff880`0878bcc0 fffff960`0010dc71 win32k!xxxRealSleepThread+0×257
fffff880`0878bd60 fffff960`000c4bf7 win32k!xxxSleepThread+0×59
fffff880`0878bd90 fffff960`000d07a5 win32k!xxxInterSendMsgEx+0×112a
fffff880`0878bea0 fffff960`00151bf8 win32k!xxxCallHook2+0×62d
fffff880`0878c010 fffff960`000d2454 win32k!xxxCallMouseHook+0×40
fffff880`0878c050 fffff960`0010bf23 win32k!xxxScanSysQueue+0×1828
fffff880`0878c390 fffff960`00118fae win32k!xxxRealInternalGetMessage+0×453
fffff880`0878c470 fffff800`01a76113 win32k!NtUserRealInternalGetMessage+0×7e
fffff880`0878c500 00000000`771b913a nt!KiSystemServiceCopyEnd+0×13 (TrapFrame @ fffff880`0878c570)
00000000`053ff258 000007fe`fac910f4 USER32!NtUserRealInternalGetMessage+0xa
00000000`053ff260 000007fe`fac911fa DUser!CoreSC::xwProcessNL+0×173
00000000`053ff2d0 00000000`771b9181 DUser!MphProcessMessage+0xbd
00000000`053ff330 00000000`774111f5 USER32!_ClientGetMessageMPH+0×3d
00000000`053ff3c0 00000000`771b908a ntdll!KiUserCallbackDispatcherContinue (TrapFrame @ 00000000`053ff288)
00000000`053ff438 00000000`771b9055 USER32!NtUserPeekMessage+0xa
00000000`053ff440 000007fe`ebae03fa USER32!PeekMessageW+0×105
00000000`053ff490 000007fe`ebae4925 ProcessA+0×5a
[…]
00000000`053ff820 00000000`773ec541 kernel32!BaseThreadInitThunk+0xd
00000000`053ff850 00000000`00000000 ntdll!RtlUserThreadStart+0×1d

We see that this thread was neither waiting for significant time nor consuming CPU. It was reported that ProcessA.exe was very slow responding. So perhaps this was slowly punctuated thread execution with periodic small waits. In fact, Execution Residue analysis revealed Non-Coincidental Symbolic Information of the 3rd-party Message Hook and its Module Product Process was identified. Its removal resolved the problem.

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

Here we add yet another Technology-Specific Subtrace pattern for COM client calls (as compared to COM interface invocation for servers). We recently got a complete memory dump where we had to find the destination server process, and we used the old technique described in the article In Search of Lost CID. We reprint the 32-bit stack subtrace trace here:

[...]
00faf828 7778c38b ole32!CRpcChannelBuffer::SwitchAptAndDispatchCall+0x112
00faf908 776c0565 ole32!CRpcChannelBuffer::SendReceive2+0xd3
00faf974 776c04fa ole32!CAptRpcChnl::SendReceive+0xab
00faf9c8 77ce247f ole32!CCtxComChnl::SendReceive+0×1a9
00faf9e4 77ce252f RPCRT4!NdrProxySendReceive+0×43
00fafdcc 77ce25a6 RPCRT4!NdrClientCall2+0×206
[...]

Here’s also an x64 fragment from Semantic Structures (PID.TID) pattern:

[...]
00000000`018ce450 000007fe`ffee041b ole32!CRpcChannelBuffer::SwitchAptAndDispatchCall+0xa3
00000000`018ce4f0 000007fe`ffd819c6 ole32!CRpcChannelBuffer::SendReceive2+0×11b
00000000`018ce6b0 000007fe`ffd81928 ole32!CAptRpcChnl::SendReceive+0×52
00000000`018ce780 000007fe`ffedfcf5 ole32!CCtxComChnl::SendReceive+0×68
00000000`018ce830 000007fe`ff56ba3b ole32!NdrExtpProxySendReceive+0×45
00000000`018ce860 000007fe`ffee02d0 RPCRT4!NdrpClientCall3+0×2e2
[...]

If we have the call over ALPC it is easy to find the server process and thread (Wait Chain). In case of a modal loop we can use raw stack analysis technique mentioned above (see also this case study).

Other subtrace examples can be found in pattern examples for High Contention (.NET CLR monitors), Wait Chain (RTL_RESOURCE), and in this case study.

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

One of the questions asked was what can we do if we got a kernel memory dump instead of the requested complete memory dump? Can it be useful? Of course, if we requested a complete memory dump after analyzing a kernel memory dump then the second kernel dump may be useful for double checking. Therefore, we assume that we just got a kernel memory dump for the first time and the issue is some performance issue or system freeze and not a bugcheck. If we have a bugcheck then kernel memory dumps are sufficient most of the time, and we do not consider them for this pattern.

Such a kernel memory dump is still useful because of user space diagnostic indicators pointing to possible patterns in user space or “interspace”. We call this pattern User Space Evidence. It is a collective super-pattern like Historical Information.

We can see patterns in kernel memory dumps such as Wait Chains (for example, ALPC or Process Objects), Deadlocks (for example ALPC), kernel stack traces corresponding to specific Dual Stack Traces (for example, exception processing), Handle Leaks, Missing Threads, Module Product Process, One-Thread Processes, Spiking Thread, Process Factory (for example, PPID for Zombie Processes), and others.

Found evidence may point to specific processes and process groups (Couples Processes, session processes) and suggest process memory dump collection (especially forcing further complete memory dumps is problematic) or troubleshooting steps for diagnosed processes.

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