Software Diagnostics Library

UI Message pattern is very useful for troubleshooting system-wide issues because we can map visual behaviour to various activity regions and consider such messages as significant events.

#    Module  PID  TID  Time         Message
[...]
2782 ModuleA 2124 5648 10:58:03.356 CreateWindow: Title "..." Class "..."
[...]
3512 ModuleA 2124 5648 10:58:08.154 Menu command: Save Data
[...]
3583 ModuleA 2124 5648 10:58:08.155 CreateWindow: Title "Save As" Class "Dialog"
[... Data update and replication related messages ...]
4483 ModuleA 2124 5648 10:58:12.342 DestroyWindow: Title "Save As" Class "Dialog"
[...]

By filtering the emitting module we can create an adjoint thread:

#    Module  PID  TID  Time         Message
[...]
2782 ModuleA 2124 5648 10:58:03.356 CreateWindow: Title "..." Class "..."
3512 ModuleA 2124 5648 10:58:08.154 Menu command: Save Data
3583 ModuleA 2124 5648 10:58:08.155 CreateWindow: Title "Save As" Class "Dialog"
4483 ModuleA 2124 5648 10:58:12.342 DestroyWindow: Title "Save As" Class "Dialog"
[...]

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

“… the vital point for you to understand is that all” tracing “must be conducted with the creation of” solution “in mind. That is what must colour and control your selection of” tracing “events.”

Michael Allen, The Truth About Writing

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

Memory Dump Analysis Services is working on the “Start It” button:

http://www.dumpanalysis.com/introducing-project-start

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

Presentation Software Trace and Memory Dump Analysis: Patterns, Tools, Processes and Best Practices from E2E Virtualization Conference (13th of May, 2011) is available for download:

http://www.dumpanalysis.com/STMDA-materials

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

Most of the time software trace messages coming from the same source code fragment (PLOT) contain invariant parts such as function and variable names, descriptions, and mutable parts such as pointer values and error codes. Message Invariant is a pattern useful for comparative analysis of several trace files where we are interested in message differences. For example, in one troubleshooting scenario certain objects were not created correctly for one user. We suspected a different object version was linked to a user profile. Separate application debug traces were recorded for each user and we could see version 0×4 for the problem user and 0×5 for all other normal users:

#    Module  PID  TID  Time         Message
[...]
2782 ModuleA 2124 5648 10:58:03.356 CreateObject: pObject 0×00A83D30 data ([…]) version 0×4
[…]

#    Module  PID  TID  Time         Message
[...]
4793 ModuleA 2376 8480 09:22:01.947 CreateObject: pObject 0×00BA4E20 data ([…]) version 0×5  
[…]

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

Here we continue with Technology-Specific Subtrace pattern series started earlier with COM interface invocation example. In this part we consider dynamic memory allocation example in kernel space (kernel pool). Usually pool corruption is detected during pool memory allocation or release with a special bugcheck code, for example:

BAD_POOL_HEADER (19)
The pool is already corrupt at the time of the current request.
This may or may not be due to the caller.
The internal pool links must be walked to figure out a possible cause of the problem, and then special pool applied to the suspect tags or the driver verifier to a suspect driver.
Arguments:
Arg1: 00000020, a pool block header size is corrupt.
Arg2: 8b79d078, The pool entry we were looking for within the page.
Arg3: 8b79d158, The next pool entry.
Arg4: 8a1c0004, (reserved)

However, pool corruption might be deeper enough to trigger an access violation even before self-diagnosis. In such cases stack subtraces with functions like ExFreePoolWithTag might point to troubleshooting and debugging directions:

ATTEMPTED_WRITE_TO_READONLY_MEMORY (be)
An attempt was made to write to readonly memory. The guilty driver is on the stack trace (and is typically the current instruction pointer).
When possible, the guilty driver’s name (Unicode string) is printed on the bugcheck screen and saved in KiBugCheckDriver.
Arguments:
Arg1: 00470044, Virtual address for the attempted write.
Arg2: 06d39025, PTE contents.
Arg3: aec0fb30, (reserved)
Arg4: 0000000a, (reserved)

