none
DPC_WATCHDOG_VIOLATION Windows 10 RRS feed

  • Question

  • Hi,

    We need some advices/guidances regarding the potential root cause and how to solve the BSOD from DPC_WATCHDOG_VIOLATION(133). It seems to relate to WdfDeviceEnqueueRequest in EvtIoInCallerContext. Any advise or anything we can try will be appreciated. Thank you.

    ================================================================

    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: fffff80157e67378, cast to nt!DPC_WATCHDOG_GLOBAL_TRIAGE_BLOCK, which contains
        additional information regarding the cumulative timeout
    Arg4: 0000000000000000

    STACK_TEXT:  
    ffff8d81`d87f7b78 fffff801`57c16e31 : 00000000`00000133 00000000`00000001 00000000`00001e00 fffff801`57e67378 : nt!KeBugCheckEx
    ffff8d81`d87f7b80 fffff801`57ab08bd : 000001ea`db9a2985 ffff8d81`d87a0180 00000000`00000246 00000000`00008593 : nt!KeAccumulateTicks+0x162a51
    ffff8d81`d87f7be0 fffff801`57ab19a3 : fffff780`00000340 ffff8d81`d87a0180 00000000`00008593 00000000`00000000 : nt!KiUpdateRunTime+0x5d
    ffff8d81`d87f7c30 fffff801`58370883 : 000001ea`db99fedb 00000000`0000013c 00000000`00000000 ffff8b89`9f307000 : nt!KeClockInterruptNotify+0x8f3
    ffff8d81`d87f7f40 fffff801`57a25925 : ffffb086`e56ff300 00000000`00000000 00000000`00000000 00000000`00000000 : hal!HalpTimerClockInterrupt+0x63
    ffff8d81`d87f7f70 fffff801`57bc736a : ffff8b89`9f307080 ffffb086`e56ff300 00000000`00000054 ffffb086`e7ed6410 : nt!KiCallInterruptServiceRoutine+0xa5
    ffff8d81`d87f7fb0 fffff801`57bc7857 : 00000000`b207f997 ffffb086`e56ff300 00000000`0000013c ffff8b89`9f307110 : nt!KiInterruptSubDispatchNoLockNoEtw+0xea
    ffff8b89`9f307000 fffff801`57b4adfc : 0000000f`ffffffff 7fffffff`ffffffff 00000000`00000002 fffff801`57de8f00 : nt!KiInterruptDispatchNoLockNoEtw+0x37
    ffff8b89`9f307190 fffff801`57b4adb5 : ffffb086`e8108d90 ffff8b89`9f3072e0 ffff8b89`9f3072b0 fffff801`57b03147 : nt!KxWaitForSpinLockAndAcquire+0x2c
    ffff8b89`9f3071c0 fffff80c`959fbc1c : ffffb086`e5da0700 0a000002`5eb24867 00000000`00000000 00000000`00001001 : nt!KeAcquireSpinLockRaiseToDpc+0x65
    ffff8b89`9f3071f0 fffff80c`9598ca8f : ffffb086`eb3da750 ffffb086`e8108b00 fffff77b`bddee7f8 fffff801`57b023d0 : Wdf01000!FxCallbackSpinLock::Lock+0x7c [minkernel\wdf\framework\shared\inc\private\common\fxcallbackspinlock.hpp @ 122]
    ffff8b89`9f307230 fffff80c`9598ba43 : 00000000`42616500 00000000`00000001 ffffb086`eb5b0500 ffffb086`eb5b05b0 : Wdf01000!FxIoQueue::DispatchRequestToDriver+0x73f [minkernel\wdf\framework\shared\irphandlers\io\fxioqueue.cpp @ 3325]
    ffff8b89`9f3072d0 fffff80c`95988d49 : ffffb086`e8108b00 ffffb086`eb3da700 00000000`00000000 ffffb086`e7ed6400 : Wdf01000!FxIoQueue::DispatchEvents+0x473 [minkernel\wdf\framework\shared\irphandlers\io\fxioqueue.cpp @ 3125]
    ffff8b89`9f3073b0 fffff80c`9598207f : ffffb086`eafe6600 00004f79`14c258a8 ffffb086`eb3da750 ffffb086`eb3da901 : Wdf01000!FxPkgIo::EnqueueRequest+0x359 [minkernel\wdf\framework\shared\irphandlers\io\fxpkgio.cpp @ 697]
    ffff8b89`9f307460 fffff80c`98c12281 : 00000000`00000008 ffffb086`e8100000 ffffb086`e8100000 ffffb086`eb3da750 : Wdf01000!imp_WdfDeviceEnqueueRequest+0xbf [minkernel\wdf\framework\shared\core\fxdeviceapi.cpp @ 2074]
    ffff8b89`9f3074c0 fffff80c`959888f5 : 00000000`00000001 ffffb086`e8108b00 ffffb086`e7588e70 ffff8b89`9f3075c8 : SeaBaseDriver!EvtIoInCallerContext+0x201 [c:\users\356909\desktop\lasest seabasedriver and api\seabasedriver_last\driver.c @ 1106]
    ffff8b89`9f307550 fffff80c`959878d1 : ffffb086`e7588e70 ffffb086`eb9a96b0 fffff77b`80000000 0a000002`64908801 : Wdf01000!FxPkgIo::DispatchStep1+0x675 [minkernel\wdf\framework\shared\irphandlers\io\fxpkgio.cpp @ 324]
    ffff8b89`9f307610 fffff801`57aa4839 : 00000000`00000001 fffff801`57aa4b05 ffffb086`e64102b8 ffffb086`e6410280 : Wdf01000!FxDevice::DispatchWithLock+0x5a1 [minkernel\wdf\framework\shared\core\fxdevice.cpp @ 1430]
    ffff8b89`9f307700 fffff801`57f25f7b : ffffb086`eb9a96b0 ffff8b89`9f307a80 00000000`00000001 00000000`00000000 : nt!IofCallDriver+0x59
    ffff8b89`9f307740 fffff801`57f2a4ea : ffffb086`eb9a96b0 ffff8b89`9f307a80 00000000`20206f00 ffff8b89`9f307a80 : nt!IopSynchronousServiceTail+0x1ab
    ffff8b89`9f3077f0 fffff801`57f27ed6 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : nt!IopXxxControlFile+0x68a
    ffff8b89`9f307920 fffff801`57bd6143 : 00000000`00000000 00000000`00000000 00000000`00000000 fffff801`57b21cb5 : nt!NtDeviceIoControlFile+0x56
    ffff8b89`9f307990 00007ffb`d26caa84 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : nt!KiSystemServiceCopyEnd+0x13
    00000000`041aeaf8 00000000`00000000 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : 0x00007ffb`d26caa84

    Thursday, June 13, 2019 9:32 PM

Answers

  • Scott and Pavel - the Driver Verifier nailed it.  This is interesting.

    I was issuing a reset to some hardware which required specific timing.  I was calling KeDelayExecutionThread() from a DevIO call, and apparently when hooked to a debugger it lets you get away with it.  When I turned on the driver verifier, and hot unplugged my device, it failed the command and then the app requested a reset.  Instant BSOD.  You probably would not appreciate my timer fix, so I won't post it here.  ;)  (has to do with reading the tick counts and spinning).

    What is curious is why did the debug trace not catch this until I turned on the verifier?  

    So, KeDelayExecutionThread() was causing the entire problem, obviously because the IRQL was too high.  Sadly, per the hardware specs, I really do need to predictably reinit the HW at runtime when error conditions occur, so I need a reliable timer.  So, using the tick counts fixed the problem.

    Thanks for your help!!!


    Tuesday, June 18, 2019 8:34 PM

All replies

  • See here.

    -- pa

    Friday, June 14, 2019 1:58 PM
  • In this case, it seems that the error is in the Wdf01000!FxPkgIo::EnqueueRequest+0x359 routine.   I am assuming WDF is raising the level with some sort of a spinlock to enqueue the request (its from the EvtIoInCallerContext routine to call the WdfEnqueue routine).

    It seems like for some reason the WDF code has deadlocked?

    We have been stripping out our ISRs and DPCs to be very minimalist, but it seems the error is not actually in the ISR or DPC?  We've captured 4 traces and it always has the Enqueue request in there.  One trace even showed the other 3 processors idle.

    If our DPC was actually at fault, shouldn't it be in the call stack for one of the processors?

    Friday, June 14, 2019 3:12 PM
  • DPC_WATCHDOG happens if a single DPC is taking too long OR if the processor is stuck at DISPATCH_LEVEL or above for too long.

    In this case the bugcheck is saying it's because of staying at DISPATCH_LEVEL for too long. This could happen for lots of reasons. For example, maybe your DPC requeued itself too many times. It can also happen if you're blocked waiting for a spinlock for too long (which is what it looks like here).

    What's the output of !dpcwatchdog and !running -ti?


    Scott Noone
    Engineering Partner
    OSR Open Systems Resources, Inc.
    Windows Driver Training, Consulting, Problem Analysis, and Custom Development
    https://www.osr.com
    https://www.linkedin.com/in/scottnoone

    Friday, June 14, 2019 3:51 PM
  • I do see the comment about 18XX - we are using 17XX, we'll upgrade to 1903, perhaps that is the problem.
    Friday, June 14, 2019 3:56 PM
  • 1: kd> !running -ti

    System Processors:  (000000000000000f)
      Idle Processors:  (0000000000000000)

           Prcbs             Current         (pri) Next            (pri) Idle
      0    fffff801577db180  ffffb086eb0e4700 ( 8)                       fffff80157e85400  ................

     # Child-SP          RetAddr           Call Site
    00 ffff8b89`a13c2a00 00007ffb`d26cb264 nt!KiSystemServiceExit+0x2f
    01 00000000`0460ea18 00000000`00000000 0x00007ffb`d26cb264

      1    ffff8d81d87a0180  ffffb086e5da0700 ( 8) ffffb086ea41d600 (16) ffff8d81d87b0100  ................

     # Child-SP          RetAddr           Call Site
    00 ffff8d81`d87f7b78 fffff801`57c16e31 nt!KeBugCheckEx
    01 ffff8d81`d87f7b80 fffff801`57ab08bd nt!KeAccumulateTicks+0x162a51
    02 ffff8d81`d87f7be0 fffff801`57ab19a3 nt!KiUpdateRunTime+0x5d
    03 ffff8d81`d87f7c30 fffff801`58370883 nt!KeClockInterruptNotify+0x8f3
    04 ffff8d81`d87f7f40 fffff801`57a25925 hal!HalpTimerClockInterrupt+0x63
    05 ffff8d81`d87f7f70 fffff801`57bc736a nt!KiCallInterruptServiceRoutine+0xa5
    06 ffff8d81`d87f7fb0 fffff801`57bc7857 nt!KiInterruptSubDispatchNoLockNoEtw+0xea
    07 ffff8b89`9f307000 fffff801`57b4adfc nt!KiInterruptDispatchNoLockNoEtw+0x37
    08 ffff8b89`9f307190 fffff801`57b4adb5 nt!KxWaitForSpinLockAndAcquire+0x2c
    09 ffff8b89`9f3071c0 fffff80c`959fbc1c nt!KeAcquireSpinLockRaiseToDpc+0x65
    0a (Inline Function) --------`-------- Wdf01000!MxLockNoDynam::Acquire+0xa [minkernel\wdf\framework\shared\inc\primitives\km\mxlockkm.h @ 62] 
    0b ffff8b89`9f3071f0 fffff80c`9598ca8f Wdf01000!FxCallbackSpinLock::Lock+0x7c [minkernel\wdf\framework\shared\inc\private\common\fxcallbackspinlock.hpp @ 122] 
    0c (Inline Function) --------`-------- Wdf01000!FxLockedCallback::CallbackStart+0x5b2 [minkernel\wdf\framework\shared\inc\private\common\fxcallback.hpp @ 120] 
    0d (Inline Function) --------`-------- Wdf01000!FxIoQueueIoDeviceControl::Invoke+0x5c6 [minkernel\wdf\framework\shared\inc\private\common\fxioqueuecallbacks.hpp @ 225] 
    0e ffff8b89`9f307230 fffff80c`9598ba43 Wdf01000!FxIoQueue::DispatchRequestToDriver+0x73f [minkernel\wdf\framework\shared\irphandlers\io\fxioqueue.cpp @ 3325] 
    0f ffff8b89`9f3072d0 fffff80c`95988d49 Wdf01000!FxIoQueue::DispatchEvents+0x473 [minkernel\wdf\framework\shared\irphandlers\io\fxioqueue.cpp @ 3125] 
    10 (Inline Function) --------`-------- Wdf01000!FxIoQueue::QueueRequestFromForward+0x26e [minkernel\wdf\framework\shared\irphandlers\io\fxioqueue.cpp @ 2493] 
    11 ffff8b89`9f3073b0 fffff80c`9598207f Wdf01000!FxPkgIo::EnqueueRequest+0x359 [minkernel\wdf\framework\shared\irphandlers\io\fxpkgio.cpp @ 697] 
    12 ffff8b89`9f307460 fffff80c`98c12281 Wdf01000!imp_WdfDeviceEnqueueRequest+0xbf [minkernel\wdf\framework\shared\core\fxdeviceapi.cpp @ 2074] 
    13 ffff8b89`9f3074c0 fffff80c`959888f5 SeaBaseDriver+0x2281
    14 (Inline Function) --------`-------- Wdf01000!FxIoInCallerContext::Invoke+0x19 [minkernel\wdf\framework\shared\inc\private\common\fxdevicecallbacks.hpp @ 55] 
    15 (Inline Function) --------`-------- Wdf01000!FxPkgIo::DispathToInCallerContextCallback+0xb9 [minkernel\wdf\framework\shared\irphandlers\io\fxpkgio.cpp @ 1748] 
    16 (Inline Function) --------`-------- Wdf01000!FxPkgIo::DispatchStep2+0x5fb [minkernel\wdf\framework\shared\irphandlers\io\fxpkgio.cpp @ 459] 
    17 ffff8b89`9f307550 fffff80c`959878d1 Wdf01000!FxPkgIo::DispatchStep1+0x675 [minkernel\wdf\framework\shared\irphandlers\io\fxpkgio.cpp @ 324] 
    18 (Inline Function) --------`-------- Wdf01000!FxPkgIo::Dispatch+0x4c [minkernel\wdf\framework\shared\irphandlers\io\fxpkgio.cpp @ 118] 
    19 (Inline Function) --------`-------- Wdf01000!DispatchWorker+0x52b [minkernel\wdf\framework\shared\core\fxdevice.cpp @ 1572] 
    1a (Inline Function) --------`-------- Wdf01000!FxDevice::Dispatch+0x537 [minkernel\wdf\framework\shared\core\fxdevice.cpp @ 1586] 
    1b ffff8b89`9f307610 fffff801`57aa4839 Wdf01000!FxDevice::DispatchWithLock+0x5a1 [minkernel\wdf\framework\shared\core\fxdevice.cpp @ 1430] 
    1c ffff8b89`9f307700 fffff801`57f25f7b nt!IofCallDriver+0x59
    1d ffff8b89`9f307740 fffff801`57f2a4ea nt!IopSynchronousServiceTail+0x1ab
    1e ffff8b89`9f3077f0 fffff801`57f27ed6 nt!IopXxxControlFile+0x68a
    1f ffff8b89`9f307920 fffff801`57bd6143 nt!NtDeviceIoControlFile+0x56
    20 ffff8b89`9f307990 00007ffb`d26caa84 nt!KiSystemServiceCopyEnd+0x13
    21 00000000`041aeaf8 00000000`00000000 0x00007ffb`d26caa84

      2    ffff8d81d8300180  ffffb086e5d8d700 ( 8)                       ffff8d81d8310100  ................

     # Child-SP          RetAddr           Call Site
    00 ffff8b89`a10a2830 fffff801`57bcc756 nt!SwapContext+0x1f
    01 ffff8b89`a10a2870 fffff801`57b21cb5 nt!KiSwapContext+0x76
    02 ffff8b89`a10a29b0 fffff801`57bd6143 nt!NtYieldExecution+0x205
    03 ffff8b89`a10a2a00 00007ffb`d26cb264 nt!KiSystemServiceCopyEnd+0x13
    04 00000000`0422e938 00000000`00000000 0x00007ffb`d26cb264

      3    ffff8d81d8391180  ffffb086e5d82080 ( 8)                       ffff8d81d83a1100  ................

     # Child-SP          RetAddr           Call Site
    00 ffff8b89`9f3ba9b0 fffff801`57bd6143 nt!NtYieldExecution+0xd4
    01 ffff8b89`9f3baa00 00007ffb`d26cb264 nt!KiSystemServiceCopyEnd+0x13
    02 00000000`0439ef38 00000000`00000000 0x00007ffb`d26cb264

    ------------------------------------------------------------------------------

    1: 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

    dpcs: no pending DPCs found
    ----------------------------------------
    Last 100 DPC watchdog stack captures of this processor:Dump stack samples

    --------------------------------------------------
    CPU#1
    --------------------------------------------------
    Current DPC: No Active DPC

    Pending DPCs:
    ----------------------------------------
    CPU Type      KDPC       Function
     1: Normal  : 0xfffff80157dc3780 0xfffff80157b17be0 nt!PpmCheckPeriodicStart
     1: Normal  : 0xfffff80157dcf800 0xfffff80157a6a210 nt!KiBalanceSetManagerDeferredRoutine
     1: Normal  : 0xffff8d81d87a6568 0xfffff80157a6d490 nt!KiEntropyDpcRoutine

    ----------------------------------------
    Last 100 DPC watchdog stack captures of this processor:Dump stack samples

    --------------------------------------------------
    CPU#2
    --------------------------------------------------
    Current DPC: No Active DPC

    Pending DPCs:
    ----------------------------------------
    CPU Type      KDPC       Function

    dpcs: no pending DPCs found
    ----------------------------------------
    Last 100 DPC watchdog stack captures of this processor:Dump stack samples

    --------------------------------------------------
    CPU#3
    --------------------------------------------------
    Current DPC: No Active DPC

    Pending DPCs:
    ----------------------------------------
    CPU Type      KDPC       Function

    dpcs: no pending DPCs found
    ----------------------------------------
    Last 100 DPC watchdog stack captures of this processor:Dump stack samples

    Friday, June 14, 2019 6:58 PM
  • It looks like the processor is self deadlocked on either the device or queue lock. Do you call WdfObjectAcquireLock?

    Scott Noone
    Engineering Partner
    OSR Open Systems Resources, Inc.
    Windows Driver Training, Consulting, Problem Analysis, and Custom Development
    https://www.osr.com
    https://www.linkedin.com/in/scottnoone

    Friday, June 14, 2019 7:55 PM
  • No, in fact, when I first saw the message I thought maybe I was getting errors in my DPC in my Spinlocks.  So, I removed ALL of them and was planning to add them back in one at a time to see when it failed...Unfortunately, it still fails the same way with my SpinLocks removed.  

    The failing line seems to be in the WdfDeviceEnqueueRequest - like the WDF is deadlocked on itself.

    The only driver code of ours that seems to be running is the EvtIoInCallerContext, where I map a read and write buffer, then call the enqueue function.  

    To give you context of how it fails:

    1.  The driver is a WDF-AHCI driver (non-storport) used for testing drives.  

    2.  I currently have up to four drives per card

    3.  If I run just a series of tests, it sometimes crashes

    4.  If I hot-plug the drive while it is running, it will fail after two or three times of this (hot-plug interrupts are currently disabled - subsequent commands are setup to clear the AHCI hardware)

    5.  It is not required to hot-plug, hot-plug just makes it fail faster

    6.  Just before the GPF - the mouse hangs for sometime (20 seconds?) before it finally BSODs

    Friday, June 14, 2019 8:31 PM
  • It's definitely an internal WDF lock. Looks like your driver set a Synchronization Scope value and it's the lock used to synchronize that's the problem.

    Very strange...Sorry to say it just begs more questions at this point :)

    1. Anything interesting in the WDF Log (!wdfkd.wdflogdump drivername)?

    2. Have you run under Driver Verifier yet?


    Scott Noone
    Engineering Partner
    OSR Open Systems Resources, Inc.
    Windows Driver Training, Consulting, Problem Analysis, and Custom Development
    https://www.osr.com
    https://www.linkedin.com/in/scottnoone

    Friday, June 14, 2019 8:45 PM
  • Good suggestion on the WDF log (will try the verifier in a bit - hadn't had problems in months so we stopped using it - until we built a release to deploy, lol).  According to the log, it seems that someone already has the WDFQueue locked in the DPC (per your original suggestion)?   Perhaps some sort of problem with Wdf Completion routines?  

    WDF Log is at the bottom of this message.

    Here is our code snippet for the completion routine - you can see the Spinlock routines that I commented out (they previously had code that walked a list in them - I stripped all that out when I started seeing this to see if that was causing the problem):

    void GenericCompletionCode(sREQUEST_CONTEXT *current, struct _DEVICE_CONTEXT *DDFdo)
    {
    UNREFERENCED_PARAMETER(inSpinLock);
    UNREFERENCED_PARAMETER(DDFdo);
    NTSTATUS    status = STATUS_SUCCESS;

    //LINKEDLIST:
    /*
    WdfSpinLockAcquire(DDFdo->IOSpinLock);
    */

    // Look at the IO Code to see if we are a data command or not, and then complete the code.
    switch (current->IoControlCode)
    {
    case TARGET_DATA_IN:
    case TARGET_DATA_OUT:
    {
    //if GenericCompletionCode function is not under spinlock, we need to acquire the spinlock
    WDFDMATRANSACTION   dmaTransaction;
    dmaTransaction = current->dmaTransaction;
    // Tell the OS that the DMA is completed
    WdfDmaTransactionDmaCompleted(dmaTransaction, &status);
    // Ask the OS how many bytes were transferred
    size_t transferred = WdfDmaTransactionGetBytesTransferred(dmaTransaction);
    // Assign transferred to itself for the moment.  
    transferred = transferred;
    current->targetOutput->byteTransfered = transferred;
    // Delete the DMA object
    WdfObjectDelete(dmaTransaction);
    }
    break;
    default:
    break;
    }
    // Complete the request so that the application can continue running
    WdfRequestCompleteWithInformation(current->Request, status, current->targetOutput->sanity.sizeOfStructure);
    current->targetOutput = NULL;
    current->commandCompleted = 3;

    //LINKEDLIST:
    /*

    WdfSpinLockRelease(DDFdo->IOSpinLock);
    */
    }

    ------------ WDF Log Dump -----------------

    1: kd> !wdfkd.wdflogdump SeaBaseDriver
    Trace searchpath is: 

    Trace format prefix is: %7!u!: %!FUNC! - 
    Trying to extract TMF information from - C:\ProgramData\dbg\sym\Wdf01000.pdb\21C6668F673B09CA05ABCD75402752241\Wdf01000.pdb
    Gather log: Please wait, this may take a moment (reading 4024 bytes).
    % read so far ... 10, 20, 30, 40, 100
    There are 39 log entries
    --- start of log ---
    1: FxIFRStart - FxIFR logging started
    2: FxPkgPnp::PnpEnterNewState - WDFDEVICE 0x00004F7917EFFFF8 !devobj 0xFFFFB086E7FD6420 entering PnP State WdfDevStatePnpInit from WdfDevStatePnpObjectCreated
    3: FxPkgPnp::Dispatch - WDFDEVICE 0x00004F7917EFFFF8 !devobj 0xFFFFB086E7FD6420, IRP_MJ_PNP, 0x00000000(IRP_MN_START_DEVICE) IRP 0xFFFFB086E815B2B0
    4: FxPkgPnp::PnpEnterNewState - WDFDEVICE 0x00004F7917EFFFF8 !devobj 0xFFFFB086E7FD6420 entering PnP State WdfDevStatePnpInitStarting from WdfDevStatePnpInit
    5: FxPkgPnp::PnpEnterNewState - WDFDEVICE 0x00004F7917EFFFF8 !devobj 0xFFFFB086E7FD6420 entering PnP State WdfDevStatePnpHardwareAvailable from WdfDevStatePnpInitStarting
    6: FxInterrupt::AssignResources - Is MSI? 0, MSI-ID 0, AffinityPolicy WdfIrqPolicyOneCloseProcessor, Priority WdfIrqPriorityUndefined, Group 0, Affinity 0xf, Irql 0x9, Vector 0x91
    7: FxPkgPnp::PowerPolicyEnterNewState - WDFDEVICE 0x00004F7917EFFFF8 !devobj 0xFFFFB086E7FD6420 entering power policy state WdfDevStatePwrPolStarting from WdfDevStatePwrPolObjectCreated
    8: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE 0x00004F7917EFFFF8 !devobj 0xFFFFB086E7FD6420 entering power idle state FxIdleStarted from FxIdleStopped
    9: FxPkgPnp::PowerEnterNewState - WDFDEVICE 0x00004F7917EFFFF8 !devobj 0xFFFFB086E7FD6420 entering Power State WdfDevStatePowerStartingCheckDeviceType from WdfDevStatePowerObjectCreated
    10: FxPkgPnp::PowerEnterNewState - WDFDEVICE 0x00004F7917EFFFF8 !devobj 0xFFFFB086E7FD6420 entering Power State WdfDevStatePowerD0Starting from WdfDevStatePowerStartingCheckDeviceType
    11: FxPkgPnp::PowerEnterNewState - WDFDEVICE 0x00004F7917EFFFF8 !devobj 0xFFFFB086E7FD6420 entering Power State WdfDevStatePowerD0StartingConnectInterrupt from WdfDevStatePowerD0Starting
    12: FxPkgPnp::PowerEnterNewState - WDFDEVICE 0x00004F7917EFFFF8 !devobj 0xFFFFB086E7FD6420 entering Power State WdfDevStatePowerD0StartingDmaEnable from WdfDevStatePowerD0StartingConnectInterrupt
    13: FxPkgPnp::PowerEnterNewState - WDFDEVICE 0x00004F7917EFFFF8 !devobj 0xFFFFB086E7FD6420 entering Power State WdfDevStatePowerD0StartingStartSelfManagedIo from WdfDevStatePowerD0StartingDmaEnable
    14: FxPkgIo::ResumeProcessingForPower - Power resume all queues of WDFDEVICE 0x00004F7917EFFFF8
    15: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE 0x00004F7917EFFFF8 !devobj 0xFFFFB086E7FD6420 entering power idle state FxIdleStartedPowerUp from FxIdleStarted
    16: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE 0x00004F7917EFFFF8 !devobj 0xFFFFB086E7FD6420 entering power idle state FxIdleDisabled from FxIdleStartedPowerUp
    17: FxPkgPnp::PowerEnterNewState - WDFDEVICE 0x00004F7917EFFFF8 !devobj 0xFFFFB086E7FD6420 entering Power State WdfDevStatePowerDecideD0State from WdfDevStatePowerD0StartingStartSelfManagedIo
    18: FxPkgPnp::PowerEnterNewState - WDFDEVICE 0x00004F7917EFFFF8 !devobj 0xFFFFB086E7FD6420 entering Power State WdfDevStatePowerD0 from WdfDevStatePowerDecideD0State
    19: FxPkgPnp::PowerPolicyEnterNewState - WDFDEVICE 0x00004F7917EFFFF8 !devobj 0xFFFFB086E7FD6420 entering power policy state WdfDevStatePwrPolStartingPoweredUp from WdfDevStatePwrPolStarting
    20: FxPkgPnp::PowerPolicyEnterNewState - WDFDEVICE 0x00004F7917EFFFF8 !devobj 0xFFFFB086E7FD6420 entering power policy state WdfDevStatePwrPolStartingSucceeded from WdfDevStatePwrPolStartingPoweredUp
    21: FxPkgPnp::PowerPolicyEnterNewState - WDFDEVICE 0x00004F7917EFFFF8 !devobj 0xFFFFB086E7FD6420 entering power policy state WdfDevStatePwrPolStartingDecideS0Wake from WdfDevStatePwrPolStartingSucceeded
    22: FxPkgPnp::PowerPolicyEnterNewState - WDFDEVICE 0x00004F7917EFFFF8 !devobj 0xFFFFB086E7FD6420 entering power policy state WdfDevStatePwrPolStarted from WdfDevStatePwrPolStartingDecideS0Wake
    23: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE 0x00004F7917EFFFF8 !devobj 0xFFFFB086E7FD6420 entering power idle state FxIdleDisabled from FxIdleDisabled
    24: FxPkgPnp::PnpEnterNewState - WDFDEVICE 0x00004F7917EFFFF8 !devobj 0xFFFFB086E7FD6420 entering PnP State WdfDevStatePnpEnableInterfaces from WdfDevStatePnpHardwareAvailable
    25: FxPkgPnp::PnpEnterNewState - WDFDEVICE 0x00004F7917EFFFF8 !devobj 0xFFFFB086E7FD6420 entering PnP State WdfDevStatePnpStarted from WdfDevStatePnpEnableInterfaces
    26: FxPkgPnp::Dispatch - WDFDEVICE 0x00004F7917EFFFF8 !devobj 0xFFFFB086E7FD6420, IRP_MJ_PNP, 0x00000014(IRP_MN_QUERY_PNP_DEVICE_STATE) IRP 0xFFFFB086E7FFFBB0
    27: FxPkgFdo::HandleQueryPnpDeviceStateCompletion - WDFDEVICE 0x00004F7917EFFFF8 !devobj 0xFFFFB086E7FD6420 returning PNP_DEVICE_STATE 0x0 IRP 0xFFFFB086E7FFFBB0
    28: FxPkgPnp::Dispatch - WDFDEVICE 0x00004F7917EFFFF8 !devobj 0xFFFFB086E7FD6420, IRP_MJ_PNP, 0x00000007(IRP_MN_QUERY_DEVICE_RELATIONS) type BusRelations IRP 0xFFFFB086E7FFFBB0
    29: FxPkgPnp::Dispatch - WDFDEVICE 0x00004F7917EFFFF8 !devobj 0xFFFFB086E7FD6420, IRP_MJ_PNP, 0x00000007(IRP_MN_QUERY_DEVICE_RELATIONS) type EjectionRelations IRP 0xFFFFB086EBB6DD30
    30: FxPkgPnp::Dispatch - WDFDEVICE 0x00004F7917EFFFF8 !devobj 0xFFFFB086E7FD6420, IRP_MJ_PNP, 0x00000007(IRP_MN_QUERY_DEVICE_RELATIONS) type RemovalRelations IRP 0xFFFFB086EBB6DD30
    31: FxPkgPnp::Dispatch - WDFDEVICE 0x00004F7917EFFFF8 !devobj 0xFFFFB086E7FD6420, IRP_MJ_PNP, 0x00000007(IRP_MN_QUERY_DEVICE_RELATIONS) type PowerRelations IRP 0xFFFFB086EBB6DD30
    32: FxPkgPnp::Dispatch - WDFDEVICE 0x00004F7917EFFFF8 !devobj 0xFFFFB086E7FD6420, IRP_MJ_PNP, 0x00000007(IRP_MN_QUERY_DEVICE_RELATIONS) type TransportRelations IRP 0xFFFFB086EBB6DD30
    33: FxPkgPnp::Dispatch - WDFDEVICE 0x00004F7917EFFFF8 !devobj 0xFFFFB086E7FD6420, IRP_MJ_PNP, 0x00000007(IRP_MN_QUERY_DEVICE_RELATIONS) type EjectionRelations IRP 0xFFFFB086EBB6DD30
    34: FxPkgPnp::Dispatch - WDFDEVICE 0x00004F7917EFFFF8 !devobj 0xFFFFB086E7FD6420, IRP_MJ_PNP, 0x00000007(IRP_MN_QUERY_DEVICE_RELATIONS) type RemovalRelations IRP 0xFFFFB086EBB6DD30
    35: FxPkgPnp::Dispatch - WDFDEVICE 0x00004F7917EFFFF8 !devobj 0xFFFFB086E7FD6420, IRP_MJ_PNP, 0x00000007(IRP_MN_QUERY_DEVICE_RELATIONS) type PowerRelations IRP 0xFFFFB086EBB6DD30
    36: FxPkgPnp::Dispatch - WDFDEVICE 0x00004F7917EFFFF8 !devobj 0xFFFFB086E7FD6420, IRP_MJ_PNP, 0x00000007(IRP_MN_QUERY_DEVICE_RELATIONS) type TransportRelations IRP 0xFFFFB086EBB6DD30
    37: FxIoQueue::CanThreadDispatchEventsLocked - Presentation lock for WDFQUEUE 0x00004F7917EF74F8 is already held, deferring to dpc or workitem
    38: FxIoQueue::CanThreadDispatchEventsLocked - Presentation lock for WDFQUEUE 0x00004F7917EF74F8 is already held, deferring to dpc or workitem
    39: FxIoQueue::CanThreadDispatchEventsLocked - Presentation lock for WDFQUEUE 0x00004F7917EF74F8 is already held, deferring to dpc or workitem
    ---- end of log ----


    Friday, June 14, 2019 9:21 PM
  • Scott and Pavel - the Driver Verifier nailed it.  This is interesting.

    I was issuing a reset to some hardware which required specific timing.  I was calling KeDelayExecutionThread() from a DevIO call, and apparently when hooked to a debugger it lets you get away with it.  When I turned on the driver verifier, and hot unplugged my device, it failed the command and then the app requested a reset.  Instant BSOD.  You probably would not appreciate my timer fix, so I won't post it here.  ;)  (has to do with reading the tick counts and spinning).

    What is curious is why did the debug trace not catch this until I turned on the verifier?  

    So, KeDelayExecutionThread() was causing the entire problem, obviously because the IRQL was too high.  Sadly, per the hardware specs, I really do need to predictably reinit the HW at runtime when error conditions occur, so I need a reliable timer.  So, using the tick counts fixed the problem.

    Thanks for your help!!!


    Tuesday, June 18, 2019 8:34 PM