Archive for the ‘Trace Analysis Patterns’ Category

Trace Analysis Patterns (Part 183)

Thursday, July 9th, 2020

Defect Group analysis pattern addresses messages related to source code defects (PLOTs), problem descriptions, and Inter-Correlation with wrong configuration files (Small DA+TA). It differs from Message Set analysis pattern as a predicate to group them may not be easily available.

Such Defect Groups can be results of previous analyses activities. The name of the analysis pattern came from representation theory defect group of a block but at present, it is only name analogy.

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

Crash Dump Analysis Patterns (Part 267)

Saturday, June 13th, 2020

When developers look at crash dumps they are more interested at parameters and local variables in particular stack frames of interest. However, sometimes it is useful to look at all such frames especially to gather information that may be useful for technical support or to correlate to additional traces and logs (for example, Historical Information to establish additional Basic Facts and build Vocabulary Index).

Listing the parameters can be done, for example, by using Stack Trace command variant (kP WinDbg commend, but we use kPL to exclude source code references to reduce visual clutter):

0:000> kPL
# Child-SP          RetAddr           Call Site
00 000000e4`c0afe488 00007ffe`cc888037 ntdll!NtWaitForMultipleObjects+0x14
01 000000e4`c0afe490 00007ffe`cc887f1e KERNELBASE!WaitForMultipleObjectsEx+0x107
02 000000e4`c0afe790 00007ffe`cd8271fb KERNELBASE!WaitForMultipleObjects+0xe
03 000000e4`c0afe7d0 00007ffe`cd826ca8 kernel32!WerpReportFaultInternal+0x51b
04 000000e4`c0afe8f0 00007ffe`cc9300b8 kernel32!WerpReportFault+0xac
05 000000e4`c0afe930 00007ffe`cf6c4ab2 KERNELBASE!UnhandledExceptionFilter+0x3b8
06 000000e4`c0afea50 00007ffe`cf6ac656 ntdll!RtlUserThreadStart$filt$0+0xa2
07 000000e4`c0afea90 00007ffe`cf6c11cf ntdll!_C_specific_handler+0x96
08 000000e4`c0afeb00 00007ffe`cf68a209 ntdll!RtlpExecuteHandlerForException+0xf
09 000000e4`c0afeb30 00007ffe`cf6bfe3e ntdll!RtlDispatchException+0x219
0a 000000e4`c0aff240 00007ffe`cc8f0aa2 ntdll!KiUserExceptionDispatch+0x2e
0b 000000e4`c0aff948 00007ff6`c8ab1568 KERNELBASE!wil::details::DebugBreak+0x2
0c 000000e4`c0aff950 00007ff6`c8ab1560 FrameTrace!foo(
unsigned int64 num = 0,
class std::basic_string<wchar_t,std::char_traits<wchar_t>,std::allocator<wchar_t> > * str = 0×000000e4`c0aff9d0 “Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! “)+0×68
0d 000000e4`c0aff9b0 00007ff6`c8ab1560 FrameTrace!foo(
unsigned int64 num = 0,
class std::basic_string<wchar_t,std::char_traits<wchar_t>,std::allocator<wchar_t> > * str = 0×000000e4`c0affa30 “Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! “)+0×60
0e 000000e4`c0affa10 00007ff6`c8ab1560 FrameTrace!foo(
unsigned int64 num = 1,
class std::basic_string<wchar_t,std::char_traits<wchar_t>,std::allocator<wchar_t> > * str = 0×000000e4`c0affa90 “Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! “)+0×60
0f 000000e4`c0affa70 00007ff6`c8ab1560 FrameTrace!foo(
unsigned int64 num = 2,
class std::basic_string<wchar_t,std::char_traits<wchar_t>,std::allocator<wchar_t> > * str = 0×000000e4`c0affaf0 “Hello World! Hello World! Hello World! Hello World! “)+0×60
10 000000e4`c0affad0 00007ff6`c8ab1560 FrameTrace!foo(
unsigned int64 num = 3,
class std::basic_string<wchar_t,std::char_traits<wchar_t>,std::allocator<wchar_t> > * str = 0×000000e4`c0affb50 “Hello World! Hello World! “)+0×60
11 000000e4`c0affb30 00007ff6`c8ab15b5 FrameTrace!foo(
unsigned int64 num = 4,
class std::basic_string<wchar_t,std::char_traits<wchar_t>,std::allocator<wchar_t> > * str = 0×000000e4`c0affbb0 “Hello World! “)+0×60
12 000000e4`c0affb90 00007ff6`c8ab2b14 FrameTrace!main(void)+0×25
13 (Inline Function) ——–`——– FrameTrace!invoke_main+0×22
14 000000e4`c0affbe0 00007ffe`cd7d7bd4 FrameTrace!__scrt_common_main_seh(void)+0×10c
15 000000e4`c0affc20 00007ffe`cf68ce51 kernel32!BaseThreadInitThunk+0×14
16 000000e4`c0affc50 00000000`00000000 ntdll!RtlUserThreadStart+0×21

The stack trace comes from the following modeling application:

void foo(std::size_t num, const std::wstring& str)
{
if (std::wstring concatStr{ str }; num)
{
concatStr += str;

foo(–num, concatStr);
}
else
{
::DebugBreak();
}
}

int main()
{
foo(5, L”Hello World! “);
}

To list local variable we need to use !for_each_frame WinDbg command:

0:000> !for_each_frame "dv"
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
00 000000e4`c0afe488 00007ffe`cc888037 ntdll!NtWaitForMultipleObjects+0x14
Unable to enumerate locals, Win32 error 0n87
Private symbols (symbols.pri) are required for locals.
Type ".hh dbgerr005" for details.
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
01 000000e4`c0afe490 00007ffe`cc887f1e KERNELBASE!WaitForMultipleObjectsEx+0x107
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
02 000000e4`c0afe790 00007ffe`cd8271fb KERNELBASE!WaitForMultipleObjects+0xe
Unable to enumerate locals, Win32 error 0n87
Private symbols (symbols.pri) are required for locals.
Type ".hh dbgerr005" for details.
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
03 000000e4`c0afe7d0 00007ffe`cd826ca8 kernel32!WerpReportFaultInternal+0x51b
Unable to enumerate locals, Win32 error 0n87
Private symbols (symbols.pri) are required for locals.
Type ".hh dbgerr005" for details.
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
04 000000e4`c0afe8f0 00007ffe`cc9300b8 kernel32!WerpReportFault+0xac
Unable to enumerate locals, Win32 error 0n87
Private symbols (symbols.pri) are required for locals.
Type ".hh dbgerr005" for details.
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
05 000000e4`c0afe930 00007ffe`cf6c4ab2 KERNELBASE!UnhandledExceptionFilter+0x3b8
Unable to enumerate locals, Win32 error 0n87
Private symbols (symbols.pri) are required for locals.
Type ".hh dbgerr005" for details.
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
06 000000e4`c0afea50 00007ffe`cf6ac656 ntdll!RtlUserThreadStart$filt$0+0xa2
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
07 000000e4`c0afea90 00007ffe`cf6c11cf ntdll!_C_specific_handler+0x96
Unable to enumerate locals, Win32 error 0n87
Private symbols (symbols.pri) are required for locals.
Type ".hh dbgerr005" for details.
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
08 000000e4`c0afeb00 00007ffe`cf68a209 ntdll!RtlpExecuteHandlerForException+0xf
Unable to enumerate locals, Win32 error 0n87
Private symbols (symbols.pri) are required for locals.
Type ".hh dbgerr005" for details.
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
09 000000e4`c0afeb30 00007ffe`cf6bfe3e ntdll!RtlDispatchException+0x219
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
0a 000000e4`c0aff240 00007ffe`cc8f0aa2 ntdll!KiUserExceptionDispatch+0x2e
Unable to enumerate locals, Win32 error 0n87
Private symbols (symbols.pri) are required for locals.
Type ".hh dbgerr005" for details.
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
0b 000000e4`c0aff948 00007ff6`c8ab1568 KERNELBASE!wil::details::DebugBreak+0x2
Unable to enumerate locals, Win32 error 0n87
Private symbols (symbols.pri) are required for locals.
Type ".hh dbgerr005" for details.
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
0c 000000e4`c0aff950 00007ff6`c8ab1560 FrameTrace!foo+0x68 [C:\NewWork\FrameTrace\FrameTrace.cpp @ 14]
concatStr = "Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! "
num = 0
str = 0x000000e4`c0aff9d0 "Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! "
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
0d 000000e4`c0aff9b0 00007ff6`c8ab1560 FrameTrace!foo+0x60 [C:\NewWork\FrameTrace\FrameTrace.cpp @ 11]
concatStr = "Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! "
num = 0
str = 0x000000e4`c0affa30 "Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! "
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
0e 000000e4`c0affa10 00007ff6`c8ab1560 FrameTrace!foo+0x60 [C:\NewWork\FrameTrace\FrameTrace.cpp @ 11]
concatStr = "Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! "
num = 1
str = 0x000000e4`c0affa90 "Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! "
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
0f 000000e4`c0affa70 00007ff6`c8ab1560 FrameTrace!foo+0x60 [C:\NewWork\FrameTrace\FrameTrace.cpp @ 11]
concatStr = "Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! "
num = 2
str = 0x000000e4`c0affaf0 "Hello World! Hello World! Hello World! Hello World! "
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
10 000000e4`c0affad0 00007ff6`c8ab1560 FrameTrace!foo+0x60 [C:\NewWork\FrameTrace\FrameTrace.cpp @ 11]
concatStr = "Hello World! Hello World! Hello World! Hello World! "
num = 3
str = 0x000000e4`c0affb50 "Hello World! Hello World! "
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
11 000000e4`c0affb30 00007ff6`c8ab15b5 FrameTrace!foo+0x60 [C:\NewWork\FrameTrace\FrameTrace.cpp @ 11]
concatStr = "Hello World! Hello World! "
num = 4
str = 0x000000e4`c0affbb0 "Hello World! "
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
12 000000e4`c0affb90 00007ff6`c8ab2b14 FrameTrace!main+0x25 [C:\NewWork\FrameTrace\FrameTrace.cpp @ 20]
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
13 (Inline Function) --------`-------- FrameTrace!invoke_main+0x22 [d:\A01\_work\6\s\src\vctools\crt\vcstartup\src\startup\exe_common.inl @ 78]
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
14 000000e4`c0affbe0 00007ffe`cd7d7bd4 FrameTrace!__scrt_common_main_seh+0x10c [d:\A01\_work\6\s\src\vctools\crt\vcstartup\src\startup\exe_common.inl @ 288]
has_cctor = false
main_result = <value unavailable>
tls_init_callback = <value unavailable>
is_nested = <value unavailable>
tls_dtor_callback = <value unavailable>
main_result = <value unavailable>
__scrt_current_native_startup_state = <value unavailable>
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
15 000000e4`c0affc20 00007ffe`cf68ce51 kernel32!BaseThreadInitThunk+0x14
Unable to enumerate locals, Win32 error 0n87
Private symbols (symbols.pri) are required for locals.
Type ".hh dbgerr005" for details.
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
16 000000e4`c0affc50 00000000`00000000 ntdll!RtlUserThreadStart+0x21
Unable to enumerate locals, Win32 error 0n87
Private symbols (symbols.pri) are required for locals.
Type ".hh dbgerr005" for details.
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
15 000000e4`c0affc20 00007ffe`cf68ce51 kernel32!BaseThreadInitThunk+0x14

