Software Diagnostics Library

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 -

Typical software narrative history consists of requests and responses, for example, function or object method calls and returns:

#     Module PID  TID  Time         File    Function Message
[...]
26060 dllA   1604 7108 10:06:21.746 fileA.c foo      Calling bar
[...]
26232 dllA   1604 7108 10:06:22.262 fileA.c foo      bar returns 0x5
[...]

The code that generates execution history is response-complete if it traces both requests and responses. For such code (except in cases where tracing is stopped before a response) the absence of expected responses could be a sign of blocked threads or quiet exception processing. The code that generates execution history is exception-complete if it also traces exception processing. Response-complete and exception-complete code is called call-complete. If we don’t see response messages for call-complete code we have Incomplete History.

In general, we can talk about the absence of certain messages in a trace as a deviation from the standard trace sequence template corresponding to a use case. The difference there is in a missing request too. This is a topic for next patterns.

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

Here is one of the first case studies in pattern-driven software trace analysis. A user starts printing but nothing comes out. However, if the older printer driver is installed everything works as expected. We suspect that print spooler crashes if the newer printer driver is used. Based on known module name in ETW trace we find PID for print spooler process (19984) and immediately see discontinuity in the trace with the large time delta between the last PID message and the last trace statement (almost 4 minutes): 

No   Source        PID   TID   Time         Message
712  \src\print\ui 19984 16200 12:22:31.571 PropertySheet returns 1
[… no messages for PID 19984 …]
5103　\src\mgmt　　 1292  7604  12:26:11.659 WaitAction

If we select the adjoint thread of source \src\print\driver (in other words, filter only its messages) we would see discontinuity with the similar time delta. We know that printer driver runs in print spooler context. However, PID had changed and that means print spooler was restarted (perhaps after a crash):

No   Source            PID   TID   Time         Message
557  \src\print\driver 19984 16200 12:22:28.069 DisableDevice returns
[… discontinuity for \print\driver …]
1462 \src\print\driver 10828 17584 12:26:03.854 DllMain

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

Recently, a reader of this blog sent me a minidump file and a debugger log of an application that had about 300 modules loaded in a process address space. What was interesting is the huge amount of ModLoad / Unload module debugger events in the log prior to an access violation exception. Some modules were loaded / unloaded many times, for example (only included lines for just one module but there were many other):

[...]
ModLoad: 16640000 16649000   X:\Client\Bin\ModuleA.dll
[...]
Unload module X:\Client\Bin\ModuleA.dll at 16640000
[...]
ModLoad: 192b0000 192b9000   X:\Client\Bin\ModuleA.dll
[...]
Unload module X:\Client\Bin\ModuleA.dll at 192b0000
[...]
ModLoad: 192b0000 192b9000   X:\Client\Bin\ModuleA.dll
[...]
Unload module X:\Client\Bin\ModuleA.dll at 192b0000
[...]
ModLoad: 161b0000 161b9000   X:\Client\Bin\ModuleA.dll
[...]
Unload module X:\Client\Bin\ModuleA.dll at 161b0000
[...]
ModLoad: 161e0000 161e9000   X:\Client\Bin\ModuleA.dll
[...]
Unload module X:\Client\Bin\ModuleA.dll at 161e0000
[...]
ModLoad: 161f0000 161f9000   X:\Client\Bin\ModuleA.dll
[...]
Unload module X:\Client\Bin\ModuleA.dll at 161f0000
[...]
ModLoad: 161f0000 161f9000   X:\Client\Bin\ModuleA.dll
[...]
Unload module X:\Client\Bin\ModuleA.dll at 161f0000
[...]
ModLoad: 161f0000 161f9000   X:\Client\Bin\ModuleA.dll
[...]
Unload module X:\Client\Bin\ModuleA.dll at 161f0000
[...]
ModLoad: 161f0000 161f9000   X:\Client\Bin\ModuleA.dll
[...]
Unload module X:\Client\Bin\ModuleA.dll at 161f0000
[...]
ModLoad: 161f0000 161f9000   X:\Client\Bin\ModuleA.dll
[...]
Unload module X:\Client\Bin\ModuleA.dll at 161f0000
[...]
ModLoad: 161f0000 161f9000   X:\Client\Bin\ModuleA.dll
[...]
Unload module X:\Client\Bin\ModuleA.dll at 161f0000
[...]
ModLoad: 161f0000 161f9000   X:\Client\Bin\ModuleA.dll
[...]
Unload module X:\Client\Bin\ModuleA.dll at 161f0000
[...]
ModLoad: 171b0000 171b9000   X:\Client\Bin\ModuleA.dll
[...]
Unload module X:\Client\Bin\ModuleA.dll at 171b0000
[...]
ModLoad: 25180000 25189000   X:\Client\Bin\ModuleA.dll
[...]
Unload module X:\Client\Bin\ModuleA.dll at 25180000
[...]
ModLoad: 171b0000 171b9000   X:\Client\Bin\ModuleA.dll
[...]
Unload module X:\Client\Bin\ModuleA.dll at 171b0000
[...]
ModLoad: 171b0000 171b9000   X:\Client\Bin\ModuleA.dll
[...]
Unload module X:\Client\Bin\ModuleA.dll at 171b0000
[...]
[...]
[...]
ModLoad: 0df60000 0df69000   X:\Client\Bin\ModuleA.dll
[...]
Unload module X:\Client\Bin\ModuleA.dll at 0df60000
[...]
(f38.560): Access violation - code c0000005 (first chance)
---
--- 1st chance AccessViolation exception ----
[...]

