本「
IT談話館」一般公開記事は、10年以上の実務経験を持つ上級Windowsエンジニアを想定しています。
本館は、Windowsカーネル深層を解析し、クラッシュ原因をはじめとするシステム内の「異様な動き」を検出・分析する
超高度な技術と実績を保有しています。
Windows 8/10、WinDbg、割り込み、DPC
本「IT談話館」の「一般公開記事」は、「Active Memory Dump とカーネルメモリダンプ」の解析結果を基に起草されています。公開内容はあくまでも本館ビジネスに支障の出ない範囲に制限されていますが、Windowsビジネスを展開する上で必要となる、新規「商材」の発掘や同業他社との「差異」を確保し、人材と予算をはじめとする所有資源を適切に配置・投資する一助にはなるかもしれません。本「IT談話館」主筆の「豊田孝」は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"
本館はこのような情報を基にさらに深層解析を進め、ルートキットをはじめとする通常検出されないデバイスドライバーを解析することがあります。