Software Diagnostics Library

Like in a literature (and in a narratology in general) we have components that trace themselves and components that tell the story of a computation including status updates they query about other components and subsystems. This pattern gets its name Diegetic Messages from diegesis. Here’s the difference between diegetic (in blue bold) and non-diegetic trace messages:

PID    TID    TIME          MESSAGE     
11864  11912  06:34:53.598  ModuleA: foo called bar. Status OK.
11620  10372  06:34:59.754  ModuleB: ModuleA integrity check. Status OK.

Some modules may emit messages that tell about their status but from their message text we know the larger computation story like in a process startup sequence example.  

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

Sometimes a software trace is truncated when the trace session was stopped prematurely, often when a problem didn’t manifest itself visually. We can diagnose such traces by their short time duration, missing anchor messages or components necessary for analysis. My favourite example is user session initialization in a Citrix terminal services environment when problem effects are visible only after the session is fully initialized and an application is launched but a truncated CDF trace only shows the launch of winlogon.exe despite the presence of a process creation trace provider or other components that record the process launch sequence and the trace itself lasts only a few seconds after that.

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

Adding AI. Analysis Improvement.

After reading earlier today Windows Internals pages about system audit an idea came to my mind in the evening to provide audit services for memory dump and software trace analysis. One mind is good but two are better, especially if the second is a pattern-driven AI. Here are possible problem scenarios:

Problem: You are not satisfied with a crash report.

Problem: Your critical issue is escalated to the VP level. Engineers analyze memory dumps and software traces. No definite conclusion so far. You want to be sure that nothing has been omitted from the analysis.

Problem: You analyze a system dump or a software trace. You need a second pair of eyes but don’t want to send your memory dump due to your company security policies.

Other scenarios (use cases) will be added as soon as I see the service fit to the realities of software technical support.

I plan to make this service operational in July - August, 2010. Prices to be announced soon.

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

Here we introduce a software narratological partitioning of a trace into Head, Prologue, Core, Epilogue and Tail segments. This is useful for comparative software trace analysis. Suppose, a trace started just before the reproduction steps or a start marker was injected (by CDFMarker, for example) and finished just after the last repro steps or after an end marker was injected. Then its core trace messages are surrounded by prologue and epilogue statements. What is before and after are not necessary for analysis and usually distract an analyst. They are shown as grey areas on the following picture where the left trace is for working (non-working) scenario and the right trace is for non-working (working) scenario:

The size of a core segment need not be the same because environments and executed code paths might be different. However, often some traces are truncated (another pattern). Also sometimes it is difficult to establish whether the first trace is normal and the second has a tail or the first one is truncated and the second one is normal with an optional tail. Here artificial markers are important.

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

This paleodebugging tool was excavated from Central Russia (thanks to Mr. Kutuzov) and generously provided for a photo session by its owner Mr. Mansour:

It also inspired this sequence of strcat: Analog -> Anatrace -> Analyzer -> Tracelyzer -> Loglyzer.

… enough tracing. It’s time to close our session:

… what is left? If you are curious, look at this conceptual picture:

Component Trace

If you wonder what electricity has to do with tracing (at a metaphorical level) look at this trace analysis pattern:

Statement Density and Current

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

The limit of Discontinuity pattern is No Activity. The absence of activity can be seen at a thread level or at a process level where it is similar to Missing Component pattern. The difference from the latter pattern is that we know for certain that we selected our process modules for tracing but don’t see any trace messages. Consider this example:

#  Source        PID  TID  Time         Function     Message
1  TraceSettings 1480 8692 08:04:20.682              **** Start Trace Session 
[... TraceSettings messages 2-11 show that we selected AppA for tracing ...]
12 ModuleB       3124 4816 08:04:37.049 WorkerThread Worker thread running
13 TraceSettings 1480 8692 08:04:41.966              **** Trace Session was stopped

Only modules from AppA process and modules from a coupled process (for example, ModuleB) were selected. However, we only see a reminder message from the coupled process (3124.4816:ModuleB!WorkerThread) and no messages for 21 seconds. Fortunately, AppA process memory dump was saved during the tracing session:

Debug session time: Fri May 21 08:04:31.000 2010 (GMT+0)

We see 2 threads waiting for a critical section:

