Software Diagnostics Library

Sometimes we see a functional activity in a trace and / or see basic facts. Then we might want to find a correlation between that activity or facts in another part of the trace. If that intra-correlation fits into our problem description we may claim a possible explanation or, if we are lucky, we have just found, an inference to the best explanation, as philosophers of science like to say. Here is an example, but this time using Citrix WindowHistory tracing tool. A third-party application was frequently loosing the focus and the suspicion was on a terminal services client process. It was found that the following WindowHistory trace fragment corresponds to that application:

Handle: 00050586 Class: "Application A Class" Title: ""
     Title changed at 15:52:4:3 to "Application A"
     Title changed at 15:52:10:212 to "Application A - File1"
[...]
   Process ID: 89c
   Thread ID: d6c
[...]
   Visible: true
   Window placement command: SW_SHOWNORMAL
        Placement changed at 15:54:57:506 to SW_SHOWMINIMIZED
        Placement changed at 15:55:2:139 to SW_SHOWNORMAL
   Foreground: false
        Foreground changed at 15:52:4:3 to true
        Foreground changed at 15:53:4:625 to false
        Foreground changed at 15:53:42:564 to true
        Foreground changed at 15:53:44:498 to false
        Foreground changed at 15:53:44:498 to true
        Foreground changed at 15:53:44:592 to false
        Foreground changed at 15:53:45:887 to true
        Foreground changed at 15:53:47:244 to false
        Foreground changed at 15:53:47:244 to true
        Foreground changed at 15:53:47:353 to false
        Foreground changed at 15:54:26:416 to true
        Foreground changed at 15:54:27:55 to false
        Foreground changed at 15:54:27:55 to true
        Foreground changed at 15:54:27:180 to false
        Foreground changed at 15:54:28:428 to true
        Foreground changed at 15:54:28:771 to false
        Foreground changed at 15:54:28:865 to true
        Foreground changed at 15:54:29:99 to false
        Foreground changed at 15:54:30:877 to true
        Foreground changed at 15:54:57:521 to false
        Foreground changed at 15:55:2:76 to true
        Foreground changed at 15:57:3:378 to false
        Foreground changed at 15:57:11:396 to true
        Foreground changed at 15:57:29:601 to false
        Foreground changed at 15:57:39:803 to true
        Foreground changed at 15:58:54:41 to false
        Foreground changed at 15:59:8:96 to true
        Foreground changed at 16:1:19:478 to false
        Foreground changed at 16:1:27:527 to true
        Foreground changed at 16:1:39:914 to false
        Foreground changed at 16:2:0:515 to true
        Foreground changed at 16:7:14:628 to false
        Foreground changed at 16:7:24:246 to true
        Foreground changed at 16:9:53:523 to false
        Foreground changed at 16:10:15:919 to true
        Foreground changed at 16:10:31:426 to false
        Foreground changed at 16:11:12:818 to true
        Foreground changed at 16:11:59:538 to false
        Foreground changed at 16:12:39:456 to true
        Foreground changed at 16:13:6:364 to false

Corresponding terminal services client window trace fragment doesn’t have any foreground changes but another application main window has lots of them:

Handle: 000D0540 Class: "Application B Class" Title: "Application B"
[...]
   Process ID: 3ac
   Thread ID: bd4
[...]
   Foreground: false
        Foreground changed at 15:50:36:972 to true
        Foreground changed at 15:50:53:732 to false
        Foreground changed at 15:50:53:732 to true
        Foreground changed at 15:50:53:826 to false
        Foreground changed at 15:51:51:352 to true
        Foreground changed at 15:51:53:941 to false
        Foreground changed at 15:53:8:135 to true
        Foreground changed at 15:53:8:182 to false
        Foreground changed at 15:53:10:178 to true
        Foreground changed at 15:53:13:938 to false
        Foreground changed at 15:53:30:443 to true
        Foreground changed at 15:53:31:20 to false
        Foreground changed at 15:53:31:20 to true
        Foreground changed at 15:53:31:129 to false
        Foreground changed at 15:53:34:78 to true
        Foreground changed at 15:53:34:795 to false
        Foreground changed at 15:53:34:795 to true
        Foreground changed at 15:53:34:873 to false
        Foreground changed at 15:53:36:901 to true
        Foreground changed at 15:53:42:502 to false
        Foreground changed at 15:53:42:502 to true
        Foreground changed at 15:53:42:564 to false
        Foreground changed at 15:57:3:425 to true
        Foreground changed at 15:57:4:595 to false
        Foreground changed at 15:57:10:507 to true
        Foreground changed at 15:57:11:318 to false
        Foreground changed at 15:57:29:632 to true
        Foreground changed at 15:57:31:67 to false
        Foreground changed at 15:57:32:721 to true
        Foreground changed at 15:57:33:844 to false
        Foreground changed at 15:58:54:88 to true
        Foreground changed at 15:58:56:178 to false
        Foreground changed at 15:59:6:505 to true
        Foreground changed at 15:59:7:987 to false
        Foreground changed at 16:1:19:525 to true
        Foreground changed at 16:1:19:961 to false
        Foreground changed at 16:1:26:607 to true
        Foreground changed at 16:1:27:434 to false
        Foreground changed at 16:1:39:914 to true
        Foreground changed at 16:1:39:992 to false
        Foreground changed at 16:1:49:798 to true
        Foreground changed at 16:2:0:437 to false
        Foreground changed at 16:7:14:628 to true
        Foreground changed at 16:7:14:847 to false
        Foreground changed at 16:7:18:76 to true
        Foreground changed at 16:7:24:106 to false
        Foreground changed at 16:9:58:790 to true
        Foreground changed at 16:10:4:16 to false
        Foreground changed at 16:10:4:874 to true
        Foreground changed at 16:10:4:890 to false
        Foreground changed at 16:10:8:634 to true
        Foreground changed at 16:10:15:779 to false
        Foreground changed at 16:10:56:766 to true
        Foreground changed at 16:10:59:402 to false
        Foreground changed at 16:10:59:652 to true
        Foreground changed at 16:10:59:667 to false
        Foreground changed at 16:12:9:397 to true
        Foreground changed at 16:12:39:347 to false
        Foreground changed at 16:13:18:375 to true
        Foreground changed at 16:14:33:656 to false

