オンサイトセミナー
豊田孝の「IT談話館」 Windowsメモリダンプ解析を依頼する WinDbgとシステム分析




 本「IT談話館」一般公開記事は、書籍 「インサイド Microsoft Windows」 程度の基礎知識をお持ちの方を想定しています。



Windows 8/10、WinDbg、割り込み、DPC


 本「IT談話館」の「一般公開記事」は、「Active Memory Dump とカーネルメモリダンプ」の解析結果を基に起草されています。公開内容はあくまでも本館ビジネスに支障の出ない範囲に制限されていますが、Windowsビジネスを展開する上で必要となる、新規「商材」の発掘や同業他社との「差異」を確保し、人材と予算をはじめとする所有資源を適切に配置・投資する一助にはなるかもしれません。本「IT談話館」主筆の「豊田孝」はDKOM(Direct Kernel Object Manipulation)ベースの解析手法の第一人者であり、Windowsカーネル空間の解析分野では世界の先頭を走っています。

 現在、セキュリティー問題を無視することはできません。Microsoft社側の負担だけではなく、同社製品の利用者側の負担も増しています。困ったことではありますが、当面避けられません。セキュリティーの視点から「Windows10ソフトウェアセンサー」を見た場合、本「IT談話館」の確認範囲では、「カーネル層保護ロジック」に加え、次のような保護メカニズム階層が考案・実装されています。下記リンクはすべて本館記事を指しています。
  1. Silo/Server Silo
  2. Job
  3. Session
  4. Protected Process
  5. Mandatory Integrity Control(MIC)
  6. Windows API(+CPU)
  7. 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"
 本館はこのような情報を基にさらに深層解析を進め、ルートキットをはじめとする通常検出されないデバイスドライバーを解析することがあります。


ビジネスメニュー




 本「IT談話館」一般公開記事は、書籍 「インサイド Microsoft Windows」 程度の基礎知識をお持ちの方々を想定しています。
Windowsメモリダンプ解析技術開発室 ビジネスメニュー

Copyright©豊田孝 2004- 2021
本日は2021-07-24です。