TRAP_FRAME:  aec0fb30 -- (.trap 0xffffffffaec0fb30)
ErrCode = 00000003
eax=8ac12d38 ebx=8b700040 ecx=000001ff edx=00470040 esi=8ac12db8 edi=808b0b40
eip=808949e7 esp=aec0fba4 ebp=aec0fbf0 iopl=0 nv up ei pl nz na po nc
cs=0008  ss=0010  ds=0023  es=0023  fs=0030  gs=0000  efl=00010202
nt!ExFreePoolWithTag+0x6a3:
808949e7 895a04          mov     dword ptr [edx+4],ebx ds:0023:00470044=????????

STACK_TEXT:
aec0faa0 80860121 000000be 00470044 06d39025 nt!KeBugCheckEx+0x1b
aec0fb18 8088e490 00000001 00470044 00000000 nt!MmAccessFault+0xb25
aec0fb18 808949e7 00000001 00470044 00000000 nt!KiTrap0E+0xdc
aec0fbf0 808d93b5 8ac12dc0 00000000 00000000 nt!ExFreePoolWithTag+0×6a3
aec0fc08 808cd304 e5ae5770 8ac12dc0 8aa77db0 nt!CmpFreePostBlock+0×4d
aec0fc3c 8082ea53 8ac12dc0 aec0fc88 aec0fc7c nt!CmpPostApc+0xde
aec0fc8c 80833eec 00000000 00000000 00000000 nt!KiDeliverApc+0xf9
aec0fcc4 808290bd aec0fd64 8099781c 0160fd44 nt!KiSwapThread+0×300
aec0fd0c 809978a0 00000001 00000000 f77275e0 nt!KeDelayExecutionThread+0×2ab
aec0fd54 8088b45c 00000000 0160fd74 0160fd9c nt!NtDelayExecution+0×84
aec0fd54 7c82847c 00000000 0160fd74 0160fd9c nt!KiFastCallEntry+0xfc
WARNING: Frame IP not in any known module. Following frames may be wrong.
0160fd9c 00000000 00000000 00000000 00000000 0×7c82847c

1: kd> !pool 8ac12dc0
Pool page 8ac12dc0 region is Nonpaged pool
 8ac12000 size:  858 previous size:    0  (Allocated)  TWPG
 8ac12858 size:    8 previous size:  858  (Free)       ….
 8ac12860 size:   20 previous size:    8  (Allocated)  VadS
 8ac12880 size:    8 previous size:   20  (Free)       NtFs
 8ac12888 size:   20 previous size:    8  (Allocated)  VadS
 8ac128a8 size:   28 previous size:   20  (Allocated)  Ntfn
 8ac128d0 size:   30 previous size:   28  (Allocated)  Vad
 8ac12900 size:   40 previous size:   30  (Allocated)  Muta (Protected)
 8ac12940 size:   38 previous size:   40  (Allocated)  Sema (Protected)
 8ac12978 size:   40 previous size:   38  (Allocated)  Muta (Protected)
 8ac129b8 size:  270 previous size:   40  (Allocated)  Thre (Protected)
 8ac12c28 size:   40 previous size:  270  (Allocated)  Ntfr
 8ac12c68 size:   d0 previous size:   40  (Allocated)  DRIV
8ac12d38 is not a valid large pool allocation, checking large session pool…
8ac12d38 is freed (or corrupt) pool
Bad previous allocation size @8ac12d38, last size was 1a

***
*** An error (or corruption) in the pool was detected;
*** Attempting to diagnose the problem.
***
*** Use !poolval 8ac12000 for more details.
***

Pool page [ 8ac12000 ] is __inVALID.

Analyzing linked list...
[ 8ac12c68 --> 8ac12db8 (size = 0x150 bytes)]: Corrupt region
Scanning for single bit errors...

None found

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

I’m pleased to announce that MDAA, Volume 5 is available in PDF format:

www.dumpanalysis.org/Memory+Dump+Analysis+Anthology+Volume+5

It features:

- 25 new crash dump analysis patterns
- 11 new pattern interaction case studies (including software tracing)
- 16 new trace analysis patterns
- 7 structural memory patterns
- 4 modeling case studies for memory dump analysis patterns
- Discussion of 3 common analysis mistakes
- Malware analysis case study
- Computer independent architecture of crash analysis report service
- Expanded coverage of software narratology
- Metaphysical and theological implications of memory dump worldview
- More pictures of memory space and physicalist art
- Classification of memory visualization tools
- Memory visualization case studies
- Close reading of the stories of Sherlock Holmes: Dr. Watson’s observational patterns
- Fully cross-referenced with Volume 1, Volume 2, Volume 3, and Volume 4

Its table of contents is available here:

www.dumpanalysis.org/MDAA/MDA-Anthology-V5-TOC.pdf

Paperback and hardcover versions should be available in a week or two. I also started working on Volume 6 that should be available in November-December.

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

I’m to present pattern-driven software trace analysis with examples from application and desktop delivery environments featuring Memory Dump Analysis Services at the forthcoming E2E Virtualization Conference (PubForum) in Dublin on 13th of May, 2011. Topics include a case study covering simultaneous analysis of software traces and memory dumps.

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

Because the number of software trace patterns is growing I’m starting another checklist in addition to memory dump analysis checklist. The goal is to help experienced engineers not to miss any important information. The checklist doesn’t prescribe any specific steps, just lists all possible points to double check when looking at a software trace. Of course, it is not complete at the moment and any suggestions are welcome. This post will be modified on the ongoing basis.

General:

• Check overall trace time delta
• Check no trace metafile message density
• Check whether a trace is a multi-part or a circular
• Check for basic facts and the story (software narrative)
• Check for any exceptions, non-false positive errors and periodic errors
• Check for significant events
• Check for discontinuities in the time domain
• Check for message current and acceleration in the frequency domain

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

The first Webinar to start an in-depth discussion of pattern-driven software troubleshooting, debugging and maintenance:

Date: 25th of March 2011
Time: 18:30 (GMT) 14:30 (EST) 11:30 (PST)
Duration: 60 minutes

Space is limited.
Reserve your Webinar seat now at:
https://www3.gotomeeting.com/register/448268158

Topics include:

• A Short History of DumpAnalysis.org
• Memory Dump Analysis Patterns
• Troubleshooting and Debugging Tools (Debugware) Patterns
• Software Trace Analysis Patterns
• From Software Defects to Software Behavior
• Workaround Patterns
• Structural Memory Patterns
• Memory Analysis Domain Pattern Hierarchy
• New Directions

Prerequisites: experience in software troubleshooting and/or debugging.

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

Sometimes, we look at a trace and say it’s Impossible Trace. For example, this fragment shows that the function foo had been called:

#     Module  PID  TID  Message
[...]
1001  ModuleA 202  404  foo: start
1002  ModuleA 202  404  foo: end
[...]

However, if we look at the corresponding source code (PLOT) we would see that something is missing: the function bar must have been called with its own set of trace messages we don’t see in the trace:

void foo()
{
    TRACE("foo: start");
    bar();  
    TRACE("foo: end");
}

void bar()
{
    TRACE("bar: start");
    // some code ... 
    TRACE("bar: end");
}

We suspect the runtime code being modified, perhaps by patching. In other cases of missing messages we can also suspect thrown exceptions or local buffer overflows that led to wrong return address skipping the code with expected tracing statements. The mismatch between the trace and the source code we are looking at is also possible if the old source code didn’t have bar function called.

Note: I’m grateful for this pattern idea to Gary Barton.

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

This pattern has a funny name Gossip. I thought originally to call it Duplicated Message but gave it the new name allowing for the possibility of semantics of the same message to be distorted in subsequent trace messages from different adjoint threads. Typical ETW / CDF trace example (distortion free) of the same message content seen in different modules (some columns like Date and Time are omitted):

