D
Sometimes we are interested in changes in particular {property, value} pairs or tuples {x1, x2, x3, ...) in general where xi can be a number or a substring. It is a more general pattern than Message Change because such tuples can be from different sources and belong to different messages:
This pattern is also different from Data Flow, where a value stays constant across different sources and messages. It is also different from Gossip pattern that involves more semantic changes. Metaphorically we can think of this pattern as a partial derivative36.
If trace messages contain some character or formatted data that is passed from module to module or between threads and processes it is possible to trace that data and form Data Flow thread similar to Adjoint Thread we have when we filter by a specific message. However, in the former case, we have different message types.
When we have very large traces and Basic Facts containing some data values such as a user name, device name, or registry key value we may use Data Interval analysis pattern to select the trace fragment for the initial log analysis. The first and the last trace messages containing selected data for the closed Data Interval. Depending on the trace size and other considerations, we can also choose open Data Intervals. It is illustrated in the following diagram where we use Analysis interval notation borrowed mathematics37:
Interval boundary messages may also be used as Trace Mask for another trace.
Sometimes we notice that data values are in a different order than expected. We call this pattern Data Reversal. By data values, we mean some variable parts of a specific repeated message such as the address of some structure or object. Data Reversal may happen for one message type:
However, it can also happen for some message types and not for others. A typical example here is Enter/Leave trace messages for nested synchronization objects such as monitors and critical sections:
Since we talk about the same message type (the same Message Invariant), this pattern is different from Event Sequence Order pattern.
In rare cases, we may observe Data Reversal inside one message with several variable parts, but this may also be a case of Data Association.
Data Selector is a variant of Inter-Correlation trace analysis pattern where we use data found in one trace to select Message Set or Adjoint Thread of Activity in another trace. This analysis activity is depicted in the following picture where we have a client log and corresponding server log. In the server log, we have entries for many client sessions. To select messages corresponding to our client session we use some data attribute in the client trace, for example, the username, and Linked Messages analysis pattern to find one of the messages in the server log that contains the same username. Then we find out which user session it belongs to and form its Adjoint Thread:
This pattern is different from Identification Messages, where we don’t even know the object that emitted trace messages. In Data Selector case we know in principle what kind of messages we are looking for. We just need to select among many alternatives.
Recently we found a correlation between software trace with high Statement Density and Current of Periodic Error with uniform Error Distribution and process heap Memory Leak38 suspected from memory dump analysis. If we metaphorically view periodic errors as “frequency” and the size of a heap as “mass,” we may see that the growth of “frequency” correlates with the growth of “mass” and vice versa. Since frequency is inversely proportional to wavelength, we see a metaphorical analog to Louis de Broglie’s wave-particle duality39. In general, as we already pointed in the discussion of narrativity and spatiality of software execution artifacts40 (see also Software Trace and Memory Dump Analysis41 seminar), software traces / logs and memory dumps can be seen as “dual” to each other according (metaphorically again) to de Broglie’s “duality of the laws of nature”. So we name this analysis pattern De Broglie Trace Duality since some memory dump regions can be considered of a general trace42 nature. Our correlation can be depicted in this diagram:
Practically, when we see Memory Consumption Patterns43 (but don’t know their source/root cause yet), we can ask for traces and logs, and in the case of frequent Periodic Errors found there we can suggest troubleshooting steps that may serve as a resolution or workaround.
The trace statements in source code can be considered as Declarative Trace by analogy with variable declaration and definition in programming languages such as C and C++. Declaration of the variable doesn’t mean that the variable is used. Some declared variables such as arrays expand in memory when used (as in .bss sections). The same is with trace messages from Declarative Trace. Some of them don’t appear in the actual software execution trace, and some are repeated because of loops and multiple code reentrance. However, Declarative Traces are useful for studying the possibilities of tracing and logging design, implementation, and coverage (for example, Sparse Trace). Some trace analysis patterns are also applicable for Declarative Traces such as Message Sets and Bifurcation Points among different source code versions. This is illustrated in the following picture:
“Capturing delicate moments, one gives birth to a poetry of traces ...”
Ange Leccia, Motionless Journeys, by Fabien Danesi
In this pattern from software narratology,44 we see sudden unfamiliar trace statements across the familiar landscape of Characteristic Blocks and Activity Regions.
An example of a familiar trace:
An example of the new trace from a problem system:
Here we introduce Delay Dynamics analysis pattern. It is not an oxymoron and dynamics is referred to by what happens during the delay (Discontinuity with Time Delta) in other Threads of Activity as depicted in the following diagram:
Instead of threads, various Adjoint Threads of Activity may also be inspected.
Sometimes we find a grouping of some messages in one trace and then we are interested in the same groupings either in the same trace (Intra-Correlation) or in another trace (Inter-Correlation). We may consider such grouping as having some local density compared to the global Statement Density pattern. Then we might be interested in that selected message grouping density distribution as illustrated on this minimal trace graph:
Dialogue is an important pattern, especially in the network trace analysis. It usually involves a message source, a different message target (although both can be the same) and some alternation between them as shown in this abstract trace diagram:
Message and source are not only IP addresses or port numbers but also window handles, for example. Sometimes, the roles of source and target play different Process ID and Thread ID combinations (Client ID, CID). In such cases some parts of a message text may signify reply and response as shown graphically:
The similar illustration can be done for multi-computer trace, for example, when several traces from different servers are combined into one, where a combination of CID and a computer ID (Co) or just Co can play the roles of source and target.
Note that on all illustrations above the 3rd request does not have a reply message: a possible Incomplete History pattern.
Like in literature (and in narratology, in general), we have components that trace themselves, and components that tell the story of computation including status updates they query from other components and subsystems. This pattern gets its name from diegesis45. Here’s the difference between diegetic (in blue) and non-diegetic trace messages:
PID TID TIME MESSAGE
11864 11912 06:34:53.598 ModuleA: foo called bar. Status OK.
11620 10372 06:34:59.754 ModuleB: ModuleA integrity check. Status OK.
Some modules may emit messages that tell about their status, but from their message text, we know the larger computation story like in a process startup sequence example46.
The following diagram illustrates this analysis pattern:
Sometimes there are reported delays in application startup, session initialization, long response times, and simply the absence of response. All these problems can be reflected in software traces showing sudden gaps in Threads of Activity. This pattern is called Discontinuity per analogy with continuous and discontinuous functions in mathematics. Here is an example. One process had a long period of CPU spiking calculation, and we recorded a trace. When we open it, we see this Periodic Error:
N PID TID Time Message
[...]
326 2592 5476 08:17:18.823 OpenRegistry: Attempting to open [.. Hive path ..]
327 2592 5476 08:17:18.824 OpenRegistry: Failed: 2
[...]
However, when looking for any Discontinuities for the thread 5476 we see the gap of more than 7 minutes:
N PID TID Time Message
[...]
3395 2592 5476 08:17:19.608 OpenRegistry: Attempting to open [.. Hive path ..]
3396 2592 5476 08:17:19.608 OpenRegistry: Failed: 2
3461 2592 5476 08:24:31.137 OpenRegistry: Attempting to open [.. Hive path ..]
3462 2592 5476 08:24:31.137 OpenRegistry: Failed: 2
[...]
For this reason, we have three possibilities here:
- The process twice did lengthy CPU spiking calculations involving registry access and was quiet between them.
- Registry access belonged to some background activity and ceased for 7 minutes, and during that time the process had CPU spiking intensive calculation.
- This discontinuity is irrelevant because either the calculation module was not selected for tracing or it simply doesn’t have relevant tracing statement coverage for the code that does the calculation.
The full case study is covered in the September 2009 issue of Debugged! MZ/PE magazine47.
The following diagram illustrates Discontinuity analysis pattern:
Sometimes we have insufficiently detailed problem description, or there are several similar parallel user activities going on simultaneously, for example, several sessions are launched in a terminal services environment. In such cases, when tracing is done for the duration of specific user activity, this pattern may help. Here we select a full sequence of events or event sequence based on some Basic Facts. For example, if a session ID was missing in the problem description, we can choose the longest and fullest process launch sequence48 and assume that its session ID was the one missing:
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 an analogy with Drone effect49 in music.