Archive for November, 2012

The Exception Point

Friday, November 23rd, 2012

This is the title of a novella to be published in Spring 2013 (ISBN: 978-1908043412). Book description:

Russia, 1908, June 30, 7:14 a.m., the court of Tsar Nicholas II is wiped out by an impact, an enormous explosion over St. Petersburg. In an ensuring chaos State Duma takes power over Imperial Russia changing the course of World history forever. Russia, 2017, an alternative history novella is published about the Tunguska event that missed the capital of Russia…

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

Bugtation No.161

Sunday, November 18th, 2012

Cyberwar industry 100 years after WWI arms and munitions profiteering. A call for 98% tax on cyberweapons.

… international cyberracketeers bent upon gaining profit through a game of cyberarming the world to cyberfight ….

Senator Gerald Nye, Nevada State Journal, October 4, 1934

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

Software Trace Analysis Patterns Domain Hierarchy

Sunday, November 18th, 2012

I get many questions on whether software log analysis patterns from Software Diagnostics Institute are OS or platform or product specific. My answer is that they are independent from all of them because they are based on viewing software logs as stories of computation and were discovered by application of narratological analysis (software narratology). In addition to these patterns there exist domain specific problem patterns such as wrong hotfix level or specific product error code during software installation or execution. Typical examples of support for such platform and product specific type of patterns include Microsoft Windows Problem Reporting and Citrix Auto Support.

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

Crash Dump Analysis Patterns (Part 187, Mac OS X)

Saturday, November 17th, 2012

Here we publish Active Thread pattern that was previously introduced in Accelerated Mac OS X Core Dump Analysis training. Basically it is a thread that is not waiting or suspended (most threads are). However, from a memory dump it is not possible to find out whether it was spiking at the dump generation time (unless we have a set of memory snapshots and in each one we have the same or similar back trace) and we don’t have any paratext with CPU consumption stats for threads. For example, in one core dump we have these threads:

(gdb) info threads
12 0x98c450ee in __workq_kernreturn ()
11 0x98c4280e in semaphore_wait_trap ()
10 0x98c448e2 in __psynch_cvwait ()
9 0×00110171 in std::_Rb_tree<int, std::pair<int const, _iCapture*>, std::_Select1st<std::pair<int const, _iCapture*> >, std::less<int>, std::allocator<std::pair<int const, _iCapture*> > >::find ()
8 0×98c428e6 in mach_wait_until ()
7 0×98c448e2 in __psynch_cvwait ()
6 0×98c427d2 in mach_msg_trap ()
5 0×98c427d2 in mach_msg_trap ()
4 0×98c428e6 in mach_wait_until ()
3 0×98c427d2 in mach_msg_trap ()
2 0×98c459ae in kevent ()
*  1 0×014bcee0 in cgGLGetLatestProfile ()

Threads #9 and #1 are not waiting so we inspect their back traces:

(gdb) bt
#0  0x014bcee0 in cgGLGetLatestProfile ()
#1  0x99060dd5 in exit ()
#2  0x001ef859 in os_exit ()
#3  0x001dc873 in luaD_precall ()
#4  0x001e7d9e in luaV_execute ()
#5  0x001dc18b in luaD_rawrunprotected ()
#6  0x001dced4 in lua_resume ()
#7  0x0058a526 in ticLuaManager::executeProgram ()
#8  0x005a09af in ticLuaScript::_execute ()
#9  0x003a6480 in darcScript::execute ()
#10 0x003af4d8 in darcTimeline::execute ()
#11 0x0034a2ba in darcSequenceur::executeAll ()
#12 0x0036904b in darcEventManager::ExecuteEventHandler ()
#13 0x003a37d2 in darcScene::process ()
#14 0x0034a2ba in darcSequenceur::executeAll ()
#15 0x0036904b in darcEventManager::ExecuteEventHandler ()
#16 0x00343ec0 in darcContext::process ()
#17 0x00347339 in darcContext::main ()
#18 0x003cf73d in darcPlayerImpl::renderOneFrame ()
#19 0x003cf078 in darcPlayerImpl::render ()
#20 0x000b1f6f in Run ()
#21 0x000b1fe9 in tiMain ()
#22 0x000c73ee in main ()

(gdb) thread 9
[Switching to thread 9 (core thread 8)]
0x00110171 in std::_Rb_tree<int, std::pair<int const, _iCapture*>, std::_Select1st<std::pair<int const, _iCapture*> >, std::less<int>, std::allocator<std::pair<int const, _iCapture*> > >::find ()