0:000> ~*kL

  14  Id: 640.8b8 Suspend: 1 Teb: 7ffa7000 Unfrozen
ChildEBP RetAddr 
0248f8c0 7c827d29 ntdll!KiFastSystemCallRet
0248f8c4 7c83d266 ntdll!ZwWaitForSingleObject+0xc
0248f900 7c83d2b1 ntdll!RtlpWaitOnCriticalSection+0x1a3
0248f920 0040dea8 ntdll!RtlEnterCriticalSection+0xa8
[…]
0248f9a4 77ce78aa rpcrt4!Invoke+0×30
0248f9c0 77ce7a94 rpcrt4!NdrCallServerManager+0×17
0248fcb8 77ce7b7c rpcrt4!NdrStubCall+0×1d6
0248fcd0 77c7ff7a rpcrt4!NdrServerCall+0×15
0248fd04 77c8042d rpcrt4!DispatchToStubInCNoAvrf+0×38
0248fd58 77c80353 rpcrt4!RPC_INTERFACE::DispatchToStubWorker+0×11f
0248fd7c 77c7e0d4 rpcrt4!RPC_INTERFACE::DispatchToStub+0xa3
0248fdbc 77c7e080 rpcrt4!RPC_INTERFACE::DispatchToStubWithObject+0xc0
0248fdfc 77c812f0 rpcrt4!LRPC_SCALL::DealWithRequestMessage+0×41e
0248fe20 77c88678 rpcrt4!LRPC_ADDRESS::DealWithLRPCRequest+0×127
0248ff84 77c88792 rpcrt4!LRPC_ADDRESS::ReceiveLotsaCalls+0×430
0248ff8c 77c8872d rpcrt4!RecvLotsaCallsWrapper+0xd
0248ffac 77c7b110 rpcrt4!BaseCachedThreadRoutine+0×9d

  15  Id: 640.18c0 Suspend: 1 Teb: 7ffdb000 Unfrozen
ChildEBP RetAddr 
01b8ff40 7c827d29 ntdll!KiFastSystemCallRet
01b8ff44 7c83d266 ntdll!ZwWaitForSingleObject+0xc
01b8ff80 7c83d2b1 ntdll!RtlpWaitOnCriticalSection+0x1a3
01b8ffa0 0040dba7 ntdll!RtlEnterCriticalSection+0xa8
[…]
01b8ffec 00000000 kernel32!BaseThreadStart+0×34

Unfortunately it belongs to a missing thread and blocked threads wait forever:

0:000> !cs -l -o -s
-----------------------------------------
DebugInfo          = 0x01facdd0
Critical section   = 0x01da19c0 (+0x1DA19C0)
LOCKED
LockCount          = 0×2
WaiterWoken        = No
OwningThread       = 0×00001384
RecursionCount     = 0×1
LockSemaphore      = 0×578
SpinCount          = 0×00000000
ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled

0:000> ~~[1384]
              ^ Illegal thread error in ‘~~[1384]’

Apparently AppA process was hanging and it explains why we don’t see any activity in the trace. We suggested to enable user mode stack trace database using this article as an example: CTX106970 and get a new dump.

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

Finally, after careful consideration, I’ve come up with the topic that has been neglected so far but at the same time important for both camps (kernel space and user space, including managed space): complete memory dump and software trace analysis. I plan to publish the first webinar agenda early in July and deliver the webinar in August (the date should be finalized by mid July).

PS. Sailing memory spaces under an RGB flag

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

Finally Citrix has published a tool (written by my colleague Colm Naish, lead escalation engineer) that allows controlled injection of events into CDF (ETW) trace message stream. This is useful in many troubleshooting scenarios where we need to rely on Significant Event and Anchor Message analysis patterns to partition traces into artificial Activity Regions to start our analysis with. This is also analogous for the imposition of the external time on the stream of tracing events from software narratology perspective:

CDFMarker On Demand - For XenApp and XenDesktop

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

When we have a software trace we read it in two directions. The first one is to deconstruct it into a linear ordered source code based on PLOT fragments. The second direction is to construct an interpretation that serve as an explanation for reported software behaviour. During the interpretive reading we remove irrelevant information, compress relevant activity regions and construct the new fictional software trace based on discovered patterns and our problem description.

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