We can also apply “dv /i /V” command to each frame to get additional low-level frame details:

[...]
11 000000e4`c0affb30 00007ff6`c8ab15b5 FrameTrace!foo+0x60 [C:\NewWork\FrameTrace\FrameTrace.cpp @ 11]
prv local  000000e4`c0affb50 @rsp+0x0020             concatStr = "Hello World! Hello World! "
prv param  000000e4`c0affb90 @rsp+0x0060                   num = 4
prv param  000000e4`c0affb98 @rsp+0x0068                   str = 0x000000e4`c0affbb0 "Hello World! "
[...]

We see this as a form of back tracing Execution Residue, for example:

0:000> !for_each_frame ".frame /c @$frame; dps rsp"
[...]
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
04 000000e4`c0afe8f0 00007ffe`cc9300b8 kernel32!WerpReportFault+0xac
04 000000e4`c0afe8f0 00007ffe`cc9300b8 kernel32!WerpReportFault+0xac
rax=000000000000005b rbx=0000000000000000 rcx=0000000000000003
rdx=000000e4c0afe888 rsi=0000000000000000 rdi=0000000000000003
rip=00007ffecd826ca8 rsp=000000e4c0afe8f0 rbp=0000000000000000
r8=0000000000000000  r9=00000000ffffffff r10=0000000000000000
r11=000000e4c0afdc30 r12=000000e4c0afeac0 r13=ffffffffffffffff
r14=000000e4c0afeac0 r15=0000000000001a38
iopl=0         nv up ei pl zr na po nc
cs=0033  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000246
kernel32!WerpReportFault+0xac:
00007ffe`cd826ca8 8bf8            mov     edi,eax
000000e4`c0afe8f0  00000000`00000000
000000e4`c0afe8f8  00000000`00000000
000000e4`c0afe900  00000000`00000003
000000e4`c0afe908  000000e4`c0afeac0
000000e4`c0afe910  00000000`00000004
000000e4`c0afe918  00000000`00000001
000000e4`c0afe920  00000000`00000000
000000e4`c0afe928  00007ffe`cc9300b8 KERNELBASE!UnhandledExceptionFilter+0x3b8
000000e4`c0afe930  00000000`00000000
000000e4`c0afe938  000000e4`c0affc50
000000e4`c0afe940  00007ffe`cd7c0000 kernel32!RtlVirtualUnwindStub <PERF> (kernel32+0x0)
000000e4`c0afe948  00000207`5d660000
000000e4`c0afe950  00000000`00000000
000000e4`c0afe958  00007ffe`cf6660b9 ntdll!RtlpFindEntry+0x4d
000000e4`c0afe960  00000004`00000006
000000e4`c0afe968  00000001`00000000
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
05 000000e4`c0afe930 00007ffe`cf6c4ab2 KERNELBASE!UnhandledExceptionFilter+0x3b8
05 000000e4`c0afe930 00007ffe`cf6c4ab2 KERNELBASE!UnhandledExceptionFilter+0x3b8
rax=000000000000005b rbx=0000000000000000 rcx=0000000000000003
rdx=000000e4c0afe888 rsi=00007ffecd7c0000 rdi=0000000000000000
rip=00007ffecc9300b8 rsp=000000e4c0afe930 rbp=000000e4c0affc50
r8=0000000000000000  r9=00000000ffffffff r10=0000000000000000
r11=000000e4c0afdc30 r12=000000e4c0afeac0 r13=ffffffffffffffff
r14=0000000000000001 r15=0000000000000004
iopl=0         nv up ei pl zr na po nc
cs=0033  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000246
KERNELBASE!UnhandledExceptionFilter+0x3b8:
00007ffe`cc9300b8 0f1f440000      nop     dword ptr [rax+rax]
000000e4`c0afe930  00000000`00000000
000000e4`c0afe938  000000e4`c0affc50
000000e4`c0afe940  00007ffe`cd7c0000 kernel32!RtlVirtualUnwindStub <PERF> (kernel32+0x0)
000000e4`c0afe948  00000207`5d660000
000000e4`c0afe950  00000000`00000000
000000e4`c0afe958  00007ffe`cf6660b9 ntdll!RtlpFindEntry+0x4d
000000e4`c0afe960  00000004`00000006
000000e4`c0afe968  00000001`00000000
000000e4`c0afe970  00000000`00000001
000000e4`c0afe978  00007ffe`cd7c0000 kernel32!RtlVirtualUnwindStub <PERF> (kernel32+0x0)
000000e4`c0afe980  00000207`5d662ff0
000000e4`c0afe988  00000000`00000000
000000e4`c0afe990  000000e4`c0afeac0
000000e4`c0afe998  00007ffe`cd7c0000 kernel32!RtlVirtualUnwindStub <PERF> (kernel32+0x0)
000000e4`c0afe9a0  00000000`005a0058
000000e4`c0afe9a8  00007ffe`cca6ff70 KERNELBASE!`string'
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
06 000000e4`c0afea50 00007ffe`cf6ac656 ntdll!RtlUserThreadStart$filt$0+0xa2
06 000000e4`c0afea50 00007ffe`cf6ac656 ntdll!RtlUserThreadStart$filt$0+0xa2
rax=000000000000005b rbx=00007ffecf764420 rcx=0000000000000003
rdx=000000e4c0afe888 rsi=0000000000000000 rdi=0000000000000000
rip=00007ffecf6c4ab2 rsp=000000e4c0afea50 rbp=000000e4c0affc50
r8=0000000000000000  r9=00000000ffffffff r10=0000000000000000
r11=000000e4c0afdc30 r12=000000e4c0aff730 r13=000000e4c0affc50
r14=000000e4c0aff0c0 r15=00007ffecf620000
iopl=0         nv up ei pl zr na po nc
cs=0033  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000246
ntdll!RtlUserThreadStart$filt$0+0xa2:
00007ffe`cf6c4ab2 eb16            jmp     ntdll!RtlUserThreadStart$filt$0+0xba (00007ffe`cf6c4aca)
000000e4`c0afea50  00000000`00000000
000000e4`c0afea58  00007ffe`cf764420 ntdll!`string'+0x9aa8
000000e4`c0afea60  00000000`00000000
000000e4`c0afea68  000000e4`c0affbe0
000000e4`c0afea70  00000000`00000000
000000e4`c0afea78  00007ffe`cf6457d8 ntdll!LdrpAppendUnicodeStringToFilenameBuffer+0x50
000000e4`c0afea80  00000000`0006ce51
000000e4`c0afea88  00007ffe`cf6ac656 ntdll!_C_specific_handler+0x96
000000e4`c0afea90  000000e4`c0afeb40
000000e4`c0afea98  00007ffe`cf642930 ntdll!LdrpFindLoadedDllByNameLockHeld+0xe4
000000e4`c0afeaa0  000000e4`c0aff088
000000e4`c0afeaa8  000000e4`c0aff110
000000e4`c0afeab0  000000e4`c0aff240
000000e4`c0afeab8  00000000`00000000
000000e4`c0afeac0  000000e4`c0aff730
000000e4`c0afeac8  000000e4`c0aff240
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
07 000000e4`c0afea90 00007ffe`cf6c11cf ntdll!_C_specific_handler+0x96
07 000000e4`c0afea90 00007ffe`cf6c11cf ntdll!_C_specific_handler+0x96
rax=000000000000005b rbx=00007ffecf764420 rcx=0000000000000003
rdx=000000e4c0afe888 rsi=0000000000000000 rdi=0000000000000000
rip=00007ffecf6ac656 rsp=000000e4c0afea90 rbp=000000000006ce51
r8=0000000000000000  r9=00000000ffffffff r10=0000000000000000
r11=000000e4c0afdc30 r12=000000e4c0aff730 r13=000000e4c0affc50
r14=000000e4c0aff0c0 r15=00007ffecf620000
iopl=0         nv up ei pl zr na po nc
cs=0033  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000246
ntdll!_C_specific_handler+0x96:
00007ffe`cf6ac656 85c0            test    eax,eax
000000e4`c0afea90  000000e4`c0afeb40
000000e4`c0afea98  00007ffe`cf642930 ntdll!LdrpFindLoadedDllByNameLockHeld+0xe4
000000e4`c0afeaa0  000000e4`c0aff088
000000e4`c0afeaa8  000000e4`c0aff110
000000e4`c0afeab0  000000e4`c0aff240
000000e4`c0afeab8  00000000`00000000
000000e4`c0afeac0  000000e4`c0aff730
000000e4`c0afeac8  000000e4`c0aff240
000000e4`c0afead0  00000000`00000000
000000e4`c0afead8  000000e4`c0afeb70
000000e4`c0afeae0  000000e4`c0aff240
000000e4`c0afeae8  00007ffe`cf6ac5c0 ntdll!_C_specific_handler
000000e4`c0afeaf0  00000000`00000000
000000e4`c0afeaf8  00007ffe`cf6c11cf ntdll!RtlpExecuteHandlerForException+0xf
000000e4`c0afeb00  00000000`00000000
000000e4`c0afeb08  000000e4`c0aff070
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
08 000000e4`c0afeb00 00007ffe`cf68a209 ntdll!RtlpExecuteHandlerForException+0xf
08 000000e4`c0afeb00 00007ffe`cf68a209 ntdll!RtlpExecuteHandlerForException+0xf
rax=000000000000005b rbx=0000000000000000 rcx=0000000000000003
rdx=000000e4c0afe888 rsi=000000e4c0aff730 rdi=0000000000000000
rip=00007ffecf6c11cf rsp=000000e4c0afeb00 rbp=000000e4c0aff070
r8=0000000000000000  r9=00000000ffffffff r10=0000000000000000
r11=000000e4c0afdc30 r12=00007ffecf6ac5c0 r13=000000e4c0aff240
r14=000000e4c0afeb70 r15=0000000000000000
iopl=0         nv up ei pl zr na po nc
cs=0033  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000246
ntdll!RtlpExecuteHandlerForException+0xf:
00007ffe`cf6c11cf 90              nop
000000e4`c0afeb00  00000000`00000000
000000e4`c0afeb08  000000e4`c0aff070
000000e4`c0afeb10  000000e4`c0aff730
000000e4`c0afeb18  000000e4`c0aff730
000000e4`c0afeb20  000000e4`c0aff0c0
000000e4`c0afeb28  00007ffe`cf68a209 ntdll!RtlDispatchException+0x219
000000e4`c0afeb30  000000e4`00000001
000000e4`c0afeb38  00007ffe`cf620000 ntdll!RtlStringCchCopyW <PERF> (ntdll+0x0)
000000e4`c0afeb40  00000000`00000000
000000e4`c0afeb48  00007ffe`cf78e9f0 ntdll!__PchSym_ <PERF> (ntdll+0x16e9f0)
000000e4`c0afeb50  000000e4`c0afeb70
000000e4`c0afeb58  000000e4`c0aff090
000000e4`c0afeb60  000000e4`c0aff080
000000e4`c0afeb68  00000000`00000000
000000e4`c0afeb70  000000e4`00000000
000000e4`c0afeb78  00007ffe`cc8300f0 KERNELBASE!UrlHashW <PERF> (KERNELBASE+0xf0)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
09 000000e4`c0afeb30 00007ffe`cf6bfe3e ntdll!RtlDispatchException+0x219
09 000000e4`c0afeb30 00007ffe`cf6bfe3e ntdll!RtlDispatchException+0x219
rax=000000000000005b rbx=0000000000000000 rcx=0000000000000003
rdx=000000e4c0afe888 rsi=000000e4c0aff730 rdi=0000000000000000
rip=00007ffecf68a209 rsp=000000e4c0afeb30 rbp=000000e4c0aff070
r8=0000000000000000  r9=00000000ffffffff r10=0000000000000000
r11=000000e4c0afdc30 r12=00007ffecf6ac5c0 r13=000000e4c0aff240
r14=000000e4c0afeb70 r15=0000000000000000
iopl=0         nv up ei pl zr na po nc
cs=0033  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000246
ntdll!RtlDispatchException+0x219:
00007ffe`cf68a209 8bd0            mov     edx,eax
000000e4`c0afeb30  000000e4`00000001
000000e4`c0afeb38  00007ffe`cf620000 ntdll!RtlStringCchCopyW <PERF> (ntdll+0x0)
000000e4`c0afeb40  00000000`00000000
000000e4`c0afeb48  00007ffe`cf78e9f0 ntdll!__PchSym_ <PERF> (ntdll+0x16e9f0)
000000e4`c0afeb50  000000e4`c0afeb70
000000e4`c0afeb58  000000e4`c0aff090
000000e4`c0afeb60  000000e4`c0aff080
000000e4`c0afeb68  00000000`00000000
000000e4`c0afeb70  000000e4`00000000
000000e4`c0afeb78  00007ffe`cc8300f0 KERNELBASE!UrlHashW <PERF> (KERNELBASE+0xf0)
000000e4`c0afeb80  00000001`00000000
000000e4`c0afeb88  00000012`00000018
000000e4`c0afeb90  00000000`00000000
000000e4`c0afeb98  00360030`00300030
000000e4`c0afeba0  00001f80`0010000f
000000e4`c0afeba8  00000000`00000033
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
0a 000000e4`c0aff240 00007ffe`cc8f0aa2 ntdll!KiUserExceptionDispatch+0x2e
0a 000000e4`c0aff240 00007ffe`cc8f0aa2 ntdll!KiUserExceptionDispatch+0x2e
rax=000000000000005b rbx=000002075d662a10 rcx=0000000000000003
rdx=000000e4c0afe888 rsi=0000000000000000 rdi=000002075d666e40
rip=00007ffecf6bfe3e rsp=000000e4c0aff240 rbp=0000000000000000
r8=0000000000000000  r9=00000000ffffffff r10=0000000000000000
r11=000000e4c0afdc30 r12=0000000000000000 r13=0000000000000000
r14=0000000000000000 r15=0000000000000000
iopl=0         nv up ei pl zr na po nc
cs=0033  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000246
ntdll!KiUserExceptionDispatch+0x2e:
00007ffe`cf6bfe3e 84c0            test    al,al
000000e4`c0aff240  00007ff6`c8ac32f0 FrameTrace!`string'
000000e4`c0aff248  00000000`000a0008
000000e4`c0aff250  00000207`5d662a10
000000e4`c0aff258  00007ff6`00200000
000000e4`c0aff260  000000e4`c0aff2f0
000000e4`c0aff268  000000e4`c0aff2f0
000000e4`c0aff270  00001f80`0010005f
000000e4`c0aff278  0053002b`002b0033
000000e4`c0aff280  00000246`002b002b
000000e4`c0aff288  00000000`00000000
000000e4`c0aff290  00000000`00000000
000000e4`c0aff298  00000000`00000000
000000e4`c0aff2a0  00000000`00000000
000000e4`c0aff2a8  00000000`00000000
000000e4`c0aff2b0  00000000`00000000
000000e4`c0aff2b8  000000e4`c0aff970
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
0b 000000e4`c0aff948 00007ff6`c8ab1568 KERNELBASE!wil::details::DebugBreak+0x2
0b 000000e4`c0aff948 00007ff6`c8ab1568 KERNELBASE!wil::details::DebugBreak+0x2
rax=000000000000005b rbx=000002075d662a10 rcx=0000000000000003
rdx=000000e4c0afe888 rsi=0000000000000000 rdi=000002075d666e40
rip=00007ffecc8f0aa2 rsp=000000e4c0aff948 rbp=0000000000000000
r8=0000000000000000  r9=00000000ffffffff r10=0000000000000000
r11=000000e4c0afdc30 r12=0000000000000000 r13=0000000000000000
r14=0000000000000000 r15=0000000000000000
iopl=0         nv up ei pl zr na po nc
cs=0033  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000246
KERNELBASE!wil::details::DebugBreak+0x2:
00007ffe`cc8f0aa2 cc              int     3
000000e4`c0aff948  00007ff6`c8ab1568 FrameTrace!foo+0x68 [C:\NewWork\FrameTrace\FrameTrace.cpp @ 14]
000000e4`c0aff950  000000e4`c0aff970
000000e4`c0aff958  000000e4`c0aff9d0
000000e4`c0aff960  00000000`000000d0
000000e4`c0aff968  00000207`5d66a990
000000e4`c0aff970  00000207`5d66b070
000000e4`c0aff978  00007ff6`c8ab15ed FrameTrace!std::basic_string<wchar_t,std::char_traits<wchar_t>, std::allocator<wchar_t> >::operator+=+0x1d [C:\Program Files (x86)\Microsoft Visual Studio\2019\Professional\VC\Tools\MSVC\14.26.28801\include\xstring @ 2821]
000000e4`c0aff980  00000000`000001a0
000000e4`c0aff988  00000000`000001a7
000000e4`c0aff990  0000e8d4`e5494150
000000e4`c0aff998  0000e8d4`e5494150
000000e4`c0aff9a0  000000e4`c0affa30
000000e4`c0aff9a8  00007ff6`c8ab1560 FrameTrace!foo+0x60 [C:\NewWork\FrameTrace\FrameTrace.cpp @ 11]
000000e4`c0aff9b0  00000000`00000000
000000e4`c0aff9b8  000000e4`c0aff9d0
000000e4`c0aff9c0  00000000`00000068
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
0c 000000e4`c0aff950 00007ff6`c8ab1560 FrameTrace!foo+0x68 [C:\NewWork\FrameTrace\FrameTrace.cpp @ 14]
0c 000000e4`c0aff950 00007ff6`c8ab1560 FrameTrace!foo+0x68 [C:\NewWork\FrameTrace\FrameTrace.cpp @ 14]
rax=000000000000005b rbx=000002075d662a10 rcx=0000000000000003
rdx=000000e4c0afe888 rsi=0000000000000000 rdi=000002075d666e40
rip=00007ff6c8ab1568 rsp=000000e4c0aff950 rbp=0000000000000000
r8=0000000000000000  r9=00000000ffffffff r10=0000000000000000
r11=000000e4c0afdc30 r12=0000000000000000 r13=0000000000000000
r14=0000000000000000 r15=0000000000000000
iopl=0         nv up ei pl zr na po nc
cs=0033  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000246
FrameTrace!foo+0x68:
00007ff6`c8ab1568 90              nop
000000e4`c0aff950  000000e4`c0aff970
000000e4`c0aff958  000000e4`c0aff9d0
000000e4`c0aff960  00000000`000000d0
000000e4`c0aff968  00000207`5d66a990
000000e4`c0aff970  00000207`5d66b070
000000e4`c0aff978  00007ff6`c8ab15ed FrameTrace!std::basic_string<wchar_t,std::char_traits<wchar_t>, std::allocator<wchar_t> >::operator+=+0x1d [C:\Program Files (x86)\Microsoft Visual Studio\2019\Professional\VC\Tools\MSVC\14.26.28801\include\xstring @ 2821]
000000e4`c0aff980  00000000`000001a0
000000e4`c0aff988  00000000`000001a7
000000e4`c0aff990  0000e8d4`e5494150
000000e4`c0aff998  0000e8d4`e5494150
000000e4`c0aff9a0  000000e4`c0affa30
000000e4`c0aff9a8  00007ff6`c8ab1560 FrameTrace!foo+0x60 [C:\NewWork\FrameTrace\FrameTrace.cpp @ 11]
000000e4`c0aff9b0  00000000`00000000
000000e4`c0aff9b8  000000e4`c0aff9d0
000000e4`c0aff9c0  00000000`00000068
000000e4`c0aff9c8  00000207`5d66a8a0
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[...]

We need to reset the current context after the command above since the last frame becomes the current:

0:000> kc
*** Stack trace for last set context - .thread/.cxr resets it
# Call Site
15 ntdll!RtlUserThreadStart

0:000> .cxr
Resetting default scope

0:000> kc
# Call Site
00 ntdll!NtWaitForMultipleObjects
01 KERNELBASE!WaitForMultipleObjectsEx
02 KERNELBASE!WaitForMultipleObjects
03 kernel32!WerpReportFaultInternal
04 kernel32!WerpReportFault
05 KERNELBASE!UnhandledExceptionFilter
06 ntdll!RtlUserThreadStart$filt$0
07 ntdll!_C_specific_handler
08 ntdll!RtlpExecuteHandlerForException
09 ntdll!RtlDispatchException
0a ntdll!KiUserExceptionDispatch
0b KERNELBASE!wil::details::DebugBreak
0c FrameTrace!foo
0d FrameTrace!foo
0e FrameTrace!foo
0f FrameTrace!foo
10 FrameTrace!foo
11 FrameTrace!foo
12 FrameTrace!main
13 FrameTrace!invoke_main
14 FrameTrace!__scrt_common_main_seh
15 kernel32!BaseThreadInitThunk
16 ntdll!RtlUserThreadStart

We call this analysis pattern Frame Trace.

The example memory dump, the application PDB file, and source code can be downloaded from here.

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

Trace Analysis Patterns (Part 182)

Tuesday, April 14th, 2020

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 -

Trace Analysis Patterns (Part 181)

Wednesday, November 6th, 2019

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 -

Trace Analysis Patterns (Part 180)

Thursday, October 17th, 2019

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 -

Trace Analysis Patterns (Part 179)

Wednesday, October 2nd, 2019

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 -

Trace Analysis Patterns (Part 178)

Sunday, September 15th, 2019

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 Analysis Patterns (Part 177)

Tuesday, July 30th, 2019

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 -

Trace Analysis Patterns (Part 176)

Saturday, July 27th, 2019

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 -

Trace Analysis Patterns (Part 175)

Sunday, July 21st, 2019

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 -

Trace Analysis Patterns (Part 174)

Saturday, July 20th, 2019

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 -

Trace Analysis Patterns (Part 173)

Tuesday, July 16th, 2019

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 -

Trace Analysis Patterns (Part 172)

Sunday, July 14th, 2019

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 -

Trace Analysis Patterns (Part 171)

Wednesday, July 10th, 2019

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 -

Trace Analysis Patterns (Part 170)

Monday, May 27th, 2019

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 -

Trace Analysis Patterns (Part 169)

Monday, May 6th, 2019

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 -

Trace Analysis Patterns (Part 168)

Sunday, April 7th, 2019

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 -

Trace Analysis Patterns (Part 167)

Sunday, March 31st, 2019

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 -

Trace Analysis Patterns (Part 166)

Tuesday, March 26th, 2019

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 -

Trace Analysis Patterns (Part 165)

Saturday, November 17th, 2018

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 -