Here we introduce Delay Dynamics analysis pattern. It is not an oxymoron and dynamics is referred to by what actually 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.
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
One of the trace attributes we didn’t pay much attention to in the past is CPU. This column is present in some ETW-based trace implementations such as Citrix CDF traces. As any trace attribute, it can be used to form Adjoint Thread of Activity (as all messages from code executed on that particular CPU). As we already considered threads as braids, we use braid groups as a further metaphor. In our case we combine CPUs and threads into one group which uses permutation for CPU scheduling. Instead of permutations, twists may be modeled as changes of threads. The Braid Group analysis pattern is illustrated in the following diagram:
This is a preliminary description of the analysis pattern. We plan to elaborate on it in further case studies. For example, instead of multithreading we can use multibraiding.
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
We got the idea of Unified Stack Trace analysis pattern from Flame Graphs. Like the latter, we combine Stack Trace Collection into one aggregate trace, but we may use the same length for repeated frames and may use different color intensities to present multiplicities. Different frame height may also be used to unify top frames such as waiting API. Different collections may be used in addition to database-like stack traces (Unmanaged, Managed, Predicate, I/O, CPU). The collections may be composed from different varieties of stack traces, such as General, Managed, Module, Quotient, Filters).
As a very simple example, consider this Stack Trace Collection from Notepad:
0:003> ~*kc
0 Id: 984.994 Suspend: 1 Teb: 00007ff6`f411d000 Unfrozen
# Call Site
00 USER32!NtUserGetMessage
01 USER32!GetMessageW
02 notepad!WinMain
03 notepad!WinMainCRTStartup
04 KERNEL32!BaseThreadInitThunk
05 ntdll!RtlUserThreadStart
1 Id: 984.eb8 Suspend: 1 Teb: 00007ff6`f411b000 Unfrozen
# Call Site
00 ntdll!NtWaitForWorkViaWorkerFactory
01 ntdll!TppWorkerThread
02 KERNEL32!BaseThreadInitThunk
03 ntdll!RtlUserThreadStart
2 Id: 984.1a8c Suspend: 1 Teb: 00007ff6`f4119000 Unfrozen
# Call Site
00 ntdll!NtWaitForWorkViaWorkerFactory
01 ntdll!TppWorkerThread
02 KERNEL32!BaseThreadInitThunk
03 ntdll!RtlUserThreadStart
# 3 Id: 984.11b0 Suspend: 1 Teb: 00007ff6`f4117000 Unfrozen
# Call Site
00 ntdll!DbgBreakPoint
01 ntdll!DbgUiRemoteBreakin
02 KERNEL32!BaseThreadInitThunk
03 ntdll!RtlUserThreadStart
The collection can be represented in a more compact form with multiplicities:
USER32!NtUserGetMessage
USER32!GetMessageW
notepad!WinMain | 2* ntdll!NtWaitForWorkViaWorkerFactory | ntdll!DbgBreakPoint
notepad!WinMainCRTStartup | 2* ntdll!TppWorkerThread | ntdll!DbgUiRemoteBreakin
4* KERNEL32!BaseThreadInitThunk
4* ntdll!RtlUserThreadStart
It can also be illustrated in the following diagram:
Such diagrams may help to spot Ubiquitous Components quickly.
Unified Stack Trace is also a generalization of Stack Trace Set where the latter only excludes fully duplicated stack traces but the former takes into account Constant Subtraces.
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
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 Leak 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 wave length we see a metaphorical analog to Louis de Broglie’s wave-particle duality. In general, as we already pointed in the discussion of narrativity and spatiality of software execution artifacts (see also Software Trace and Memory Dump Analysis 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 trace nature. Our correlation can be depicted in this diagram:
Practically, when we see Memory Consumption Patterns (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.
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
Visio was freezing after saving a diagram as a picture after we tried to close it. It eventually crashed with WER saving a crash dump file in LocalDumps folder. After a few such incidents Visio suggested to disable a 3rd-party plugin. We did that and double checked in Options \ Add-Ins dialog. Unfortunately, the same abnormal behaviour continued. When we looked at the crash dump stack trace we noticed Foreign Module Frame:
0:000> k
# ChildEBP RetAddr
00 0019cbac 746b1556 ntdll!NtWaitForMultipleObjects+0xc
01 0019cd40 746b1408 KERNELBASE!WaitForMultipleObjectsEx+0x136
02 0019cd5c 747ea02a KERNELBASE!WaitForMultipleObjects+0x18
03 0019d198 747e9ac6 kernel32!WerpReportFaultInternal+0x545
04 0019d1a8 747ccf09 kernel32!WerpReportFault+0x7a
05 0019d1b0 746c9f53 kernel32!BasepReportFault+0x19
06 0019d244 76fc2de5 KERNELBASE!UnhandledExceptionFilter+0x1b3
07 0019d2e8 76f8acd6 ntdll!LdrpLogFatalUserCallbackException+0x4d
08 0019d2f4 76f9d572 ntdll!KiUserCallbackExceptionHandler+0x26
09 0019d318 76f9d544 ntdll!ExecuteHandler2+0x26
0a 0019d3e0 76f8ad8f ntdll!ExecuteHandler+0x24
0b 0019d3e0 55403000 ntdll!KiUserExceptionDispatcher+0xf
WARNING: Stack unwind information not available. Following frames may be wrong.
0c 0019d8d0 55402faa VISLIB!Ordinal1+0x24f3b
0d 0019d914 5b85c67e VISLIB!Ordinal1+0x24ee5
0e 0019d940 5b85c638 MSO!Ordinal2138+0x10a
0f 0019d950 5b8e7620 MSO!Ordinal2138+0xc4
10 0019d964 5b8e7602 MSO!Ordinal9998+0x3bc
11 0019d97c 5bc938a6 MSO!Ordinal9998+0x39e
12 0019dbb0 5c240add MSO!Ordinal7238+0x25bef
13 0019ddec 65598ed1 MSO!Ordinal2007+0x1766
14 0019de78 655c5eaa VisioPlugin!DllRegisterServer+0×43bf1
15 0019dfbc 555601db VisioPlugin!DllRegisterServer+0×70bca
16 0019dfe8 5555fe61 VISLIB!Ordinal1+0×182116
17 0019e028 55421b7c VISLIB!Ordinal1+0×181d9c
18 0019e070 5549f1a9 VISLIB!Ordinal1+0×43ab7
19 0019e090 5549ebba VISLIB!Ordinal1+0xc10e4
1a 0019e0c0 5540dd14 VISLIB!Ordinal1+0xc0af5
1b 0019e110 55426168 VISLIB!Ordinal1+0×2fc4f
1c 0019e134 55425446 VISLIB!Ordinal1+0×480a3
1d 0019e20c 5549eace VISLIB!Ordinal1+0×47381
1e 0019e264 5549e90e VISLIB!Ordinal1+0xc0a09
1f 0019e28c 6571fb03 VISLIB!Ordinal1+0xc0849
20 0019e334 6571f6cc mfc90u!CWnd::OnWndMsg+0×410
21 0019e354 553ef572 mfc90u!CWnd::WindowProc+0×24
22 0019e370 6571e2f2 VISLIB!Ordinal1+0×114ad
23 0019e3d8 6571e57e mfc90u!AfxCallWndProc+0xa3
24 0019e3fc 553ef518 mfc90u!AfxWndProc+0×37
25 0019e440 553ef4d9 VISLIB!Ordinal1+0×11453
26 0019e458 553ef49e VISLIB!Ordinal1+0×11414
27 0019e480 553ef338 VISLIB!Ordinal1+0×113d9
28 0019e49c 553ef2d6 VISLIB!Ordinal1+0×11273
29 0019e4c4 553ef107 VISLIB!Ordinal1+0×11211
2a 0019e528 75864923 VISLIB!Ordinal1+0×11042
2b 0019e554 75844790 user32!_InternalCallWinProc+0×2b
2c 0019e5fc 75844527 user32!UserCallWinProcCheckWow+0×1f0
2d 0019e638 71db7d40 user32!CallWindowProcW+0×97
2e 0019e6b8 71db7996 comctl32!CallNextSubclassProc+0×140
2f 0019e6d8 5b84d95a comctl32!DefSubclassProc+0×56
30 0019e720 5b84d7ad MSO!Ordinal6319+0×25e
31 0019e74c 71db7db8 MSO!Ordinal6319+0xb1
32 0019e7d0 71db7b61 comctl32!CallNextSubclassProc+0×1b8
33 0019e82c 75864923 comctl32!MasterSubclassProc+0xa1
34 0019e858 75844790 user32!_InternalCallWinProc+0×2b
35 0019e900 75844370 user32!UserCallWinProcCheckWow+0×1f0
36 0019e960 7584b179 user32!DispatchClientMessage+0xf0
37 0019e9a0 76f8ad66 user32!__fnDWORD+0×49
38 0019e9d8 75864dac ntdll!KiUserCallbackDispatcher+0×36
39 0019e9dc 75842ce8 user32!NtUserMessageCall+0xc
3a 0019ea68 758423ba user32!RealDefWindowProcWorker+0×148
3b 0019ea80 71f882ee user32!RealDefWindowProcW+0×5a
3c 0019eaa0 71f88145 uxtheme!DoMsgDefault+0×3a
3d 0019eab0 71f87bba uxtheme!OnDwpSysCommand+0×35
3e 0019eb1c 71f868d8 uxtheme!_ThemeDefWindowProc+0×6ca
3f 0019eb30 75842b66 uxtheme!ThemeDefWindowProcW+0×18
40 0019eb80 758415ee user32!DefWindowProcW+0×176
41 0019eb98 75851e3b user32!DefWindowProcWorker+0×2e
42 0019ec1c 758aa09b user32!DefFrameProcWorker+0xb7
43 0019ec34 55718ac5 user32!DefFrameProcW+0×1b
44 0019ec58 55708027 VISLIB!Ordinal1+0×33aa00
45 0019ec70 6571e3c1 VISLIB!Ordinal1+0×329f62
46 0019ec84 65725604 mfc90u!CWnd::Default+0×30
47 0019ec94 5549e617 mfc90u!CFrameWnd::OnSysCommand+0×50
48 0019ecb4 6571fd15 VISLIB!Ordinal1+0xc0552
49 0019ed64 6571f6cc mfc90u!CWnd::OnWndMsg+0×622
4a 0019ed84 553ef572 mfc90u!CWnd::WindowProc+0×24
4b 0019eda0 6571e2f2 VISLIB!Ordinal1+0×114ad
4c 0019ee08 6571e57e mfc90u!AfxCallWndProc+0xa3
4d 0019ee2c 553ef518 mfc90u!AfxWndProc+0×37
4e 0019ee70 553ef4d9 VISLIB!Ordinal1+0×11453
4f 0019ee88 553ef49e VISLIB!Ordinal1+0×11414
50 0019eeb0 553ef338 VISLIB!Ordinal1+0×113d9
51 0019eecc 553ef2d6 VISLIB!Ordinal1+0×11273
52 0019eef4 553ef107 VISLIB!Ordinal1+0×11211
53 0019ef58 75864923 VISLIB!Ordinal1+0×11042
54 0019ef84 75844790 user32!_InternalCallWinProc+0×2b
55 0019f02c 75844527 user32!UserCallWinProcCheckWow+0×1f0
56 0019f068 71db7d40 user32!CallWindowProcW+0×97
57 0019f0e8 71db7996 comctl32!CallNextSubclassProc+0×140
58 0019f108 5b84d95a comctl32!DefSubclassProc+0×56
59 0019f150 5b84d7ad MSO!Ordinal6319+0×25e
5a 0019f17c 71db7db8 MSO!Ordinal6319+0xb1
5b 0019f200 71db7b61 comctl32!CallNextSubclassProc+0×1b8
5c 0019f25c 75864923 comctl32!MasterSubclassProc+0xa1
5d 0019f288 75844790 user32!_InternalCallWinProc+0×2b
5e 0019f330 75844370 user32!UserCallWinProcCheckWow+0×1f0
5f 0019f390 7584b179 user32!DispatchClientMessage+0xf0
60 0019f3d0 76f8ad66 user32!__fnDWORD+0×49
61 0019f408 00000000 ntdll!KiUserCallbackDispatcher+0×36
Next, we applied lmv WinDbg command to the module name and followed its image path to rename it. After that, the problem disappeared. We call such modules Foreign because they were created not by the OS or the main process module vendors. Most likely these modules are either value-adding plugins or exposed Message Hooks.
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
This is a Linux variant of Module Stack Trace pattern previously described for Windows platform. Linux core dumps are Abridged Dumps by default with shared libraries code and paged out pages missing. To enable saving full process dumps use this command (see core man page for more details):
[training@localhost CentOS]$ echo 0x7f > /proc/$$/coredump_filter
Compare the file sizes for sleep process core dump generated before (core.3252) and after (core.3268) changing coredump_filter value:
[training@localhost CentOS]$ ls -l
-rwxrwxrwx. 1 root root 323584 Oct 3 07:39 core.3252
-rwxrwxrwx. 1 root root 103337984 Oct 3 07:40 core.3268
Although GDB is not able to get symbolic stack trace for both dumps above due to the absence of symbols, CODA tool is able to show stack trace variant with modules (with Reduced Symbolic Information):
(gdb) bt
#0 0x00000032bd4accc0 in ?? ()
#1 0x0000000000403ce8 in ?? ()
#2 0x00000000000004d2 in ?? ()
#3 0x0000000000000000 in ?? ()
[training@localhost CentOS]$ ./coda/coda -i core.3268
Welcome to coda interactive command line.
THE SOFTWARE IS PROVIDED 'AS IS', WITHOUT WARRANTY OF ANY KIND.
Supported on x86_64-linux.
Coredump generated by command line => sleep 1234
coda > bt
[0] 0x00000032bd4accc0 <0x00000032bd4accb0 - 0x00000032bd4acd0e> __nanosleep+0x10 [RO TEXT]:/lib64/libc.so.6
[1] 0×0000000000403ce8 <0×0000000000403c40 - 0×0000000000403cf3> close_stdout+0×2378 [RO TEXT]:sleep
[2] 0×000000000040336d <0×00000000004032c0 - 0×00000000004033e9> close_stdout+0×19fd [RO TEXT]:sleep
[3] 0×00000000004016bc <0×00000000004014c0 - 0×0000000000401775> usage+0×3fc [RO TEXT]:sleep
[4] 0×00000032bd41ed1d <0×00000032bd41ec20 - 0×00000032bd41ede7> __libc_start_main+0xfd [RO TEXT]:/lib64/libc.so.6
[5] 0×00000000004011f9 <0×00000000004012c0 - 0×00000000004014bb> ?? [RO TEXT]:sleep
[6] 0×00007fff89d82a68 <————-RANGE UNKNOWN————-> ?? [RW DATA]:
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
For completeness, we introduce Module Stack Trace analysis pattern, which is a tack trace with module (or components) and offsets into their address range. Offsets distinguish it from Collapsed Stack Trace. We see only modules names in case of No Component Symbols or Unrecognizable Symbolic Information. Sometimes, we also have exported functions present with resulting offsets reduced in value but still large. This is a case of Reduced Symbolic Information. Such emerging symbols may form Incorrect Stack Trace frames. On some platforms Module Stack Traces become Truncated Stack Traces because a debugger is not able to reconstruct the stack trace. The following stack traces shows Module Stack Trace fragment for PhotosApp_Windows (and also frames with exported functions for ntdll, combase, twinapi_appcore):
0:034> kL
# Child-SP RetAddr Call Site
00 0000005b`03acc5c0 00007ff9`b6288935 KERNELBASE!RaiseFailFastException+0x74
01 0000005b`03accb90 00007ff9`b399654f combase!RoParameterizedTypeExtraGetTypeSignature+0×8db5
02 0000005b`03acccd0 00007ff9`b39965d0 twinapi_appcore!BiNotifyNewSession+0×2628f
03 0000005b`03accd10 00007ff9`b6186e1a twinapi_appcore!BiNotifyNewSession+0×26310
04 0000005b`03accd40 00007ff9`9eaca4a0 combase!RoReportUnhandledError+0xea
05 0000005b`03accdc0 00007ff9`af37be60 MSVCP140_APP!`Concurrency::details::_ExceptionHolder::ReportUnhandledError’::`1′::catch$3+0×39
06 0000005b`03acce00 00007ff9`af3729b2 VCRUNTIME140_APP!CallSettingFrame+0×20
07 0000005b`03acce30 00007ff9`b8625c53 VCRUNTIME140_APP!_CxxCallCatchBlock+0×122
08 0000005b`03accef0 00007ff9`9ea99129 ntdll!RtlCaptureContext+0×3c3
09 0000005b`03acf490 00007ff9`861137e6 MSVCP140_APP!Concurrency::details::_ExceptionHolder::ReportUnhandledError+0×29
0a 0000005b`03acf4e0 00007ff9`86112142 PhotosApp_Windows+0×737e6
0b 0000005b`03acf520 00007ff9`86111e6c PhotosApp_Windows+0×72142
0c 0000005b`03acf560 00007ff9`86113e38 PhotosApp_Windows+0×71e6c
0d 0000005b`03acf590 00007ff9`8611307d PhotosApp_Windows+0×73e38
0e 0000005b`03acf5f0 00007ff9`86113619 PhotosApp_Windows+0×7307d
0f 0000005b`03acf630 00007ff9`b85caefa PhotosApp_Windows+0×73619
10 0000005b`03acf680 00007ff9`b85c97ea ntdll!EtwEventRegister+0×1e3a
11 0000005b`03acf790 00007ff9`b7df2d92 ntdll!EtwEventRegister+0×72a
12 0000005b`03acfb90 00007ff9`b8599f64 kernel32!BaseThreadInitThunk+0×22
13 0000005b`03acfbc0 00000000`00000000 ntdll!RtlUserThreadStart+0×34
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
Considering and extending Trace Dimension to TID, ATID, and Time we use Poincaré section and Poincaré map analogies to introduce Poincaré Trace analysis pattern. We choose a value of one “coordinate”, for example, Time, and then form the new trace that consists of messages from different (A)TIDs that have the same timestamp as Time value or the last message(s) from other different ATIDs if they happened before section Time:
If we choose a different ATID than Time and TID, then Poincare Trace is equivalent to Adjoint Thread of Activity. If ATID is TID we have Thread of Activity as a trivial case. If we have Thread of Activity, we can choose some ATID and get Poincaré Trace as illustrated in the following diagram where the thick black line in the right Poincaré Trace represents Discontinuity and its Time Delta:
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
There are messages in traces and logs that alone do not have useful information. These are adornments or ornamentation messages that we initially called Delineator or Separator messages that structure message stream or Figural Events (where we borrowed the name figural from Lyotard) such as formatting the next message with { }. Such messages only make meaning with other meaningful messages. We call this pattern Ornament. It helps in using trace analysis patterns and trace pattern identification.
Ornament can also be present inside individual messages, for example, as a character prefix. It can be a part of Message Invariant or variable itself. Some ornamentation can play a rhetorical function.
Although ornament is present in non-software architecture this concept has never been explored in pattern–oriented software architecture and construction. We propose similar concept for source code (software construction) in addition to ornamentation of its Declarative Trace. For software post-construction, we also add ornament part to software structure and behavior parts.
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
When we have hundreds of separate trace files from Split Trace and a smaller Split Trace with fewer files or just a single trace file that was recorded simultaneously (for example, a client from client-server environment) we can “project” the smaller Message Space into the larger Message Space as depicted in the following diagram:
This Projective Space analysis pattern can be used in conjunction with Indexical Trace where time interval can be used as an index into the larger Split Trace. Such projection may not be accurate but, assuming that the target trace Statement Current is uniform on average, can still be a very good heuristic instead of a binary search. For example, recently we had 4 sequential trace files for the client and 36 sequential files for the server. The software problem interval was specified in Basic Facts. We found that it in the second path of the 4th client trace. We, therefore, only inspected the last 4 traces of the 36 server sequential trace set and found it contained in the 35th server trace.
This pattern uses projective space metaphor from mathematics.
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
Long time go we introduced the notion of Collapsed Stack Trace (Volume 3, page 381) when all functions are removed from Stack Trace (for example, kc WinDbg command) and remaining repeated modules are removed similar to Quotient Trace analysis pattern. It is similar to Stack Trace Signature with frame count set to 1. We originally planned to call this pattern Compact Stack (Trace) and it was on our list of possible future analysis patterns. This came to our attention again while preparing “Theoretical Software Diagnostics” book and we decided to publish it under the name Quotient Stack Trace as a specialization of the more general trace and log analysis pattern.
Such a pattern may be useful for the analysis of module Wait Chains.
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
In Adjoint Message analysis pattern description we mentioned compressing message sequences having the same message attribute into one message. Considering the trace as “topological” space and message attribute as “equivalence” relation we introduce Quotient Trace analysis pattern by analogy with quotient space in topology. By endowing message sequences having the same attribute with some “metric” such as cardinality of Message Set we can also visually distinguish resulted quotient messages if they have the same attribute but from different sequences at different times. All this is illustrated in the following diagram:
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
This is C++ condition variable Wait Chain pattern variant. When we have a waiting Blocked Thread stack trace that shows conditional variable implementation functions we are interested in the owner thread:
0:012> kL
# ChildEBP RetAddr
00 03a6f684 748d8ee9 ntdll!NtWaitForSingleObject+0xc
01 03a6f6f8 5f5fcba5 KERNELBASE!WaitForSingleObjectEx+0x99
02 03a6f70c 5f5fb506 msvcr120!Concurrency::details::ExternalContextBase::Block+0×37
03 03a6f778 639cea79 msvcr120!Concurrency::details::_Condition_variable::wait+0xab
04 03a6f7ac 639ceb58 msvcp120!do_wait+0×42
05 03a6f7c0 5c8c5a43 msvcp120!_Cnd_wait+0×10
WARNING: Stack unwind information not available. Following frames may be wrong.
06 03a6f7d0 5c8c4ee6 AppA!foo+0×48883
07 03a6f804 5c8c4bde AppA!foo+0×47d26
08 03a6f834 5c8c4b9c AppA!foo+0×47a1e
09 03a6f848 5c8c4a27 AppA!foo+0×479dc
0a 03a6f854 00dcc4e9 AppA!foo+0×47867
0b 03a6f86c 75823744 AppA+0×1c4e9
0c 03a6f880 76ef9e54 kernel32!BaseThreadInitThunk+0×24
0d 03a6f8c8 76ef9e1f ntdll!__RtlUserThreadStart+0×2f
0e 03a6f8d8 00000000 ntdll!_RtlUserThreadStart+0×1b
We see the thread is waiting for an event 4ac:
0:012> kv 2
# ChildEBP RetAddr Args to Child
00 03a6f684 748d8ee9 000004ac 00000000 00000000 ntdll!NtWaitForSingleObject+0xc (FPO: [3,0,0])
01 03a6f6f8 5f5fcba5 000004ac ffffffff 00000000 KERNELBASE!WaitForSingleObjectEx+0×99 (FPO: [SEH])
0:012> !handle 4ac
Handle 000004ac
Type Event
Instead of digging into implementation internals we show a different approach. We can use Constant Subtrace analysis pattern to find out possible owner thread candidates, and we can also check raw stack region Execution Residue of different threads for Place Trace of synchronization primitives and associated symbolic references (beware of Coincidental Symbolic Information though), and, if possible, Past Stack Traces involving synchronization.
If we look at Stack Trace Collection we can match the following thread that has the same Constant Subtrace as our original waiting thread above:
14 Id: 17a0.39d0 Suspend: 1 Teb: fee4f000 Unfrozen
# ChildEBP RetAddr
00 0679f9f0 748d9edc ntdll!NtReadFile+0xc
01 0679fa54 5c8f38f2 KERNELBASE!ReadFile+0xec
WARNING: Stack unwind information not available. Following frames may be wrong.
02 0679fa84 5c8f3853 AppA!foo+0x76732
03 0679fac8 5c8f37cd AppA!foo+0x76693
04 0679fae0 5c8c4a27 AppA!foo+0x7660d
05 0679faec 00dcc4e9 AppA!foo+0×47867
06 0679fb04 75823744 AppA+0×1c4e9
07 0679fb18 76ef9e54 kernel32!BaseThreadInitThunk+0×24
08 0679fb60 76ef9e1f ntdll!__RtlUserThreadStart+0×2f
09 0679fb70 00000000 ntdll!_RtlUserThreadStart+0×1b
When we dump raw stack data from all threads using this WinDbg script and search for 000004ac we find its occurrences in the raw stack that corresponds to thread #14 we already found:
[...]
TEB at fee4f000
ExceptionList: 0679fa44
StackBase: 067a0000
StackLimit: 0679e000
[…]
0679f90c 0679f918
0679f910 5f5a4894 msvcr120!Concurrency::details::SchedulerBase::CurrentContext+0×1e
0679f914 00000033
0679f918 0679f950
0679f91c 5f5a48ca msvcr120!Concurrency::details::LockQueueNode::LockQueueNode+0×2a
0679f920 0679f998
0679f924 071cf9ac
0679f928 0679f94c
0679f92c 5f5ff57e msvcr120!Concurrency::critical_section::_Acquire_lock+0×2e
0679f930 071cf9ac
0679f934 0679f994
0679f938 0679f998
0679f93c 00000001
0679f940 070f4bfc
0679f944 0679f970
0679f948 5f5ff41f msvcr120!Concurrency::critical_section::lock+0×31
0679f94c 0679f980
0679f950 5f5ff6dc msvcr120!Concurrency::critical_section::scoped_lock::scoped_lock+0×3b
0679f954 0679f998
0679f958 76f08bcc ntdll!NtSetEvent+0xc
0679f95c 748e30b0 KERNELBASE!SetEvent+0×10
0679f960 000004ac
0679f964 00000000
0679f968 0679f984
0679f96c 5f5fcbe6 msvcr120!Concurrency::details::ExternalContextBase::Unblock+0×3f
0679f970 000004ac
0679f974 03a6f750
0679f978 03a6f750
0679f97c 0679f9b4
0679f980 5f5fb70d msvcr120!Concurrency::details::_Condition_variable::notify_all+0×3f
0679f984 0679f9b4
0679f988 5f5fb722 msvcr120!Concurrency::details::_Condition_variable::notify_all+0×54
0679f98c 07481380
0679f990 05ba6f60
0679f994 071cf9ac
[…]
Both methods point to the same possible owner thread which is also blocked in reading a file.
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
JIT compiling is not restricted to .NET in Windows and we decided to add Java variant of JIT Code (.NET) analysis pattern. Here’s one thread example from java.exe process memory dump:
0:071> k
# ChildEBP RetAddr
00 536cf424 770c15ce ntdll!NtWaitForSingleObject+0×15
01 536cf490 76f31194 KERNELBASE!WaitForSingleObjectEx+0×98
02 536cf4a8 76f31148 kernel32!WaitForSingleObjectExImplementation+0×75
03 536cf4bc 59207cb3 kernel32!WaitForSingleObject+0×12
WARNING: Stack unwind information not available. Following frames may be wrong.
04 536cf4e4 5918dbb1 jvm!JVM_FindSignal+0×5833
05 536cf558 03b6db25 jvm!JVM_Clone+0×30161
06 536cf588 03c4b0f4 0×3b6db25
07 536cf690 0348339a 0×3c4b0f4
08 536cf7d8 034803d7 0×348339a
09 536cf7e4 591a0732 0×34803d7
0a 536cf870 75bb9cde jvm!JVM_Clone+0×42ce2
0b 536cf87c 5926529e msvcrt!_VEC_memzero+0×82
0c 536cf8c4 591a1035 jvm!JVM_FindSignal+0×62e1e
0d 536cf908 591a1097 jvm!JVM_Clone+0×435e5
0e 536cf978 5914c49f jvm!JVM_Clone+0×43647
0f 536cf9d4 591c22dc jvm!jio_printf+0xaf
10 536cfa20 591c2d37 jvm!JVM_Clone+0×6488c
11 536cfa58 592071e9 jvm!JVM_Clone+0×652e7
12 536cfc98 5d34c556 jvm!JVM_FindSignal+0×4d69
13 536cfcd0 5d34c600 msvcr100!_endthreadex+0×3f
14 536cfcdc 76f3338a msvcr100!_endthreadex+0xce
15 536cfce8 77829902 kernel32!BaseThreadInitThunk+0xe
16 536cfd28 778298d5 ntdll!__RtlUserThreadStart+0×70
17 536cfd40 00000000 ntdll!_RtlUserThreadStart+0×1b
We see that the return addresses are indeed return addresses saved on stack with the preceding call instruction:
0:071> ub 03b6db25
03b6db03 50 push eax
03b6db04 57 push edi
03b6db05 e876586455 call jvm!JVM_Clone+0x55930 (591b3380)
03b6db0a 83c408 add esp,8
03b6db0d 8d9730010000 lea edx,[edi+130h]
03b6db13 891424 mov dword ptr [esp],edx
03b6db16 c7876c01000004000000 mov dword ptr [edi+16Ch],4
03b6db20 e8dbff6155 call jvm!JVM_Clone+0×300b0 (5918db00)
0:071> ub 03c4b0f4
03c4b0cd 891c24 mov dword ptr [esp],ebx
03c4b0d0 894c2404 mov dword ptr [esp+4],ecx
03c4b0d4 899c2480000000 mov dword ptr [esp+80h],ebx
03c4b0db 898c2484000000 mov dword ptr [esp+84h],ecx
03c4b0e2 b928b0b91a mov ecx,1AB9B028h
03c4b0e7 89bc248c000000 mov dword ptr [esp+8Ch],edi
03c4b0ee 90 nop
03c4b0ef e8ac29f2ff call 03b6daa0
0:071> ub 034803d7
034803c6 89049c mov dword ptr [esp+ebx*4],eax
034803c9 43 inc ebx
034803ca 49 dec ecx
034803cb 75f5 jne 034803c2
034803cd 8b5d14 mov ebx,dword ptr [ebp+14h]
034803d0 8b4518 mov eax,dword ptr [ebp+18h]
034803d3 8bf4 mov esi,esp
034803d5 ffd0 call eax
0:071> ub 591a0732
jvm!JVM_Clone+0x42ccc:
591a071c 57 push edi
591a071d 89461c mov dword ptr [esi+1Ch],eax
591a0720 e8ab110000 call jvm!JVM_Clone+0x43e80 (591a18d0)
591a0725 6a08 push 8
591a0727 6a06 push 6
591a0729 57 push edi
591a072a 894514 mov dword ptr [ebp+14h],eax
591a072d e86e9af2ff call jvm+0×6a1a0 (590ca1a0)
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
In case of parallel memory leak for process heap and .NET heap (or generally with several dynamic memory allocators) we are interested in relative growth to see whether they are interdependent, i.e. managed heap objects have pointers to process heap entries. When we have a set of consecutive memory dumps we can construct a table of heap sizes and plot the graph where the axes represents memory snapshot numbers and total heap size in bytes:
Unfortunately, the relative growth sizes can be disproportionate as the picture above shows. To overcome this, we can normalize size by the lowest corresponding heap size, i.e. Sn/S1:
Still this doesn’t show the absence of correlation if there is no such. We can plot the relative growth, i.e. Sn/Sn-1, n > 1:
The graph shows that there is no obvious correlation between Relative Heap Leaks. Similar graphs can be constructed for relative object distributions.
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
Stack traces resemble functions: they have prolog, body, and epilog. Frame trace is also similar to trace Partition analysis pattern. Bottom stack subtrace plays the role of prolog, for example, thread initialization and RPC call stub dispatch. Middle stack subtrace plays the role of body or core, for example, application specific function calls invoked by RPC. Top stack subtrace plays the role of epilogue, for example, system calls. Such stack trace partition is useful for stack trace matching, especially when symbols are not available. In such a case Stack Trace Signature of module names and their frame counts may help (together with Crash Signature where appropriate):
The following stack trace may be split into TMB (pronounced Tomb):
0:001> kc
# Call Site
00 ntdll!RtlEnterCriticalSection
01 ModuleA
02 ModuleA
03 ModuleA
04 ModuleA
05 ModuleA
06 ModuleA
07 ModuleA
08 ModuleA
09 ModuleA
0a ModuleA
0b ModuleA
0c ModuleA
0d ModuleA
0e ModuleA
0f ModuleA
10 rpcrt4!Invoke
11 rpcrt4!NdrStubCall2
12 rpcrt4!NdrServerCall2
13 rpcrt4!DispatchToStubInCNoAvrf
14 rpcrt4!RPC_INTERFACE::DispatchToStubWorker
15 rpcrt4!RPC_INTERFACE::DispatchToStub
16 rpcrt4!RPC_INTERFACE::DispatchToStubWithObject
17 rpcrt4!LRPC_SCALL::DispatchRequest
18 rpcrt4!LRPC_SCALL::HandleRequest
19 rpcrt4!LRPC_SASSOCIATION::HandleRequest
1a rpcrt4!LRPC_ADDRESS::HandleRequest
1b rpcrt4!LRPC_ADDRESS::ProcessIO
1c rpcrt4!LrpcIoComplete
1d ntdll!TppAlpcpExecuteCallback
1e ntdll!TppWorkerThread
1f kernel32!BaseThreadInitThunk
20 ntdll!RtlUserThreadStart
It has the following signature:
T<ntdll,1>M<ModuleA,15>B<rpcrt4,13>B<ntdll,2>B<kernel32,1>B<ntdll,1>
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
We do not write a special pattern for individual stowed exceptions (0xC000027B, an application-internal exception) because we consider them examples of Mixed Exceptions (for example, as Managed Code Exceptions enveloped by unmanaged code Software Exception, see stowed exception examples here). However, we introduce a variant of Multiple Exceptions analysis patterns for them because the default analysis WinDbg command (!analyze -v) only shows the first exception or error message stored in the array of stowed exception information structures. The following example shows 3 exceptions. When we load the dump we get this indication of the stowed exceptions:
This dump file has an exception of interest stored in it.
The stored exception information can be accessed via .ecxr.
(2784.2068): Unknown exception - code c000027b (first/second chance not available)
eax=059be538 ebx=00000000 ecx=00000000 edx=00000000 esi=059be898 edi=059be538
eip=750510c0 esp=059be81c ebp=059be940 iopl=0 nv up ei pl nz ac po nc
cs=0023 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00000212
combase!RoFailFastWithErrorContextInternal2+0×109 [inlined in combase!RoFailFastWithErrorContextInternal+0×240]:
750510c0 6a03 push 3
0:008> !error c000027b
Error code: (NTSTATUS) 0xc000027b (3221226107) - An application-internal exception has occurred.
We check Stored Exception:
0:008> .exr -1
ExceptionAddress: 66fc2408 (Windows_UI_Xaml!DirectUI::ErrorHelper::ProcessUnhandledError+0x00432e07)
ExceptionCode: c000027b
ExceptionFlags: 00000001
NumberParameters: 2
Parameter[0]: 08d9bfa8
Parameter[1]: 00000003
We see it has 3 stowed exceptions pointed to by array elements:
0:008> dp 08d9bfa8 L3
08d9bfa8 08d8e084 08d928a8 08d928d0
We check what kind of stowed information structures they point to:
0:008> dt -a3 08d9bfa8 _STOWED_EXCEPTION_INFORMATION_HEADER*
[0] @ 08d9bfa8
———————————————
0×08d8e084
+0×000 Size : 0×28
+0×004 Signature : 0×53453032
[1] @ 08d9bfac
---------------------------------------------
0x08d928a8
+0x000 Size : 0x28
+0×004 Signature : 0×53453032
[2] @ 08d9bfb0
---------------------------------------------
0x08d928d0
+0x000 Size : 0x28
+0×004 Signature : 0×53453032
0:008> .formats 0x53453032
Evaluate expression:
Hex: 53453032
Decimal: 1397043250
Octal: 12321230062
Binary: 01010011 01000101 00110000 00110010
Chars: SE02
Time: Wed Apr 09 12:34:10 2014
Float: low 8.46917e+011 high 0
Double: 6.90231e-315
Since these are version 2 stowed information structures we use this command:
0:008> dt -a3 08d9bfa8 _STOWED_EXCEPTION_INFORMATION_V2*
[0] @ 08d9bfa8
———————————————
0×08d8e084
+0×000 Header : _STOWED_EXCEPTION_INFORMATION_HEADER
+0×008 ResultCode : 802b000a
+0×00c ExceptionForm : 0y01
+0×00c ThreadId : 0y000000000000000000100000011010 (0×81a)
+0×010 ExceptionAddress : 0×74f562f2 Void
+0×014 StackTraceWordSize : 4
+0×018 StackTraceWords : 0×3c
+0×01c StackTrace : 0×07731c08 Void
+0×010 ErrorText : 0×74f562f2 “趍ﯰ???”
+0×020 NestedExceptionType : 0
+0×024 NestedException : (null)
[1] @ 08d9bfac
---------------------------------------------
0x08d928a8
+0x000 Header : _STOWED_EXCEPTION_INFORMATION_HEADER
+0×008 ResultCode : 80004001
+0×00c ExceptionForm : 0y01
+0×00c ThreadId : 0y000000000000000000000000000000 (0)
+0×010 ExceptionAddress : (null)
+0×014 StackTraceWordSize : 4
+0×018 StackTraceWords : 0×3c
+0×01c StackTrace : 0×077d5d4c Void
+0×010 ErrorText : (null)
+0×020 NestedExceptionType : 0
+0×024 NestedException : (null)
[2] @ 08d9bfb0
---------------------------------------------
0x08d928d0
+0x000 Header : _STOWED_EXCEPTION_INFORMATION_HEADER
+0×008 ResultCode : 80004005
+0×00c ExceptionForm : 0y01
+0×00c ThreadId : 0y000000000000000000000000000000 (0)
+0×010 ExceptionAddress : (null)
+0×014 StackTraceWordSize : 4
+0×018 StackTraceWords : 0×19
+0×01c StackTrace : 0×0772df74 Void
+0×010 ErrorText : (null)
+0×020 NestedExceptionType : 0
+0×024 NestedException : (null)
Now we check Stack Traces for individual entries and their error codes:
0:008> !error 802b000a
Error code: (HRESULT) 0×802b000a (2150301706) - <Unable to get error code text>
0:008> .lines -d
Line number information will not be loaded
0:008> dps 0×07731c08 L3c
07731c08 74fba2be combase!RoOriginateErrorW+0×3e
07731c0c 66b900d7 Windows_UI_Xaml!DirectUI::ErrorHelper::OriginateError+0×8d
07731c10 66b8fe5f Windows_UI_Xaml!CJupiterErrorServiceListener::NotifyErrorAdded+0xaf
07731c14 66b8fd60 Windows_UI_Xaml!CErrorService::AddError+0×130
07731c18 66b8f0f8 Windows_UI_Xaml!CErrorService::ReportParserError+0×88
07731c1c 66b8f000 Windows_UI_Xaml!ParserErrorService::ReportError+0xd0
07731c20 670f9654 Windows_UI_Xaml!ParserErrorReporter::SetError+0×61
07731c24 670fbe70 Windows_UI_Xaml!XamlBinaryMetadataReader2::LogError+0×6c
07731c28 670fbd37 Windows_UI_Xaml!<lambda_1d4791754290213f1bf5bc456a504cc5>::operator()+0×41
07731c2c 67032601 Windows_UI_Xaml!XamlBinaryMetadataReader2::LoadProperty+0×1f7e82
07731c30 66cab9d9 Windows_UI_Xaml!XamlBinaryMetadataReader2::GetProperty+0×5c
07731c34 66d528e0 Windows_UI_Xaml!XamlBinaryFormatSubReader2::ReadXamlProperty+0×1d0
07731c38 66d520cc Windows_UI_Xaml!XamlBinaryFormatSubReader2::ReadSetValueConstantNode+0×3c
07731c3c 66d53b55 Windows_UI_Xaml!XamlBinaryFormatSubReader2::TryRead+0×135
07731c40 66d539ec Windows_UI_Xaml!XamlBinaryFormatSubReader2::TryReadHRESULT+0×3c
07731c44 66ca329e Windows_UI_Xaml!CParser::LoadXamlCore+0×5ae
07731c48 66da83d2 Windows_UI_Xaml!CCoreServices::ParseXamlWithExistingFrameworkRoot+0×100
07731c4c 66da8131 Windows_UI_Xaml!CApplication::LoadComponent+0×261
07731c50 66da7e56 Windows_UI_Xaml!Application_LoadComponent+0xaa
07731c54 66da7cfc Windows_UI_Xaml!DirectUI::FrameworkApplication::LoadComponent+0xc2
07731c58 66dab49d Windows_UI_Xaml!DirectUI::FrameworkApplicationFactory::LoadComponentWithResourceLocationImpl+0×6a
07731c5c 66dab418 Windows_UI_Xaml!DirectUI::FrameworkApplicationFactory::LoadComponentWithResourceLocation+0×28
07731c60 6c186b95*** WARNING: Unable to verify checksum for Microsoft.Msn.Weather.dll
*** ERROR: Symbol file could not be found. Defaulted to export symbols for Microsoft.Msn.Weather.dll -
Microsoft_Msn_Weather_6bb10000!RHBinder__ShimExeMain+0×1b2515
07731c64 6c186af1 Microsoft_Msn_Weather_6bb10000!RHBinder__ShimExeMain+0×1b2471
07731c68 6c199d37 Microsoft_Msn_Weather_6bb10000!RHBinder__ShimExeMain+0×1c56b7
07731c6c 6c366cd8 Microsoft_Msn_Weather_6bb10000!DllGetActivationFactory+0xaf038
07731c70 6c366c8d Microsoft_Msn_Weather_6bb10000!DllGetActivationFactory+0xaefed
07731c74 6c366b4d Microsoft_Msn_Weather_6bb10000!DllGetActivationFactory+0xaeead
07731c78 6c365b50 Microsoft_Msn_Weather_6bb10000!DllGetActivationFactory+0xadeb0
07731c7c 6c3cc1d7 Microsoft_Msn_Weather_6bb10000!DllGetActivationFactory+0×114537
07731c80 6c3cbb9a Microsoft_Msn_Weather_6bb10000!DllGetActivationFactory+0×113efa
07731c84 6c3cb9c0 Microsoft_Msn_Weather_6bb10000!DllGetActivationFactory+0×113d20
07731c88 6c35a658 Microsoft_Msn_Weather_6bb10000!DllGetActivationFactory+0xa29b8
07731c8c 6c0fd56e Microsoft_Msn_Weather_6bb10000!RHBinder__ShimExeMain+0×128eee
07731c90 6c21e3d5 Microsoft_Msn_Weather_6bb10000!RHBinder__ShimExeMain+0×249d55
07731c94 66e50d37 Windows_UI_Xaml!DirectUI::FrameworkApplicationGenerated::OnLaunchedProtected+0×47
07731c98 66e509d0 Windows_UI_Xaml!DirectUI::FrameworkView::OnActivated+0×240
07731c9c 66cf4b28 Windows_UI_Xaml!`Microsoft::WRL::Callback< Windows::Foundation::ITypedEventHandler< Windows::UI::Core::CoreWindow *,IInspectable *>,DirectUI::Page,Windows::UI::Core::ICoreWindow *,IInspectable *>’::`2′::ComObject::Invoke+0×28
07731ca0 7035361e twinapi_appcore!Microsoft::WRL::InvokeTraits<-2>::InvokeDelegates< <lambda_45dc3980e5a5ff53a9eb289d8a61b7e3>, Windows::Foundation::ITypedEventHandler< Windows::ApplicationModel::Core::CoreApplicationView *,Windows::ApplicationModel::Activation::IActivatedEventArgs *> >+0×4f
07731ca4 70353493 twinapi_appcore!Microsoft::WRL::EventSource< Windows::Foundation::ITypedEventHandler< Windows::ApplicationModel::Core::CoreApplicationView *,Windows::ApplicationModel::Activation::IActivatedEventArgs *>,Microsoft::WRL::InvokeModeOptions<-2> >::DoInvoke< <lambda_45dc3980e5a5ff53a9eb289d8a61b7e3> >+0×42
07731ca8 70342a06 twinapi_appcore!Windows::ApplicationModel::Core::CoreApplicationView::Activate+0×296
07731cac 77425ebc rpcrt4!Invoke+0×34
07731cb0 773f37e3 rpcrt4!NdrStubCall2+0×2e3
07731cb4 74efc1ce combase!CStdStubBuffer_Invoke+0xde
07731cb8 7742364c rpcrt4!CStdStubBuffer_Invoke+0×2c
07731cbc 74fb659b combase!ObjectMethodExceptionHandlingAction< <lambda_adf5d6ba83bff890864fd80ca2bbf1eb> >+0×7b
07731cc0 74f83091 combase!DefaultStubInvoke+0×211
07731cc4 74f8d59e combase!ServerCall::ContextInvoke+0×38e
07731cc8 74f8ecc5 combase!AppInvoke+0xb75
07731ccc 74f81c8c combase!ComInvokeWithLockAndIPID+0×62c
07731cd0 74f66d72 combase!CComApartment::ASTAHandleMessage+0×2c2
07731cd4 74f65bfa combase!ASTAWaitContext::Wait+0×47a
07731cd8 74fbb1b4 combase!ASTAWaitInNewContext+0×81
07731cdc 74fbb0ee combase!ASTAThreadWaitForHandles+0×4e
07731ce0 74fbaf1a combase!CoWaitForMultipleHandles+0xaa
07731ce4 7035772d twinapi_appcore!CTSimpleArray<COSTaskCompletion::TaskContext *,4294967294, CTPolicyCoTaskMem<COSTaskCompletion::TaskContext *>,CSimpleArrayStandardCompareHelper<COSTaskCompletion::TaskContext *>,CSimpleArrayStandardMergeHelper<COSTaskCompletion::TaskContext *> >::RemoveAt+0×9f
07731ce8 747d3bea SHCore!CTSimpleArray<Microsoft::WRL::ComPtr< IWindowMonitorChangeListener>,4294967294, CTPolicyCoTaskMem<Microsoft::WRL::ComPtr< IWindowMonitorChangeListener> >,CSimpleArrayStandardCompareHelper<Microsoft::WRL::ComPtr< IWindowMonitorChangeListener> >,CSimpleArrayStandardMergeHelper<Microsoft::WRL::ComPtr< IWindowMonitorChangeListener> > >::_Add<Microsoft::WRL::ComPtr< IWindowMonitorChangeListener> const &>+0×120
07731cec 75423744 kernel32!BaseThreadInitThunk+0×24
07731cf0 776d9e54 ntdll!__RtlUserThreadStart+0×2f
07731cf4 776d9e1f ntdll!_RtlUserThreadStart+0×1b
0:008> !error 80004001
Error code: (HRESULT) 0×80004001 (2147500033) - Not implemented
0:008> dps 0×077d5d4c L3c
077d5d4c 66f42bbe Windows_UI_Xaml!DirectUI::MetadataAPI::ImportClassInfo+0×2ed89e
077d5d50 66e451ce Windows_UI_Xaml!DirectUI::MetadataAPI::ImportClassInfoFromMetadataProvider+0×86
077d5d54 66c87bf9 Windows_UI_Xaml!DirectUI::MetadataAPI::GetClassInfoByTypeName+0×219
077d5d58 66c55ea0 Windows_UI_Xaml!DirectUI::MetadataAPI::GetClassInfoByXamlType+0×50
077d5d5c 66c5365d Windows_UI_Xaml!DirectUI::MetadataAPI::ImportPropertyInfo+0×8a
077d5d60 66c542a0 Windows_UI_Xaml!DirectUI::MetadataAPI::TryImportPropertyInfoFromMetadataProvider+0×9f
077d5d64 66c53f94 Windows_UI_Xaml!DirectUI::MetadataAPI::TryGetPropertyByName+0xde
077d5d68 66c564e7 Windows_UI_Xaml!XamlManagedTypeInfoProvider::ResolvePropertyName+0×47
077d5d6c 66c930c2 Windows_UI_Xaml!XamlType::GetProperty+0×1a2
077d5d70 66e3a830 Windows_UI_Xaml!XamlBinaryMetadataReader2::LoadProperty+0xb1
077d5d74 66cab9d9 Windows_UI_Xaml!XamlBinaryMetadataReader2::GetProperty+0×5c
077d5d78 66d528e0 Windows_UI_Xaml!XamlBinaryFormatSubReader2::ReadXamlProperty+0×1d0
077d5d7c 66d520cc Windows_UI_Xaml!XamlBinaryFormatSubReader2::ReadSetValueConstantNode+0×3c
077d5d80 66d53b55 Windows_UI_Xaml!XamlBinaryFormatSubReader2::TryRead+0×135
077d5d84 66d539ec Windows_UI_Xaml!XamlBinaryFormatSubReader2::TryReadHRESULT+0×3c
077d5d88 66ca329e Windows_UI_Xaml!CParser::LoadXamlCore+0×5ae
077d5d8c 66da83d2 Windows_UI_Xaml!CCoreServices::ParseXamlWithExistingFrameworkRoot+0×100
077d5d90 66da8131 Windows_UI_Xaml!CApplication::LoadComponent+0×261
077d5d94 66da7e56 Windows_UI_Xaml!Application_LoadComponent+0xaa
077d5d98 66da7cfc Windows_UI_Xaml!DirectUI::FrameworkApplication::LoadComponent+0xc2
077d5d9c 66dab49d Windows_UI_Xaml!DirectUI::FrameworkApplicationFactory::LoadComponentWithResourceLocationImpl+0×6a
077d5da0 66dab418 Windows_UI_Xaml!DirectUI::FrameworkApplicationFactory::LoadComponentWithResourceLocation+0×28
077d5da4 6c186b95 Microsoft_Msn_Weather_6bb10000!RHBinder__ShimExeMain+0×1b2515
077d5da8 6c186af1 Microsoft_Msn_Weather_6bb10000!RHBinder__ShimExeMain+0×1b2471
077d5dac 6c199d37 Microsoft_Msn_Weather_6bb10000!RHBinder__ShimExeMain+0×1c56b7
077d5db0 6c366cd8 Microsoft_Msn_Weather_6bb10000!DllGetActivationFactory+0xaf038
077d5db4 6c366c8d Microsoft_Msn_Weather_6bb10000!DllGetActivationFactory+0xaefed
077d5db8 6c366b4d Microsoft_Msn_Weather_6bb10000!DllGetActivationFactory+0xaeead
077d5dbc 6c365b50 Microsoft_Msn_Weather_6bb10000!DllGetActivationFactory+0xadeb0
077d5dc0 6c3cc1d7 Microsoft_Msn_Weather_6bb10000!DllGetActivationFactory+0×114537
077d5dc4 6c3cbb9a Microsoft_Msn_Weather_6bb10000!DllGetActivationFactory+0×113efa
077d5dc8 6c3cb9c0 Microsoft_Msn_Weather_6bb10000!DllGetActivationFactory+0×113d20
077d5dcc 6c35a658 Microsoft_Msn_Weather_6bb10000!DllGetActivationFactory+0xa29b8
077d5dd0 6c0fd56e Microsoft_Msn_Weather_6bb10000!RHBinder__ShimExeMain+0×128eee
077d5dd4 6c21e3d5 Microsoft_Msn_Weather_6bb10000!RHBinder__ShimExeMain+0×249d55
077d5dd8 66e50d37 Windows_UI_Xaml!DirectUI::FrameworkApplicationGenerated::OnLaunchedProtected+0×47
077d5ddc 66e509d0 Windows_UI_Xaml!DirectUI::FrameworkView::OnActivated+0×240
077d5de0 66cf4b28 Windows_UI_Xaml!`Microsoft::WRL::Callback< Windows::Foundation::ITypedEventHandler< Windows::UI::Core::CoreWindow *,IInspectable *>,DirectUI::Page,Windows::UI::Core::ICoreWindow *,IInspectable *>’::`2′::ComObject::Invoke+0×28
077d5de4 7035361e twinapi_appcore!Microsoft::WRL::InvokeTraits<-2>::InvokeDelegates< <lambda_45dc3980e5a5ff53a9eb289d8a61b7e3>, Windows::Foundation::ITypedEventHandler< Windows::ApplicationModel::Core::CoreApplicationView *,Windows::ApplicationModel::Activation::IActivatedEventArgs *> >+0×4f
077d5de8 70353493 twinapi_appcore!Microsoft::WRL::EventSource< Windows::Foundation::ITypedEventHandler< Windows::ApplicationModel::Core::CoreApplicationView *,Windows::ApplicationModel::Activation::IActivatedEventArgs *>,Microsoft::WRL::InvokeModeOptions<-2> >::DoInvoke< <lambda_45dc3980e5a5ff53a9eb289d8a61b7e3> >+0×42
077d5dec 70342a06 twinapi_appcore!Windows::ApplicationModel::Core::CoreApplicationView::Activate+0×296
077d5df0 77425ebc rpcrt4!Invoke+0×34
077d5df4 773f37e3 rpcrt4!NdrStubCall2+0×2e3
077d5df8 74efc1ce combase!CStdStubBuffer_Invoke+0xde
077d5dfc 7742364c rpcrt4!CStdStubBuffer_Invoke+0×2c
077d5e00 74fb659b combase!ObjectMethodExceptionHandlingAction< <lambda_adf5d6ba83bff890864fd80ca2bbf1eb> >+0×7b
077d5e04 74f83091 combase!DefaultStubInvoke+0×211
077d5e08 74f8d59e combase!ServerCall::ContextInvoke+0×38e
077d5e0c 74f8ecc5 combase!AppInvoke+0xb75
077d5e10 74f81c8c combase!ComInvokeWithLockAndIPID+0×62c
077d5e14 74f66d72 combase!CComApartment::ASTAHandleMessage+0×2c2
077d5e18 74f65bfa combase!ASTAWaitContext::Wait+0×47a
077d5e1c 74fbb1b4 combase!ASTAWaitInNewContext+0×81
077d5e20 74fbb0ee combase!ASTAThreadWaitForHandles+0×4e
077d5e24 74fbaf1a combase!CoWaitForMultipleHandles+0xaa
077d5e28 7035772d twinapi_appcore!CTSimpleArray<COSTaskCompletion::TaskContext *,4294967294, CTPolicyCoTaskMem<COSTaskCompletion::TaskContext *>,CSimpleArrayStandardCompareHelper<COSTaskCompletion::TaskContext *>,CSimpleArrayStandardMergeHelper<COSTaskCompletion::TaskContext *> >::RemoveAt+0×9f
077d5e2c 747d3bea SHCore!CTSimpleArray<Microsoft::WRL::ComPtr< IWindowMonitorChangeListener>,4294967294, CTPolicyCoTaskMem<Microsoft::WRL::ComPtr< IWindowMonitorChangeListener> >,CSimpleArrayStandardCompareHelper<Microsoft::WRL::ComPtr< IWindowMonitorChangeListener> >,CSimpleArrayStandardMergeHelper<Microsoft::WRL::ComPtr< IWindowMonitorChangeListener> > >::_Add<Microsoft::WRL::ComPtr< IWindowMonitorChangeListener> const &>+0×120
077d5e30 75423744 kernel32!BaseThreadInitThunk+0×24
077d5e34 776d9e54 ntdll!__RtlUserThreadStart+0×2f
077d5e38 776d9e1f ntdll!_RtlUserThreadStart+0×1b
0:008> ub 66f42bbe
Windows_UI_Xaml!DirectUI::MetadataAPI::ImportClassInfo+0×2ed87f:
66f42b9f 8bce mov ecx,esi
66f42ba1 e8b96ecfff call Windows_UI_Xaml!OnFailure<1354> (66c39a5f)
66f42ba6 e92d2bd1ff jmp Windows_UI_Xaml!DirectUI::MetadataAPI::ImportClassInfo+0×3b8 (66c556d8)
66f42bab 8bce mov ecx,esi
66f42bad e8ad6ecfff call Windows_UI_Xaml!OnFailure<1354> (66c39a5f)
66f42bb2 e9212bd1ff jmp Windows_UI_Xaml!DirectUI::MetadataAPI::ImportClassInfo+0×3b8 (66c556d8)
66f42bb7 8bce mov ecx,esi
66f42bb9 e8a16ecfff call Windows_UI_Xaml!OnFailure<1354> (66c39a5f)
0:008> !error 80004005
Error code: (HRESULT) 0×80004005 (2147500037) - Unspecified error
0:008> dps 0×0772df74 L19
0772df74 66bc3963 Windows_UI_Xaml!CWindowsServices::CreatePalAppChromeProxy+0×23
0772df78 66bc3912 Windows_UI_Xaml!AppChromeProxy::EnsureAppChromeProxy+0×44
0772df7c 66bc38b6 Windows_UI_Xaml!AppChromeProxy::SetThemeOverride+0xf
0772df80 66e51074 Windows_UI_Xaml!DirectUI::DXamlCore::ConfigureCoreWindow+0×95
0772df84 66e50e6f Windows_UI_Xaml!DirectUI::FrameworkView::SetWindow+0×1f
0772df88 70342def twinapi_appcore!Windows::ApplicationModel::Core::CoreApplicationView::SetWindowAndGetDispatcher + 0×20f
0772df8c 77425ebc rpcrt4!Invoke+0×34
0772df90 773f37e3 rpcrt4!NdrStubCall2+0×2e3
0772df94 74efc1ce combase!CStdStubBuffer_Invoke+0xde
0772df98 7742364c rpcrt4!CStdStubBuffer_Invoke+0×2c
0772df9c 74fb659b combase!ObjectMethodExceptionHandlingAction<
<lambda_adf5d6ba83bff890864fd80ca2bbf1eb> >+0×7b
0772dfa0 74f83091 combase!DefaultStubInvoke+0×211
0772dfa4 74f8d59e combase!ServerCall::ContextInvoke+0×38e
0772dfa8 74f8ecc5 combase!AppInvoke+0xb75
0772dfac 74f81c8c combase!ComInvokeWithLockAndIPID+0×62c
0772dfb0 74f66d72 combase!CComApartment::ASTAHandleMessage+0×2c2
0772dfb4 74f65bfa combase!ASTAWaitContext::Wait+0×47a
0772dfb8 74fbb1b4 combase!ASTAWaitInNewContext+0×81
0772dfbc 74fbb0ee combase!ASTAThreadWaitForHandles+0×4e
0772dfc0 74fbaf1a combase!CoWaitForMultipleHandles+0xaa
0772dfc4 7035772d twinapi_appcore!CTSimpleArray<COSTaskCompletion::TaskContext *,4294967294, CTPolicyCoTaskMem<COSTaskCompletion::TaskContext *>,CSimpleArrayStandardCompareHelper<COSTaskCompletion::TaskContext *>,CSimpleArrayStandardMergeHelper<COSTaskCompletion::TaskContext *> >::RemoveAt+0×9f
0772dfc8 747d3bea SHCore!CTSimpleArray<Microsoft::WRL::ComPtr< IWindowMonitorChangeListener>,4294967294, CTPolicyCoTaskMem<Microsoft::WRL::ComPtr< IWindowMonitorChangeListener> >,CSimpleArrayStandardCompareHelper<Microsoft::WRL::ComPtr< IWindowMonitorChangeListener> >,CSimpleArrayStandardMergeHelper<Microsoft::WRL::ComPtr< IWindowMonitorChangeListener> > >::_Add<Microsoft::WRL::ComPtr< IWindowMonitorChangeListener> const &>+0×120
0772dfcc 75423744 kernel32!BaseThreadInitThunk+0×24
0772dfd0 776d9e54 ntdll!__RtlUserThreadStart+0×2f
0772dfd4 776d9e1f ntdll!_RtlUserThreadStart+0×1b
0:008> ub 66bc3963
Windows_UI_Xaml!CWindowsServices::CreatePalAppChromeProxy+0×5:
66bc3945 56 push esi
66bc3946 8b7508 mov esi,dword ptr [ebp+8]
66bc3949 832600 and dword ptr [esi],0
66bc394c e83ebd2d00 call Windows_UI_Xaml!IsConfigureStatusBarDefaultsPresent (66e9f68f)
66bc3951 84c0 test al,al
66bc3953 0f856c1a4100 jne Windows_UI_Xaml!CWindowsServices::CreatePalAppChromeProxy+0×411a85 (66fd53c5)
66bc3959 be05400080 mov esi,80004005h
66bc395e e80c000000 call Windows_UI_Xaml!OnFailure<91> (66bc396f)
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
Sometimes log messages are formatted with mistakes, buffers are not cleared before copying, copied strings are truncated, tracing implementation and presentation contains coding defects. There can be internal corruption when messages are formed or “corruption” during presentation, for example, default field conversion rules (like in Excel). We call this pattern Corrupt Message. Such messages may affect trace and log analysis where data search may not show full relevant results. We then recommend to double check findings by using Data Flow of a different Message Invariant.
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
Sometimes, the presence of some messages in a trace or log shows that some other tracing or logging tool was running or that some process was also doing tracing. We call this analysis pattern Surveyor. Such discovered tracing may not be related to the trace we are looking at (compare to Trace Extension) but may help with finding additional traces in the system as illustrated in the following diagram:
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -
Recently we performed the diagnostic analysis of a software incident where certain functionality was not available to users and provided the report based on analysis patterns such as Focus of Tracing and Opposition Messages. We also conjectured some hypotheses explaining the observed abnormal behaviour. However, at the end, the problem was solved not by the analysis of a lengthy software execution log but by looking at the small configuration INI file where not working functionality was simply disabled in one line:
EnableFunctionality = 0
Even before that analysis we were thinking about the importance of Small DA+TA such as configuration files and registry details that can be considered as general software traces. Here DA+TA means Dump Artefact + Trace Artefact and Big DA+TA refers to software execution memory dump artefacts and trace artefacts that can be really huge. The analysis pattern is illustrated in the following diagram where we see no difference between working and non-working scenarios due to insufficient trace coverage (Sparse Trace):
- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -