Crash Dump Analysis Patterns (Part 13c)

Although handle leaks may result in insufficient pool memory, many drivers allocate their own private memory and specify a 4-letter ASCII tag, for example, non-paged pool from my x64 Vista workstation:

lkd> !poolused 3
   Sorting by  NonPaged Pool Consumed

  Pool Used:
            NonPaged
 Tag    Allocs    Frees     Diff     Used
 EtwB      304      134      170  6550080  Etw Buffer , Binary: nt!etw
 File 32630649 32618671    11978  3752928  File objects
 Pool       16       11        5  3363472  Pool tables, etc.
 Ntfr   204791   187152    17639  2258704  ERESOURCE , Binary: ntfs.sys
 FMsl   199039   187685    11354  2179968  STREAM_LIST_CTRL structure , Binary: fltmgr.sys
 MmCa   250092   240351     9741  2134368  Mm control areas for mapped files , Binary: nt!mm
 ViMm   135503   134021     1482  1783824  Video memory manager , Binary: dxgkrnl.sys
 Cont       53       12       41  1567664  Contiguous physical memory allocations for device drivers
 Thre    72558    71527     1031  1234064  Thread objects , Binary: nt!ps
 VoSm      872      851       21  1220544  Bitmap allocations , Binary: volsnap.sys
 NtFs  8122505  8110933    11572  1190960  StrucSup.c , Binary: ntfs.sys
 AmlH        1        0        1  1048576  ACPI AMLI Pooltags
 SaSc    20281    14820     5461  1048512  UNKNOWN pooltag ‘SaSc’, please update pooltag.txt
 RaRS     1000        0     1000   960000  UNKNOWN pooltag ‘RaRS’, please update pooltag.txt


If the pool tag is unknown the following Microsoft article KB298102 explains how to locate the corresponding driver. We can also use memory search in WinDbg to locate kernel space addresses and see what modules they correspond to. 

WinDbg shows the number of failed pool allocations and also shows a message when pool usage is nearly its maximum. Below I put some examples with possible troubleshooting hints.

Session pool

3: kd> !vm

*** Virtual Memory Usage ***
       Physical Memory:     1572637 (   6290548 Kb)
       Page File: \??\C:\pagefile.sys
         Current:   3145728 Kb  Free Space:   3001132 Kb
         Minimum:   3145728 Kb  Maximum:      3145728 Kb
       Available Pages:     1317401 (   5269604 Kb)
       ResAvail Pages:      1478498 (   5913992 Kb)
       Locked IO Pages:         114 (       456 Kb)
       Free System PTEs:     194059 (    776236 Kb)
       Free NP PTEs:          32766 (    131064 Kb)
       Free Special NP:           0 (         0 Kb)
       Modified Pages:          443 (      1772 Kb)
       Modified PF Pages:       442 (      1768 Kb)
       NonPagedPool Usage:    13183 (     52732 Kb)
       NonPagedPool Max:      65215 (    260860 Kb)

       PagedPool 0 Usage:     11328 (     45312 Kb)
       PagedPool 1 Usage:      1473 (      5892 Kb)
       PagedPool 2 Usage:      1486 (      5944 Kb)
       PagedPool 3 Usage:      1458 (      5832 Kb)
       PagedPool 4 Usage:      1505 (      6020 Kb)
       PagedPool Usage:       17250 (     69000 Kb)
       PagedPool Maximum:     65536 (    262144 Kb)

 

       ********** 3441 pool allocations have failed **********
 

       Shared Commit:          8137 (     32548 Kb)
       Special Pool:              0 (         0 Kb)
       Shared Process:         8954 (     35816 Kb)
       PagedPool Commit:      17312 (     69248 Kb)
       Driver Commit:          2095 (      8380 Kb)
       Committed pages:      212476 (    849904 Kb)
       Commit limit:        2312654 (   9250616 Kb)

Paged and non-paged pool usage is far from maximum therefore we check session pool:

3: kd> !vm 4

       Terminal Server Memory Usage By Session:
 

       Session Paged Pool Maximum is 32768K
       Session View Space Maximum is 20480K

 

       Session ID 0 @ f79a1000:
       Paged Pool Usage:        9824K
       Commit Usage:           10148K

 

       Session ID 2 @ f7989000:
       Paged Pool Usage:        1212K
       Commit Usage:            2180K

 

       Session ID 9 @ f79b5000:
       Paged Pool Usage:       32552K

 

       *** 7837 Pool Allocation Failures ***
 

       Commit Usage:           33652K

Here Microsoft article KB840342 might help.

Paged pool

We might have a direct warning:

1: kd> !vm

*** Virtual Memory Usage ***
 Physical Memory:   511881   ( 2047524 Kb)
 Page File: \??\S:\pagefile.sys
    Current:   2098176Kb Free Space:   1837740Kb
    Minimum:   2098176Kb Maximum:      2098176Kb
 Page File: \??\R:\pagefile.sys
    Current:   1048576Kb Free Space:    792360Kb
    Minimum:   1048576Kb Maximum:      1048576Kb
 Available Pages:   201353   (  805412 Kb)
 ResAvail Pages:    426839   ( 1707356 Kb)
 Modified Pages:     45405   (  181620 Kb)
 NonPagedPool Usage: 10042   (   40168 Kb)
 NonPagedPool Max:   68537   (  274148 Kb)
 PagedPool 0 Usage:  26820   (  107280 Kb)
 PagedPool 1 Usage:   1491   (    5964 Kb)
 PagedPool 2 Usage:   1521   (    6084 Kb)
 PagedPool 3 Usage:   1502   (    6008 Kb)
 PagedPool 4 Usage:   1516   (    6064 Kb)
 ********** Excessive Paged Pool Usage *****
 PagedPool Usage:    32850   (  131400 Kb)
 PagedPool Maximum:  40960   (  163840 Kb)
 Shared Commit:      14479   (   57916 Kb)
 Special Pool:           0   (       0 Kb)
 Free System PTEs:  135832   (  543328 Kb)
 Shared Process:     15186   (   60744 Kb)
 PagedPool Commit:   32850   (  131400 Kb)
 Driver Commit:       1322   (    5288 Kb)
 Committed pages:   426786   ( 1707144 Kb)
 Commit limit:     1259456   ( 5037824 Kb)

or if there is no warning we can check the size manually and if paged pool usage is close to its maximum but for non-paged pool it is not then most likely failed allocations were from paged pool:

0: kd> !vm
 

*** Virtual Memory Usage ***
       Physical Memory:     4193696 (  16774784 Kb)
       Page File: \??\C:\pagefile.sys
         Current:   4193280 Kb  Free Space:   3313120 Kb
         Minimum:   4193280 Kb  Maximum:      4193280 Kb
       Available Pages:     3210617 (  12842468 Kb)
       ResAvail Pages:      4031978 (  16127912 Kb)
       Locked IO Pages:         120 (       480 Kb)
       Free System PTEs:      99633 (    398532 Kb)
       Free NP PTEs:          26875 (    107500 Kb)
       Free Special NP:           0 (         0 Kb)
       Modified Pages:          611 (      2444 Kb)
       Modified PF Pages:       590 (      2360 Kb)
       NonPagedPool 0 Used:    8271 (   33084 Kb)
       NonPagedPool 1 Used:   13828 (   55312 Kb)
       NonPagedPool Usage:    37846 (    151384 Kb)
       NonPagedPool Max:      65215 (    260860 Kb)

       PagedPool 0 Usage:     82308 (    329232 Kb)
       PagedPool 1 Usage:     12700 (     50800 Kb)
       PagedPool 2 Usage:     25702 (    102808 Kb)
       PagedPool Usage:      120710 (    482840 Kb)
       PagedPool Maximum:    134144 (    536576 Kb)

 

      ********** 818 pool allocations have failed **********
 

       Shared Commit:         80168 (    320672 Kb)
       Special Pool:              0 (         0 Kb)
       Shared Process:        55654 (    222616 Kb)
       PagedPool Commit:     120772 (    483088 Kb)
       Driver Commit:          1890 (      7560 Kb)
       Committed pages:     1344388 (   5377552 Kb)
       Commit limit:        5177766 (  20711064 Kb)

!poolused 4 WinDbg command will sort paged pool consumption by pool tag:

0: kd> !poolused 4
   Sorting by  Paged Pool Consumed

 

  Pool Used:
            NonPaged            Paged
 Tag    Allocs     Used    Allocs     Used
 MmSt        0        0     85622 140642616     Mm section object prototype ptes , Binary: nt!mm
 Ntff        5     1040     63715 51991440      FCB_DATA , Binary: ntfs.sys

