Software Diagnostics Library

Now a bit of theory behind bugtations. If you know about semiotics you will instantly recognize bugtations as paradigmatic substitutions in quotations (syntagmatic axis). This is better illustrated on the following picture adopted from Daniel Chandler’s book Semiotics, The Basics (2nd ed., figure 3.1, page 84) using this simple bugtation created from Pythagoras famous quotation:

All bugtations are featured here:

http://www.dumpanalysis.org/Bugtations 

- Dmitry Vostokov @ DumpAnalysis.org -

“The only way to read” code “without being bored is to” browse “it at random and, having found something that interests you, close the” browser “and meditate.”

Charles-Joseph, Prince de Ligne, Mes écarts

- Dmitry Vostokov @ DumpAnalysis.org -

“Crash dumps are fossils” 

Here is the draft TOC for the previously announced book Crash Dump Analysis for System Administrators and Support Engineers (Windows Edition) which I’m co-authoring with Thomas Monahan, a Lead Escalation Engineer at Citrix Systems:

Table of Contents

 - Dmitry Vostokov @ DumpAnalysis.org -

Another pattern that logically flows from Tool Chain is called Tool Box. Their principal difference is that the former launches subordinated tools in a sequence to reach the common goal and the latter is the tool that launches other tools in any sequence independently:

Often tool boxes are implemented as toolbars. Another boundary example is the so called resource kit tools where an HTML page or taskbar menu serves the role of tool box.

- Dmitry Vostokov @ DumpAnalysis.org -

Opentask plans to publish full-color children’s book series called “Baby Turing”:

• Title: Baby Turing
• Authors: Alexandra Vostokova, Dmitry Vostokov
• Publisher: Opentask (01 November 2008)
• Language: English
• Product Dimensions: 21.6 x 21.6
• ISBN-13: 978-1-906717-26-1
• Paperback: 16 pages

- Dmitry Vostokov @ DumpAnalysis.org -

Comments “are not” code.

Gertrude Stein, The Autobiography of Alice B. Toklas

- Dmitry Vostokov @ DumpAnalysis.org -

“You can take better care of your” code “than another can.”

Ralph Waldo Emerson, Journals

- Dmitry Vostokov @ DumpAnalysis.org -

“One can best feel in dealing with” systems “how primitive” debugging “still is.”

Albert Einstein, Communication to Leó Szilárd

- Dmitry Vostokov @ DumpAnalysis.org -

Dealing with a problem today where NTSD failed to save a dump file either because of improper configuration for a default postmortem debugger or for other reasons I advised to use ADPlus from Debugging Tools for Windows in crash mode but found that I haven’t yet written about it. In the past I didn’t recommend ADPlus because no one wanted to install something extra on production environments. 

I had to show how ADPlus works for crashes because the usual Microsoft article was too big for an immediate grasp:

How to use ADPlus to troubleshoot “hangs” and “crashes”

Here is the quick polished tutorial: 

1. Download and install Debugging Tools for Windows appropriate for your application or service platform. For example, if your service is 32-bit but runs on x64 you need to download 32-bit package. Refer to http://www.windbg.org for quick download links.

2. Get ready for the test and download TesDefaultDebugger package.

3. Open a command prompt elevated as Administrator and cd to Debugging Tools for Windows installation folder.

4. Run ADPlus command:

5. Skip any warnings related to script interpreter if any:

6. Another command line window appears with ADPlus switches:

7. Close it, go back to the first command line window we used to launch-test ADPlus and type this command:

ADPlus -crash -pn TestDefaultDebugger64.exe

8. Skip warnings from step 5 if any and the symbol path warning if it appears too:

9. The second command line window is opened with the following expected output because we didn’t run TestDefaultDebugger64.exe:

10. Close it and launch TestDefaultDebugger64.exe from the package downloaded in step 2:

