F
We borrowed the next trace and log analysis pattern name from factor groups in mathematics (or quotient groups57). Here a group is, of course, not a mathematical group58, but just a group (or set) of log messages or trace statements. However, every trace message has variable and invariant parts (Message Invariant). Variable parts usually contain some values, addresses, or status bits. They can even be string values. Such values from a set too and can be partitioned into disjoint (non-overlapping) subsets. For example, a window foreground status can be either true or false. Also, we can group messages into disjoint factor groups each one having either only true or only false foreground status. The following trace graph illustrates a WindowHistory6459 log where it was reported that one window was periodically losing and gaining focus:
We found messages related to the reported process window title. We found another such group of messages for a different process window by using Density Distribution pattern. Then a factor group was formed with two subgroups, and their Relative Density was compared. For correlated alternating values, it was expected to be 1. It was a very simple case, of course, which was analyzed just by looking at a textual log, but in more complex cases, computer assistance is required. A member of a factor group can also be generalized as a message subset with messages having variable part values from some domain subset or even calculated from it (a predicate): Mi = { m | P(m) }, where the original group of messages is a disjoint union of such message subsets: M = U Mi.
We often see such errors in software traces recorded during deviant software behavior (often called non-working software traces). When we double check their presence in normally expected software behavior traces (often called working traces), we find them there too. We already mentioned similar false positives when we introduced the first software trace analysis pattern called Periodic Error. Here is an example that was taken from the real trace. In a non-working trace, we found the following error in Adjoint Thread of Foreground Component:
OpenProcess error 5
However, we found the same error in the working trace, continued looking, and found several other errors:
Message request report: last error 1168, ...
[...]
GetMsg result -2146435043
The last one is 8010001D if converted to a hex status, but, unfortunately, the same errors were present in the working trace too in the same Activity Regions.
After that, we started comparing both traces looking for Bifurcation Point, and we found the error that was only present in a non-working trace with significant trace differences after that:
Error reading from the named pipe: 800700E9
My favorite tool (WinDbg) to convert error and status values gave this description:
0:000> !error 800700E9
Error code: (HRESULT) 0x800700e9 (2147942633) - No process is on the other end of the pipe.
The modern software trace recording, visualization, and analysis tools such as Process Monitor, Xperf, WPR, and WPA provide stack traces associated with trace messages. Consider stack traces as software traces we have, in a more general case, traces (fibers) bundled together on (attached to) a base software trace. For example, a trace message, that mentions an IRP can have its I/O stack attached, together with its thread stack trace with function calls leading to a function that emitted the trace message. Another example is an association of different types of traces with trace messages such as managed and unmanaged ones. This general trace analysis pattern needed a name, so we opted for Fiber Bundle as an analogy with a fiber bundle60 from mathematics. Here’s a graphical representation of stack traces recorded for each trace message where one message also has an associated I/O stack trace:
When using complex trace and log analysis patterns such as Fourier Activity we may be first interested in selecting all instances of a particular message type from specific Thread of Activity and then look for Time Deltas, Discontinuities, Data Flow, and other patterns. We call this analysis pattern Fiber of Activity by the analogy of fibers61 (lightweight threads) since the individual thread execution flow is “co-operative” inside, whereas threads themselves are preempted outside. The following diagram from Fourier Activity analysis pattern example illustrates the concept by showing three fibers:
This analysis pattern is different from trace-wide Sheaf of Activities where the latter is about selecting messages as Adjoint Threads of Activity, which may span several processes and threads.
Trace and log analysis starts with the assessment of artifact File Size, especially with multiple logging scenarios in distributed systems. If all log files are of the same size, we might have either Circular Traces or Truncated Traces. Both point to wrong trace timing plan62 or just using the default tracing tool configuration.
Activity Region pattern highlights “mechanical” and syntactical aspects of trace analysis whereas this pattern brings attention to changing the semantics of trace message flow, for example, in a terminal services environment, from login messages during session initialization to database search. Here is a graphical illustration of the pattern where the tracing focus region spans three regions of activity:
Sometimes we have trace and log messages that appear with certain time-frequency throughout all log or specific Thread of Activity. Such frequencies may fluctuate, reflecting varying system or process performance. Analyzing trace areas where such messages have different Time Deltas may point to additional diagnostic log messages useful for root cause analysis. The following minimal trace graph depicts the recent log analysis for proprietary file copy operation where the frequency of internal communication channel entry/exit Opposition Messages was decreasing from time to time. Such periods were correlating with increased time intervals between “entry” and “exit” messages. Analysis of messages between them revealed additional diagnostic statements missing in periods of higher frequency and corresponding Timeouts adding up to overall performance degradation and slowness of copy operation.
Additional analysis of Data Association in a different message type between available communication buffers and the total number of such buffers revealed significant frequency drop during constant Data Flow of zero available communication buffers:
We call this analysis pattern Fourier Activity by analogy with Fourier series63 in mathematics. This pattern is for individual message types and can also be considered a fine-grained example of Statement Current and Trace Acceleration analysis patterns which can be used to detect areas of different frequencies in individual Fibers (Adjoint Threads of Activities, formed from the same Thread of Activity).