Software Diagnostics Library

Source code can be considered as a type of a general trace from a corresponding generative narrative plane. We call it Generative Trace since it can generate different traces of execution. If such a trace contains logging code statements, then they form Declarative Trace as a subset of messages. Generative Trace also overlaps with the corresponding Moduli Trace. We can apply many trace and log analysis patterns and even consider line number axis as pseudo-time. The following diagram illustrates Linked Messages analysis pattern in the context of Generative Trace and generated traces:

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

Full symbol files usually include source code information for UI debugging. Debuggers, like WinDbg, may show it for each relevant stack trace frame:

0:001> k
# Child-SP          RetAddr           Call Site
00 00000074`fe5fe3c8 00007ff9`72937ff7 ntdll!NtWaitForMultipleObjects+0x14
01 00000074`fe5fe3d0 00007ff9`72937ede KERNELBASE!WaitForMultipleObjectsEx+0x107
02 00000074`fe5fe6d0 00007ff9`74a671fb KERNELBASE!WaitForMultipleObjects+0xe
03 00000074`fe5fe710 00007ff9`74a66ca8 kernel32!WerpReportFaultInternal+0x51b
04 00000074`fe5fe830 00007ff9`729df848 kernel32!WerpReportFault+0xac
05 00000074`fe5fe870 00007ff9`75304af2 KERNELBASE!UnhandledExceptionFilter+0x3b8
06 00000074`fe5fe990 00007ff9`752ec6d6 ntdll!RtlUserThreadStart$filt$0+0xa2
07 00000074`fe5fe9d0 00007ff9`753011ff ntdll!_C_specific_handler+0x96
08 00000074`fe5fea40 00007ff9`752ca289 ntdll!RtlpExecuteHandlerForException+0xf
09 00000074`fe5fea70 00007ff9`752ffe6e ntdll!RtlDispatchException+0x219
0a 00000074`fe5ff180 00007ff7`bbd51cb0 ntdll!KiUserExceptionDispatch+0x2e
0b 00000074`fe5ff930 00007ff7`bbd51983 SourceStackTrace!std::_Deque_unchecked_const_iterator<std::_Deque_val< std::_Deque_simple_types<int> > >::operator*+0x50 [C:\Program Files (x86)\Microsoft Visual Studio\2019\Professional\VC\Tools\MSVC\14.23.28105\include\deque @ 55]
0c 00000074`fe5ff970 00007ff7`bbd51883 SourceStackTrace!std::_Deque_unchecked_iterator<std::_Deque_val< std::_Deque_simple_types<int> > >::operator*+0×13 [C:\Program Files (x86)\Microsoft Visual Studio\2019\Professional\VC\Tools\MSVC\14.23.28105\include\deque @ 175]
0d 00000074`fe5ff9a0 00007ff7`bbd515f6 SourceStackTrace!std::deque<int,std::allocator<int> >::back+0×33 [C:\Program Files (x86)\Microsoft Visual Studio\2019\Professional\VC\Tools\MSVC\14.23.28105\include\deque @ 1091]
0e 00000074`fe5ff9f0 00007ff7`bbd5156c SourceStackTrace!std::stack<int,std::deque<int,std::allocator<int> > >::top+0×16 [C:\Program Files (x86)\Microsoft Visual Studio\2019\Professional\VC\Tools\MSVC\14.23.28105\include\stack @ 66]
0f 00000074`fe5ffa20 00007ff7`bbd521a3 SourceStackTrace!Info::gather+0×3c [C:\NewWork\SourceStackTrace\InfoGather.cpp @ 9]
10 00000074`fe5ffa90 00007ff7`bbd5108d SourceStackTrace!Info::scatter+0×13 [C:\NewWork\SourceStackTrace\InfoScatter.cpp @ 6]
11 00000074`fe5ffac0 00007ff7`bbd510a9 SourceStackTrace!worker_bar+0×1d [C:\NewWork\SourceStackTrace\bar.cpp @ 10]
12 00000074`fe5ffb00 00007ff7`bbd522b9 SourceStackTrace!worker_foo+0×9 [C:\NewWork\SourceStackTrace\foo.cpp @ 6]
13 00000074`fe5ffb30 00007ff7`bbd526b5 SourceStackTrace!worker+0×9 [C:\NewWork\SourceStackTrace\SourceStackTrace.cpp @ 8]
14 00000074`fe5ffb60 00007ff7`bbd5269b SourceStackTrace!std::_Invoker_functor::_Call<void (__cdecl*)(void)>+0×15 [C:\Program Files (x86)\Microsoft Visual Studio\2019\Professional\VC\Tools\MSVC\14.23.28105\include\type_traits @ 1571]
15 00000074`fe5ffb90 00007ff7`bbd525d4 SourceStackTrace!std::invoke<void (__cdecl*)(void)>+0×1b [C:\Program Files (x86)\Microsoft Visual Studio\2019\Professional\VC\Tools\MSVC\14.23.28105\include\type_traits @ 1571]
16 00000074`fe5ffbc0 00007ff7`bbd59784 SourceStackTrace!std::thread::_Invoke<std::tuple<void (__cdecl*)(void)>,0>+0×64 [C:\Program Files (x86)\Microsoft Visual Studio\2019\Professional\VC\Tools\MSVC\14.23.28105\include\thread @ 40]
17 00000074`fe5ffc10 00007ff9`74a17bd4 SourceStackTrace!thread_start<unsigned int (__cdecl*)(void *),1>+0×50 [minkernel\crts\ucrt\src\appcrt\startup\thread.cpp @ 97]
18 00000074`fe5ffc40 00007ff9`752cced1 kernel32!BaseThreadInitThunk+0×14
19 00000074`fe5ffc70 00000000`00000000 ntdll!RtlUserThreadStart+0×21