11. Go back to the first command line window and repeat the command from step 7. You can also specify PID by -p <PID> instead of -pn <Name> option. Skip warnings from steps 5 and 8 if any and you would see the following message showing where ADPlus will store logs and memory dumps if any:

There are also 2 additional command line windows appear. One is showing which PID the debugger was attached to:

and the other showing the output of attached console debugger, CDB by default:

12. We can dismiss the message from the previous step and wait for the crash to occur when we push the big button on TestDefaultDebugger window from step 10. We see the crash instantaneously in debugger console window if it is still running:

The following message box might appear and that depends on AEDebug registry key and WER settings which are beyond the scope of this post:

In case it appears you can simply choose to close the program.

13. That’s it. All files appear in this folder:

C:\Program Files\Debugging Tools for Windows 64-bit\Crash_Mode__Date_09-12-2008__Time_16-55-5151:

- Dmitry Vostokov @ DumpAnalysis.org -

Usually after writing and using a tool we think about an extension of it or we find another tool that is suitable as that extension. In such cases it is better to reuse existing components and adapt the former tool to use the latter. Tool Chain is a good pattern name here. A programming analogy could be a compiler and linker:

Typical example could be a logging tool that now acquires log viewer functionality by implementing a button that launches a separate log viewer or vice versa, a log viewer that can now do logging. Another simple example is a command file that launches different tools in a sequence. The tools might not be related by the data they produce and operate upon: this not the same as well-known architectural Filters and Pipes pattern. What is important is the fact that tools are related buy overall tool chain goal, for example, to debug problems by recording and analyzing log files or monitor some process activity and periodically create memory dumps:

- Dmitry Vostokov @ DumpAnalysis.org -

Last week I noticed this book on Amazon and I would have passed over it if I didn’t discover 2600 magazine when browsing Microsoft Encyclopedia of Security a few months ago This morning it arrived in post and I’m looking forward reading it during my lunch time. Anthology books are well suited for such breaks because articles are not long and usually self sufficient to learn about something discrete:

The Best of 2600: A Hacker Odyssey

- Dmitry Vostokov @ DumpAnalysis.org -

“I like people who can do” debugging.

Ralph Waldo Emerson, Journals

- Dmitry Vostokov @ DumpAnalysis.org -

New cartoon and a word “bugxorcist” from Narasimha Vedala (click on it to enlarge):

Bugs At The Gate

- Dmitry Vostokov @ DumpAnalysis.org -

“Crash dumps are fossils” of computations.

Thomas Monahan and Dmitry Vostokov, Crash Dump Analysis for System Administrators and Support Engineers (Chapter 1: The Origin of Crash Dumps)

- Dmitry Vostokov @ DumpAnalysis.org -

Dynamic memory allocation architecture usually consists of different layers where the lower layers provide support for the upper ones and some general layers can be combined or omitted like in TCP/IP implementation of OSI reference model:

• 1a. Custom memory management library.

• 1b. Runtime language support (malloc/free, new/delete, gc).

• 1c. OS dynamic memory support (HeapAlloc/HeapFree, ExAllocatePool/ExFreePool).

• 2. OS virtual and/or segmented memory infrastructure support (VirtualAlloc/VirtualFree).

• 3. OS hardware memory layer and storage support.

We can call it DMI (Dynamic Memory Infrastructure) and this can be summarized on the following diagram:

First-order memory leaks happen when an application uses layers 1a, 1b or 1c and doesn’t free allocated memory. Typical pattern examples include:

• Memory Leak (process heap)
• Memory Leak (.NET heap)
• Insufficient Memory (kernel pool)
• Insufficient Memory (handle leak)

What we cover here are second-order leaks in layers 2 an 3. These include cases when an application frees memory but the underlying supporting layer doesn’t due to its design or factors like fragmentation. Consider an example of a Windows service that undergone committed memory increase from 600Mb to almost 1.2Gb during peak hours and then remained at that size even when no activity happened afterwards. We can examine virtual memory statistics using !address WinDbg command from 3 sampled memory dumps:

Before peak hours:

-------------------- Usage SUMMARY --------------------------
    TotSize (      KB)   Pct(Tots) Pct(Busy)   Usage
    734d000 (  118068) : 05.63%    07.50%    : RegionUsageIsVAD
   1ff11000 (  523332) : 24.96%    00.00%    : RegionUsageFree
    4352000 (   68936) : 03.29%    04.38%    : RegionUsageImage
    5a00000 (   92160) : 04.39%    05.86%    : RegionUsageStack
      5a000 (     360) : 00.02%    00.02%    : RegionUsageTeb
   4efe3000 ( 1294220) : 61.72%    82.24%    : RegionUsageHeap
          0 (       0) : 00.00%    00.00%    : RegionUsagePageHeap
       1000 (       4) : 00.00%    00.00%    : RegionUsagePeb
       1000 (       4) : 00.00%    00.00%    : RegionUsageProcessParametrs
       1000 (       4) : 00.00%    00.00%    : RegionUsageEnvironmentBlock
       Tot: 7fff0000 (2097088 KB) Busy: 600df000 (1573756 KB)

-------------------- Type SUMMARY --------------------------
    TotSize (      KB)   Pct(Tots)  Usage
   1ff11000 (  523332) : 24.96%   : <free>
    4352000 (   68936) : 03.29%   : MEM_IMAGE
     b78000 (   11744) : 00.56%   : MEM_MAPPED
   5b215000 ( 1493076) : 71.20%   : MEM_PRIVATE

-------------------- State SUMMARY --------------------------
    TotSize (      KB)   Pct(Tots)  Usage
   25e50000 (  620864) : 29.61%   : MEM_COMMIT
   1ff11000 (  523332) : 24.96%   : MEM_FREE
   3a28f000 (  952892) : 45.44%   : MEM_RESERVE

During peak hours:

-------------------- Usage SUMMARY --------------------------
  TotSize ( KB) Pct(Tots) Pct(Busy) Usage
  734d000 ( 118068) : 05.63% 07.49% : RegionUsageIsVAD
  1fd0f000 ( 521276) : 24.86% 00.00% : RegionUsageFree
  4352000 ( 68936) : 03.29% 04.37% : RegionUsageImage
  5c00000 ( 94208) : 04.49% 05.98% : RegionUsageStack
  5c000 ( 368) : 00.02% 00.02% : RegionUsageTeb
4efe3000 ( 1294220) : 61.72% 82.13% : RegionUsageHeap
  0 ( 0) : 00.00% 00.00% : RegionUsagePageHeap
  1000 ( 4) : 00.00% 00.00% : RegionUsagePeb
  1000 ( 4) : 00.00% 00.00% : RegionUsageProcessParametrs
  1000 ( 4) : 00.00% 00.00% : RegionUsageEnvironmentBlock
  Tot: 7fff0000 (2097088 KB) Busy: 602e1000 (1575812 KB)

-------------------- Type SUMMARY --------------------------
  TotSize ( KB) Pct(Tots) Usage
  1fd0f000 ( 521276) : 24.86% :
  4352000 ( 68936) : 03.29% : MEM_IMAGE
  b78000 ( 11744) : 00.56% : MEM_MAPPED
  5b417000 ( 1495132) : 71.30% : MEM_PRIVATE

-------------------- State SUMMARY --------------------------
  TotSize ( KB) Pct(Tots) Usage
41498000 ( 1069664) : 51.01% : MEM_COMMIT
  1fd0f000 ( 521276) : 24.86% : MEM_FREE
  1ee49000 ( 506148) : 24.14% : MEM_RESERVE

After peak hours:

-------------------- Usage SUMMARY --------------------------
    TotSize (      KB)   Pct(Tots) Pct(Busy)   Usage
    734d000 (  118068) : 05.63%    07.49%    : RegionUsageIsVAD
   1fd0f000 (  521276) : 24.86%    00.00%    : RegionUsageFree
    4352000 (   68936) : 03.29%    04.37%    : RegionUsageImage
    5c00000 (   94208) : 04.49%    05.98%    : RegionUsageStack
      5c000 (     368) : 00.02%    00.02%    : RegionUsageTeb
   4efe3000 ( 1294220) : 61.72%    82.13%    : RegionUsageHeap
          0 (       0) : 00.00%    00.00%    : RegionUsagePageHeap
       1000 (       4) : 00.00%    00.00%    : RegionUsagePeb
       1000 (       4) : 00.00%    00.00%    : RegionUsageProcessParametrs
       1000 (       4) : 00.00%    00.00%    : RegionUsageEnvironmentBlock
       Tot: 7fff0000 (2097088 KB) Busy: 602e1000 (1575812 KB)

-------------------- Type SUMMARY --------------------------
    TotSize (      KB)   Pct(Tots)  Usage
   1fd0f000 (  521276) : 24.86%   : <free>
    4352000 (   68936) : 03.29%   : MEM_IMAGE
     b78000 (   11744) : 00.56%   : MEM_MAPPED
   5b417000 ( 1495132) : 71.30%   : MEM_PRIVATE

-------------------- State SUMMARY --------------------------
    TotSize (      KB)   Pct(Tots)  Usage
   4505d000 ( 1130868) : 53.93%   : MEM_COMMIT
   1fd0f000 (  521276) : 24.86%   : MEM_FREE
   1b284000 (  444944) : 21.22%   : MEM_RESERVE

We see that in every memory dump the amount of process heap is the same 1.2Gb but during peak hours the amount of committed memory increased by 20% and remained the same even after. At the same time if we look at process heap statistics we would see the increase of free heap KB and blocks and this means that allocated memory was freed after peak hours but underlying virtual memory ranges were not decommitted and fragmentation increased by 25%.

Before peak hours:

0:000> !heap -s
LFH Key : 0x07262959
  Heap     Flags   Reserv  Commit  Virt   Free  List   UCR  Virt  Lock  Fast
                    (k)     (k)    (k)     (k) length      blocks cont. heap
[...]
00310000 00001002 1255320 512712 1177236 260583 45362 41898 2 3751a5 L
  External fragmentation 50 % (45362 free blocks)
  Virtual address fragmentation 56 % (41898 uncommited ranges)
  Lock contention 3625381
[…]

During peak hours:

0:000> !heap -s
LFH Key : 0x07262959
  Heap     Flags   Reserv  Commit  Virt   Free  List   UCR  Virt  Lock  Fast
                    (k)     (k)    (k)     (k) length      blocks cont. heap
[...]
00310000 00001002 1255320 961480 1249548 105378 0 16830 2 453093 L
  Virtual address fragmentation 23 % (16830 uncommited ranges)
  Lock contention 4534419
[…]

After peak hours:

0:000> !heap -s
LFH Key : 0x07262959
  Heap     Flags   Reserv  Commit  Virt   Free  List   UCR  Virt  Lock  Fast
                    (k)     (k)    (k)     (k) length      blocks cont. heap
[...]
00310000 00001002 1255320 1022648 1224344 772682 264787 17512 2 580634 L
  External fragmentation 75 % (264787 free blocks)
  Virtual address fragmentation 16 % (17512 uncommited ranges)
  Lock contention 5768756
[…]

Another example would be custom memory management library that by design never releases virtual memory allocated to accommodate the increased number of allocation requests after all of them are freed.

- Dmitry Vostokov @ DumpAnalysis.org -

“A perfectly healthy” program “, it is true, is extremely rare.”

Henry David Thoreau, The Journal of Henry D. Thoreau

- Dmitry Vostokov @ DumpAnalysis.org -

New cartoon from Narasimha Vedala (click on it to enlarge):

Bugs Trying To Bell The Cat…

