Pool が枯渇した場合の調査方法

 

こんにちは。プラットフォーム サポートの大貫です。

今回は、Pool が枯渇する現象のトラブル シューティングについてお話したいと思います。

Pool の説明やトラブル シューティングなどについては、以下のブログでも紹介されています。

- リソース不足について - 第 1 回

- リソース不足について - 第 2 回

- リソース不足について - 第 3 回

この内容を踏まえて、Pool が枯渇している環境をデバックしてみます。調査する環境は、2 つあります。環境は Windows 7 です。

まずは、ひとつ目の環境から。

- 環境 1 – Paged Pool 枯渇

 まずは、!vm コマンドを実行します。この結果から Paged Pool の枯渇が確認でき、かなりの回数の Pool の確保が失敗しています。

 

1: kd> !vm 5

*** Virtual Memory Usage ***

Physical Memory: 524174 ( 2096696 Kb)

Page File: \??\C:\pagefile.sys

Current: 2096696 Kb Free Space: 2096692 Kb

Minimum: 2096696 Kb Maximum: 6290088 Kb

Available Pages: 425421 ( 1701684 Kb)

ResAvail Pages: 484901 ( 1939604 Kb)

Locked IO Pages: 0 ( 0 Kb)

Free System PTEs: 2680 ( 10720 Kb)

Modified Pages: 4455 ( 17820 Kb)

Modified PF Pages: 4401 ( 17604 Kb)

NonPagedPool Usage: 11089 ( 44356 Kb)

NonPagedPool Max: 385022 ( 1540088 Kb)

PagedPool 0 Usage: 425939 ( 1703756 Kb)

PagedPool 1 Usage: 2408 ( 9632 Kb)

PagedPool 2 Usage: 59 ( 236 Kb)

PagedPool 3 Usage: 45 ( 180 Kb)

PagedPool 4 Usage: 93 ( 372 Kb)

PagedPool Usage: 428544 ( 1714176 Kb) <<< 大きな値を示しています。

PagedPool Maximum: 523264 ( 2093056 Kb)

********** 34553 pool allocations have failed ********** <<< 34553 回 Pool の確保に失敗しています。

Shared Commit: 6605 ( 26420 Kb)

Special Pool: 0 ( 0 Kb)

Shared Process: 1692 ( 6768 Kb)

PagedPool Commit: 428544 ( 1714176 Kb)

Driver Commit: 1857 ( 7428 Kb)

Committed pages: 516797 ( 2067188 Kb)

Commit limit: 1048348 ( 4193392 Kb)

Terminal Server Memory Usage By Session:

Session ID 0 @ 8fe87000:

Paged Pool Usage: 2740K

Commit Usage: 5296K

Session ID 1 @ 8fe9a000:

Paged Pool Usage: 13908K

Commit Usage: 16492K

 

では、なぜ Pool が枯渇しているのでしょうか？

どの Tag で大量に Paged Pool が確保されているかを確認すると、Tag "MSKK" で Paged Pool が確保されていることが確認できます。

 

1: kd> !poolused 4

Sorting by Paged Pool Consumed

Pool Used:

NonPaged Paged

Tag Allocs Used Allocs Used

MSKK 0 0 415447 1701670912 UNKNOWN pooltag 'MSKK', please update pooltag.txt

CM31 0 0 5555 24899584 Internal Configuration manager allocations , Binary: nt!cm

CM25 0 0 2026 8814592 Internal Configuration manager allocations , Binary: nt!cm

CIcr 0 0 1295 2990224 Code Integrity allocations for image integrity checking , Binary: ci.dll

MmRe 0 0 401 2765280 ASLR relocation blocks , Binary: nt!mm

ClfI 0 0 19 1782880 CLFS Log marshal buffer lookaside list , Binary: clfs.sys

MmSt 0 0 664 1268752 Mm section object prototype ptes , Binary: nt!mm

VmbK 51 403064 8 876544 Volume Manager Extension , Binary: volmgrx.sys

 

次に、この Tag がどのドライバで確保されているのかを確認します。

確認するには、”!for_each_module” コマンドを使い、各モジュールのアドレス領域から "MSKK" タグを検索します。

 

1: kd> !for_each_module s -a @#Base @#End "MSKK"

83184218 4d 53 4b 4b 67 00 46 00-69 00 6c 00 65 00 49 00 MSKKg.F.i.l.e.I.

9196b324 4d 53 4b 4b 68 00 10 00-00 6a 01 ff 15 10 90 96 MSKKh....j......

 

2 箇所で MSKK という文字列が確認できました。

では、本当に上記箇所で Tag "MSKK" を使用して、Pool を確保しているのかを確認しましょう。

最初のアドレスを見ると、以下のような結果になり Pool を確保している形跡は見当たりません。

 

1: kd> u 83184218-1

nt!KdpBreakpointTable+0x1ff:

83184217 004d53 add byte ptr [ebp+53h],cl

8318421a 4b dec ebx

8318421b 4b dec ebx

8318421c 67004600 add byte ptr [bp+0],al

83184220 69006c006500 imul eax,dword ptr [eax],65006Ch

83184226 49 dec ecx

83184227 006e00 add byte ptr [esi],ch

8318422a 66006f00 add byte ptr [edi],ch

 

では、次のアドレスを見てみます。すると、引数を 3 つスタックに積み、関数を呼び出していることが確認できます。

 

1: kd> u 9196b324-1

SIoctl+0x4323:

9196b323 684d534b4b push 4B4B534Dh

9196b328 6800100000 push 1000h

9196b32d 6a01 push 1

9196b32f ff1510909691 call dword ptr [SIoctl+0x2010 (91969010)]

9196b335 4e dec esi

9196b336 75eb jne SIoctl+0x4323 (9196b323)

9196b338 cc int 3

9196b339 eb07 jmp SIoctl+0x4342 (9196b342)

 

呼び出している関数を確認してみます。すると、呼び出しているのは、ExAllocatePoolWithTag 関数であることが確認できます。

 

1: kd> ln poi(91969010)

(82f37bab) nt!ExAllocatePoolWithTag | (82f38660) nt!ExDeferredFreePool

Exact matches:

nt!ExAllocatePoolWithTag (_POOL_TYPE, unsigned long, unsigned long)

ExAllocatePoolWithTag 関数は、以下のように定義されています。

PVOID ExAllocatePoolWithTag(

IN POOL_TYPE PoolType,

IN SIZE_T NumberOfBytes,

IN ULONG Tag               

);

 

そうすると、引数は以下のように渡されていることがわかります。

第一引数 1

第二引数 0x1000

第三引数 4B4B534Dh

 

DDK のドキュメントを確認すると、POOL_TYPE は以下のように定義されていますので、第一引数では、Paged Pool が指定されていることが確認できます。

 

typedef enum _POOL_TYPE {

NonPagedPool,

PagedPool,

NonPagedPoolMustSucceed,

DontUseThisType,

NonPagedPoolCacheAligned,

PagedPoolCacheAligned,

NonPagedPoolCacheAlignedMustS

} POOL_TYPE;

 

第二引数では、サイズとして 0x1000 バイト確保するように引数が渡されています。

第三引数は Tag です。では、Tag を確認します。すると、"MSKK" という文字列であることが確認できます。

 

1: kd> .formats 4B4B534Dh

Evaluate expression:

Hex: 4b4b534d

Decimal: 1263227725

Octal: 11322651515

Binary: 01001011 01001011 01010011 01001101

Chars: KKSM

Time: Tue Jan 12 01:35:25 2010

Float: low 1.33251e+007 high 0

Double: 6.24117e-315

 

では、この処理をしているモジュールを確認します。アドレス 9196b324 が含まれることが分かっているので、この領域を含むドライバを出力します。

 

1: kd> lmva 9196b324

start end module name

91967000 9196f000 SIoctl (no symbols)

Loaded symbol image file: SIoctl.sys

Image path: SIoctl.sys

Image name: SIoctl.sys

Timestamp: Mon Apr 12 18:37:08 2010 (4BC2E9C4)

CheckSum: 000106CF

ImageSize: 00008000

Translations: 0000.04b0 0000.04e4 0409.04b0 0409.04e4

 

この結果から、SIoctl.sys が Paged Pool を確保していることが確認できます。この場合は、このモジュールの製造元に確認していただく必要があり、なぜ、こんなに確保するのかなどを確認するのか、問題があれば修正することで問題は解決です。

  

次に、2 つめの環境を Debug してみます。

- 環境 2 – NonPaged Pool 枯渇

まずは、何はともあれ、!vm コマンドを実行します。この結果からみると、NonPaged Pool が大きく消費されているように見えます。

 

1: kd> !vm 5

*** Virtual Memory Usage ***

Physical Memory: 524174 ( 2096696 Kb)

Page File: \??\C:\pagefile.sys

Current: 2096696 Kb Free Space: 1996300 Kb

Minimum: 2096696 Kb Maximum: 6290088 Kb

Available Pages: 71341 ( 285364 Kb)

ResAvail Pages: 124674 ( 498696 Kb)

Locked IO Pages: 0 ( 0 Kb)

Free System PTEs: 23357 ( 93428 Kb)

Modified Pages: 1919 ( 7676 Kb)

Modified PF Pages: 1831 ( 7324 Kb)

NonPagedPool Usage: 384704 ( 1538816 Kb) <<<< 非常に大きくなっている

NonPagedPool Max: 385022 ( 1540088 Kb)

********** Excessive NonPaged Pool Usage *****

PagedPool 0 Usage: 37001 ( 148004 Kb)

PagedPool 1 Usage: 2297 ( 9188 Kb)

PagedPool 2 Usage: 291 ( 1164 Kb)

PagedPool 3 Usage: 231 ( 924 Kb)

PagedPool 4 Usage: 264 ( 1056 Kb)

PagedPool Usage: 40084 ( 160336 Kb)

PagedPool Maximum: 523264 ( 2093056 Kb)

********** 196 pool allocations have failed ********** <<<< Pool の確保も失敗している

Shared Commit: 6286 ( 25144 Kb)

Special Pool: 0 ( 0 Kb)

Shared Process: 1536 ( 6144 Kb)

PagedPool Commit: 40100 ( 160400 Kb)

Driver Commit: 1813 ( 7252 Kb)

Committed pages: 740898 ( 2963592 Kb)

Commit limit: 1048348 ( 4193392 Kb)

Terminal Server Memory Usage By Session:

Session ID 0 @ 9008b000:

Paged Pool Usage: 3620K

Commit Usage: 6176K

Session ID 1 @ 90092000:

Paged Pool Usage: 15680K

Commit Usage: 18272K

 

では、どの Tag で消費しているのか確認します。NonPaged Pool が枯渇しているので、NonPaged Pool でソートします。この結果から、Tag "Thre" で NonPaged Pool が大量に確保されていることが確認できます。

 

1: kd> !poolused 2

Sorting by NonPaged Pool Consumed

Pool Used:

NonPaged Paged

Tag Allocs Used Allocs Used

Thre 1908328 1419794592 0 0 Thread objects , Binary: nt!ps

nVsC 519 1474176 0 0 UNKNOWN pooltag 'nVsC', please update pooltag.txt

Pool 5 1156680 0 0 Pool tables, etc.

Mm 9 595712 3 88 general Mm Allocations , Binary: nt!mm

EtwB 71 577960 6 135200 Etw Buffer , Binary: nt!etw

netv 2065 323664 1 128 UNKNOWN pooltag 'netv', please update pooltag.txt

:

:

 

では、なぜ、こんなに大量に Tag "Thre" で NonPaged Pool が確保されるのでしょうか？

まず、Tag "Thre" は何をしめすものなのでしょうか？ !Poolused コマンドの結果にありますように、Tag "Thre" は Thread Object を示します。ということは、大量に Thread が作られているということになります。

 

次に、Tag "Thre" で確保された Pool のサンプルを取得してみます。

 

1: kd> !poolfind Thre 0

Scanning large pool allocation table for Tag: Thre

Scanning large pool allocation table for Tag: Thre (8a957000 : 8aa57000)

*89bc1b48 size: 2d8 previous size: 68 (Allocated) Thre (Protected)

*8a140a60 size: 2e8 previous size: 180 (Allocated) Thre (Protected)

*8a625180 size: 2e8 previous size: 60 (Allocated) Thre (Protected)

*9dd7c178 size: 2e8 previous size: a8 (Allocated) Thre (Protected)

*9dd7c460 size: 2e8 previous size: 2e8 (Allocated) Thre (Protected)

:

:

*82945000 size: 2e8 previous size: 0 (Allocated) Thre (Protected)

*82945460 size: 2e8 previous size: 178 (Allocated) Thre (Protected)

*82945748 size: 2e8 previous size: 2e8 (Allocated) Thre (Protected)

*82945a30 size: 2e8 previous size: 2e8 (Allocated) Thre (Protected)

*82945d18 size: 2e8 previous size: 2e8 (Allocated) Thre (Protected)

*82946000 size: 2e8 previous size: 0 (Allocated) Thre (Protected)

:

:

KTHREAD 構造体は、"Thre" タグで確保された Pool 内に存在します。なので、適当な Thread の KTHREAD 構造体がどのプールにあるかを確認することで、プールの先頭からのオフセットを計算することができます。例として、以下の Thread を確認します。

 

1: kd> !THREAD 8ab94030

THREAD 8ab94030 Cid 0564.0568 Teb: 7ffde000 Win32Thread: fe9ab4e8 WAIT: (WrUserRequest) UserMode Non-Alertable

8ab8a458 SynchronizationEvent

Not impersonating

DeviceMap 8f072fc8

Owning Process 8ab897f0 Image: explorer.exe

Attached Process N/A Image: N/A

Wait Start TickCount 90686 Ticks: 354 (0:00:00:05.531)

Context Switch Count 12622

UserTime 00:00:00.484

KernelTime 00:00:01.093

Win32 Start Address 0x00c2a8df

Stack Init 94393fd0 Current 94393ba0 Base 94394000 Limit 94391000 Call 0

Priority 10 BasePriority 8 UnusualBoost 0 ForegroundBoost 2 IoPriority 2 PagePriority 5

ChildEBP RetAddr Args to Child

94393bb8 82ebfb15 8ab94030 82f7df08 82f7ad20 nt!KiSwapContext+0x26 (FPO: [Uses EBP] [0,0,4])

94393bf0 82ebe403 8ab940f0 8ab94030 8ab8a458 nt!KiSwapThread+0x266 (CONV: fastcall)

94393c18 82eb82cf 8ab94030 8ab940f0 00000000 nt!KiCommitThreadWait+0x1df (CONV: stdcall)

94393c90 97870d75 8ab8a458 0000000d 00000001 nt!KeWaitForSingleObject+0x393 (CONV: stdcall)

94393cec 97870e10 000024ff 00000000 00000001 win32k!xxxRealSleepThread+0x1d7 (FPO: [Non-Fpo]) (CONV: stdcall)

94393d08 9782bd56 000024ff 00000000 00000001 win32k!xxxSleepThread+0x2d (FPO: [Non-Fpo]) (CONV: stdcall)

94393d1c 97861eba 000024ff 00000000 0006fd30 win32k!xxxRealWaitMessageEx+0x12 (FPO: [Non-Fpo]) (CONV: stdcall)

94393d2c 82e9442a 0006fd44 772d64f4 badb0d00 win32k!NtUserWaitMessage+0x14 (FPO: [0,0,4]) (CONV: stdcall)

94393d2c 772d64f4 0006fd44 772d64f4 badb0d00 nt!KiFastCallEntry+0x12a (FPO: [0,3] TrapFrame @ 94393d34)

0006fd44 00000000 00000000 00000000 00000000 ntdll!KiFastSystemCallRet (FPO: [0,0,0])

 

!Pool コマンドで、プールのアドレスを計算します。

 

1: kd> !pool 8ab94030 2

Pool page 8ab94030 region is Nonpaged pool

*8ab94000 size: 2e8 previous size: 0 (Allocated) *Thre (Protected)

Pooltag Thre : Thread objects, Binary : nt!ps

 

上記の結果を用いることで、KTHREAD 構造体のオフセットが確認できます。Pool の先頭のアドレスが 8ab94000、KTHREAD 構造体のアドレスが 8ab94030 です。なので、以下の計算でオフセットが計算できます。

 

1: kd> ? 8ab94030 - 8ab94000

Evaluate expression: 48 = 00000030

 

KTHREAD 構造体は、プールの先頭から +0x30 バイトに始まります。

これを踏まえ、Pool のサンプルからいくつかの KTHREAD 構造体を確認すると以下のような結果がでます。

 

1: kd> !thread 82943d18+30

THREAD 82943d48 Cid 12ce80.60ae30 Teb: 00000000 Win32Thread: 00000000 TERMINATED

Not impersonating

DeviceMap 9805fec8

Owning Process 8947ea58 Image: TestApp.exe

Attached Process N/A Image: N/A

Wait Start TickCount 61686 Ticks: 29354 (0:00:07:38.656)

Context Switch Count 5

UserTime 00:00:00.000

KernelTime 00:00:00.000

Win32 Start Address 0x00401000

Stack Init 0 Current 9b6cbbf8 Base 9b6cc000 Limit 9b6c9000 Call 0

Priority 9 BasePriority 8 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5

1: kd> !thread 82945460+30

THREAD 82945490 Cid 12ce80.60ae64 Teb: 00000000 Win32Thread: 00000000 TERMINATED

Not impersonating

DeviceMap 9805fec8

Owning Process 8947ea58 Image: TestApp.exe

Attached Process N/A Image: N/A

Wait Start TickCount 61686 Ticks: 29354 (0:00:07:38.656)

Context Switch Count 4

UserTime 00:00:00.000

KernelTime 00:00:00.000

Win32 Start Address 0x00401000

Stack Init 0 Current 9baebbf8 Base 9baec000 Limit 9bae9000 Call 0

Priority 9 BasePriority 8 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5

 

Thread は終了していることを考えると、TestApp.exe が Thread Handle を Close していないということが考えられます。

TestApp.exe を確認します。Handle Count が非常に大きいです。

 

1: kd> !process 8947ea58 0

PROCESS 8947ea58 SessionId: 1 Cid: 12ce80 Peb: 7ffdf000 ParentCid: 09dc

DirBase: 7ee534c0 ObjectTable: 9be74bb8 HandleCount: 1907884.

Image: TestApp.exe

 

このプロセスで開いている Handle を確認すると、大量の Thread Handle があることが確認できます。

 

1: kd> !handle 0 2 8947ea58

PROCESS 8947ea58 SessionId: 1 Cid: 12ce80 Peb: 7ffdf000 ParentCid: 09dc

DirBase: 7ee534c0 ObjectTable: 9be74bb8 HandleCount: 1907884.

Image: TestApp.exe

Handle table at 9bfaf490 with 1907884 entries in use

0004: Object: 93a7b0c0 GrantedAccess: 00000003 Entry: 8ea37008

Object: 93a7b0c0 Type: (8928c7c8) Directory

ObjectHeader: 93a7b0a8 (new version)

0008: Object: 8a7cc038 GrantedAccess: 00100020 Entry: 8ea37010

Object: 8a7cc038 Type: (89324f78) File

ObjectHeader: 8a7cc020 (new version)

000c: Object: 8a8f26a0 GrantedAccess: 001f0003 Entry: 8ea37018

Object: 8a8f26a0 Type: (8931e330) Event

ObjectHeader: 8a8f2688 (new version)

:

:

74acdc: Object: f850bd48 GrantedAccess: 001fffff Entry: f649b9b8

Object: f850bd48 Type: (8928c1e8) Thread

ObjectHeader: f850bd30 (new version)

74ace0: Object: f850ba60 GrantedAccess: 001fffff Entry: f649b9c0

Object: f850ba60 Type: (8928c1e8) Thread

ObjectHeader: f850ba48 (new version)

74ace4: Object: f850b778 GrantedAccess: 001fffff Entry: f649b9c8

Object: f850b778 Type: (8928c1e8) Thread

ObjectHeader: f850b760 (new version)

 

この環境で確認すると、1907864 個の Thread Object がわかりました。これらの Handle を Thread Object としてデコードすると、ほとんどが終了している Thread です。

よって、TestApp.exe が Thread Handle を Close してないことが原因になるので、アプリケーションの開発元に確認することで問題は解決です。

 

このように、Pool の問題はドライバが単独で大きく Pool を使用している場合、ほかの処理によって OS が使用している Pool が大量に確保される場合などがあり、状況によって調査の方針などを考える必要があります。

この確認を行うことによって、Pool の問題の切り分けも可能になるかと思います。

今後の、問題解決にぜひお役立てください。