Such Source Stack Trace frames has a similar structure as native module!function+offset format and can be mined as well including most of traditional stack trace patterns:

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

Message Flow trace and log analysis pattern generalizes NetFlow to software narratives. We count messages based on the set of Adjoint Threads of Activity, for example PID.TID. This also subsumes network traces aggregated by Src.Dst. Individual single attributes can also be used, for example, aggregation by Thread of Activity, and also by Message Sets.

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

Traces and logs may show drastic qualitative and quantitative pattern changes. We call this analysis pattern Phase Transition by analogy with phase transitions in physical, biological and other complex systems. Usually the goal of the analysis is to find a parameter that caused such transition. Here are a few examples which are self-explanatory.

Change in Statement Density and Current:

Sudden proliferation of (Adjoint) Threads of Activity:

Discontinuity of Activity Region with only Drone Messages left:

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

Raw stack memory region analysis is more productive with Region Clusters analysis pattern. Here we apply simple clustering techniques to organize various region values into disjoint sets with chosen semantics. For our purposes simple sort suffices to generate such clusters that can be visually inspected. We take the same stack.csv file from Region Profile analysis pattern. It’s values are sorted and the results are shown in sorted order with corresponding count of occurrences and symbolic references (we use the internal version of Narrascope written in C++, a narrative debugger, but you can use your favorite scripting language here):

