The free OSR Learning Library has more than 50 articles on a wide variety of topics about writing and debugging device drivers and Minifilters. From introductory level to advanced. All the articles have been recently reviewed and updated, and are written using the clear and definitive style you've come to expect from OSR over the years.
Check out The OSR Learning Library at: https://www.osr.com/osr-learning-library/
We have encountered an ASSERTION,
Assertion: *** DPC execution time exceeds system limit
This is NOT a break in update time
This is a BUG in a DPC routine
Perform a stack trace to find the culprit
The time out limit will be doubled on continuation
Use gh to continue!!
fffff805`7a8b862a cd2c int 2Ch
ERROR_CODE: (NTSTATUS) 0xc0000420 - An assertion failure has occurred.
EXCEPTION_CODE: (NTSTATUS) 0xc0000420 - An assertion failure has occurred.
e2aa1bb0 fffff80112715a4f : 0001311f
cccea0dd ffffc601e2a85180 00000000
00000286 000000000055d1bd : nt!KeAccumulateTicks+0x18756a
e2aa1c10 fffff8011260847c : 00000000
00000000 ffff9a0313ab8b00 ffff8381
37e5a680 ffff9a0313ab8bb0 : nt!KeClockInterruptNotify+0xcf
e2aa1f30 fffff80112780a15 : ffff9a03
13ab8b00 0000000000000000 00000000
00000001 ffffc601e2a85180 : hal!HalpTimerClockIpiRoutine+0x1c
e2aa1f60 fffff8011284f92a : ffff8381
37e5a680 ffff9a0313ab8b00 ffff9a07
0ba97000 ffff9a0313ab8b00 : nt!KiCallInterruptServiceRoutine+0xa5
e2aa1fb0 fffff8011284fe77 : 00000000
04d11000 0000000000000000 00000000
00000002 0000000000000000 : nt!KiInterruptSubDispatchNoLockNoEtw+0xfa
37e5a600 fffff8011271edd1 : 00000000
00000000 0000000000010008 00000000
00000460 ffff9a070737a000 : nt!KiInterruptDispatchNoLockNoEtw+0x37
37e5a790 fffff801129b942d : ffff9a03
13aa0500 fffff801129b7eef 00000000
00000460 ffff9a070ba96ba0 : nt!KiAcquireKobjectLockSafe+0x31
37e5a7c0 fffff801128a9d57 : 00000000
00000460 0000000000000000 00000000
00000460 0000000000000000 : nt!ExpCheckForWorker+0xf9
37e5a820 fffff801129baf5c : ffff9a03
1340b000 0000000000000000 00000000
5843424e fffff8011272b023 : nt!ExpFreePoolChecks+0x170c1b
37e5a850 fffff801129eb9c2 : ffff9a03
1340b000 ffff9a03c76f0b70 00000000
00000000 ffff800000000000 : nt!ExpFreeHeapSpecialPool+0x54
37e5a8a0 fffff80f123a8bf1 : ffff9a07
0ba96ba0 ffff9a070ba96ba0 000044da
05c7ef00 ffff9a03192f3dc8 : nt!ExFreePoolWithTag+0x3992
37e5aa50 fffff80112f447d7 : ffff9a07
0ba96ba0 ffff9a03c76f0b70 ffff9a07
0ba96ba0 fffff80f127b7665 : VerifierExt!ExFreePoolWithTag_wrapper+0x11
37e5aa80 fffff80112f4474c : ffff9a03
1fdc8580 0000000000000000 00000000
00000000 ffff9a03732e3930 : nt!VerifierExFreePoolWithTag+0x57
37e5aab0 fffff8011042bbfa : 00000000
00000000 ffff9a070ba96ba0 ffff9a03
1fdc8580 ffff9a031bba3000 : nt!VerifierExFreePool+0x1c
Q1. It is not a Bug Check 0x133 DPC_WATCHDOG_VIOLATION but an ASSERTION. Not sure why bug check did not happen ?
Started debugging and want to measure the time taken in each DPC (Average, Min and the Max values)
So, added a KeQueryPerformanceCounter() at the beginning and at the end of the DPCHandler took the difference and divided by PerformanceFrequency to obtain the time taken.
The min value was around 20us but the max value obtained was 2Secs, and there are few completions finishing in millisecs.
Later, realized that this may not be the correct way to measure DPC and it might include the time the DPC gets interrupted by the ISR.
Found the following ways to measure the DPC,
b) xperf from Windows SDK(Windows Performance Toolkit)
From the ETL log the following is observed, 649.477935200(Fragment Enter), 650.533282500(Fragment Exit), 1,057.932500(Exclusive Duration)
It looks like the xperf/tracelog both using a similar logic of have a KeQueryPerformanceCounter() at the entry and exit and measuring the difference.
Also, to note that in this run there is no ASSERTION or Bug Check, which means the DPC/ISR did not actually took 1Sec or exceed the limit.
It appears to be that the DPC got interrupted and got the control back after 1 sec.
In other runs, the max time went up to 2 and 3secs.
Q2. Is the understanding of taking more time is correct i.e., is it becausAe the DPC is interrupted and then resumed back after the elapsed time and hence showing more time in the tools ?
The original issue is longer time taken by the DPC, which is under investigation and in process to understand where the driver is spending time.
Q3. If the DPC is waiting for the spinlock (KeAcquireInStackQueuedSpinLockAtDpcLevel), Will this waiting time considered for the Watchdog ticks ?
|Upcoming OSR Seminars|
|OSR has suspended in-person seminars due to the Covid-19 outbreak. But, don't miss your training! Attend via the internet instead!|
|Developing Minifilters||24 May 2021||Live, Online|
|Writing WDF Drivers||14 June 2021||Live, Online|
|Internals & Software Drivers||27 September 2021||Live, Online|
|Kernel Debugging||15 November 2021||Live, Online|