This pattern is similar to No Component Symbols memory analysis pattern and is called No Trace Metafile:

#     Module    PID  TID  Time        Message
21372 \src\dllA 2968 5476 3:55:10.004 Calling foo()
21373 Unknown   2968 5476 3:55:10.004 ????? Unknown( 27): GUID=1EF56EBD-A7FC-4892-8DBA-00AD813F8A24 (No Format Information found).
21374 Unknown   2968 5476 3:55:10.004 ????? Unknown( 27): GUID=1EF56EBD-A7FC-4892-8DBA-00AD813F8A24 (No Format Information found). 
21375 Unknown   2968 5476 3:55:10.004 ????? Unknown( 27): GUID=1EF56EBD-A7FC-4892-8DBA-00AD813F8A24 (No Format Information found).
21376 Unknown   2968 5476 3:55:10.004 ????? Unknown( 28): GUID=1EF56EBD-A7FC-4892-8DBA-00AD813F8A24 (No Format Information found).
21377 Unknown   2968 5476 3:55:10.004 ????? Unknown( 23): GUID=1EF56EBD-A7FC-4892-8DBA-00AD813F8A24 (No Format Information found).
21378 \src\dllA 2968 5476 3:55:10.004 Calling bar()

In some case when we don’t have TMF files it is possible to detect broad behavioral patterns such as:

• Circular Trace
• Statement Density and Current
• Discontinuity
• Time Delta
• Trace Acceleration

By looking at Thread of Activity we can also sometimes infer the possible component name based on surrounding trace messages with present TMF files, escpecially when we have source code access. For example, in the trace above it can be dllA or any other module that foo function calls.

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

My drive to generalization led me to place an adornment on the portal to highlight the fact that memory and software trace analysis patterns are under an umbrella of general software behaviour patterns:

http://www.dumpanalysis.org/Software-Behavior-Patterns-Headline

In the forthcoming post series I plan to write about similarities between these two branches and also provide pattern examples from non-Windows platforms. All this material will provide the foundation for the forthcoming book Software Behavior: A Guide to Systematic Analysis (ISBN: 978-1906717162).

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

PLOT - Program Lines of Trace - the source code lines behind trace messages

Examples: What a plot do we have here! The struggle against the monster database component and endless voyages across space boundaries.

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org

Modern pattern-driven software trace analysis on Microsoft and Citrix platforms urgently requires a practical guide and OpenTask plans to publish this summer the following book in both Practical Foundations and Systematic Software Fault Analysis series:

• Title: Citrix Common Diagnostic Facility (CDF) and Microsoft Event Tracing for Windows (ETW) Software Trace Analysis: Practical Foundations
• Author: Dmitry Vostokov
• Publisher: Opentask (August 2010)
• Language: English
• Product Dimensions: 22.86 x 15.24
• ISBN: 1906717176
• ISBN-13: 978-1906717179
• Paperback: 200 pages

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

I’ve decided to adapt archaeological classificatory framework (using my favourite method of inquiry: metaphorical bijectionism) to lay out foundations for yet another attempt to classify DA+TA patterns):

Attribute  ↔ Pattern
Artefact   ↔ Component Artefact1
Assemblage ↔ Component Assemblage
Culture    ↔ Memory System Culture²

1 Can be either a component-generated artefact or a component like a module or symbol file
2 Typical examples of memory system cultures are Windows, UNIX or even “Multiplatform”

I propose a word Memoarchaeological for such a framework and Memoarchaeology for a branch of Memoretics that studies saved computer memory artifacts from past computations (as opposed to live memory).

Note: In one of the forthcoming issues of Debugged! MZ/PE magazine there will be presented yet another classificatory scheme.

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

Forthcoming CARE and STARE online systems additionally aim to provide software behaviour pattern identification via debugger log and trace analysis and suggest possible software troubleshooting patterns. The purpose of these post series is to provide high level overview of possible patterns of software behavior and how they can be recognised and analyzed. This work started in October, 2006 with the identification of computer memory patterns and later continued with software trace patterns. Bringing all of them under a unified linked framework seems quite natural to me.

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

OpenTask to offer first 3 volumes of Memory Dump Analysis Anthology in one set:

The set is available exclusively from OpenTask e-Commerce web site starting from June. Individual volumes are also available from Amazon, Barnes & Noble and other bookstores worldwide.

