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 a print spooler process (19984) and immediately see discontinuity (Volume 4, page 341) in the trace with the large time delta (page 282) between the last PID message and the last trace statement (almost 4 minutes):
No Source PID TID Time Message 712 srcprintui16200 12:1998422:31.571 PropertySheet returns 1 [... no messages for PID 19984 ...] 5103 srcmgmt 1292 7604 12:26:11.659 WaitAction
If we select the adjoint thread (page 283) of source srcprintdriver (in other words, filter only its messages) we would see discontinuity with the similar time delta. We know that the printer driver runs in print spooler context. However, PID had changed and that means the print spooler was restarted (perhaps after a crash):
No Source PID TID Time Message 557 srcprintdriver16200 12:1998422:28.069 DisableDevice returns [... discontinuity for printdriver ...] 1462 srcprintdriver17584 12:1082826:03.854 DllMain
Befind every trace and its messages is source code:
Borrowing the acronym PLOT (Program Lines of Trace, page 235) we now try to discern basic source code patterns that give rise to simple message patterns in soft-ware traces. There are only a few distinct PLOTs and the ability to mentally map trace statements to source code is crucial to software trace reading and comprehension. More complex message patterns (for example, specific message blocks or correlated messages) arise from supportable and maintainable realizations of architectural, de-sign and implementation patterns and.
We were thinking about acronym SLOT (Source Lines of Trace) but decided to use PLOT because it metaphorically bijects (Volume 4, page 241) into literary theory[40] and narrative plots[41].
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 (page 272). The second direction is to construct an interpretation that serve as an explanation for re-ported 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.
Finally Citrix has published a tool[42] (written by my colleague Colm Naish) 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 (page 281) and Anchor Message (page 293) analysis patterns to partition traces into artificial Activity Regions (Volume 4, page 348) 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.
By analogy with paratext[43] let's introduce a software narratological concept of the extended software trace that consists of a software trace plus additional supporting information that makes troubleshooting and debugging easier. Such "paratextual" information can consists of pictures, videos, accounts of scenarios and past problem histories, customer interviews and even software trace delivery medium and format (if preformatted).
It's time to introduce a conceptual software narratological framework for viewing soft-ware traces (using rich ETW / CDF tracing as our main focus). Here we consider a soft-ware story (fabula[44]) as a full trace when every component was selected for tracing and emits debug messages during code execution paths. However, during viewing we can filter on and off certain modules, threads, processes, messages, etc. (adjoint threading, Volume 4, page 330) and see a different sub-story or plot (sujet[45]). Every software plot (please do not confuse with PLOT acronym, page 272) can be presented differently (us-ing appropriate discourse[46]). Some presentational examples include temporal rearrange-ment, collapse of repetitive regions, source code hypertext (lexia) and allegorical de-vices such as message tool-tip comments. Here is a diagram that depicts story (fable, fabula) - plot (sujet) - presentation (discourse):
Another tool that supports adjoint threading (Volume 4, page 330) in addition to Citrix CDFAnalyzer[47] (see also Debugging Experts magazine article[48] for a pictorial description of this concept) is Process Monitor[49]. We can view adjoint threads having common attributes like TID (ordinary threads), PID, operation (function), process name, etc. by using this right click context menu:
For example, this adjoint thread having RegOpenKey as its ATID (Adjoint Thread ID) where we excluded Path, Result and Detail fields for viewing clarity (together these fields can constitute an analogous Message field in ETW / CDF traces):
Time of Day Process Name PID TID Operation [...] 09:33:25.9545410 Explorer.EXE 1292 1032RegOpenKey09:33:25.9548650 Explorer.EXE 1292 1032RegOpenKey09:33:25.9550234 Explorer.EXE 1292 1032RegOpenKey09:33:25.9551656 Explorer.EXE 1292 1032RegOpenKey09:33:25.9692456 WFICA32.EXE 3588 3496RegOpenKey09:33:25.9761325 wfcrun32.exe 852 1148RegOpenKey09:33:25.9761912 wfcrun32.exe 852 1148RegOpenKey09:33:25.9762295 wfcrun32.exe 852 1148RegOpenKey09:33:25.9984547 wfcrun32.exe 852 1148RegOpenKey09:33:26.0023831 wfcrun32.exe 852 1148RegOpenKey09:33:26.0074675 wfcrun32.exe 852 1148RegOpenKey09:33:26.0087191 Explorer.EXE 1292 1032RegOpenKey09:33:26.1618595 iexplore.exe 1348 2228RegOpenKey09:33:26.1625697 iexplore.exe 1348 2228RegOpenKey09:33:26.1632745 iexplore.exe 1348 2228RegOpenKey09:33:26.1633924 iexplore.exe 1348 2228RegOpenKey09:33:26.1639209 iexplore.exe 1348 2228RegOpenKey[...]
[40] http://en.wikipedia.org/wiki/Literary_theory
[41] http://en.wikipedia.org/wiki/Plot_(narrative)
[42] http://support.citrix.com/article/CTX124577
[43] http://en.wikipedia.org/wiki/Paratext
[44] http://en.wikipedia.org/wiki/Sujet
[45] Ibid.
[46] http://en.wikipedia.org/wiki/Discourse
[47] http://support.citrix.com/article/CTX122741
[48] http://www.debuggingexperts.com/adjoint-thread
[49] http://technet.microsoft.com/en-us/sysinternals/bb896645.aspx