#     Module  PID  TID  Message[...]26875 ModuleA 
2172 5284 LoadImageEvent: ImageName(\Device\HarddiskVolume2\Windows\System32\notepad.exe) ProcessId(0x000000000000087C)26876 ModuleB 
2172 5284 LoadImageEvent: ImageName(\Device\HarddiskVolume2\Windows\System32\notepad.exe), ProcessId(2172)26877 ModuleC 
2172 5284 ImageLoad: fileName=notepad.exe, pid: 000000000000087C[...]

In such cases, when constructing event sequence order it is recommended to choose messages from the one source instead of mixing events from different sources, for example:

#     Module  PID  TID  Message[...]26875 ModuleA 
2172 5284 LoadImageEvent: ImageName(\Device\HarddiskVolume2\Windows\System32\notepad.exe) ProcessId(0×000000000000087C)[…]33132 ModuleA 
4180 2130 LoadImageEvent: ImageName(\Device\HarddiskVolume2\Windows\System32\calc.exe) ProcessId(0×0000000000001054)[…]

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

When reading and analyzing software traces we always compare them to Master Trace. Another name for this pattern borrowed from narrative theory is Archetype. When looking at the software trace from a system we either know the correct sequence of Activity Regions, expect certain Background and Foreground Components, Event Sequence Order or mentally construct a model based on our experience and Implementation Discourse. For the latter example software engineers internalize software master narratives when they construct code and write tracing code for supportability. For the former example it is important to have a repository of traces corresponding to master traces. This helps in finding deviations after Bifurcation Point. Consider such comparisons similar to regression testing when we check the computation output against the expected prerecorded sequence.

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

The Window of Opportunity - WYSIWYG. Requires scrolling or search to get most of it.

Examples: He opened a log file in notepad and was staring at it with disbelief. There was no error. After some time he closed the window of opportunity.

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

Software trace analysis is difficult and it is very common to hear “couldn’t see anything …”. One of advantages of software trace analysis patterns is that we can use that pattern language to write analysis reports. Here I provide an example for an analysis of a CDF trace from Citrix XenApp server. Instead of replying “didn’t find anything suspicious …” an engineer identified the following patterns:

• low Statement Current (sparse trace)
• Significant Event from Vocabulary Index
• Discontinuity for an Adjoint Thread
• Missing Component(s)
• Background Component
• Truncated Trace
• significant Time Delta

Seeing the list of patterns it was much easier to ask questions to aid in further troubleshooting.

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

Stack Trace is a general pattern and there can always be found fine-grained patterns in stack traces as well. Here we discuss the general category of such stack trace patterns called Technology-Specific Subtrace (TSST) and give examples related to COM technology.

Consider this trace:

1: kd> k250
ChildEBP RetAddr            
8d5d2808 82a7eb15 nt!KiSwapContext+0x26
8d5d2840 82a7d403 nt!KiSwapThread+0x266
8d5d2868 82a772cf nt!KiCommitThreadWait+0x1df
8d5d28e0 82550d75 nt!KeWaitForSingleObject+0x393
8d5d293c 82550e10 win32k!xxxRealSleepThread+0x1d7
8d5d2958 824ff4b0 win32k!xxxSleepThread+0x2d
8d5d29cc 825547e8 win32k!xxxInterSendMsgEx+0xb1c
8d5d2a1c 825546a4 win32k!xxxSendMessageTimeout+0x13b
8d5d2a44 82533843 win32k!xxxSendMessage+0×28
8d5d2b08 824fd865 win32k!xxxCalcValidRects+0xf7
8d5d2b64 82502c98 win32k!xxxEndDeferWindowPosEx+0×100
8d5d2b84 825170c9 win32k!xxxSetWindowPos+0xf6
8d5d2c08 82517701 win32k!xxxActivateThisWindow+0×2b1
8d5d2c38 82517537 win32k!xxxActivateWindow+0×144
8d5d2c4c 824fd9dd win32k!xxxSwpActivate+0×44
8d5d2ca4 82502c98 win32k!xxxEndDeferWindowPosEx+0×278
8d5d2cc4 824fff82 win32k!xxxSetWindowPos+0xf6
8d5d2d10 82a5342a win32k!NtUserSetWindowPos+0×140
8d5d2d10 76ee64f4 nt!KiFastCallEntry+0×12a (TrapFrame @ 8d5d2d34)
01e2cea0 7621358d ntdll!KiFastSystemCallRet
01e2cea4 6a8fa0eb USER32!NtUserSetWindowPos+0xc
01e2cf14 6a894b13 IEFRAME!SHToggleDialogExpando+0×15a
01e2cf28 6a894d5d IEFRAME!EleDlg::ToggleExpando+0×20
01e2d74c 6a895254 IEFRAME!EleDlg::OnInitDlg+0×229
01e2d7b8 762186ef IEFRAME!EleDlg::DlgProcEx+0×189
01e2d7e4 76209eb2 USER32!InternalCallWinProc+0×23
01e2d860 7620b98b USER32!UserCallDlgProcCheckWow+0xd6
01e2d8a8 7620bb7b USER32!DefDlgProcWorker+0xa8
01e2d8c4 762186ef USER32!DefDlgProcW+0×22
01e2d8f0 76218876 USER32!InternalCallWinProc+0×23
01e2d968 76217631 USER32!UserCallWinProcCheckWow+0×14b
01e2d9a8 76209b1d USER32!SendMessageWorker+0×4d0
01e2da64 76235500 USER32!InternalCreateDialog+0xb0d
01e2da94 76235553 USER32!InternalDialogBox+0xa7
01e2dab4 76235689 USER32!DialogBoxIndirectParamAorW+0×37
01e2dad8 6a5d4952 USER32!DialogBoxParamW+0×3f
01e2db00 6a5d5024 IEFRAME!Detour_DialogBoxParamW+0×47
01e2db24 6a8956df IEFRAME!SHFusionDialogBoxParam+0×32
01e2db58 6a8957bb IEFRAME!EleDlg::ShowDialog+0×398
01e2e638 6a8959d3 IEFRAME!ShowDialogBox+0xb6
01e2eb9c 6a9013ed IEFRAME!ShowElevationPrompt+0×1dd
01e2f010 7669fc8f IEFRAME!CIEUserBrokerObject::BrokerCoCreateInstance+0×202
01e2f040 76704c53 RPCRT4!Invoke+0×2a
01e2f448 76d9d936 RPCRT4!NdrStubCall2+0×2d6
01e2f490 76d9d9c6 ole32!CStdStubBuffer_Invoke+0xb6
01e2f4d8 76d9df1f ole32!SyncStubInvoke+0×3c
01e2f524 76cb213c ole32!StubInvoke+0xb9
01e2f600 76cb2031 ole32!CCtxComChnl::ContextInvoke+0xfa
01e2f61c 76d9a754 ole32!MTAInvoke+0×1a
01e2f64c 76d9dcbb ole32!AppInvoke+0xab
01e2f72c 76d9a773 ole32!ComInvokeWithLockAndIPID+0×372
01e2f778 7669f34a ole32!ThreadInvoke+0×302
01e2f7b4 7669f4da RPCRT4!DispatchToStubInCNoAvrf+0×4a
01e2f80c 7669f3c6 RPCRT4!RPC_INTERFACE::DispatchToStubWorker+0×16c
01e2f834 766a0cef RPCRT4!RPC_INTERFACE::DispatchToStub+0×8b
01e2f86c 7669f882 RPCRT4!RPC_INTERFACE::DispatchToStubWithObject+0xb2
01e2f8b8 7669f7a4 RPCRT4!LRPC_SCALL::DispatchRequest+0×23b
01e2f8d8 7669f763 RPCRT4!LRPC_SCALL::QueueOrDispatchCall+0xbd
01e2f8f4 7669f5ff RPCRT4!LRPC_SCALL::HandleRequest+0×34f
01e2f928 7669f573 RPCRT4!LRPC_SASSOCIATION::HandleRequest+0×144
01e2f960 7669ee4f RPCRT4!LRPC_ADDRESS::HandleRequest+0xbd
01e2f9dc 7669ece7 RPCRT4!LRPC_ADDRESS::ProcessIO+0×50a
01e2f9e8 766a1357 RPCRT4!LrpcServerIoHandler+0×16
01e2f9f8 76ecd3a3 RPCRT4!LrpcIoComplete+0×16
01e2fa20 76ed0748 ntdll!TppAlpcpExecuteCallback+0×1c5
01e2fb88 76e11174 ntdll!TppWorkerThread+0×5a4
01e2fb94 76efb3f5 kernel32!BaseThreadInitThunk+0xe
01e2fbd4 76efb3c8 ntdll!__RtlUserThreadStart+0×70
01e2fbec 00000000 ntdll!_RtlUserThreadStart+0×1b