(gdb) bt
#0  0x00110171 in std::_Rb_tree<int, std::pair<int const, _iCapture*>, std::_Select1st<std::pair<int const, _iCapture*> >, std::less<int>, std::allocator<std::pair<int const, _iCapture*> > >::find ()
#1  0x0010f936 in ticVideoManager::isPaused ()
#2  0x00201801 in ticMLT_VideoCapture::Execute ()
#3  0x0020aa0b in ticModuleGraph::runOnce ()
#4  0x002632be in TrackingApp::ProcessTracking ()
#5  0x005b2f5d in ticMLTTracking::processInternal ()
#6  0x005b322d in ticMLTTracking::processThread ()
#7  0x005b36f3 in trackingThread ()
#8  0x004eaf1e in ticThread::threadFunc ()
#9  0x99023557 in _pthread_start ()
#10 0x9900dcee in thread_start ()

Windows equivalent would be a process memory dump which doesn’t have any information saved for !runaway WinDbg command.

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

Optimization Patterns

Friday, November 16th, 2012

A page to reference all different kinds of optimization patterns is necessary, so I created this post:

I’ll update it as soon as I add more similar patterns.

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

WinDbg Reference Cards Version 2 (Page 1)

Thursday, November 15th, 2012

Finally, the new version of WinDbg: A Reference Poster and Learning Cards is under development. This time every page is published online for comments, suggestions and corrections which are very welcome. The format of every page follows colored memory space diagram where red cards are for native kernel space commands, blue cards are for unmanaged user space, and green cards are for managed .NET space (click on a picture to open a PDF file):

Download page 1 PDF file

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

Trace Analysis Patterns (Part 58)

Tuesday, November 13th, 2012

Most of the time it is not possible to trace from the beginning. Obviously, internal application tracing cannot trace anything before that application start and its early initialization. The same is for system wide tracing which cannot trace before the tracing subsystem or service starts. Therefore, each log has its Visibility Limit in addition to possible truncation or missing components:

One of solutions would be to use different tracing tools and inter-correlation to glue activities, for example, Process Monitor and CDFControl.

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

Crash Dump Analysis Patterns (Part 186)

Tuesday, November 13th, 2012

Not all processes are linked into a list that some commands traverse such as !process 0 0. A processes may unlink itself or be in an initialization stage. However, a process structure is allocated from nonpaged pool and such pool can be searched for ”Proc” pool tag (unless a process changes that in memory). We call such pattern Hidden Process. For example:

0: kd> !poolfind Proc

Searching NonPaged pool (83c3c000 : 8bc00000) for Tag: Proc

*87b15000 size:  298 previous size:    0  (Free)      Pro.
*87b18370 size:  298 previous size:   98  (Allocated) Proc (Protected)
[...]
*8a35e900 size:  298 previous size:   30  (Allocated) Proc (Protected)
*8a484000 size:  298 previous size:    0  (Allocated) Proc (Protected)
*8a4a2d68 size:  298 previous size:   28  (Allocated) Proc (Protected)
[…]

One such structure is missing from active process linked list (note that it has a parent PID):

0: kd> !process 8a484000+20
PROCESS 8a484020  SessionId: 0  Cid: 05a0    Peb: 00000000  ParentCid: 0244
DirBase: bffc2200  ObjectTable: e17e6a78  HandleCount:   0.
Image: AppChild.exe
VadRoot 8a574f80 Vads 4 Clone 0 Private 3. Modified 0. Locked 0.
DeviceMap e1002898
Token                             e1a36030
ElapsedTime                       00:00:00.000
UserTime                          00:00:00.000
KernelTime                        419 Days 13:24:16.625
QuotaPoolUsage[PagedPool]         7580
QuotaPoolUsage[NonPagedPool]      160
Working Set Sizes (now,min,max)  (12, 50, 345) (48KB, 200KB, 1380KB)
PeakWorkingSetSize                12
VirtualSize                       1 Mb
PeakVirtualSize                   1 Mb
PageFaultCount                    5
MemoryPriority                    BACKGROUND
BasePriority                      8
CommitCharge                      156

No active threads

We may think that this process is zombie (note that unlike terminated processes it has a non-zero data such as VAD and object table and zero PEB and elapsed time) but inspection of its parent process thread stacks reveals that it was in the process of creation (note an attached process field):

