Pool が枯渇した場合の調査方法
こんにちは。プラットフォーム サポートの大貫です。
今回は、Pool が枯渇する現象のトラブル シューティングについてお話したいと思います。
Pool の説明やトラブル シューティングなどについては、以下のブログでも紹介されています。
この内容を踏まえて、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 の問題の切り分けも可能になるかと思います。
今後の、問題解決にぜひお役立てください。