In the middle of the stack trace we see COM interface invocation in IEFRAME module. The similar stack trace fragment can be found in the following stack trace where COM IRemUnknown interface implementation resides in .NET CLR mscorwks module:

0:000> kL
ChildEBP RetAddr 
0018a924 68b5f8f0 mscorwks!SafeReleaseHelper+0x77
0018a958 68b04a99 mscorwks!SafeRelease+0x2f
0018a98c 68b04860 mscorwks!IUnkEntry::Free+0x68
0018a9a0 68b049b5 mscorwks!RCW::ReleaseAllInterfaces+0x18
0018a9d0 68b049e1 mscorwks!RCW::ReleaseAllInterfacesCallBack+0xbd
0018aa00 68c0a108 mscorwks!RCW::Cleanup+0x22
0018aa0c 68c0a570 mscorwks!RCWCleanupList::ReleaseRCWListRaw+0x16
0018aa3c 68bd4b3d mscorwks!RCWCleanupList::ReleaseRCWListInCorrectCtx+0xdf
0018aa4c 75dd8c2e mscorwks!CtxEntry::EnterContextCallback+0×89
0018aa68 763c586c ole32!CRemoteUnknown::DoCallback+0×7a
0018aa84 764405f1 rpcrt4!Invoke+0×2a
0018ae88 75efd936 rpcrt4!NdrStubCall2+0×2ea
0018aed0 75efd9c6 ole32!CStdStubBuffer_Invoke+0xb6
0018af18 75efdf1f ole32!SyncStubInvoke+0×3c
0018af64 75e1223c ole32!StubInvoke+0xb9
0018b040 75e12131 ole32!CCtxComChnl::ContextInvoke+0xfa
0018b05c 75e130fa ole32!MTAInvoke+0×1a
0018b088 75efde47 ole32!STAInvoke+0×46
0018b0bc 75efdcbb ole32!AppInvoke+0xab
0018b19c 75efe34c ole32!ComInvokeWithLockAndIPID+0×372
0018b1c4 75e12ed2 ole32!ComInvoke+0xc5
0018b1d8 75e12e91 ole32!ThreadDispatch+0×23
0018b21c 75a06238 ole32!ThreadWndProc+0×161
0018b248 75a068ea user32!InternalCallWinProc+0×23
0018b2c0 75a07d31 user32!UserCallWinProcCheckWow+0×109
0018b320 75a07dfa user32!DispatchMessageWorker+0×3bc
0018b330 75ddd6be user32!DispatchMessageW+0xf
0018b360 75ddd66d ole32!CCliModalLoop::PeekRPCAndDDEMessage+0×4c
0018b390 75ddd57e ole32!CCliModalLoop::FindMessage+0×30
0018b3f0 75ddd633 ole32!CCliModalLoop::HandleWakeForMsg+0×41
0018b408 75dd1117 ole32!CCliModalLoop::BlockFn+0xc3
0018b488 68a6c905 ole32!CoWaitForMultipleHandles+0xcd
0018b4a8 68a6c866 mscorwks!NT5WaitRoutine+0×51
0018b514 68a6c7ca mscorwks!MsgWaitHelper+0xa5
0018b534 68b5fbe4 mscorwks!Thread::DoAppropriateAptStateWait+0×28
0018b5b8 68b5fc79 mscorwks!Thread::DoAppropriateWaitWorker+0×13c
0018b608 68b5fdf9 mscorwks!Thread::DoAppropriateWait+0×40
0018b664 68a1c5b6 mscorwks!CLREvent::WaitEx+0xf7
0018b678 68b1adb4 mscorwks!CLREvent::Wait+0×17
0018b6c8 68b1ab2a mscorwks!WKS::GCHeap::FinalizerThreadWait+0xfb
0018b764 08fa12c1 mscorwks!GCInterface::RunFinalizers+0×99
[…]