We see the component ModuleA was loaded at different addresses and this looks similar to a singleton object factory with Create / Destroy operations that resembles heap operations Alloc and Free where every allocation can place the same object at a different address. This is why I call all this a component or module heap. The application was COM-based and every domain-specific object was implemented in a separate in-proc COM DLL. There were thousands of such objects.

PS. This story reminds me that when I learnt about COM in 90s I wanted to redesign my word processor written in C to have every paragraph, line and even word to be implemented as a COM object.

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

Sometimes we have a sequence of Activity Regions with increasing values of Statement Current, like depicted here:

The boundaries of regions may be blurry and arbitrarily drawn. Nevertheless, the current is visibly increasing or decreasing, hence the name of this pattern: Trace Acceleration, by analogy with physical acceleration, second-order derivative. We can also metaphorically use here the notion of a partial derivative for trace statement current and acceleration for Threads of Activity and Adjoint Threads of Activity but whether it is useful remains to be seen.

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

This is an extension of Thread of Activity pattern based on the concept of multibraiding and it is called Adjoint Thread of Activity correspondingly. I’m going to illustrate it soon when I publish a synthetic case study involving several software trace analysis patterns.

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

Another useful pattern is called Time Delta. This is a time interval between significant events. For example,

#     Module PID  TID  Time         File    Function Message
1                      10:06:18.994                  (Start)
[...]
6060  dllA   1604 7108 10:06:21.746 fileA.c DllMain  DLL_PROCESS_ATTACH
[…]
24480 dllA   1604 7108 10:06:32.262 fileA.c Exec     Path: C:\Program Files\CompanyA\appB.exe
[…]
24550 dllB   1604 9588 10:06:32.362 fileB.c PostMsg  Event Q
[…]
28230                  10:07:05.170                  (End)

Such deltas are useful in examining delays. In the trace fragment above we are interested in dllA activity from its load until it launches appB.exe. We see that the time delta was only 10 seconds. The message #24550 was the last message from the process ID 1604 and after that we didn’t “hear” from that PID for more than 30 seconds until the tracing was stopped.

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

When looking at software traces and doing either a search for or just scrolling certain messages have our attention immediately. We call them Significant Events and hence the name of this pattern, Significant Event. It could be a recorded exception or an error, a basic fact, a trace message from vocabulary index, or just any trace statement that marks the start of some activity we want to explore in depth, for example, a certain DLL is attached to the process, a coupled process is started or a function is called. The start of a trace and the end of it are trivial significant events and are used in deciding whether the trace is circular, in determining the trace recording interval or its average statement current.

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

Computer memory analysis is based on interconnected structures of symbols and we state that there exists a memory language that extends a hierarchy of modeling and implementation languages (both domain-specific and general-purpose):

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

