Software Diagnostics Library

“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 -

I discovered today that great IDA book was published last month:

The IDA Pro Book: The Unofficial Guide to the World’s Most Popular Disassembler

Curious about this published book I did some digging and finally ordered it because in the past I was always interested in knowing more about IDA after reading about it in some reverse engineering and disassembly books (more about them later) but was somewhat dissatisfied with IDA freeware version 4.3. The last argument in buying the book was my discovery that the new freeware version is available 4.9 which looks much better:

http://www.hex-rays.com/idapro/idadownfreeware.htm

I’ll keep investigating it for the purposes of memory dump analysis.

- Dmitry Vostokov @ DumpAnalysis.org -

Previously I wrote about security options in WinDbg but recently discovered that PEB is included with sensitive data for full user dumps despite stack and page cleaning and removing module paths. Module paths are removed indeed from lmv command output but _PEB.Ldr lists contain full module path information:

0:000> dt _PEB Ldr
ntdll!_PEB
   +0x018 Ldr : Ptr64 _PEB_LDR_DATA

0:000> dt _PEB_LDR_DATA
ntdll!_PEB_LDR_DATA
   +0x000 Length           : Uint4B
   +0x004 Initialized      : UChar
   +0x008 SsHandle         : Ptr64 Void
   +0×010 InLoadOrderModuleList : _LIST_ENTRY
   +0×020 InMemoryOrderModuleList : _LIST_ENTRY
   +0×030 InInitializationOrderModuleList : _LIST_ENTRY
   +0×040 EntryInProgress  : Ptr64 Void

0:000> !peb
PEB at 000007fffffdb000
[...]

You can see this in the dump sample saved with /r and /R options:

ftp://dumpanalysis.org/pub/LargeHeapAllocations.zip 

The only options I see currently are:

• - Custom minidumps: do not save process dumps containing full user space with /ma or /mf option for .dump command 

• - Include PEB but erase specific sections and regions pointed to like environment blocks. See the previous Data Hiding in Crash Dumps post.

• - Erase specific ASCII or UNICODE fragments manually using any binary editor. This was done for the dump file above.

• Do not send dumps but logs. See All at once: postmortem logs and dump files.

Anyway manual inspection of a dump saved with security options is recommended before sending it. 

- Dmitry Vostokov @ DumpAnalysis.org -

New cartoon from Narasimha Vedala provides insight into Dr. Debugalov’s embedded programming hobby:

Dr. Debugalov tests his new invention “BugSlasher” the fuzzy logic bug hunting robot.

- Dmitry Vostokov @ DumpAnalysis.org -

“A new” bugfix “is often a” new “error.”

Malesherbes, Pensées et maximes

- Dmitry Vostokov @ DumpAnalysis.org -

I needed to check some data structures and how they change in the case of heap memory leaks and wrote a very small C program that was allocating memory in a loop using malloc function. The VM size was growing very fast and I saved process memory dumps at 200Mb and 500Mb. When checking heap segments I noticed that they had not increased although the process was allocating 0×1000000 chunks of heap memory:

0:000> !heap 0 0
Index   Address  Name      Debugging options enabled
  1:   00260000
    Segment at 0000000000260000 to 0000000000360000 (00008000 bytes committed)
  2:   00360000
    Segment at 0000000000360000 to 0000000000370000 (00004000 bytes committed)
  3:   00440000
    Segment at 0000000000440000 to 0000000000450000 (00010000 bytes committed)
    Segment at 0000000000450000 to 0000000000550000 (00021000 bytes committed)
  4:   00560000
    Segment at 0000000000560000 to 0000000000570000 (00010000 bytes committed)
    Segment at 0000000000570000 to 0000000000670000 (0003a000 bytes committed)

I was puzzled because inspection of virtual memory showed those chunks as belonging to heap regions:

0:000> !address
[...]
    0000000009700000 : 0000000009700000 - 0000000001002000
                    Type     00020000 MEM_PRIVATE
                    Protect  00000004 PAGE_READWRITE
                    State    00001000 MEM_COMMIT
                    Usage    RegionUsageHeap
                    Handle   0000000000560000
    000000000a702000 : 000000000a702000 - 000000000000e000
                    Type     00000000
                    Protect  00000001 PAGE_NOACCESS
                    State    00010000 MEM_FREE
                    Usage    RegionUsageFree
    000000000a710000 : 000000000a710000 - 0000000001002000
                    Type     00020000 MEM_PRIVATE
                    Protect  00000004 PAGE_READWRITE
                    State    00001000 MEM_COMMIT
                    Usage    RegionUsageHeap
                    Handle   0000000000560000
    000000000b712000 : 000000000b712000 - 0000000004aee000
                    Type     00000000
                    Protect  00000001 PAGE_NOACCESS
                    State    00010000 MEM_FREE
                    Usage    RegionUsageFree
[…] 

And then I recalled that large allocations for a process heap go to a separate linked list:

0:000> !peb
PEB at 000007fffffdb000

0:000> dt _PEB 000007fffffdb000
ntdll!_PEB
[...]
   +0x0f0 ProcessHeaps     : 0×00000000`77fa3460  -> 0×00000000`00260000
[..]

