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




 本「IT談話館」一般公開記事は、10年以上の実務経験を持つ上級Windowsエンジニアを想定しています。
 本館は、Windowsカーネル深層を解析し、クラッシュ原因をはじめとするシステム内の「異様な動き」を検出・分析する
超高度な技術と実績を保有しています。



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


 本「IT談話館」の「一般公開記事」は、「Active Memory Dump とカーネルメモリダンプ」の解析結果を基に起草されています。「本館」主筆の「豊田孝」は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"
 本館はこのような情報を基にさらに深層解析を進め、ルートキットをはじめとする通常検出されないデバイスドライバーを解析することがあります。


ビジネスメニュー




「Windowsメモリダンプ解析サービス」のご案内
Windowsメモリダンプ解析技術

Copyright©豊田孝 2004- 2024
本日は2024-10-12です。