Here Microsoft article KB312362 might help.

Non-paged pool

0: kd> !vm
 

*** Virtual Memory Usage ***
       Physical Memory:      851775 (   3407100 Kb)
       Page File: \??\C:\pagefile.sys
         Current:   4190208 Kb  Free Space:   4175708 Kb
         Minimum:   4190208 Kb  Maximum:      4190208 Kb
       Available Pages:      147274 (    589096 Kb)
       ResAvail Pages:       769287 (   3077148 Kb)
       Locked IO Pages:         118 (       472 Kb)
       Free System PTEs:     184910 (    739640 Kb)
       Free NP PTEs:            110 (       440 Kb)
       Free Special NP:           0 (         0 Kb)
       Modified Pages:          168 (       672 Kb)
       Modified PF Pages:       168 (       672 Kb)
       NonPagedPool Usage:    64445 (    257780 Kb)
       NonPagedPool Max:      64640 (    258560 Kb)
       ********** Excessive NonPaged Pool Usage *****
       PagedPool 0 Usage:     21912 (     87648 Kb)
       PagedPool 1 Usage:       691 (      2764 Kb)
       PagedPool 2 Usage:       706 (      2824 Kb)
       PagedPool 3 Usage:       704 (      2816 Kb)
       PagedPool 4 Usage:       708 (      2832 Kb)
       PagedPool Usage:       24721 (     98884 Kb)
       PagedPool Maximum:    134144 (    536576 Kb)

 

       ********** 429 pool allocations have failed **********
 

       Shared Commit:          5274 (     21096 Kb)
       Special Pool:              0 (         0 Kb)
       Shared Process:         3958 (     15832 Kb)
       PagedPool Commit:      24785 (     99140 Kb)
       Driver Commit:         19289 (     77156 Kb)
       Committed pages:      646282 (   2585128 Kb)
       Commit limit:        1860990 (   7443960 Kb)

!poolused 3 WinDbg command will sort non-paged pool consumption by pool tag:

0: kd> !poolused 3
   Sorting by  NonPaged Pool Consumed

 

  Pool Used:
            NonPaged
 Tag    Allocs    Frees     Diff
 Ddk   9074558  3859522  5215036  Default for driver allocated memory (user’s of ntddk.h)
 MmCm    43787    42677     1110  Calls made to MmAllocateContiguousMemory , Binary: nt!mm
 LSwi        1        0        1  initial work context
 TCPt  3281838  3281808       30  TCP/IP network protocol , Binary: TCP

Regarding Ddk tag I published a case study earlier:

The search for ‘Ddk’ tag

The following Microsoft article KB293857 explains how we can use xpool command from old kdex2×86.dll extension which even works for Windows 2003 dumps:

0: kd> !w2kfre\kdex2x86.xpool -map
unable to get NT!MmSizeOfNonPagedMustSucceed location
unable to get NT!MmSubsectionTopPage location
unable to get NT!MmKseg2Frame location
unable to get NT!MmNonPagedMustSucceed location

Status Map of Pool Area Pages
==============================
  'O': one page in use                              ('P': paged out)
  '<': start page of contiguous pages in use        ('{': paged out)
  '>': last page of contiguous pages in use         ('}': paged out)
  '=': intermediate page of contiguous pages in use ('-': paged out)
  '.': one page not used

Non-Paged Pool Area Summary
----------------------------
Maximum Number of Pages  = 64640 pages
Number of Pages In Use   = 36721 pages (56.8%)

          +00000  +08000   +10000  +18000   +20000  +28000   +30000  +38000
82780000: ..OO.OO.OO..O.OO .O..OO.OO.OO..O. OO.O..OO.O..OO.. ..OO.O..OO.OO.OO
827c0000: .O..OO....OO..O. OO.OO.OO....OO.. O....O..OO....OO .O..OO.O..OO..O.
82800000: ..O............. ................ ................ ................
82840000: ................ ................ ................ ................
82880000: ......O.....O... ..O.O.....O..... O.....O.....O... ..O.....O.......
828c0000: ..O.........O... ......OOO.....O. ....O.....O..... O.....O.........
82900000: .O.........OO... O....O........O. ......OO........ OO.O..O.........
82940000: ...............O ..O.OO........OO ................ ...O.....O......
82980000: O.........O..O.. ....O.........O. ........O.....O. ..O.........O...
829c0000: ........O....... ..O...........O. .O..O...O..O.... ..O.........O...
82a00000: ......O..O...... O.........O..... ....O.........O. ................
82a40000: ............O... O..O.O......OO.. ......O.....O... ..O.....O...O.OO
...
...
...
893c0000: ................ ................ ................ ................
89400000: ..........=..=.. ....=.....=..... =..=......=..=.. ....=..=......=.
89440000: ..=............. ............=... =..=.....=..=... =...=.=.....==..
89480000: ....==......=.=. .........=...... ====.=.=........ ................
894c0000: ................ ................ ..........=.=... ...==...........
89500000: ..=............. ..=............. ..=............. ..=.............
89540000: ..=............. ..=............. ..=............. ..=...=.....=..=
89580000: ......=..=...... =..=......=.==== ==..==.=....=... .=....=....=.==.
895c0000: =.....==........ ..=............. =..=......=...=. ................
89600000: ........=...=..= .....=......=..= ==....=......... .........=....=.
89640000: ..=...===...=... ==......=..=..=. ..=..=......=... ......=.=.....=.
...
...
...

Here is another example:

0: kd> !vm

*** Virtual Memory Usage ***
 Physical Memory:   786299   ( 3145196 Kb)
 Page File: \??\C:\pagefile.sys
    Current:   4193280Kb Free Space:   3407908Kb
    Minimum:   4193280Kb Maximum:      4193280Kb
 Available Pages:   200189   (  800756 Kb)
 ResAvail Pages:    657130   ( 2628520 Kb)
 Modified Pages:       762   (    3048 Kb)
 NonPagedPool Usage: 22948   (   91792 Kb)
 NonPagedPool Max:   70145   (  280580 Kb)
 PagedPool 0 Usage:  19666   (   78664 Kb)
 PagedPool 1 Usage:   3358   (   13432 Kb)
 PagedPool 2 Usage:   3306   (   13224 Kb)
 PagedPool 3 Usage:   3312   (   13248 Kb)
 PagedPool 4 Usage:   3309   (   13236 Kb)
 ********** Excessive Paged Pool Usage *****
 PagedPool Usage:    32951   (  131804 Kb)
 PagedPool Maximum:  40960   (  163840 Kb)
 Shared Commit:       9664   (   38656 Kb)
 Special Pool:           0   (       0 Kb)
 Free System PTEs:  103335   (  413340 Kb)
 Shared Process:     45024   (  180096 Kb)
 PagedPool Commit:   32951   (  131804 Kb)
 Driver Commit:       1398   (    5592 Kb)
 Committed pages:   864175   ( 3456700 Kb)
 Commit limit:     1793827   ( 7175308 Kb)

0: kd> !poolused 4
   Sorting by Paged Pool Consumed

  Pool Used:
            NonPaged            Paged
 Tag    Allocs     Used    Allocs     Used
 CM         85     5440     11045 47915424
 MyAV        0        0       186 14391520

 MmSt        0        0     11795 13235744
 Obtb      709    90752      2712 11108352
 Ntff        5     1120      9886  8541504


MyAV tag seems to be the prefix for MyAVDrv module and this is hardly a coincidence. Looking at the list of drivers we see that MyAVDrv.sys was loaded and unloaded several times. Could it be that it didn’t free its non-paged pool allocations?

0: kd> lmv m MyAVDrv.sys
start    end        module name

Unloaded modules:
a5069000 a5084000   MyAVDrv.sys
    Timestamp: unavailable (00000000)
    Checksum:  00000000
a5069000 a5084000   MyAVDrv.sys
    Timestamp: unavailable (00000000)
    Checksum:  00000000
a5069000 a5084000   MyAVDrv.sys
    Timestamp: unavailable (00000000)
    Checksum:  00000000
b93e1000 b93fc000   MyAVDrv.sys
    Timestamp: unavailable (00000000)
    Checksum:  00000000
b9ae5000 b9b00000   MyAVDrv.sys
    Timestamp: unavailable (00000000)
    Checksum:  00000000
be775000 be790000   MyAVDrv.sys
    Timestamp: unavailable (00000000)
    Checksum:  00000000

Also we see that CM tag has the most allocations and !locks command shows hundreds of threads waiting for registry, an example of High Contention pattern:

0: kd> !locks

Resource @ nt!CmpRegistryLock (0x80478b00)    Shared 10 owning threads
    Contention Count = 9149810
    NumberOfSharedWaiters = 718
    NumberOfExclusiveWaiters = 21

Therefore we see at least two problems in this memory dump: excessive paged pool usage and high thread contention around registry resource slowing down if not halting the system. 

- Dmitry Vostokov @ DumpAnalysis.org -

13 Responses to “Crash Dump Analysis Patterns (Part 13c)”

  1. Dmitry Vostokov Says:

    Here is another example:

    http://blogs.msdn.com/ntdebugging/archive/2008/03/26/nonpagedpool-depletion.aspx

  2. Crash Dump Analysis » Blog Archive » Crash Dump Analysis Patterns (Part 58a) Says:

    […] Memory pattern there is so called session pool leak briefly touched in the previous kernel pool leaks post. I decided to factor it out separately because it also involves GDI handles and structures […]

  3. Crash Dump Analysis » Blog Archive » First-order and second-order memory leaks Says:

    […] Insufficient Memory (kernel pool) […]

  4. !analyze -v : Crash Dump Analysis Patterns (Part 13c) Says:

    […] Crash Dump Analysis Patterns (Part 13c) […]

  5. Crash Dump Analysis » Blog Archive » Insufficient memory, handle leak, wait chain, deadlock, inconsistent dump and overaged system: pattern cooperation Says:

    […] 2009 (0×7D9) - The Year of DebuggingIn one complete memory dump taken from the system refusing user connections but not hung completely we can see the signs of past pool allocation failures (see Insufficient Memory): […]

  6. Crash Dump Analysis » Blog Archive » Insufficient memory, handle leak, process factory, high contention and busy system: pattern cooperation Says:

    […] dump was generated for analysis. Usual !vm 4 command shows pool allocation errors and particularly insufficient session pool memory for user session […]

  7. Crash Dump Analysis » Blog Archive » Invalid pointer, incorrect stack trace, multiple exceptions, insufficient memory and memory leak: pattern cooperation Says:

    […] suspect that users cannot connect because of the lack of kernel pool resources and see the shortage of paged pool along with session pool shortage for one […]

  8. Crash Dump Analysis » Blog Archive » Icons for Memory Dump Analysis Patterns (Part 24) Says:

    […] Today we introduce an icon for Insufficient Memory (kernel pool) pattern: […]

  9. Crash Dump Analysis » Blog Archive » Reflecting on 2008 (Part 1) Says:

    […] system_thread_exception_not_handled system_thread_exception_not_handled (7e) windbg command pool allocations have failed receivelotsacalls trap frame vista dr watson bios disassembly ninjutsu uncovered citrix tools at […]

  10. Crash Dump Analysis » Blog Archive » Insufficient kernel pool memory, spiking thread and data contents locality: pattern cooperation Says:

    […] Debugging Experts Magazine Online A complete memory dump was generated from a totally unresponsive frozen system. Looking at its virtual memory stats we see the shortage of nonpaged pool (insufficient kernel pool memory pattern): […]

  11. Dmitry Vostokov Says:

    To see session pool usage you need to switch to a session process first:

    1: kd> !sprocess 3
    [...]
    PROCESS 88b0dd88 SessionId: 3 Cid: 1b90 Peb: 7ffde000 ParentCid: 1b84
    DirBase: 4072d000 ObjectTable: d8651450 HandleCount: 414.
    Image: ApplicationA.exe
    [...]

    1: kd> .process /r /p 88b0dd88
    Implicit process is now 88b0dd88
    Loading User Symbols

    1: kd> !poolused 8
    Sorting by Session Tag
    [...]

  12. Dmitry Vostokov Says:

    False positive excessive nonpaged pool memory usage messages: http://support.microsoft.com/kb/2509968

  13. Dmitry Vostokov Says:

    !poolused 5 produces the same level of detail for paged pool as !poolused 3 for nonpaged pool

Leave a Reply

You must be logged in to post a comment.