DPC_WATCHDOG_VIOLATION蓝屏问题分析
在Windows 10之下,引入了DPC_WATCHDOG_VIOLATION
蓝屏错误,这个错误引入的原因是为了防止内核代码处于错误状态在DPC以及以上级别执行太久,影响系统的稳定性。
对于DPC_WATCHDOG_VIOLATION
这个蓝屏错误码,存在两种类型(使用第一个参数来区分):
- 第一个参数为0表示单个DPC例程执行超时了(A single DPC or ISR exceeded its time allotment)。
- 第一个参数为1表示系统在DPC上面执行超时了(The system cumulatively spent an extended period of time at IRQL DISPATCH_LEVEL or above)。
这两种蓝屏代码分别如下:
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: fffff8077ff73358, cast to nt!DPC_WATCHDOG_GLOBAL_TRIAGE_BLOCK, which contains
additional information regarding this single DPC timeout
DPC_WATCHDOG_VIOLATION (133)
The DPC watchdog detected a prolonged run time at an IRQL of DISPATCH_LEVEL
or above.
Arguments:
Arg1: 0000000000000001, The system cumulatively spent an extended period of time at
DISPATCH_LEVEL or above. The offending component can usually be
identified with a stack trace.
Arg2: 0000000000001e00, The watchdog period.
Arg3: fffff80080705330, cast to nt!DPC_WATCHDOG_GLOBAL_TRIAGE_BLOCK, which contains
additional information regarding the cumulative timeout
Arg4: 0000000000000000
下面我们通过要给实例来探讨一下DPC_WATCHDOG_VIOLATION
的基本原理以及分析过程。
1. 原理
1.1 DPC WATCHDOG
Windows对于系统运行在DPC和中断的时间做了相关限定,一般来说DPC不能运行超过100MS,IRS不能运行超过25MS(但是实际值却比这个要高)。
在Windows中,通过KeAccumulateTicks
对运行时间做相关限定,如下:
__int64 __fastcall KeAccumulateTicks(...)
{
//...
if (pcrb->NestingLevel == 2 && pcrb->DpcRoutineActive)
{
DpcTimeCount = pcrb->DpcTimeCount;
pcrb->DpcTime += KernelTime;
NewDpcTimeCount = DpcTimeCount + 1;
DpcTimeLimit = pcrb->DpcTimeLimit;
pcrb->DpcTimeCount = NewDpcTimeCount;
if (DpcTimeLimit)
{
//...
if (NewDpcTimeCount > DpcTimeLimit)
{
if (KeEnableWatchdogTimeout)
{
HvlInvokeHypervisorDebugger(3i64, 0i64);
if (!(_BYTE)KdDebuggerEnabled || (_BYTE)KdDebuggerNotPresent)
KeBugCheckEx(
0x133u,
0i64,
pcrb->DpcTimeCount,
pcrb->DpcTimeLimit,
(ULONG_PTR)&KeDpcWatchdogProfileGlobalTriageBlock);
}
pcrb->DpcTimeCount = 0;
KiResetGlobalDpcWatchdogProfiler(pcrb);
}
}
}
//...
if (Irql < 2u)
{
DpcWatchdogProfile = pcrb->DpcWatchdogProfile;
pcrb->DpcWatchdogCount = 0;
//...
goto Over;
}
DpcWatchdogPeriod = pcrb->DpcWatchdogPeriod;
NewDpcWatchdogCount = pcrb->DpcWatchdogCount + 1;
pcrb->DpcWatchdogCount = NewDpcWatchdogCount;
if (DpcWatchdogPeriod)
{
//...
if (DpcWatchdogCount >= DpcWatchdogPeriod)
{
if (KeEnableWatchdogTimeout)
{
HvlInvokeHypervisorDebugger(2i64, 0i64);
if (!(_BYTE)KdDebuggerEnabled || (_BYTE)KdDebuggerNotPresent)
KeBugCheckEx(0x133u,
1ui64,
pcrb->DpcWatchdogPeriod,
(ULONG_PTR)&KeDpcWatchdogProfileGlobalTriageBlock,
0i64);
}
}
}
//...
}
从这里看,如果超过时间并且KeEnableWatchdogTimeout
为真的话,那么引发133蓝屏。那么KeEnableWatchdogTimeout
这个是什么时候初始化的呢?我们可以看到初始化的代码如下:
char __fastcall KeInitSystem(int a1)
{
//...
if (!HviIsAnyHypervisorPresent())
KeEnableWatchdogTimeout = 1;
//...
}
HviIsAnyHypervisorPresent
这个函数返回cpuid指令是否由hypervisor实现,如果不是的话,那么开启WatchDog。
在上述中KeBugCheckEx
存在两种情况:
- 如果是
pcrb->DpcRoutineActive
在DPC例程中,那么判断是否DPC例程超时,DPC例程判断使用的是PRCB中的DpcTimeCount
和DpcTimeLimitTicks
比较。 - 接着是判断整体是否运行在DPC基本下面,使用的是PRCB中的
DpcWatchdogCount
和DpcWatchdogPeriodTicks
。
由于DpcTimeCount
表示的是单个DPC例程的执行时间,因此每一个DPC执行的时候都会设置改值为0。
__int64 __fastcall KiExecuteAllDpcs(...)
{
//...
a1->DpcTimeCount = 0;
//...
}
1.2 DPC超时时间获取
通过KeQueryDpcWatchdogInformation
可以获取到当前处理器的DPC超时时间信息,如下:
NTSTATUS KeQueryDpcWatchdogInformation(
PKDPC_WATCHDOG_INFORMATION WatchdogInformation
);
typedef struct _KDPC_WATCHDOG_INFORMATION {
ULONG DpcTimeLimit;
ULONG DpcTimeCount;
ULONG DpcWatchdogLimit;
ULONG DpcWatchdogCount;
ULONG Reserved;
} KDPC_WATCHDOG_INFORMATION, *PKDPC_WATCHDOG_INFORMATION;
其中:
DpcTimeLimit
: 当前处理器单个延迟过程调用的时间限制。如果已禁用DPC超时,则此值设置为0。DpcTimeCount
: 如果已启用DPC超时,则本次延迟过程调用的使用时间。DpcWatchdogLimit
: 一系列延迟过程调用所允许的总时间限制。如果已禁用DPC看门狗,则此值设置为零。DpcWatchdogCount
: 如果启用DPC看门狗,则当前连续延迟过程调用序列的剩余时间值。
例如我们可以看到如下:
0: kd> dt nt!_KPRCB fffff8007bfe9180 DPC*
+0x3310 DpcRuntimeHistoryHashTable : 0xffffaf0c`1f0d5690 _RTL_HASH_TABLE
+0x3318 DpcRuntimeHistoryHashTableCleanupDpc : 0xffffaf0c`1f122c40 _KDPC
+0x3338 DpcDelegateThread : 0xffffaf0c`1f150140 _KTHREAD
+0x3340 DpcData : [2] _KDPC_DATA
+0x33a0 DpcStack : 0xfffff800`7c395fb0 Void
+0x33ac DpcRequestRate : 0
+0x33b4 DpcLastCount : 0x67518e
+0x33ba DpcRoutineActive : 0 ''
+0x33bc DpcRequestSummary : 0n131174
+0x33bc DpcRequestSlot : [2] 0n102
+0x33bc DpcNormalProcessingActive : 0y0
+0x33bc DpcNormalProcessingRequested : 0y1
+0x33bc DpcNormalThreadSignal : 0y1
+0x33bc DpcNormalTimerExpiration : 0y0
+0x33bc DpcNormalDpcPresent : 0y0
+0x33bc DpcNormalLocalInterrupt : 0y1
+0x33bc DpcNormalPriorityAntiStarvation : 0y1
+0x33bc DpcNormalSwapToDpcDelegate : 0y0
+0x33bc DpcNormalSpare : 0y00000000 (0)
+0x33bc DpcThreadActive : 0y0
+0x33bc DpcThreadRequested : 0y1
+0x33bc DpcThreadSpare : 0y00000000000000 (0)
+0x7e40 DpcGate : _KGATE
+0x7ea8 DpcWatchdogPeriodTicks : 0n7680
+0x7eac DpcWatchdogCount : 0n7680
+0x7eb4 DpcWatchdogProfileCumulativeDpcThresholdTicks : 0x1b80
+0x7eec DpcWatchdogSequenceNumber : 0x18794c
+0x814c DpcTime : 0x4c56
+0x815c DpcTimeCount : 0
+0x8160 DpcTimeLimitTicks : 0x500
+0x8240 DpcWatchdogProfileSingleDpcThresholdTicks : 0x496
+0x85d8 DpcWatchdogDpc : _KDPC
+0x8618 DpcWatchdogTimer : _KTIMER
+0x88a8 DpcWatchdogProfile : 0xffffaf0c`1f16a000 -> 0x00000000`00000011 Void
+0x88b0 DpcWatchdogProfileCurrentEmptyCapture : 0xffffaf0c`1f181cf8 -> (null)
综上,针对DPC的监控有两个:
- 使用
DpcTimeCount
和DpcTimeLimitTicks
来监控单个DPC例程执行的时间,防止DPC例程执行过长。 - 使用
DpcWatchdogCount
和DpcWatchdogPeriodTicks
来监控CPU执行的DPC时间总和,防止CPU一直执行一系列DPC函数。
2. 实例
下面我们通过一个DPC_WATCHDOG_VIOLATION
蓝屏转储文件来进行实例分析。
2.1 分析
我们先来看一下蓝屏代码DPC_WATCHDOG_VIOLATION
,如下:
DPC_WATCHDOG_VIOLATION (133)
The DPC watchdog detected a prolonged run time at an IRQL of DISPATCH_LEVEL
or above.
Arguments:
Arg1: 0000000000000001, The system cumulatively spent an extended period of time at
DISPATCH_LEVEL or above. The offending component can usually be
identified with a stack trace.
Arg2: 0000000000001e00, The watchdog period.
Arg3: fffff80080705330, cast to nt!DPC_WATCHDOG_GLOBAL_TRIAGE_BLOCK, which contains
additional information regarding the cumulative timeout
Arg4: 0000000000000000
此时调用堆栈如下:
0: kd> k
# Child-SP RetAddr Call Site
00 fffff800`7c39cdd8 fffff800`7fc31c8f nt!KeBugCheckEx
01 fffff800`7c39cde0 fffff800`7fc318a1 nt!KeAccumulateTicks+0x20f
02 fffff800`7c39ce50 fffff800`7fc2fa8a nt!KiUpdateRunTime+0x61
03 fffff800`7c39ceb0 fffff800`7fc2f876 nt!KeClockInterruptNotify+0x11a
04 fffff800`7c39cf40 fffff800`7fc14650 nt!HalpTimerClockIpiRoutine+0x16
05 fffff800`7c39cf70 fffff800`7fe1e05a nt!KiCallInterruptServiceRoutine+0xa0
06 fffff800`7c39cfb0 fffff800`7fe1e8c7 nt!KiInterruptSubDispatchNoLockNoEtw+0xfa
07 fffff882`a7a57430 fffff800`7fd67972 nt!KiInterruptDispatchNoLockNoEtw+0x37
08 fffff882`a7a575c0 fffff800`7fc6cb64 nt!KiAcquireKobjectLockSafe+0x32
09 fffff882`a7a575f0 fffff800`7fc44136 nt!KeSetEvent+0x64
0a fffff882`a7a57680 fffff800`7fc18496 nt!IopCompleteRequest+0x396
0b fffff882`a7a57760 fffff800`7fc70846 nt!KiDeliverApc+0x1b6
0c fffff882`a7a57820 fffff800`7fc72169 nt!KiSwapThread+0x936
0d fffff882`a7a57900 fffff800`7fc75e26 nt!KiCommitThreadWait+0x159
0e fffff882`a7a579a0 fffff800`8cce1cc1 nt!KeDelayExecutionThread+0x416
0f fffff882`a7a57a30 fffff800`8cce3b7a xxxDrv_x64+0x1cc1
10 fffff882`a7a57a60 fffff800`7fd54295 xxxDrv_x64+0x3b7a
11 fffff882`a7a57af0 fffff800`7fe20e34 nt!PspSystemThreadStartup+0x55
12 fffff882`a7a57b40 00000000`00000000 nt!KiStartSystemThread+0x34
这里我们可以得出的是蓝屏并不是执行某个DPC例程导致的时间够长,而是该CPU在DPC模式下面执行过长。
此时我们看到DCP的时间如下:
0: kd> dt nt!_KPRCB fffff8007bfe9180 DPC*
+0x7ea8 DpcWatchdogPeriodTicks : 0n7680
+0x7eac DpcWatchdogCount : 0n7680
+0x815c DpcTimeCount : 0
+0x8160 DpcTimeLimitTicks : 0x500
从这里我们也可以发现:
DpcTimeCount
为0,说明我们没有执行DPC例程。DpcWatchdogCount
和DpcWatchdogPeriodTicks
相等,说明CPU在DPC下面执行时间过长。
我们可以看一下当前DPC的信息,如下:
0: kd> !dpcs 0
CPU Type KDPC Function
0: Normal : 0xffffaf0c32787278 0xfffff8007fe56420 nt!IopPassiveInterruptDpc
0: Normal : 0xffffaf0c21e7b520 0xfffff80082092550 Wdf01000!FxInterrupt::_InterruptDpcThunk
0: Normal : 0xffffaf0c23ce9808 0xfffff80082c314d0 ndis!ndisInterruptDpc
0: Normal : 0xffffaf0c21eb26e8 0xfffff800858666c0 dxgkrnl!DpiFdoDpcForIsr
0: Normal : 0xfffff882acf91f60 0xfffff8007fc13ff0 nt!PopExecuteProcessorCallback
0: Normal : 0xfffff8007bff15d8 0xfffff8007fc26b60 nt!PpmPerfAction
0: Normal : 0xffffaf0c2173a0c8 0xfffff80082ec51d0 tcpip!TcpPeriodicTimeoutHandler
0: Normal : 0xffffaf0c211f71e8 0xfffff80082732000 stornvme!NVMeCompletionDpcRoutine
0: Normal : 0xfffff8007bff1c68 0xfffff8007fd4c800 nt!KiEntropyDpcRoutine
0: Normal : 0xfffff882a8ab6f60 0xfffff8007fc13ff0 nt!PopExecuteProcessorCallback
0: Normal : 0xfffff882ad376f60 0xfffff8007fc13ff0 nt!PopExecuteProcessorCallback
0: Normal : 0xffffaf0c1f122c40 0xfffff8007fd3fd30 nt!KiDpcRuntimeHistoryHashTableCleanupDpcRoutine
0: Normal : 0xffffaf0c231d0de0 0xfffff80082092550 Wdf01000!FxInterrupt::_InterruptDpcThunk
0: Normal : 0xffffaf0c21d93db0 0xfffff800b332b470 i8042prt!I8042KeyboardIsrDpc
0: Normal : 0xffffaf0c23ce9a48 0xfffff80082c314d0 ndis!ndisInterruptDpc
0: Normal : 0xfffff882a8476f60 0xfffff8007fc13ff0 nt!PopExecuteProcessorCallback
0: Normal : 0xffffaf0c21233000 0xfffff8008278c0f0 storport!RaidpAdapterRedirectDpcRoutine
0: Normal : 0xffffaf0c23081270 0xfffff800ae096d90 Ndu!NduQueryStatisticsDpc
0: Normal : 0xfffff882a7f26f60 0xfffff8007fc13ff0 nt!PopExecuteProcessorCallback
0: Normal : 0xfffff882ac1a6f60 0xfffff8007fc13ff0 nt!PopExecuteProcessorCallback
0: Threaded: 0xfffff8007bff1758 0xfffff8007fd59dc0 nt!KiDpcWatchdog
发现大量DPC,为什么呢?导致DPC执行不了的一个原因是CPU一直处于高IRQL下面,例如中断,是不是CPU一直处于中断下面呢?
我们可以使用!dpcwatchdog
查看dpcwatchdog的情况,如下:
0: 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: No Active DPC
Pending DPCs:
----------------------------------------
CPU Type KDPC Function
0: Normal : 0xffffaf0c32787278 0xfffff8007fe56420 nt!IopPassiveInterruptDpc
0: Normal : 0xffffaf0c21e7b520 0xfffff80082092550 Wdf01000!FxInterrupt::_InterruptDpcThunk
0: Normal : 0xffffaf0c23ce9808 0xfffff80082c314d0 ndis!ndisInterruptDpc
0: Normal : 0xffffaf0c21eb26e8 0xfffff800858666c0 dxgkrnl!DpiFdoDpcForIsr
0: Normal : 0xfffff882acf91f60 0xfffff8007fc13ff0 nt!PopExecuteProcessorCallback
0: Normal : 0xfffff8007bff15d8 0xfffff8007fc26b60 nt!PpmPerfAction
0: Normal : 0xffffaf0c2173a0c8 0xfffff80082ec51d0 tcpip!TcpPeriodicTimeoutHandler
0: Normal : 0xffffaf0c211f71e8 0xfffff80082732000 stornvme!NVMeCompletionDpcRoutine
0: Normal : 0xfffff8007bff1c68 0xfffff8007fd4c800 nt!KiEntropyDpcRoutine
0: Normal : 0xfffff882a8ab6f60 0xfffff8007fc13ff0 nt!PopExecuteProcessorCallback
0: Normal : 0xfffff882ad376f60 0xfffff8007fc13ff0 nt!PopExecuteProcessorCallback
0: Normal : 0xffffaf0c1f122c40 0xfffff8007fd3fd30 nt!KiDpcRuntimeHistoryHashTableCleanupDpcRoutine
0: Normal : 0xffffaf0c231d0de0 0xfffff80082092550 Wdf01000!FxInterrupt::_InterruptDpcThunk
0: Normal : 0xffffaf0c21d93db0 0xfffff800b332b470 i8042prt!I8042KeyboardIsrDpc
0: Normal : 0xffffaf0c23ce9a48 0xfffff80082c314d0 ndis!ndisInterruptDpc
0: Normal : 0xfffff882a8476f60 0xfffff8007fc13ff0 nt!PopExecuteProcessorCallback
0: Normal : 0xffffaf0c21233000 0xfffff8008278c0f0 storport!RaidpAdapterRedirectDpcRoutine
0: Normal : 0xffffaf0c23081270 0xfffff800ae096d90 Ndu!NduQueryStatisticsDpc
0: Normal : 0xfffff882a7f26f60 0xfffff8007fc13ff0 nt!PopExecuteProcessorCallback
0: Normal : 0xfffff882ac1a6f60 0xfffff8007fc13ff0 nt!PopExecuteProcessorCallback
0: Threaded: 0xfffff8007bff1758 0xfffff8007fd59dc0 nt!KiDpcWatchdog
c0000094 Exception in kdexts.dpcwatchdog debugger extension.
PC: 00007ffa`507625c0 VA: 00000000`00000000 R/W: 0 Parameter: 00000000`00000000
同样也可以看到大量Pending DPCs,Current DPC: No Active DPC。
3. 总结
DPC_WATCHDOG_VIOLATION
有两种蓝屏情况:
Parameter 1 = 0
说明当前正在执行DPC例程,并且超时了,可以直接看到DPC超时的原因(或者由于其他线程导致该DPC一直无法退出)。Parameter 1 = 1
说明此时该CPU一直处于DPC状态执行,这个原因需要具体分析。
有两个WinDBG命令可以协助分析该蓝屏:
!dpcwatchdog
查看所有cpu的dpcwatchdog信息。!dpcs
查看指定cpu的dpc例程信息。