0 count: 13718
1 count: 273
2 count: 23
3 count: 22
4 count: 28
5 count: 9
6 count: 5
7 count: 18
8 count: 35
9 count: 5
a count: 24
b count: 12
c count: 4
d count: 3
e count: 1
f count: 28
10 count: 14
...
c0000034 count: 2
c0000388 count: 2
c01c0001 count: 1
c0a70000 count: 1
d0908070 count: 1
dcae0fa0 count: 1
e30000e3 count: 1
f80004fc count: 2
ffff5815 count: 2
fffffed3 count: 2
fffffffd count: 2
ffffffff count: 18
100000000 count: 6
100000001 count: 4
100001f80 count: 1
100001fa0 count: 16
100001fa4 count: 2
100003033 count: 2
100010000 count: 1
...
7ff700000000 count: 1
7ff700000001 count: 2
7ff70000000d count: 1
7ff747390000 Photoshop_exe count: 1
7ff74ebd4ec0 Photoshop_exe+0x7844ec0 count: 1
7ff74ef351c7 Photoshop_exe+0x7ba51c7 count: 1
7ff74ef4e2f0 Photoshop_exe+0x7bbe2f0 count: 1
7ff74ef4e5a9 Photoshop_exe+0x7bbe5a9 count: 1
...
7fff00000000 count: 21
7fff00000001 count: 7
7fff00000002 count: 1
7fff00000003 count: 1
7fff00000004 count: 1
7fff00000011 count: 1
7fff00000020 count: 1
7fff00000040 count: 3
7fff00000102 count: 1
7fff0000029e count: 3
7fff00140000 count: 1
7fff02000002 count: 1
7fff4782c33b libcef!GetHandleVerifier+0x61d7b count: 1
7fff4782c884 libcef!GetHandleVerifier+0x622c4 count: 1
7fff493749cc libcef!cef_time_to_timet+0x1a9228 count: 2
...
7fff9a0c1e57 GdiPlus!GpGraphics::MeasureString+0x333 count: 1
7fff9a128c2a GdiPlus!FastTextImager::MeasureString+0x32 count: 1
7fff9a174e18 GdiPlus!GpFontFamily::vftable' count: 2
7fff9b6055b3 DWrite!FontFace::GetDesignGlyphAdvances+0x57 count: 1
7fffa7e6c260 comctl32!ListBox_WndProc count: 5
7fffa7e6c357 comctl32!ListBox_WndProc+0xf7 count: 2
7fffb1373c18 npmproxy!INotifyNetworkListManagerEventsProxyVtbl+0x1b8 count: 1
7fffb2c14e96 msvcp140!_Mbrtowc+0x66 [f:\dd\vctools\crt\crtw32\stdcpp\xmbtowc.c @ 156] count: 1
...
7fffc09f0359 ntdll!qsort+0x379 count: 1
7fffc09fa1e4 ntdll!woutput_s+0x8e8 count: 1
7fffc09fa297 ntdll!write_string+0x3f count: 1
7fffc09fbd30 ntdll!NtdllDefWindowProc_W count: 2
7fffc09fbf10 ntdll!NtdllDispatchHook_W count: 2
7fffc09ffc54 ntdll!KiUserCallForwarder+0x24 count: 1
7fffc09ffdb4 ntdll!KiUserCallbackDispatcherContinue count: 2
800000000000 count: 1
800000000001 count: 2
800063640000 count: 36
800066660000 count: 38
80006f6f0000 count: 2
800072720000 count: 8
800075750000 count: 1
974b00000000 count: 1
974b8118d10d count: 1
a76b00000000 count: 1
a76bb8365307 count: 1
a76bb8378c47 count: 1
a76bb8378f77 count: 1
a76bb837bfd7 count: 1
a8c300000000 count: 1
a8c311cf265f count: 1
...
30000000000000 count: 1
30000000310030 count: 1
30000300470048 count: 1
30002000100000 count: 1
3000300030007b count: 1
3000300031002d count: 1
30003000310031 count: 2
300031002d0037 count: 1
30003800390032 count: 3
31000000000000 count: 1
310000007d0036 count: 1
31002d00310037 count: 1
310032002d0035 count: 1
...
7fdf7fbd7f9c7f7b count: 2
8000800000000001 count: 1
8000800000001fa0 count: 1
8000800080000000 count: 6
8000800080008000 count: 52
80121a254b25250a count: 1
923800003f000000 count: 2
bf000000bf000000 count: 1
bff0000000000000 count: 2
e5b2a56118358cbe count: 2
ffff0072656c6c6f count: 1
fffffdb773438b57 count: 3
ffffff0000000005 count: 1
ffffff7bc010786f count: 1
ffffff7bc010787f count: 1
fffffffb00000000 count: 1
ffffffff00000000 count: 4
ffffffff00000001 count: 3
ffffffff00000005 count: 1
ffffffff00001fa0 count: 2
ffffffff4c494146 count: 2
ffffffffffffc3ce count: 1
fffffffffffffef6 count: 1
ffffffffffffff00 count: 2
ffffffffffffff01 count: 2
fffffffffffffffe count: 166
ffffffffffffffff count: 38