THREAD 8a35dad8  Cid 0244.0248  Teb: 7ffdd000 Win32Thread: bc3aa688 WAIT: (Unknown) KernelMode Non-Alertable
ba971608  NotificationEvent
Impersonation token:  e2285030 (Level Impersonation)
DeviceMap                 e1a31a58
Owning Process            8a35e920       Image:         AppParent.exe
Attached Process          8a484020       Image:         AppChild.exe
Wait Start TickCount      2099           Ticks: 1 (0:00:00:00.015)
Context Switch Count      279                 LargeStack
UserTime                  00:00:00.046
KernelTime                00:00:00.046
Win32 Start Address AppParent!mainCRTStartup (0×0100d303)
Start Address kernel32!BaseProcessStartThunk (0×77e617f8)
Stack Init ba972000 Current ba971364 Base ba972000 Limit ba96e000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0
ChildEBP RetAddr
ba97137c 80833f2d nt!KiSwapContext+0×26
ba9713a8 80829c72 nt!KiSwapThread+0×2e5
ba9713f0 bad3c9db nt!KeWaitForSingleObject+0×346
[…]
ba971b94 8094cfc3 nt!MmCreatePeb+0×2cc
ba971ce4 8094d42d nt!PspCreateProcess+0×5a9
ba971d38 8088b4ac nt!NtCreateProcessEx+0×77

ba971d38 7c82845c nt!KiFastCallEntry+0xfc (TrapFrame @ ba971d64)
0006f498 7c826d09 ntdll!KiFastSystemCallRet
0006f49c 77e6cf95 ntdll!ZwCreateProcessEx+0xc
0006fcc0 7d1ec670 kernel32!CreateProcessInternalW+0×15e5
0006fd0c 01008bcf ADVAPI32!CreateProcessAsUserW+0×108

[…]

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

Surfaces in Nature

Tuesday, November 13th, 2012

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

Bugtation No.160

Friday, November 9th, 2012

Computation is short. Debugging is long. Problem is fleeting. Troubleshooting is risky. Diagnosis is difficult.

Hippocrates, Aphorisms

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

Crash Dump Analysis Patterns (Part 185)

Monday, November 5th, 2012

Similar to Network Packet Buildup pattern we also have Disk Packet Buildup. This can be detectable either through SCSI WinDbg extension or using IRP Distribution Anomaly pattern:

0: kd> .load scsikd

0: kd> !scsikd.classext
Storage class devices:

* !classext fffffa80026395b0 [1,2] SAMSUNG HS082HB Paging Disk

Usage: !classext <class device> <level [0-2]>

0: kd> !scsikd.classext fffffa80026395b0
Storage class device fffffa80026395b0 with extension at fffffa8002639700

Classpnp Internal Information at fffffa8002648010

-- dt classpnp!_CLASS_PRIVATE_FDO_DATA fffffa8002648010 --

Classpnp External Information at fffffa8002639700

SAMSUNG HS082HB NL100-01 S140JR0SA00025

Minidriver information at fffffa8002639bc0
Attached device object at fffffa80017ecda0
Physical device object at fffffa80024ab060

Media Geometry:

Bytes in a Sector = 512
Sectors per Track = 63
Tracks / Cylinder = 255
Media Length      = 80026361856 bytes = ~74 GB

-- dt classpnp!_FUNCTIONAL_DEVICE_EXTENSION fffffa8002639700 --

This is a normal case:

0: kd> !scsikd.classext fffffa80026395b0 2
Storage class device fffffa80026395b0 with extension at fffffa8002639700

Classpnp Internal Information at fffffa8002648010

Transfer Packet Engine:

Packet          Status  DL Irp          Opcode  Sector/ListId   UL Irp
--------         ------ --------         ------ --------------- --------
fffffa8002648e80  Free  fffffa800249eac0
fffffa8002644220  Free  fffffa80024aa4f0
fffffa80026898a0  Free  fffffa80019d2b30
fffffa800267ad40  Free  fffffa8001801b90
fffffa800267aa60  Free  fffffa8001835e10
fffffa8002679010  Free  fffffa80019fac40
fffffa8002679770  Free  fffffa8002679500
fffffa80027659a0  Free  fffffa8002764e10
fffffa8002790e80  Free  fffffa800267a6a0
fffffa800278f5e0  Free  fffffa80019d53c0
fffffa8002599410  Free  fffffa8002785600
fffffa80027f7490  Free  fffffa800278ea00
fffffa80027f6e80  Free  fffffa80027f6c80
fffffa80027f69a0  Free  fffffa80027f67a0
fffffa80027f64c0  Free  fffffa80027f62c0
fffffa8002dd4440  Free  fffffa80027fc600
fffffa8002dced30  Free  fffffa8002dceb30
fffffa8002dce850  Free  fffffa8002ddc010
fffffa8002ddc530  Free  fffffa8002ddc330
fffffa8002de2d30  Free  fffffa8002de2b30
fffffa8002de2850  Free  fffffa8002de2650
fffffa8002de2370  Free  fffffa8002de2170
fffffa8002ddbe80  Free  fffffa8002ddbc80
fffffa8002ddb9a0  Free  fffffa8002ddb7a0
fffffa8002dda010  Free  fffffa8002ddae10
[...]