- Dmitry Vostokov @ DumpAnalysis.org -

Previously we discussed High Contention pattern in kernel mode involving executive resources. The same pattern can be observed in user space involving critical sections guarding shared regions like serialized process heap or a memory database, for example, in one Windows service process during increased workload:

0:000> !locks

CritSec +310608 at 00310608
WaiterWoken        No
LockCount          6
RecursionCount     1
OwningThread       d9c
EntryCount         0
ContentionCount    453093
*** Locked

CritSec +8f60f78 at 08f60f78
WaiterWoken        No
LockCount          8
RecursionCount     1
OwningThread       d9c
EntryCount         0
ContentionCount    af7f0
*** Locked

CritSec +53bf8f10 at 53bf8f10
WaiterWoken        No
LockCount          0
RecursionCount     1
OwningThread       1a9c
EntryCount         0
ContentionCount    e
*** Locked

Scanned 7099 critical sections

Looking at the owning thread we see that contention involves process heap: 

0:000> ~~[d9c]kL
ChildEBP RetAddr 
0e2ff9d4 7c81e845 ntdll!RtlpFindAndCommitPages+0×14e
0e2ffa0c 7c81e4ef ntdll!RtlpExtendHeap+0xa6
0e2ffc38 7c3416b3 ntdll!RtlAllocateHeap+0×645
0e2ffc78 7c3416db msvcr71!_heap_alloc+0xe0
0e2ffc80 7c3416f8 msvcr71!_nh_malloc+0×10
0e2ffc8c 672e14fd msvcr71!malloc+0xf
0e2ffc98 0040bc28 dll!MemAlloc+0xd
[…]
0e2fff84 7c349565 dll!WorkItemThread+0×152
0e2fffb8 77e6608b msvcr71!_endthreadex+0xa0
0e2fffec 00000000 kernel32!BaseThreadStart+0×34

However two critical section addresses belong to the same heap: 

0:000> !address 00310608
    00310000 : 00310000 - 00010000
                    Type     00020000 MEM_PRIVATE
                    Protect  00000004 PAGE_READWRITE
                    State    00001000 MEM_COMMIT
                    Usage    RegionUsageHeap
                    Handle   00310000

0:000> !address 08f60f78
    08f30000 : 08f30000 - 00200000
                    Type     00020000 MEM_PRIVATE
                    Protect  00000004 PAGE_READWRITE
                    State    00001000 MEM_COMMIT
                    Usage    RegionUsageHeap
                    Handle   00310000

Lock contention is confirmed in heap statistics as well: 

0:000> !heap -s
LFH Key                   : 0x07262959
  Heap     Flags   Reserv  Commit  Virt   Free  List   UCR  Virt  Lock  Fast
                    (k)     (k)    (k)     (k) length      blocks cont. heap
00140000 00000002    8192   2876   3664    631   140    46    0     1e   L 
    External fragmentation  21 % (140 free blocks)
00240000 00008000      64     12     12     10     1     1    0      0     
Virtual block: 0ea20000 - 0ea20000 (size 00000000)
Virtual block: 0fa30000 - 0fa30000 (size 00000000)
00310000 00001002 1255320 961480 1249548 105378     0 16830    2 453093   L 
    Virtual address fragmentation  23 % (16830 uncommited ranges)
    Lock contention  4534419
003f0000 00001002      64     36     36      0     0     1    0      0   L 
00610000 00001002      64     16     16      4     2     1    0      0   L
[…]

- Dmitry Vostokov @ DumpAnalysis.org -

After writing about large heap allocations I updated the sample chapter for Windows Debugging Notebook:

Draft Sample Chapter

- Dmitry Vostokov @ DumpAnalysis.org -

Engineers’ source codes “reveal their characters.”

Luc de Clapiers, marquis de Vauvenargues, Reflexions and Maximes

- Dmitry Vostokov @ DumpAnalysis.org -