We can easily identify error values, module boundaries, and Regular Data. The sorting can also be done for double word or word values, for example to isolate errors or wide character values, but this will have to be seen whether it is useful.

This clustering approach can be depicted in the following idealized diagram:

The full output can be found here: stack-clusters.txt for stack.csv file.

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

Depending on tracing architecture we may have trace or log messages split into several statements. For example, some API and library tracing tools may log a function call after it returns with a result, but some tools or tracing libraries may log calls in the context of corresponding threads and, therefore, be preempted by other tracing and logging threads, and even interrupted. In the latter cases we may have Split Message like depicted in the following diagram:

Typical example here is Linux strace. We can recognize such messages by their Message Invariant and Ornament.

Split Message is different from Opposition Messages analysis pattern where we have messages logged from different source code tracing statements, when, for example, a function call result is logged separately. But, in the same vein, when we see an unfinished Split Message we may assume some sort of Discontinuity.

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

When we analyze a trace or log we may produce CoTrace of analyzed messages and visited regions. But the ultimate goal of any trace and log analysis is to construct the explanation of the observed behavoir to justify the root cause analysis and the proposed mechanism. There may be several proposed explanations each having a different set of messages from the analyzed trace that illustrate them. We call them Explanation Traces. This is illustrated in the picture where we use the same trace from CoTrace analysis pattern.

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

Trace Similarity analysis pattern uses various similarity measures to assess the closeness of one trace or log to another. Here we provide an illustrative example using Jaccard index. Consider three simple logs where sample sets consist from Activity Regions:

The following table shows calculation of similarity between A and B, A and C, and B and C:

It’s possible to use sample sets consisting of messages instead. For our toy example we get similar index numbers:

We get different indexes though for individual regions and messages, for example:

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

In addition to Declarative Trace we have code statements that may be intercepted by external API tracing tools (CreateFile, CloseHandle):

In the sample code above we have different logs resulted from Declarative Trace (DebugLog, OutputDebugString):

In addition, we have a log saved by an external tracing tool (for example, Process Monitor) that includes our API calls:

All such trace-generating source code statements form Moduli Trace as soon as they are executed:

Such a trace can also be analyzed using trace and log analysis patterns like other trace types. We took the idea of this analysis pattern from moduli spaces in mathematics that parametrize other spaces.

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

When we do trace and log analysis (and software data in general) we look at specific messages found from search (Message Patterns), Error Messages, Significant Events, visit Activity Regions, filter Message Sets, walk through (Adjoint) Threads of Activity, and do other actions necessitated by trace and log analysis patterns. All these can be done in random order (starting from some analysis point), not necessarily representing the flow of Time or some other metric:

Analyzed messages form their own analysis trace that we call CoTrace (CoLog, CoData) where the prefix Co- denotes a space dual to trace (log, data) space:

Instead of messages (or in addition to) we can also form CoTraces consisting of visited Activity Regions or some other areas:

We can apply trace analysis patterns to CoTraces as well. The latter can also be used in creation of higher-order pattern narratives.

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