This is not:

0: kd> !scsikd.classext fffffa80026395b0 2

Storage class device fffffa80026395b0 with extension at fffffa8002639700

Classpnp Internal Information at fffffa8002648010

Transfer Packet Engine:

Packet           Status DL Irp           Opcode Sector   UL Irp
--------         ------ --------         ------ -------- --------
fffffa80c71d9560 Queued fffffa80c71d9360   2a   03cbb948 fffffa80c4f269d0 \FileName
fffffa80c77a3360 Queued fffffa80c77a3160   2a   0400f0a8 fffffa80c59c1010 \FileName
fffffa80c6cefe60 Queued fffffa80c6cefc60   2a   0400f128 fffffa80c59c1010 \FileName
fffffa80c6e92260 Queued fffffa80c4f80010   2a   0400f1e8 fffffa80c59c1010 \FileName
fffffa80c79dbca0 Queued fffffa80c79dbaa0   2a   0400c4e8 fffffa80c59c1010 \FileName
fffffa80c83f2d90 Queued fffffa80c3b23bc0   2a   0400f168 fffffa80c59c1010 \FileName
fffffa80c4a94640 Queued fffffa80c4a94440   2a   0400d5e8 fffffa80c59c1010 \FileName
fffffa80c7984010 Queued fffffa80c7984210   2a   0400d328 fffffa80c59c1010 \FileName
fffffa80c6e52be0 Queued fffffa80c6e529e0   2a   0400f1a8 fffffa80c59c1010 \FileName
fffffa80c7afada0 Queued fffffa80c7afaba0   2a   04010268 fffffa80c59c1010 \FileName
fffffa80c7c19d90 Queued fffffa80ca2c5e10   2a   0400c628 fffffa80c59c1010 \FileName
fffffa80c6182d60 Queued fffffa80c6182b60   2a   0400f9a8 fffffa80c59c1010 \FileName
fffffa80c8695ba0 Queued fffffa80c86959a0   2a   0400d128 fffffa80c59c1010 \FileName
fffffa80c6b42b40 Queued fffffa80c6b42940   2a   0400ed28 fffffa80c59c1010 \FileName
fffffa80c5e1ab00 Queued fffffa80c5e1a900   2a   0400eee8 fffffa80c59c1010 \FileName
fffffa80c5d80a30 Queued fffffa80c4841e10   2a   0400fba8 fffffa80c59c1010 \FileName
fffffa80c48255d0 Queued fffffa80c48253d0   2a   040119e8 fffffa80c59c1010 \FileName
fffffa80c718a270 Queued fffffa80c47d0010   2a   0400d1e8 fffffa80c59c1010 \FileName
fffffa80c51a94b0 Queued fffffa80c51a92b0   2a   0400bd28 fffffa80c59c1010 \FileName
fffffa80ca280990 Queued fffffa80c52b2930   2a   0400d268 fffffa80c59c1010 \FileName
fffffa80c586f280 Queued fffffa80c551fe10   2a   0400f068 fffffa80c59c1010 \FileName
fffffa80c8413540 Queued fffffa80c544ae10   2a   04011a68 fffffa80c59c1010 \FileName
fffffa80c544ac60 Queued fffffa80c535ba90   2a   0400e7e8 fffffa80c59c1010 \FileName
fffffa80c4678010 Queued fffffa80c4678230   2a   04011168 fffffa80c59c1010 \FileName
fffffa80c9d94be0 Queued fffffa80c59205e0   2a   0400d4a8 fffffa80c59c1010 \FileName
fffffa80c5920430 Queued fffffa80c59248f0   2a   0400ea68 fffffa80c59c1010 \FileName
fffffa80c737e8f0 Queued fffffa80c737e6f0   2a   0400fee8 fffffa80c59c1010 \FileName
fffffa80c4797c60 Queued fffffa80c5d31800   2a   0400f328 fffffa80c59c1010 \FileName
fffffa80c711d270 Queued fffffa80c76ee390   2a   0400eaa8 fffffa80c59c1010 \FileName
fffffa80c872dba0 Queued fffffa80c872d9a0   2a   0400eb28 fffffa80c59c1010 \FileName
fffffa80c9e67d10 Queued fffffa80c9e67b10   2a   04012168 fffffa80c59c1010 \FileName
fffffa80ca3bb350 Queued fffffa80c66e4370   2a   0400c928 fffffa80c59c1010 \FileName
fffffa80c5894ab0 Queued fffffa80c58948b0   2a   0400c368 fffffa80c59c1010 \FileName
fffffa80c305fe60 Queued fffffa80c305fc60   2a   04013168 fffffa80c59c1010 \FileName
fffffa80c496cce0 Queued fffffa80c496cae0   2a   0400d168 fffffa80c59c1010 \FileName
fffffa80c5e78c60 Queued fffffa80c905c7f0   2a   0400f8a8 fffffa80c59c1010 \FileName
fffffa80c905c640 Queued fffffa80c5c1c410   2a   0400f428 fffffa80c59c1010 \FileName
fffffa80c68ffc40 Queued fffffa80c68ffa40   2a   0400f468 fffffa80c59c1010 \FileName
fffffa80c3aa3e60 Queued fffffa80c3aa3c60   2a   0400c7a8 fffffa80c59c1010 \FileName
fffffa80c5e8dc60 Queued fffffa80c8852cf0   2a   0400f4a8 fffffa80c59c1010 \FileName
fffffa80c90082b0 Queued fffffa80c7907440   2a   04013428 fffffa80c59c1010 \FileName
fffffa80c7907290 Queued fffffa80c67aea80   2a   0400fe68 fffffa80c59c1010 \FileName
fffffa80c67ae8d0 Queued fffffa80c9383cf0   2a   0400f3a8 fffffa80c59c1010 \FileName
fffffa80c8497010 Queued fffffa80c8497270   2a   0400c5e8 fffffa80c59c1010 \FileName
fffffa80c78c7480 Queued fffffa80c78c7280   2a   0400c3e8 fffffa80c59c1010 \FileName
fffffa80c7f37d90 Queued fffffa80c618b480   2a   0400cce8 fffffa80c59c1010 \FileName
fffffa80c618b2d0 Queued fffffa80ca2e9e10   2a   0400ee28 fffffa80c59c1010 \FileName
fffffa80ca2e9c60 Queued fffffa80c5e783f0   2a   0400d8e8 fffffa80c59c1010 \FileName
fffffa80c64e1650 Queued fffffa80c64e1450   2a   0400d0e8 fffffa80c59c1010 \FileName
fffffa80c684dd60 Queued fffffa80c684db60   2a   0400c6a8 fffffa80c59c1010 \FileName
fffffa80c3b2bac0 Queued fffffa80c3b2b8c0   2a   040127a8 fffffa80c59c1010 \FileName
fffffa80c5ff64d0 Queued fffffa80c5ff62d0   2a   0400de68 fffffa80c59c1010 \FileName
fffffa80c99a84b0 Queued fffffa80c99a82b0   2a   0400cfe8 fffffa80c59c1010 \FileName
fffffa80ca300510 Queued fffffa80ca300310   2a   0400c168 fffffa80c59c1010 \FileName
[...]

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

