本「
IT談話館」一般公開記事は、10年以上の実務経験を持つ上級Windowsエンジニアを想定しています。
本館は、Windowsカーネル深層を解析し、クラッシュ原因をはじめとするシステム内の「異様な動き」を検出・分析する
超高度な技術と実績を保有しています。
Windows 8/10、WinDbg、割り込み、DPC
本「IT談話館」の「一般公開記事」は、「Active Memory Dump とカーネルメモリダンプ」の解析結果を基に起草されています。「本館」主筆の「豊田孝」はDKOM(Direct Kernel Object Manipulation)ベースの解析手法の第一人者であり、Windowsカーネル空間の解析分野では世界の先頭を走っています。
現在、セキュリティー問題を無視することはできません。Microsoft社側の負担だけではなく、同社製品の利用者側の負担も増しています。困ったことではありますが、当面避けられません。セキュリティーの視点から「Windows10ソフトウェアセンサー」を見た場合、本「IT談話館」の確認範囲では、「カーネル層保護ロジック」に加え、次のような保護メカニズム階層が考案・実装されています。下記リンクはすべて本館記事を指しています。
- Silo/Server Silo
- Job
- Session
- Protected Process
- Mandatory Integrity Control(MIC)
- Windows API(+CPU)
- CPU
本稿では、割り込み（CPU）と密接な関係にある「DPC（Deferred Procedure Call）」を取り上げます。割り込みについては、 本「IT談話館」の「オンサイトセミナー教材」や本館一般記事「WinDbgとWindows XP/7/8/10割り込みテーブル（IDT)の内部解析」が参考になるかもしれません。また、クラッシュダンプ解析技術に関しては、本館一般公開記事「豊田孝のクラッシュダンプ解析技術」に目を通すとよいかもしれません。
DPCに起因する障害が発生すると、指定のクラッシュダンプが作成されます。この記事ではWindows 8.1環境で採取されたカーネルメモリダンプを解析する例を紹介します。DPC障害情報は次のようなWinDbgコマンドを実行することにより収集できます。
2: kd> .bugcheck
Bugcheck code 00000133
Arguments 00000000`00000000 00000000`00000501 00000000`00000500 00000000`00000000
2: kd> !analyze -show 00000133 00000000`00000000 00000000`00000501 00000000`00000500 00000000`00000000
DPC_WATCHDOG_VIOLATION (133)
The DPC watchdog detected a prolonged run time at an IRQL of DISPATCH_LEVEL
or above.
Arguments:
Arg1: 0000000000000000, A single DPC or ISR exceeded its time allotment. The offending
component can usually be identified with a stack trace.
Arg2: 0000000000000501, The DPC time count (in ticks).
Arg3: 0000000000000500, The DPC time allotment (in ticks).
Arg4: 0000000000000000, cast to nt!DPC_WATCHDOG_GLOBAL_TRIAGE_BLOCK, which contains
additional information regarding this single DPC timeout
*******************************************************************************
* *
* Bugcheck Analysis *
* *
*******************************************************************************
Use !analyze -v to get detailed debugging information.
BugCheck 133, {0, 501, 500, 0}
Probably caused by : usb8023x.sys ( usb8023x!CancelSendsTimerDpc+5b )
Followup: MachineOwner
---------
赤色の文字列は、DPC障害が発生していることを示しています。この障害は、DPC処理が既定の時間を超過しているのが原因です。既定の時間は500ですが、501かかっているというわけです。超過時間は次のようなWinDbgコマンドで確認できます。
2: kd> !whattime 0000000000000500
1280 Ticks in Standard Time: 20.000s
2: kd> !whattime 0000000000000501
1281 Ticks in Standard Time: 20.015s
ご覧のように、「015」ミリ秒超過し、「DPC_WATCHDOG_VIOLATION」が発生したと判定されています。発生しているDPC障害に関する情報を収集したい場合には、Windows Server 2003から利用できる「!dpcs」というWinDbgコマンドを使用することができます。
2: kd> !dpcs
CPU Type KDPC Function
1: Normal : 0xffffd00130bd9c28 0xfffff80168791028 nt!KiEntropyDpcRoutine
2: Normal : 0xfffff8016895dae0 0xfffff8016878a190 nt!KiBalanceSetManagerDeferredRoutine
この出力情報は、CPU1とCPU2でDPCが実行されていることを示していますが、それ以外のことは分かりません。Windows 8.1以降には「!dpcwatchdog」コマンドが導入され、次のような情報を返してきます。
2: kd> !dpcwatchdog
All durations are in seconds (1 System tick = 15.625000 milliseconds)
Circular Kernel Context Logger history: !logdump 0x2
DPC and ISR stats: !intstats /d
--------------------------------------------------
CPU#0
--------------------------------------------------
Current DPC: Wdf01000!FxInterrupt::_InterruptDpcThunk (Normal DPC)
Debugger Saved IRQL: 0
Cumulative DPC Time Limit: 120.000 seconds
Current Cumulative DPC Time: 100.469 seconds
Single DPC Time Limit: 20.000 seconds
Current Single DPC Time: 19.109 seconds
dt nt!_ISRDPCSTATS ffffd001311700b0
IsrActive: FALSE
Pending DPCs:
----------------------------------------
CPU Type KDPC Function
dpcs: no pending DPCs found
--------------------------------------------------
CPU#1
--------------------------------------------------
Current DPC: No Active DPC
Pending DPCs:
----------------------------------------
CPU Type KDPC Function
1: Normal : 0xffffd00130bd9c28 0xfffff80168791028 nt!KiEntropyDpcRoutine
--------------------------------------------------
CPU#2
--------------------------------------------------
Current DPC: usb8023x!CancelSendsTimerDpc (Normal DPC)
Debugger Saved IRQL: 13
Cumulative DPC Time Limit: 120.000 seconds
Current Cumulative DPC Time: 99.797 seconds
Single DPC Time Limit: 20.000 seconds
Current Single DPC Time: 20.016 seconds
dt nt!_ISRDPCSTATS ffffe00142c003b0
IsrActive: TRUE
Pending DPCs:
----------------------------------------
CPU Type KDPC Function
2: Normal : 0xfffff8016895dae0 0xfffff8016878a190 nt!KiBalanceSetManagerDeferredRoutine
--------------------------------------------------
CPU#3
--------------------------------------------------
Current DPC: No Active DPC
Pending DPCs:
----------------------------------------
CPU Type KDPC Function
dpcs: no pending DPCs found
「!dpcs」コマンドの出力結果とこの情報を比較すると、CPU1のDPC情報は無視し、CPU2上のDPC障害解析に解析焦点を絞ってよいと判断できます。CPU2上では、DPCの超過時間は「015」ミリ秒ではなく「016」ミリ秒となっており、四捨五入されていますが、既定の処理時間を超過していることは間違いないようです。通常はここまでのDPC障害情報をベンダーあるいは担当開発者に提供し、対処をお願いすることになるでしょう。
ここでふと考えます。デバイスドライバー（usb8023x.sys）には制御するデバイスオブジェクトが存在しているはずです。DPC障害の発生原因は、ソフトウェアの不具合だけではなく、ハードウェアデバイスの不具合だって十分考えられます。このレベルの解析は、本館の「この記事」で紹介する一連のWinDbgコマンド操作で可能です。
2: kd> !ndiskd.minidriver
ffffe001435b58e0 - usb_rndisx
ffffe0014c2309c0 - tunnel
ffffe0014c110020 - vwifimp
ffffe0014b528020 - BthPan
ffffe001477ffba0 - NETwNb64
ffffe00147dc5600 - RTL8168
2: kd> !ndiskd.minidriver ffffe001435b58e0
MINIPORT DRIVER
usb_rndisx
Ndis handle ffffe001435b58e0
Driver context NULL
DRIVER_OBJECT ffffe0014957c5b0
Driver image usb8023x.sys
Registry path [Zero-length string]
Reference Count 2
Flags [No flags set]
MINIPORTS
Miniport
ffffe0014d6f41a0 - Remote NDIS based Internet Sharing Device
Handlers
Device objects
この出力情報の技術的な背景を理解したい場合には、独自の解析コードを作成し、次のような情報を取得します。解析コードの開発知識の習得には、「時間と予算」の投資が必要です。
ActiveDpc->0xffffe00143c91f80 Context->0xffffe00143c91cd0 DeferredRoutine->usb8023x!CancelSendsTimerDpc (fffff800`5236fc58)
00: RelatedDpc->0xffffd00130d52ef8 Context->0x0003c37200000001 DeferredRoutine->00000000`00000000
01: RelatedDpc->0xfffff8016895dae0 Context->0xfffff8016895dac0 DeferredRoutine->nt!KiBalanceSetManagerDeferredRoutine (fffff801`6878a190)
赤色のContext（文脈や状況））はDPC実行時の背景を記録している領域と考えられますから、次のようなWinDbgコマンド操作を通して調査します。
2: kd> dt ndis!_NDK_ADAPTER 0xffffe00143c91cd0
+0x000 Header : _NDK_OBJECT_HEADER
+0x028 Dispatch : 0xffffe001`47610060 _NDK_ADAPTER_DISPATCH
2: kd> !devstack 0xffffe00147610060
!DevObj !DrvObj !DevExt ObjectName
ffffe0014d6f4050 \Driver\usb_rndisx ffffe0014d6f41a0 NDMP8
> ffffe00147610060 \Driver\usbccgp ffffe001476101b0 00000076
!DevNode ffffe0014d618550 :
DeviceInst is "USB\VID_18D1&PID_4EE3&MI_00\6&6cdfc6f&0&0000"
ServiceName is "usb_rndisx"
本館はこのような情報を基にさらに深層解析を進め、ルートキットをはじめとする通常検出されないデバイスドライバーを解析することがあります。