ネットワークファイルコピー中にWindows Server 2008 カーネルが高負荷(調査編)

きっかけ
twitter で 「モンテカルロ的なカーネルプロファイラー」とつぶやいたら、岩田さんがお忙しい中、記事「CPU を食べているドライバは誰？ 」を掲載してくれた。
この情報を元に、パフォーマンスについて記載したいと思う。

自分の経験
一応、製品用ドライバ開発はしたことがないが、製品のドライバの挙動解析（パフォーマンス観点）については職業としてしてたことがある。ただし Windows でもなければ Linux でもない。

その時カーネルの設計情報については上記本を参考にしていた。

昔別環境で利用した手順

1. 現象を再現させる
   ソフトウェア開発者の悲しい性であるが、現象を再現させれないと問題が特定しずらい。いや優秀な開発者の場合、当たりが付けられるように適切なログ情報をポイントとして入れるハズであるが、それはそれ。
   刑事ドラマのように「もう一度犯行を犯さないかな。ぜったいにとっ捕まえてやる」のセリフを吐くのである。
   
2. 現象再現中にモンテカルロ的なプロファイラでプロファイリングを行う
   一定周期でCPUがどの命令を実行しているか収集しその情報から求める。実際にはタイマ割込みなどとプログラムカウンタ、必要に応じてスレッド情報を記録し後々にシンボル情報を元に表示するのであろう。
   
3. 収集した情報から特定する
   スレッドコンテキストやモジュール情報を元に、どの部分がCPUを利用しているのかを調べる。
   また、そのスレッドコンテキストやモジュール情報を元に動作している関数を特定する。
   なぜその関数の中にとどまり続けるのか？、なぜその関数が沢山呼ばれるのか？、どこコールスタックでその関数にたどり着くのか？、どのシーケンスでその関数に処理が移るのか？等を考える。
   ＡＰＩ仕様書やソースコードがないと分かりづらい状況である

今回の手順

岩田さんの記事を参照し、追求方法についてみてみる。（基本的な考え方については、以前やっていた方法に近い)

1. 現象を再現させる
2. KernRateでモジュールを特定する
3. KernRateでモジュール内の関数を特定する 

解析

1st: 現象を再現させた

ちゃんとCPU負荷が高くなった。ファイルコピーは1時間かかるらしいが、どんだけ現象が再現し続けるかがキモのような気がする。

2nd: KernRate で モジュールを特定

以下のコマンドで特定した。

I:\SharedData\work\WDK\KernRate\amd64>KernRate.exe

?(snip)?
ProfileTime   6374 hits, 65536 events per hit --------
 Module                                Hits   msec  %Total  Events/Sec
NTOSKRNL                               2171      15328    34 %     9282271
INTELPPM                               1007      15312    15 %     4310002
E1E6032E                                901      15312    14 %     3856317
TCPIP                                   873      15312    13 %     3736476
HAL                                     181      15312     2 %      774687
?(snip)?

これをみると、NTOSKRNL,INTELPPM,E1E6032E,TCPIPで76%占めていることが分かった。

3rd: KernRate で モジュールを特定

I:\SharedData\work\WDK\KernRate\amd64>KernRate.exe -z ntoskrnl

?(snip)?

ProfileTime   1479 hits, 65536 events per hit --------
 Module                                Hits   msec  %Total  Events/Sec
ExpInterlockedPopEntrySList             168       9781    11 %     1125656
KeReleaseSpinLockFromDpcLevel           133       9781     8 %      891144
KeSynchronizeExecution                   98       9781     6 %      656633
PsGetCurrentProcessSessionId             89       9781     5 %      596330
IoAcquireRemoveLockEx                    61       9781     4 %      408720
ExpInterlockedPushEntrySList             55       9781     3 %      368518
KeAcquireSpinLockAtDpcLevel              47       9781     3 %      314915
MmProbeAndLockPages                      42       9781     2 %      281414
ExIsResourceAcquiredSharedLite           37       9781     2 %      247912
ExAllocatePoolWithTag                    36       9781     2 %      241212
KeUpdateSystemTime                       36       9781     2 %      241212
KeRemoveQueueEx                          35       9781     2 %      234511
KeSetEvent                               32       9781     2 %      214410
RtlPrefetchMemoryNonTemporal             32       9781     2 %      214410
NtQueryInformationThread                 28       9781     1 %      187609
memset                                   28       9781     1 %      187609
IoAllocateMdl                            27       9781     1 %      180909
?(snip)?

 まず、NTOSKRNLから調べてみるが、NTのカーネルが提供するサービスらしく様々なAPIがまんべんなく出ているように見える。
ただ、Interlocked,SpinLock,Synchronizeをみると、同期関係のAPIが頻繁に呼ばれている。
また、Dpcという文字列も見え、このDPCが Defered Procedure Call だとすると ISR（割込こみ処理ルーチン)からの積まれる遅延コール関数で使われるロックのようにも考えられる。
さすがに Windows Kernel は詳しくないので、このあたりの詳細は分からない。しかし、NTOSKRNL というモジュールは他のモジュールからの要求によりCPU使用が高められていると考えられる。

一旦、NTOSKRNL から離れ、次の INTELPPM に移る。

I:\SharedData\work\WDK\KernRate\amd64>KernRate.exe -z intelppm

?(snip)?

Symbol Enumeration failed (or no symbols found) on module INTELPPM in CreateZoom
edModuleList, Error Code= 0x000001e7
No Hits or No symbols found for module INTELPPM.SYS
================================= END OF RUN ==================================
?(snip)?

 intelppmには、シンボルがないようで、シンボル一覧が表示されない。またモジュール名は モジュール名.SYS というファイルに対応していることが予想できた。 google で intelppm.sys を調べてみると Intel CPU 用のモジュールであることが推測できた。

同様にE1E6032Eについても調べてみる 

I:\SharedData\work\WDK\KernRate\amd64>KernRate.exe -z E1E6032E
?(snip)?

===> Processing Zoomed Module E1E6032E.SYS...

Symbol Enumeration failed (or no symbols found) on module E1E6032E in CreateZoomedModuleList, Error Code= 0x000001e7
No Hits or No symbols found for module E1E6032E.SYS
?(snip)?

今回もまたシンボル情報がない。 E1E6032E.SYSはIntelのNIC用ドライバのようである

最後に TCP/IPについても見てみる

I:\SharedData\work\WDK\KernRate\amd64>KernRate.exe -z TCPIP

?(snip)?
----- Zoomed module TCPIP.SYS (Bucket size = 16 bytes, Rounding Down) --------
Percentage in the following table is based on the Total Hits for this Zoom Module

ProfileTime   1493 hits, 65536 events per hit --------
 Module                                Hits   msec  %Total  Events/Sec
EQoSTestHook                              1      26765    100 %        2448

================================= END OF RUN ==================================
?(snip)?

EQoSTestHookが100%で出ているが、2448Events/Secと少なめなので、違う可能性もある。

さいごに

今回は原因追求まではいかなかったが、Networkドライバの問題ではないかと考えられた。
最新のドライバを探したがなさそうであったので、今回はここまでとする。

なお、このマシンは、メインマシンからサブマシンに降格よていであるので、積極的に原因追求には至らないと思う。

謝辞

お忙しい中、記事の掲載、twitterにおけるつぶやきを頂きました 岩田さんに感謝します。