Software Diagnostics Training: Two Approaches

Saturday, November 3rd, 2012

Doing memory dump analysis training for more than 2 years I found that students are divided into 2 types: those who prefer to see source code first and those who want to see a memory dump first. We actually prefer to show a memory dump first and then explore it to find certain patterns of abnormal structure and behavior. Software Diagnostics Services used this approach to design its Accelerated Windows Memory Dump Analysis and Accelerated .NET Memory Dump Analysis courses. Students explore memory dumps and debugger logs to find memory dump analysis patterns which are introduced when necessary. After that they can check source code of modeling applications if they have development experience. Accelerated Windows Software Trace Analysis course uses a different approach. It introduces all software trace analysis patterns at once because they are patterns from software narratology independent from programming languages and software platforms. After that they explore and analyze software traces and logs. We can summarize these 2 approaches on this diagram:

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

Trace Analysis Patterns (Part 57)

Thursday, November 1st, 2012

Relative Density pattern describes anomalies related to the semantically related pairs of trace messages, for example, “data arrival” and “data display”. Their statement densities can be put in a ratio (also called specific gravity) and compared between working and non-working scenarios. Because the total number of trace messages cancel each other we have just mutual ratio of two message types. In our hypothetical “data” example the increased ratio of “data arrival” to “data display” messages accounts for reported visual data loss and sluggish GUI.

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