Message Annotations analysis pattern was on our list for years so it’s time to add it to trace and log analysis pattern catalog. We also allow several annotations per trace message done at different times and annotating different parts depending on the analysis flow (the topic of the next analysis pattern). Attached to log messages annotations form their own Adjoint Thread of Activity. However, sorted by their annotation time or sequence we get a different trace that we call Annotation Trace (an example of analysis narrative). We can apply all relevant analysis patterns to both traces. A sketch of this pattern is depicted in the following diagram:

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

Cartesian Trace analysis pattern has its analogical roots in Cartesian product. It covers a case where we have a long trace and a few Small DA+TA configuration traces (files). The former trace messages are associated with the latter messages (content or content changes) as depicted in the following diagram:

Think about a rectangle as a product of two line fragments or a cylinder as a product of a circle and a line fragment. Both traces are completely independent in comparison to Fiber Bundle, Trace Presheaf, or Trace Extension.

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

Some trace and log messages may have different grammatical structure and content but similar semantics. Therefore, we can create a table listing equivalent messages (using some equivalence relation) and use it to construct simpler traces and logs as depicted in this picture:

One trivial example of Equivalent Messages analysis pattern is Quotient Trace. Another example is Inter-Correlational analysis of logs that have different structure and format. In such a case Equivalent Messages simplify the analysis of higher Trace Dimensions.

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

Log message “frequencies” in time domain (Statement Current part) are addressed by Fourier Activity analysis pattern. However, we may have varying message density (Statement Density part) across different trace runs (space domain, irrespective of time irregularities):

According to OED, in computing and mathematics a string means “a linear sequence of records or data” and “a sequence of symbols or linguistic elements in a definite order”. So we propose to name this pattern that analyzes densities of messages or Activity Regions as Trace String. Such longitudinal “vibrations” can be compared and analyzed for anomalies across different log runs (Inter-Correlation) or across similar regions in the same log (Intra-Correlation). Here we consider message density change as a one-dimensional displacement. The analogy for this pattern came from one-dimensional vibrating strings (dual resonance model from 1969-70 by Nambu, Nielsen, and Leonard Susskind).

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

The advent of virtualization simplified the debugging of complex issues by allowing to save the snapshot of the execution environment and then resume it from the save point of execution. This allows continuing tracing using a different set of environmental conditions and input data. New tracing continuations constitute a network that we call Polytrace:

Bifurcation Point for two identical trace beginnings may be considered as an example of a simple Polytrace.

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

Every trace and log has its own set of constants, values that belong to global namespace such as true/false, NULL, Abnormal Values, and common error constants such as “access denied”. Trace Constants may be dependent upon Implementation Discourse. There are also constant values that are local to each trace, for example, user names and IP addresses. They may be constantly repeated in one log but may change for another log. Constants that belong to local namespace may be a part of Vocabulary Index and Basic Facts. Usually Trace Constant is not considered Message Invariant.

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

If we run software with its default configuration and no interaction (input data) we get its Minimal Trace:

Such traces may have their own Master Trace. Also, Minimal Trace is a specific Use Case Trail. Metaphorically, they can be considered as minimal surfaces.

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

Sometimes we see a constantly repeated message throughout a trace or log (a trivial Periodic Message Block) with constant Time Delta. In certain trace forms (without explicit timing information) such messages may indicate internal time references as illustrated in the following diagram:

We name this pattern Drone Message based on analogy with Drone effect in music.

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

Based on a mathematical analogy with critical points in topology (Morse theory) we introduce Critical Points in trace and log analysis where they signify the change of trace or log “shape” (topological or “geometric” properties) as illustrated in the following diagram:

Such a point may be an individual message, its Message Context, or Activity Region.

Critical Points are examples of Intra-Correlation whereas Bifurcation Points are examples of Inter-Correlation.

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

Sometimes we put trace statements to track responses to certain environmental actions and conditions but surprised to see them in logs when nothing happened outside that could have triggered them:

We call such an analysis pattern Phantom Activity. This is an indicator that internal program state was not updated correctly. The difference between such activities and Defamiliarizing Effect is that the former messages are expected but not in their current Message Context.

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