Product information:

• Title: Modern Memory Dump and Software Trace Analysis: Volumes 1-3
• Author: Dmitry Vostokov
• Language: English
• Product Dimensions: 22.86 x 15.24
• Paperback: 1600 pages
• Publisher: Opentask (31 May 2010)
• ISBN-13: 978-1-906717-99-5

Information about individual volumes:

• Volume 1
• Volume 2
• Volume 3

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

When a software trace is lengthy it is useful to partition it into several regions based on a sequence of Anchor Messages. The choice of them can be determined by a Vocabulary Index or an Adjoint Thread of Activity. For example, an ETW trace with almost 900,000 messages recorded during a desktop connection for 6 minutes can be split into 14 segments by the adjoint thread of DLL_PROCESS_ATTACH message (the message was generated by DllMain of an injected module, not shown in the trace output for formatting clarity):

#      PID  TID  Time         Message
24226  2656 3480 10:41:05.774 AppA.exe: DLL_PROCESS_ATTACH     
108813 4288 4072 10:41:05.774 AppB.exe: DLL_PROCESS_ATTACH
112246 4180 3836 10:41:05.940 DllHost.exe: DLL_PROCESS_ATTACH
135473 2040 3296 10:41:12.615 AppC.exe: DLL_PROCESS_ATTACH
694723 1112 1992 10:44:23.393 AppD.exe: DLL_PROCESS_ATTACH
703962 5020 1080 10:44:42.014 DllHost.exe: DLL_PROCESS_ATTACH
705511 4680 3564 10:44:42.197 DllHost.exe: DLL_PROCESS_ATTACH
705891 1528 2592 10:44:42.307 regedit.exe: DLL_PROCESS_ATTACH
785231 2992 4912 10:45:26.516 AppE.exe: DLL_PROCESS_ATTACH
786523 3984 1156 10:45:26.605 powershell.exe: DLL_PROCESS_ATTACH
817979 4188 4336 10:45:48.707 wermgr.exe: DLL_PROCESS_ATTACH
834875 3976 1512 10:45:52.342 LogonUI.exe: DLL_PROCESS_ATTACH
835229 4116 3540 10:45:52.420 AppG.exe: DLL_PROCESS_ATTACH

Each region can be analyzed independently for any anomalies, for example, to look for the answer to the question why wermgr.exe was launched. An example of partitioning is illustrated on the following schematic diagram:

It is also possible to make another trace segmentation by interleaving regions above with another set of anchor messages comprising of the adjoint thread of DLL_PROCESS_DETACH message:

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

Plan to start providing training and seminars in my free time. If you are interested please answer these questions (you can either respond here in comments or use this form for private communication http://www.dumpanalysis.org/contact):

• Are you interested in on-site training, prefer traveling or attending webinars?
• Are you interested in software trace analysis as well?
• What specific topics are you interested in?
• What training level (beginner, intermediate, advanced) are you interested in? (please provide an example, if possible)

Additional topics of expertise that can be integrated into training include Source Code Reading and Analysis, Debugging, Windows Architecture, Device Drivers, Troubleshooting Tools Design and Implementation, Multithreading, Deep Down C and C++, x86 and x64 Assembly Language Reading.

Looking forward to your responses. Any suggestions are welcome.

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

“Capturing delicate moments, one gives birth to a poetry of traces …”

Ange Leccia, Motionless Journeys, by Fabien Danesi

More patterns from software narratology. Now we illustrate Defamiliarizing Effect where we see sudden unfamiliar trace statements across familiar landscape of characteristic blocks and activity regions:

/familar traces/

/new trace from a problem system/

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

Metaphorical bijection from literary narratology to software narratology provides a pattern of Background and Foreground Components. This can be easily illustrated on pseudo-trace color diagrams. Suppose we troubleshoot a graphical issue using an ETW trace containing the output from all components of the problem system. Graphic components and their messages are foreground for a trace viewer (a person) against numerous background components (for example, database, file and registry access, shown in shades of green):

Trace viewers (for example, CDFAnalyzer) can filter out background component messages and present only foreground components (that I propose to call component foregrounding):

Of course, this process is iterative and parts of what once was foreground become background and candidates for further filtering:

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