0:000> dq 0×00000000`77fa3460
00000000`77fa3460  00000000`00260000 00000000`00360000
00000000`77fa3470  00000000`00440000 00000000`00560000
00000000`77fa3480  00000000`00000000 00000000`00000000
00000000`77fa3490  00000000`00000000 00000000`00000000
00000000`77fa34a0  00000000`00000000 00000000`00000000
00000000`77fa34b0  00000000`00000000 00000000`00000000
00000000`77fa34c0  00000000`00000000 00000000`00000000
00000000`77fa34d0  00000000`00000000 00000000`00000000

0:000> dt _HEAP 00000000`00260000
ntdll!_HEAP
[...]
   +0×090 VirtualAllocdBlocks : _LIST_ENTRY [ 0×00000000`00260090 - 0×260090 ]
[…]

0:000> dl 00000000`00260000+90 10 2
00000000`00260090  00000000`00260090 00000000`00260090

0:000> dl 00000000`00360000+90 10 2
00000000`00360090  00000000`00360090 00000000`00360090

0:000> dl 00000000`00440000+90 10 2
00000000`00440090  00000000`00440090 00000000`00440090

0:000> dl 00000000`00560000+90 10 2
00000000`00560090  00000000`00670000 00000000`0a710000
00000000`00670000  00000000`01680000 00000000`00560090
00000000`01680000  00000000`02690000 00000000`00670000
00000000`02690000  00000000`036a0000 00000000`01680000
00000000`036a0000  00000000`046b0000 00000000`02690000
00000000`046b0000  00000000`056c0000 00000000`036a0000
00000000`056c0000  00000000`066d0000 00000000`046b0000
00000000`066d0000  00000000`076e0000 00000000`056c0000
00000000`076e0000  00000000`086f0000 00000000`066d0000
00000000`086f0000  00000000`09700000 00000000`076e0000
00000000`09700000  00000000`0a710000 00000000`086f0000
00000000`0a710000  00000000`00560090 00000000`09700000

We see that the last process heap has large allocations directly from virtual memory, for example:

0:000> !address 00000000`0a710000
    000000000a710000 : 000000000a710000 - 0000000001002000
                    Type     00020000 MEM_PRIVATE
                    Protect  00000004 PAGE_READWRITE
                    State    00001000 MEM_COMMIT
                    Usage    RegionUsageHeap
                    Handle   0000000000560000

Actually if I used heap statistics option for !heap command I would see these large allocations:

0:000> !heap -s
LFH Key                   : 0x000000a4e8aa078c
          Heap     Flags   Reserv  Commit  Virt   Free  List   UCR  Virt  Lock  Fast
                            (k)     (k)    (k)     (k) length      blocks cont. heap
0000000000260000 00000002    1024     32     32      7     1     1    0      0   L 
0000000000360000 00008000      64     16     16     12     1     1    0      0     
0000000000440000 00001002    1088    196    196      4     1     1    0      0   LFH
Virtual block: 0000000000670000 - 0000000000670000
Virtual block: 0000000001680000 - 0000000001680000
Virtual block: 0000000002690000 - 0000000002690000
Virtual block: 00000000036a0000 - 00000000036a0000
Virtual block: 00000000046b0000 - 00000000046b0000
Virtual block: 00000000056c0000 - 00000000056c0000
Virtual block: 00000000066d0000 - 00000000066d0000
Virtual block: 00000000076e0000 - 00000000076e0000
Virtual block: 00000000086f0000 - 00000000086f0000
Virtual block: 0000000009700000 - 0000000009700000
Virtual block: 000000000a710000 - 000000000a710000
0000000000560000 00001002    1088    296    296     18     3     1   11      0   LFH


The dump file can be downloaded from FTP to play with:

ftp://dumpanalysis.org/pub/LargeHeapAllocations.zip 

- Dmitry Vostokov @ DumpAnalysis.org -

“A good” bugfix “is one that makes us wiser.”

Yuri Manin, A Course in Mathematical Logic

- Dmitry Vostokov @ DumpAnalysis.org -

Album cover and songs list from Narasimha Vedala:

DUMPSTATIC
Dr. Debugalov Feat.
Assembly Crooks and
E.I.P. Wailers.

1. Mistah Dumpstatic Feat. E.I.P Wailers.
2. Attached to your pros-ass.
3. I put a dump on you.
4. Be my debugger.
5. When push comes to shove, call Debugalov.
6. Pop ECX Feat. Assembly Crooks.
7. You corrupted my memory Feat. E.I.P Wailers.
8. Dark side of the dump.
9. Sweet Dump o’mine.
10. Optimize your soul.
11. Load address blues Feat. Assembly Crooks.
12. Good bye, Kernel.

Some music for this album will be written with the help of Dump2Wave technology Stay statically tuned to further announcements.

- Dmitry Vostokov @ DumpAnalysis.org -

Debugging “of today reminds one of the Tower of Babel, for few” engineers “can follow profitably the” internals of components “other than their own, and even there they sometimes made to feel like strangers.”

George Sarton, The Study of the History of Mathematics

- Dmitry Vostokov @ DumpAnalysis.org -

Crash dump analysis ”is anticipated with” joy, “performed with” eagerness, “and bragged about forever.”

Anonymous

- Dmitry Vostokov @ DumpAnalysis.org -

The Songs of Distant Earth is my favorite Mike Oldfield album. Highly recommended to keep optimism when doing remote debugging on different systems.

The Songs of Distant Earth

Here is my alternative track naming:

1. The Decision To Go Remote
2. Let There Be A Connection
3. Super System Crash
4. Connection Established
5. First Break In
6. The Sea Of Threads
7. Setting Breakpoints
8. Prayer For A Match
9. Lament For Users
10. The Kernel
11. Screensaver Starts
12. Tabular Output
13. The Shining Threads
14. Breakpoint Match
15. The Sunken Debugger
16. Contemplating Observations
17. A New Session

- Dmitry Vostokov @ DumpAnalysis.org -

Previously announced  Windows Debugging: Practical Foundations  book has got its front cover done in classic B/W style. A bit frightening, but shouldn’t stop if someone is determined to learn field debugging

Please let me know what do you think. Table of contents to be published next week. 

- Dmitry Vostokov @ DumpAnalysis.org -