A TSST usually spans several modules. In any stack trace we can also find several TSST that may be overlapping. For example, in the first stack trace above we can discern fragments of COM, RPC, LPC, GUI Dialog, Window Management, and Window Messaging subtraces. In the second trace we can also see GC, Modal Loop, COM Wrapper, and Interface Management stack frames.

The closest software trace analysis pattern here is Implementation Discourse.

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

In these post series we are going to discuss the best practices for software tracing implementation including appropriate patterns and their links to software trace analysis patterns. The first one is called Period Timestamp where the start and the end time (and the date if necessary) are recorded in the trace file. This helps in Inter-Correlation and News Value analysis between several different trace types. For example, in one scenario, we had WindowHistory and MessageHistory logs. We identified a problem in the former log as happening at this time:

Handle: 00010196 Class: "ClassA" Title: "TitleA"
   Captured at: 13:36:30:533
[…]

However, when we looked at the latter trace to search for specific window messages posted or sent before that time we saw that the recording started later than the former event:

Start time: 13:36:35:830

Period timestamps are necessary to distinguish Incomplete History from Truncated Trace where in the former case the absence of expected trace message is due to some problem.

From a unified debugging patterns perspective we have this sequence fragment:

Implementation Patterns: Period Timestamp

Usage Patterns: Trace Simultaneously

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

News Value is a pattern that assigns relative importance to software traces for problem solving purposes especially when related to problem description, recent incidents and timestamps of other supporting artifacts (memory dumps, other traces, etc.). For example, in one scenario, an ETW trace was provided with 3 additional log files:

# Source PID  TID  Date       Time         Message 
0 Header 1260 1728 12/14/2010 06:48:56.289 ?????  
[…] 
215301 Unknown 640 808 12/14/2010 07:22:57.508 ?????  Unknown( 16): GUID=[…] (No Format Information found). 

// LogA
05/11/10 18:28:15.1562 : Service() - entry
[...]
14/12/10 10:31:58.0381 : Notification: sleep
* Start of new log *
14/12/10 10:34:38.4687 : Service() - entry
[…]
14/12/10 11:53:35.2729 : Service.CleanUp complete
* Start of new log *
14/12/10 11:56:11.7031 : Service() - entry
[…]
14/12/10 15:25:23.3004 : Notification: sleep

// LogB
[   1] 12/14 10:34:29:890   Entry: ctor
[…]
[   2] 12/14 11:53:30:866   Exit: COMServer.Server.DeleteObject

// LogC
[   1] 12/14 11:56:03:359   Entry: ctor
[…]
[  20] 12/14 15:30:20:110   Exit: Kernel32.Buffer.Release

From the description of the problem we expected LogB and LogC to be logs from two subsequent process executions where the first launch fails (LogB) and the second launch succeeds (LogC). Looking at their start and end times we see that they make sense from the problem description perspective but we have to dismiss ETW trace and most of LogA as recorded earlier and having no value for Inter-Correlation analysis of the more recent logs. We also see that portions of LogA overlap with LogB and LogC and therefore having analysis value for us.

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

If we look at any non-trivial trace we would see different Implementation Discourses. Components are written in different languages and adhere to different runtime environments, binary models and interface frameworks. All these implementation variations influence the structure, syntax and semantics of trace messages. For example, .NET debugging traces differ from file system driver or COM debugging messages. Therefore we establish the new field of Software Trace Linguistics as a science of software trace languages. Some parallels can be drawn here towards software linguistics (the science of software languages) although we came to that conclusion independently while thinking about applying “ethnography of speaking” to software trace narration. More on this in the following posts.

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

MAaaS includes 2 complementary DA+TA services:

1. Dump Analysis as a Service (DAaaS)
2. Trace Analysis as a Service (TAaaS)

Memory Dump Analysis Services is the first organization to provide such a service at an audit and certification levels.

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