This is a revised, edited, cross-referenced and thematically organized volume of selected DumpAnalysis.org blog posts about crash dump analysis and debugging written in July 2009 - January 2010 for software engineers developing and maintaining products on Windows platforms, quality assurance engineers testing software on Windows platforms and technical support and escalation engineers dealing with complex software issues. The fourth volume features:

- 13 new crash dump analysis patterns
- 13 new pattern interaction case studies
- 10 new trace analysis patterns
- 6 new Debugware patterns and case study
- Workaround patterns
- Updated checklist
- Fully cross-referenced with Volume 1, Volume 2 and Volume 3
- New appendixes

Product information:

• Title: Memory Dump Analysis Anthology, Volume 4
• Author: Dmitry Vostokov
• Language: English
• Product Dimensions: 22.86 x 15.24

• Paperback: 410 pages
• Publisher: Opentask (30 March 2010)
• ISBN-13: 978-1-906717-86-5

• Hardcover: 410 pages
• Publisher: Opentask (30 April 2010)
• ISBN-13: 978-1-906717-87-2

Back cover features memory space art image: Internal Process Combustion.

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

Having considered computational threads as braided strings and after discerning several software trace analysis patterns (just the beginning) we can see formatted and tabulated software trace output in a new light and employ the “fabric of traces” and braid metaphors for an Adjoint Thread concept. This new concept was motivated by reading about Extended Phenotype (*) and extensive analysis of Citrix ETW-based CDF traces using CDFAnalyzer. The term Adjoint was borrowed from mathematics because the concept we discuss below resembles this metaphorical formula: (Thread A, B) = [A, Thread B]. Let me first illustrate adjoint threading using simplified trace tables. Consider this generalized software trace example (date and time column is omitted for visual clarity):

We see several threads in a process PID 2792. In CDFAnalyzer we can filter trace messages that belong to any column and if we filter by TID we get a view of any Thread of Activity. However, each thread can “run” through any source directory, file name or function. If a function belongs to a library multiple threads would access it. This source location (can be considered as a subsystem), file or function view of activity is called an Adjoint Thread. For example, if we filter only subsystemA column in the trace above we get this table:

We can graphically view subsystemA as a braid string that “permeates the fabric of threads”:

We can get many different braids by changing filters, hence multibraiding. Here is another example of a driver source file view initially permeating 2 process contexts and 4 threads:

(*) A bit of digression. Looks like biology keeps giving insights into software, there is even a software phenotype metaphor albeit a bit restricted to code, I just thought that we need also an Extended Software Phenotype.

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

The Year of Debugging, 0×7D9, was a remarkable year for DumpAnalysis.org. Here is the list of achievements to report:

- Software Trace Analysis as a new discipline with its own set of patterns

- Unification of Memory Dump Analysis with Software Trace Analysis (DA+TA)

- New computer memory dump-based art movements: Opcodism and Physicalist Art

- Discovery of 3D computer memory visualization techniques

- Establishing Software Maintenance Institute

- Broadening software fault injection as Software Defect Construction discipline

- Establishing a new profession of a Software Defect Researcher

- Starting ambitious Dictionary of Debugging

- Publishing Windows Debugging: Practical Foundations book

- Publishing the first x86-free Windows debugging book: x64 Windows Debugging: Practical Foundations

- Establishing the new debugging magazine: Debugged! MZ/PE

- Publishing Memory Dump Analysis Anthology, Volume 3

- Cooperation with OpenTask to promote First Fault Software Problem Solving book

- Establishing Debugging Expert(s) Magazine Online

- Creating the first development process for debugging and software troubleshooting tools: RADII

- Publishing the first pattern-driven memory dump analysis troubleshooting methodology as a foundation for software debugging

- Proposal for an International Memory Analysts and Debuggers Day

- Almost completed Windows Debugging Notebook to be published soon

Now DumpAnalysis.org focuses on The Year of Dump Analysis, 0×7DA, as a foundation for the forthcoming debugging decade and reveals future plans this weekend.

I’m sure that many other organizations and individuals have no less remarkable accomplishments to report for 2009. I promise to track down and write about some of them in the forthcoming book:

The Science of Dr. Watson: An Illustrated History of Debugging (ISBN: 978-1906717070)

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