We can see that most of the time when Application A window looses focus Application B window gets it.

- Dmitry Vostokov @ TraceAnalysis.org -

DumpAnalysis.org acquires TraceAnalysis.org to complete computer DATA artifact analysis. The domain currently points to Dump Analysis Portal page but this might change in the future.

- Dmitry Vostokov @ DumpAnalysis.org -

Next obvious structural trace analysis pattern is called Circular Trace. Sometimes this information is missing in the problem description or trace metadata doesn’t reflect this. Then circular traces can be detected by trace file size (usually large) and from timestamps, like this 100Mb CDF trace snippet:

No     Module  PID  TID  Date      Time         Statement
[Begin of trace listing]
1      ModuleA 4280 1736 5/28/2009 08:53:50.496 [... Trace statement 1]
2      ModuleB 6212 6216 5/28/2009 08:53:52.876 [... Trace statement 2]
3      ModuleA 4280 4776 5/28/2009 08:54:13.537 [... Trace statement 3]
[... Some traced exceptions helpful for analysis ...]
3799   ModuleA 4280 3776 5/28/2009 09:15:00.853 [… Trace statement 3799]
3800   ModuleA 4280 1736 5/27/2009 09:42:12.029 [… Trace statement 3800]
[… Skipped …]
[… Skipped …]
[… Skipped …]
579210 ModuleA 4280 4776 5/28/2009 08:53:35.989 [… Trace statement 579210]
[End of trace listing]

In such traces, the analysis region is usually found at the wrap point because, as soon as an elusive, hard-to-reproduce problem occurs, the trace is stopped.

- Dmitry Vostokov @ TraceAnalysis.org -

“A trace is a narrative, the story of a computation.”

Dmitry Vostokov, Software Tracing and Logging: Architecture, Design, Implementation and Analysis Patterns

- Dmitry Vostokov @ TraceAnalysis.org -

This is a forthcoming book to be released next year after we finally publish DebugWare book by the end of this summer:

Software Tracing and Logging: Architecture, Design, Implementation and Analysis Patterns (ISBN: 978-1906717728)

I have already begun working on it in the background. The scope of DebugWare book is too wide to cover tracing and logging in great detail not to mention the very important subject of software trace analysis.

- Dmitry Vostokov @ TraceAnalysis.org -

A typical trace is a detailed narrative. It is accompanied by a problem description that lists essential facts. Therefore the first task of any trace analysis is to check the presence of Basic Facts in the trace. If they are not visible or do not correspond then the trace was possibly not recorded during the problem or was taken from a different computer or under different conditions. Here is an example. A user “test01″ cannot connect to an application. We look at the trace and find this statement:

No   PID  TID  Date      Time         Statement
[...]
3903 3648 5436 4/29/2009 16:17:36.150 User Name: test01
[...]

At least we can be sure that this trace was taken for the user test01 especially when we expect this or similar trace statements. If we could not see this trace statement we can suppose that the trace was taken at the wrong time, for example, after the problem happened already.

- Dmitry Vostokov @ TraceAnalysis.org -

After coming back to engineering I decided to expand the domain of my research and start the new series of posts called Trace Analysis Patterns. In addition to Citrix CDF / Microsoft ETW traces I plan to cover other variants based on my extensive software engineering background in the past where I used tracing in software products ranging from soft multi-platform real-time systems to static code analysis tools. Connection with memory dump analysis will be covered too because sometimes the combination of static and dynamic data leads to interesting observations and helps to troubleshoot and resolve customer problems especially when not all data can be collected dynamically.

In fact, stack traces and their collections are specializations of the more general traces. Another example is historical information in memory dump files especially when it is somehow timestamped.  

In this part I start with the obvious and to some extent the trivial pattern called Periodic Error. This is an error or a status value that is observed periodically many times:

No     PID  TID   Date      Time         Statement
[...]
664957 1788 22504 4/23/2009 17:59:14.600 MyClass::Initialize: Cannot open connection “Client ID: 310″, status=5  
[…]
668834 1788 19868 4/23/2009 19:11:52.979 MyClass::Initialize: Cannot open connection “Client ID: 612″, status=5 
[…]

or 

No     PID  TID   Date      Time         Statement
[...] 
202314 1788 19128 4/21/2009 16:03:46.861 HandleDataLevel: Error 12005 Getting Mask
[…]
347653 1788 17812 4/22/2009 13:26:00.735 HandleDataLevel: Error 12005 Getting Mask
[…]

Here single trace entries can be isolated from the trace and studied in detail. 

Be aware though that some modules might report periodic errors that are false positive, in the sense, that they are expected as a part of implementation details, for example, when a function returns an error to indicate that bigger buffer is required or to estimate its size for a subsequent call. It merits its own pattern name and I come to it next time with more examples.

I also created a page where I’ll will be adding all tracing patterns:

Trace Analysis Patterns   

- Dmitry Vostokov @ TraceAnalysis.org -