T
The idea of Tensor Trace analysis pattern initially appeared in the context of memory dumps as general traces128 with several special traces inside but then developed further when working on Singleton Trace analysis pattern when we realized that several Singleton Traces might form a new separate log:
Therefore, we may combine several traces and logs into one global trace where each message references separate local traces and logs:
A typical example is repeated tracing. Each trace has an i-th index spanning the number of trace messages. We say it has Ti components. Each individual logging has a j-th index, and overall, the global log has Tj components. Together they form the second rank tensor129:
There can be Tensor Traces of the higher ranks, for example, the 3rd component can be spanning computers:
This analysis pattern is different from Meta Trace where the latter is about trace evolution during software development. It is also different from Trace Dimension, which is about one trace (Tensor Trace of rank 1).
When we have software traces that record process identifiers (PID) and thread identifiers (TID), it is important to differentiate between trace statements sorted by time and Thread of Activity. The latter is simply the flow of trace messages sorted by TID, and it is very helpful in cases with dense traces coming from hundreds of processes and components. Here is an example from MessageHistory130 bulk trace fragment showing different Threads of Activity in different font styles:
Start time: 21:5:36:651
Format time: 21:5:43:133
Number of messages sent: 24736
Number of messages posted: 905
[...]
21:5:41:990 S PID: a7c TID: 554 HWND: 0×0000000000010E62 Class: “ToolbarWindow32″ Title: “” WM_USER+4b (0×44b) wParam: 0×14 lParam: 0×749e300
21:5:41:990 S PID: a7c TID: 554 HWND: 0×00010E4A Class: “CtrlNotifySink” Title: “” WM_NOTIFY (0×4e) wParam: 0×0 lParam: 0×749efa8
21:5:41:990 S PID: a7c TID: 554 HWND: 0×00010E62 Class: “ToolbarWindow32″ Title: “” WM_USER+3f (0×43f) wParam: 0×14 lParam: 0×749e1e0
21:5:41:990 S PID: a7c TID: 554 HWND: 0×00010E62 Class: “ToolbarWindow32″ Title: “” WM_USER+4b (0×44b) wParam: 0×14 lParam: 0×749e300
21:5:41:990 S PID: a7c TID: 554 HWND: 0×00010E62 Class: “ToolbarWindow32″ Title: “” WM_USER+19 (0×419) wParam: 0×14 lParam: 0×0
21:5:41:990 S PID: a7c TID: 554 HWND: 0×00010E62 Class: “ToolbarWindow32″ Title: “” WM_USER+61 (0×461) wParam: 0×6 lParam: 0×0
21:5:41:990 S PID: a7c TID: 554 HWND: 0×00010E62 Class: “ToolbarWindow32″ Title: “” WM_USER+56 (0×456) wParam: 0×0 lParam: 0×0
21:5:41:990 S PID: a7c TID: 554 HWND: 0×00010E4A Class: “CtrlNotifySink” Title: “” WM_NOTIFY (0×4e) wParam: 0×0 lParam: 0×749f290
21:5:41:990 S PID: a7c TID: 554 HWND: 0×000E04A8 Class: “CtrlNotifySink” Title: “” WM_NCPAINT (0×85) wParam: 0xffffffffcc043bdb lParam: 0×0
21:5:41:990 P PID: a7c TID: 554 HWND: 0×000E04A8 Class: “CtrlNotifySink” Title: “” WM_PAINT (0xf) wParam: 0×0 lParam: 0×0
21:5:42:007 S PID: 1a8 TID: 660 HWND: 0×0001003C Class: “CiceroUIWndFrame” Title: “TF_FloatingLangBar_WndTitle” WM_WINDOWPOSCHANGING (0×46) wParam: 0×0 lParam: 0×29af030
21:5:42:007 P PID: a7c TID: 9b4 HWND: 0×00010084 Class: “CiceroUIWndFrame” Title: “TF_FloatingLangBar_WndTitle” WM_TIMER (0×113) wParam: 0×6 lParam: 0×0
21:5:42:007 P PID: 1a8 TID: 660 HWND: 0×0001003C Class: “CiceroUIWndFrame” Title: “TF_FloatingLangBar_WndTitle” WM_TIMER (0×113) wParam: 0×8 lParam: 0×0
21:5:42:007 P PID: a7c TID: 9b4 HWND: 0×00010084 Class: “CiceroUIWndFrame” Title: “TF_FloatingLangBar_WndTitle” WM_TIMER (0×113) wParam: 0×9 lParam: 0×0
21:5:42:022 P PID: a7c TID: a28 HWND: 0×0001061A Class: “WPDShServiceObject” Title: “WPDShServiceObject_WND” WM_TIMER (0×113) wParam: 0xd lParam: 0×0
21:5:42:022 P PID: a7c TID: 9b4 HWND: 0×00010084 Class: “CiceroUIWndFrame” Title: “TF_FloatingLangBar_WndTitle” WM_TIMER (0×113) wParam: 0×8 lParam: 0×0
21:5:42:022 P PID: a7c TID: 9b4 HWND: 0×00010084 Class: “CiceroUIWndFrame” Title: “TF_FloatingLangBar_WndTitle” WM_PAINT (0xf) wParam: 0×0 lParam: 0×0
21:5:42:036 P PID: 1a8 TID: 660 HWND: 0×0001003C Class: “CiceroUIWndFrame” Title: “TF_FloatingLangBar_WndTitle” WM_TIMER (0×113) wParam: 0×5 lParam: 0×0
21:5:42:054 S PID: a7c TID: 9b4 HWND: 0×0001006C Class: “ReBarWindow32″ Title: “” WM_USER+10 (0×410) wParam: 0×2 lParam: 0×0
21:5:42:054 S PID: a7c TID: 9b4 HWND: 0×0001006C Class: “ReBarWindow32″ Title: “” WM_USER+18 (0×418) wParam: 0×2 lParam: 0×1041a
21:5:42:054 S PID: a7c TID: 9b4 HWND: 0×0001006C Class: “ReBarWindow32″ Title: “” WM_USER+1a (0×41a) wParam: 0×0 lParam: 0×1041c
21:5:42:054 S PID: a7c TID: 9b4 HWND: 0×0001006C Class: “ReBarWindow32″ Title: “” WM_USER+19 (0×419) wParam: 0×0 lParam: 0×0
21:5:42:054 S PID: a7c TID: 9b4 HWND: 0×00010084 Class: “CiceroUIWndFrame” Title: “TF_FloatingLangBar_WndTitle” WM_WINDOWPOSCHANGING (0×46) wParam: 0×0 lParam: 0×2bef960
21:5:42:054 P PID: a7c TID: 9b4 HWND: 0×00010084 Class: “CiceroUIWndFrame” Title: “TF_FloatingLangBar_WndTitle” WM_TIMER (0×113) wParam: 0×10 lParam: 0×0
21:5:42:054 P PID: a7c TID: 9b4 HWND: 0×00010084 Class: “CiceroUIWndFrame” Title: “TF_FloatingLangBar_WndTitle” WM_TIMER (0×113) wParam: 0×5 lParam: 0×0
21:5:42:074 S PID: a7c TID: 554 HWND: 0×00010E32 Class: “DirectUIHWND” Title: “” WM_NCHITTEST (0×84) wParam: 0×0 lParam: 0×640406
21:5:42:074 S PID: a7c TID: 554 HWND: 0×00010E30 Class: “DUIViewWndClassName” Title: “” WM_NCHITTEST (0×84) wParam: 0×0 lParam: 0×640406
21:5:42:074 S PID: a7c TID: 554 HWND: 0×00010E32 Class: “DirectUIHWND” Title: “” WM_SETCURSOR (0×20) wParam: 0×10e32 lParam: 0×2000001
21:5:42:074 S PID: a7c TID: 554 HWND: 0×00010E30 Class: “DUIViewWndClassName” Title: “” WM_SETCURSOR (0×20) wParam: 0×10e32 lParam: 0×2000001
21:5:42:074 S PID: a7c TID: 554 HWND: 0×00010E20 Class: “ShellTabWindowClass” Title: “Release” WM_SETCURSOR
[...]
Usually, when we see an error indication, we select its current thread of activity and investigate what happened in this process and thread before. Here is a synthesized example from real CDF traces:
No PID TID Time Message
[...]
165797 4280 5696 07:07:23.709 FreeToken Handle 00000000
165798 4660 7948 07:07:23.709 EnumProcesses failed. Error=-2144534527
165799 7984 6216 07:07:23.749 GetData threw exception
165800 7984 6216 07:07:23.750 === Begin Exception Dump ===
[...]
We sort by TID 7948 to see what happened before the error and get additional information like the server name:
No PID TID Time Message
[...]
165223 4660 7948 07:07:23.704 GetServerName: Exit. ServerName = SERVER02
165224 4660 7948 07:07:23.704 GetServerProcesses: ServerName is SERVER02
165798 4660 7948 07:07:23.709 EnumProcesses failed. Error=-2144534527
[...]
Time Delta is a time interval between Significant Events or any messages of interest, in general. 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 FilesCompanyAappB.exe
[...]
24550 dllB 1604 9588 10:06:32.362 fileB.c PostMsg Event Q
[...]
28230 10:07:05.170 (End)
Such Time 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. Message #24550 was the last message from the process ID 1604, and after that, we did not “hear” from that PID for more than 30 seconds until the tracing was stopped.
The following diagram illustrates this pattern for a selected thread ID:
A software trace or log can be analyzed using different Time Scales. The coarser the scale, the more messages are included in time intervals. Such per interval Message Sets can be analyzed and transformed into one message using analysis patterns such as Significant Event, Motivic Trace, Background and Foreground Components, and Renormalization. The resulted new trace is a scaled version of the original trace as depicted in the following diagram:
Some Discontinuities may be Periodic as Silent Messages. If such Discontinuities belong to the same Thread of Activity and their Time Deltas are constant, we may see Timeout pattern. When Timeouts are followed by Error Message, we can identify them by Back Tracing. Timeouts are different from Blackouts where the latter are usually Singleton Events and have large Time Deltas.
Here is a generalized graphical case study. An error message was identified based on incident Basic Facts:
We filtered the trace for the error message TID and found three Timeouts 30 minutes each:
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, Statement Current is visibly increasing or decreasing, hence the name of this pattern by analogy with physical acceleration, a 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.
We would like to introduce Trace Dimension pattern to address the emerging complexity of logs from distributed environments. By a distributed environment we mean not only a collection of multiple computers (for example, client-server) but also terminal services environments with several different user sessions on one computer (OS) and even multiple user processes (IPC) in some cases. If some task can be performed on one machine or session or inside one process then splitting it across several computers, sessions, or processes usually results in logs with added Distributed Infrastructure Messages (DIM) such as from proxies and channels:
So, one of the trace simplification strategies is to request the reproduction and its tracing in a simplified environment (such as inside one terminal services session) to eliminate DIMs. In one case, we analyzed a trace for a clipboard paste problem in Windows terminal services environment. After a clipboard copy, different data was pasted into different applications. The same behavior was observed for application processes running inside different sessions and processes running within one session. However, the log was collected for the more complex multiple session scenario with many False Positive Errors, which completely disappeared from one session scenario log.
DIM abbreviation played a role in naming this pattern. Additionally, if sessions can be considered a second dimension, then separate VMs can be considered as a third dimension, separate clouds as a 4th dimension.
Trace Extension is an obvious log analysis pattern that is about trace messages that refer to some other trace or log that may or may not exist. Sometimes, there can be instructions to enable additional tracing that is not possible to cover by the current trace source. We have seen this in some trace statements from .NET Exception Stack Traces.
We can associate a function with a domain of trace messages (M) to some other range, either continuous (T) or discreet (D). We call this analysis pattern Trace Field by analogy with fields131 in physics:
Alternatively, in general, Trace Field is a functor132 between the domain of the category of trace messages (M) and a codomain of some other category, not necessarily numerical. Typical examples include Trace Presheaves and Fiber Bundles. Another example, for generalized logs, is Memory Fibration133 taken to the extreme.
The narrative theory distinguishes between frame types such as (Fludernik, McHale, Nelles, Wolf):
- Introductory framing (missing end frame) [—————————-
- Terminal framing (missing opening frame) —————————-]
- [—————————-]
- Interpolated framing [—-[ ]—-[ ]——–]
At the level of the software trace or Adjoint Thread as a whole, the first three types correspond to various types of the pattern Trace Partition where certain parts are missing such as Head, Prologue, Core, Epilogue, or Tail. The first two types can also be instances of Truncated Trace pattern. Interpolated framing can be an instance of multiple Discontinuities. All 4 types also correspond to Foreground Component messages, and in general, we have multiple Trace Frames as depicted:
We have analysis patterns that compare changes in software traces and logs during different executions (Master Trace) and during the evolution of software itself (Meta Trace). Such patterns are general enough, and often we are interested in their restriction to different execution paths or changes in code that leave start and end software states invariant:
We call such analysis pattern Trace Homotopy by analogy with homotopy134 in mathematics where a curve or sequence of operations can vary with constant endpoints.
Trace Mask is a superposition of two (or many) different traces. This is different from Inter-Correlation pattern, where we may only search for certain messages without the synthesis of a new log. The most useful Trace Mask is when we have different time scales (or significantly different Statement Currents). Then we impose an additional structure on one of the traces:
We got the idea from Narrative Masks discussed in Miroslav Drozda’s book “Narativní masky ruské prózy” (”Narrative Masks in Russian Prose”).
The very simple example of Trace Mask is shown in Debugging TV135 Episode 0x15.
Here we introduce a software narratological partitioning of a trace into Head, Prologue, Core, Epilogue and Tail segments. It is useful for comparative software trace analysis. Suppose, a trace started just before the reproduction steps, or a start marker was injected (by CDFMarker136, 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 prolog and epilog statements. What is before and after are not necessary for analysis and usually distract an analyst. They are shown as gray areas on the following picture where the left trace is for a working (non-working) scenario, and the right trace is for a 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. 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.
Adjoint Space and Memory Fibration137 analysis patterns may be useful in cases where complementing traces with memory dumps (and vice versa) provides better insight into software behavior. Ideally, every trace statement should have Adjoint Space, but this is not feasible practically. The solution is to save memory regions surrounding trace message data, for example, structures referenced by pointers. This can be done either for each message or selected Message Sets. Such memory data can be embedded inside logs as State Dump, Trace Extension or Inter-Correlation with a binary log of such memory fragments. This looks like mapping between trace messages and memory objects. We call this analysis pattern Trace Presheaf by analogy with presheaves138 in mathematics. In case Adjoint Spaces are available (for example, memory dumps) such memory buffers can be written to memory by a debugger (in Windows by .readmem WinDbg command) and examined in association with the rest of Adjoint Space. This is illustrated in the following diagram:
When we have very large traces (including Split Traces, page 226), we can use the concept of sharding139 to split a log into several shards for parallel processing. However, some patterns may require the analysis across the boundary of shards. Trace Sharding is illustrated in the following diagram:
Trace Similarity analysis pattern uses various similarity measures140 to assess the closeness of one trace or log to another. Here we provide an illustrative example using the Jaccard index141. Consider three simple logs where sample sets consist of Activity Regions:
The following table shows the 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:
Message based: J(A,B) = 0.463 J(A,C) = 0.258 J(B,C) = 0.482
Activity Region based: J(A,B) = 0.587 J(A,C) = 0.232 J(B,C) = 0.592
We get different indexes though for individual regions and messages, for example:
Error message (red) based: J(A,B) = 0 J(A,C) = 0 J(B,C) = 0.333
Error activity (red) based: J(A,B) = 0 J(A,C) = 0 J(B,C) = 1
Log message “frequencies” in the 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 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 model142 from 1969-70 by Nambu, Nielsen, and Leonard Susskind).
Reading Boris Uspensky143’s book “A Poetics of Composition: The Structure of the Artistic Text and Typology of a Compositional Form” (in its original Russian version) led me to borrow the concept of viewpoints. The resulting analysis pattern is called Trace Viewpoints. These viewpoints are, “subjective” (semantically laden from the perspective of a trace and log reader), and can be (not limited to):
- Error viewpoints (see also False Positive Error, Periodic Error, and Error Distribution)
- Use case (functional) viewpoints (see also Use Case Trail)
- Architectural (design) viewpoints (see also Milestones)
- Implementation viewpoints (see also Implementation Discourse, Macrofunctions, and Focus of Tracing)
- Non-functional viewpoints (see also Counter Value, and Diegetic Messages)
- Signal/noise viewpoints (see also Background and Foreground Components)
In comparison, Activity Regions, Data Flow, Thread of Activity, and Adjoint Thread of Activity are “objective” (structural, syntactical) viewpoints.
If Implementation Discourse focuses on objective technology-specific discourse, then this pattern focuses on subjective elements in a software log and its messages. Here we mean some specific naming or logging conventions either from an individual engineer habit or some corporate coding standard. As an example of it, consider a trace message from a catch statement:
"Surprise, surprise, should have never been caught."
Sometimes we have messages that report about the error but do not give exact details. For example, “Communication error. The problem on the server.” or “Access denied error.” This may be the case of Translated Messages. Such messages are plain language descriptions or interpretations of flags, error, and status codes contained in another log message. These descriptions may be coming from system API, for example, FormatMessage from Windows API, or maybe from the custom formatting code. Since the code translating the message is close to the original message both messages usually follow each other with zero or very small Time Delta, come from the same component, file, function, and belong to the same Thread of Activity:
This pattern is different from Gossip because the latter messages come from different modules, and, although they reflect some underlying event, they are independent of each.
The data in individual messages and State Dump message blocks may be truncated. This is similar to Visibility Limit at the log message level. When data values are sorted and resorted, this may result in “hidden” data replacing the previously “visible” data and vice versa, as shown in the following diagram:
Sometimes a software trace is truncated when the trace session was stopped prematurely, often when a problem did not manifest itself visually. We can diagnose such traces by their short time duration, missing Anchor Messages or Missing Components necessary for analysis. My favorite example is user session initialization in a terminal services environment when problem effects are visible only after the session is fully initialized and an application is launched, but a truncated 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 sequence144. The trace itself lasts only a few seconds after that.
