Power-managed queues and EvtIoStop

Shane_Corbin · July 22, 2013, 5:24pm

I have a really simple driver that is sporadically causing a 9F bugcheck on system shutdown. It says an IRP is taking too long to complete. The driver isn’t intended to hold any requests for any period of time and I’m looking to figure out how to determine what request it is having a hard time completing.

My suspicion, as evident by the title of this thread, is that if I were to cancel/complete outstanding requests by registering a EvtIoStop callback that I could resolve this issue. However, I want to know what this particular request is, who sent it and why it isn’t able to complete in a timely manner. My lack of WinDbg skills is holding me back though. Anybody care to school me on how I can troubleshoot this?

Doron_Holan · July 22, 2013, 5:38pm

Upon bugcheck, run
!wdfkd.wdflogdump

To see if kmdf is waiting for you to ACK any pending requests

!wdfkd.wdfdevicequeues

Will tell you all outstanding requests and what state they are in

d

-----Original Message-----
From: xxxxx@lists.osr.com [mailto:xxxxx@lists.osr.com] On Behalf Of xxxxx@hotmail.com
Sent: Monday, July 22, 2013 2:24 PM
To: Windows System Software Devs Interest List
Subject: [ntdev] Power-managed queues and EvtIoStop

I have a really simple driver that is sporadically causing a 9F bugcheck on system shutdown. It says an IRP is taking too long to complete. The driver isn’t intended to hold any requests for any period of time and I’m looking to figure out how to determine what request it is having a hard time completing.

My suspicion, as evident by the title of this thread, is that if I were to cancel/complete outstanding requests by registering a EvtIoStop callback that I could resolve this issue. However, I want to know what this particular request is, who sent it and why it isn’t able to complete in a timely manner. My lack of WinDbg skills is holding me back though. Anybody care to school me on how I can troubleshoot this?

—
NTDEV is sponsored by OSR

Visit the list at: http://www.osronline.com/showlists.cfm?list=ntdev

OSR is HIRING!! See http://www.osr.com/careers

For our schedule of WDF, WDM, debugging and other seminars visit:
http://www.osr.com/seminars

To unsubscribe, visit the List Server section of OSR Online at http://www.osronline.com/page.cfm?name=ListServer

William_J_Casey · July 22, 2013, 5:49pm

Again thanks for this but ours is only a WDM driver not KMDF. I’m
considering removing the LSI driver with ‘devcon remove (INF) (HwID)’ -
think that will work?

Bill Casey
?
== VirDIS? & VirtualSCSI? Target Mode Solutions ==
Advanced Storage Concepts, Inc.???(409) 762-0604
2200 Market Street, Suite 810??xxxxx@virtualscsi.com
Galveston, TX USA 77550-1532???www.virtualscsi.com

-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of Doron Holan
Sent: Monday, July 22, 2013 4:35 PM
To: Windows System Software Devs Interest List
Subject: RE: [ntdev] Power-managed queues and EvtIoStop

Upon bugcheck, run
!wdfkd.wdflogdump

To see if kmdf is waiting for you to ACK any pending requests

!wdfkd.wdfdevicequeues

Will tell you all outstanding requests and what state they are in

d

-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of
xxxxx@hotmail.com
Sent: Monday, July 22, 2013 2:24 PM
To: Windows System Software Devs Interest List
Subject: [ntdev] Power-managed queues and EvtIoStop

I have a really simple driver that is sporadically causing a 9F bugcheck on
system shutdown. It says an IRP is taking too long to complete. The driver
isn’t intended to hold any requests for any period of time and I’m looking
to figure out how to determine what request it is having a hard time
completing.

My suspicion, as evident by the title of this thread, is that if I were to
cancel/complete outstanding requests by registering a EvtIoStop callback
that I could resolve this issue. However, I want to know what this
particular request is, who sent it and why it isn’t able to complete in a
timely manner. My lack of WinDbg skills is holding me back though. Anybody
care to school me on how I can troubleshoot this?

—
NTDEV is sponsored by OSR

Visit the list at: http://www.osronline.com/showlists.cfm?list=ntdev

OSR is HIRING!! See http://www.osr.com/careers

For our schedule of WDF, WDM, debugging and other seminars visit:
http://www.osr.com/seminars

To unsubscribe, visit the List Server section of OSR Online at
http://www.osronline.com/page.cfm?name=ListServer

—
NTDEV is sponsored by OSR

Visit the list at: http://www.osronline.com/showlists.cfm?list=ntdev

OSR is HIRING!! See http://www.osr.com/careers

For our schedule of WDF, WDM, debugging and other seminars visit:
http://www.osr.com/seminars

To unsubscribe, visit the List Server section of OSR Online at
http://www.osronline.com/page.cfm?name=ListServer

Shane_Corbin · July 22, 2013, 6:27pm

!wdfkd.wdflogdump

warn: The log could not be accessed
hint: Are the symbols the WDF library available?
hint: The log is inaccessable after driver unload

Without being able to run logdump I don’t know how to get my WDFDEVICE to pass to !wdfkd.wdfdevicequeues

I loaded the tmf files with:
!wdftmffile C:\WinDDK\7600.16385.1\tools\tracing\i386\Wdf01009.tmf

When the bugcheck occurs here’s what I get:
DRIVER_POWER_STATE_FAILURE (9f)
A driver is causing an inconsistent power state.
Arguments:
Arg1: 00000003, A device object has been blocking an Irp for too long a time
Arg2: 86e9e428, Physical Device Object of the stack
Arg3: 831299e0, Functional Device Object of the stack
Arg4: 864c97b0, The blocked IRP

If I do a !irp 864c97b0, I get:
0: kd> !irp 864c97b0
Irp is active with 3 stacks 1 is current (= 0x864c9820)
No Mdl: No System Buffer: Thread 00000000: Irp stack trace.
cmd flg cl Device File Completion-Context
>[16, 2] 0 0 86e9e428 00000000 00000000-00000000
\Driver\mf
Args: 00016600 00000001 00000004 00000006
[16, 2] 0 e1 8702a020 00000000 83084e70-8787d2f0 Success Error Cancel pending
\Driver\MySimpleDriver nt!IopUnloadSafeCompletion
Args: 00016600 00000001 00000004 00000006
[0, 0] 0 0 00000000 00000000 00000000-86f21c80

Args: 00000000 00000000 00000000 00000000

I’m not sure where to go after this point though.

Doron_Holan · July 22, 2013, 7:40pm

Fix your symbols, retry. Force a reload. If that doesn’t work, take the fdo from the bugcheck parameters, run

!devobj (fdo)
!wdfkd.wdfdevext (device extension pointer from !devobj)

That will give you the wdfdevice

d

Bent from my phone

From: xxxxx@hotmail.com mailto:xxxxx
Sent: ?7/?22/?2013 3:27 PM
To: Windows System Software Devs Interest Listmailto:xxxxx
Subject: RE:[ntdev] Power-managed queues and EvtIoStop

!wdfkd.wdflogdump

warn: The log could not be accessed
hint: Are the symbols the WDF library available?
hint: The log is inaccessable after driver unload

Without being able to run logdump I don’t know how to get my WDFDEVICE to pass to !wdfkd.wdfdevicequeues

I loaded the tmf files with:
!wdftmffile C:\WinDDK\7600.16385.1\tools\tracing\i386\Wdf01009.tmf

When the bugcheck occurs here’s what I get:
DRIVER_POWER_STATE_FAILURE (9f)
A driver is causing an inconsistent power state.
Arguments:
Arg1: 00000003, A device object has been blocking an Irp for too long a time
Arg2: 86e9e428, Physical Device Object of the stack
Arg3: 831299e0, Functional Device Object of the stack
Arg4: 864c97b0, The blocked IRP

If I do a !irp 864c97b0, I get:
0: kd> !irp 864c97b0
Irp is active with 3 stacks 1 is current (= 0x864c9820)
No Mdl: No System Buffer: Thread 00000000: Irp stack trace.
cmd flg cl Device File Completion-Context
>[16, 2] 0 0 86e9e428 00000000 00000000-00000000
\Driver\mf
Args: 00016600 00000001 00000004 00000006
[16, 2] 0 e1 8702a020 00000000 83084e70-8787d2f0 Success Error Cancel pending
\Driver\MySimpleDriver nt!IopUnloadSafeCompletion
Args: 00016600 00000001 00000004 00000006
[0, 0] 0 0 00000000 00000000 00000000-86f21c80

Args: 00000000 00000000 00000000 00000000

I’m not sure where to go after this point though.

—
NTDEV is sponsored by OSR

Visit the list at: http://www.osronline.com/showlists.cfm?list=ntdev

OSR is HIRING!! See http://www.osr.com/careers

For our schedule of WDF, WDM, debugging and other seminars visit:
http://www.osr.com/seminars

To unsubscribe, visit the List Server section of OSR Online at http://www.osronline.com/page.cfm?name=ListServer</mailto:xxxxx></mailto:xxxxx>

Shane_Corbin · July 23, 2013, 2:18pm

I was wrong. Providing an EvtIoStop callback did not resolve my issues with my 9F bugcheck. I tried completing and canceling requests, I tried WdfRequestStopAcknowledge too. I then inserted a hardcoded breakpoint in this callback and found that it was never being called. This leads me to believe that the queue has no requests outstanding at the time of the system shutdown request.

To be certain I put a hardcode breakpoint in my EvtIoDeviceControl callback and made sure that all requests were getting completed successfully. I have no EvtIoRead/Write, only DeviceControl. When I remove this driver I no longer get the 9F bugcheck. What else could I be doing that would holdup a system shutdown? I do have an EvtDeviceD0Exit callback that I can step through to completion so I’m not suspicious that it is the root cause.

Doron_Holan · July 23, 2013, 2:25pm

You need to hook up a kernel debugger and figure this out deterministically instead of shotgunning guesses across your driver.

d

-----Original Message-----
From: xxxxx@lists.osr.com [mailto:xxxxx@lists.osr.com] On Behalf Of xxxxx@hotmail.com
Sent: Tuesday, July 23, 2013 11:18 AM
To: Windows System Software Devs Interest List
Subject: RE:[ntdev] Power-managed queues and EvtIoStop

I was wrong. Providing an EvtIoStop callback did not resolve my issues with my 9F bugcheck. I tried completing and canceling requests, I tried WdfRequestStopAcknowledge too. I then inserted a hardcoded breakpoint in this callback and found that it was never being called. This leads me to believe that the queue has no requests outstanding at the time of the system shutdown request.

To be certain I put a hardcode breakpoint in my EvtIoDeviceControl callback and made sure that all requests were getting completed successfully. I have no EvtIoRead/Write, only DeviceControl. When I remove this driver I no longer get the 9F bugcheck. What else could I be doing that would holdup a system shutdown? I do have an EvtDeviceD0Exit callback that I can step through to completion so I’m not suspicious that it is the root cause.

NTDEV is sponsored by OSR

Visit the list at: http://www.osronline.com/showlists.cfm?list=ntdev

OSR is HIRING!! See http://www.osr.com/careers

For our schedule of WDF, WDM, debugging and other seminars visit:
http://www.osr.com/seminars

To unsubscribe, visit the List Server section of OSR Online at http://www.osronline.com/page.cfm?name=ListServer

Shane_Corbin · July 23, 2013, 2:40pm

I do have the debugger attached. That’s how I’m stepping through making sure the requests are being completed with status success.

Doron_Holan · July 23, 2013, 2:47pm

the wdfkd.dll debugger extensions should tell you exactly why KMDF is waiting/blocking and thus resulting in the 9f bugcheck.

d

-----Original Message-----
From: xxxxx@lists.osr.com [mailto:xxxxx@lists.osr.com] On Behalf Of xxxxx@hotmail.com
Sent: Tuesday, July 23, 2013 11:40 AM
To: Windows System Software Devs Interest List
Subject: RE:[ntdev] Power-managed queues and EvtIoStop

I do have the debugger attached. That’s how I’m stepping through making sure the requests are being completed with status success.

NTDEV is sponsored by OSR

Visit the list at: http://www.osronline.com/showlists.cfm?list=ntdev

OSR is HIRING!! See http://www.osr.com/careers

For our schedule of WDF, WDM, debugging and other seminars visit:
http://www.osr.com/seminars

To unsubscribe, visit the List Server section of OSR Online at http://www.osronline.com/page.cfm?name=ListServer

Shane_Corbin · July 23, 2013, 3:01pm

Thanks for your patience Doron… This must be my problem… I’m unable to perform a proper wdflogdump… When I run .help here’s what I get:
1: kd> !wdfkd.help
Wdfkd.dll extension built on Feb 01 2010 at 12:11:00

When I try a logdump I get:
1: kd> !wdfkd.wdflogdump mydriver
Trace searchpath is:

Trace format prefix is: %7!u!: %!FUNC! -

Missing location of the log’s format files. Please use one
of the following options to specify their location:

(1) !wdfsearchpath command
(2) the environmental TRACE_FORMAT_SEARCH_PATH=
(3) !wdftmffile command

See !wdfhelp for more information.

I then do:
kd> !wdftmffile C:\WinDDK\7600.16385.1\tools\tracing\i386\Wdf01009.tmf
Set TMF file name is : ‘C:\WinDDK\7600.16385.1\tools\tracing\i386\Wdf01009.tmf’

Then retry the logdump:
1: kd> !wdfkd.wdflogdump mydriver

But WinDbg stays BUSY and doesn’t return. I left this running over night and it still hadn’t returned. It’s a firewire connection between two Ivy Bridge machines so they aren’t ancient. My symbols appear to be loaded properly as I can step through my driver just fine. I’m using WinDbg version 6.12.0002.633.

What’s a fella to do in a situation like this?

Doron_Holan · July 23, 2013, 3:12pm

Try using the win8 WDK’s debugger and wdfkd.dll

d

-----Original Message-----
From: xxxxx@lists.osr.com [mailto:xxxxx@lists.osr.com] On Behalf Of xxxxx@hotmail.com
Sent: Tuesday, July 23, 2013 12:00 PM
To: Windows System Software Devs Interest List
Subject: RE:[ntdev] Power-managed queues and EvtIoStop

Thanks for your patience Doron… This must be my problem… I’m unable to perform a proper wdflogdump… When I run .help here’s what I get:
1: kd> !wdfkd.help
Wdfkd.dll extension built on Feb 01 2010 at 12:11:00

When I try a logdump I get:
1: kd> !wdfkd.wdflogdump mydriver
Trace searchpath is:

Trace format prefix is: %7!u!: %!FUNC! -

Missing location of the log’s format files. Please use one of the following options to specify their location:

(1) !wdfsearchpath command
(2) the environmental TRACE_FORMAT_SEARCH_PATH=
(3) !wdftmffile command

See !wdfhelp for more information.

I then do:
kd> !wdftmffile C:\WinDDK\7600.16385.1\tools\tracing\i386\Wdf01009.tmf
Set TMF file name is : ‘C:\WinDDK\7600.16385.1\tools\tracing\i386\Wdf01009.tmf’

Then retry the logdump:
1: kd> !wdfkd.wdflogdump mydriver

But WinDbg stays BUSY and doesn’t return. I left this running over night and it still hadn’t returned. It’s a firewire connection between two Ivy Bridge machines so they aren’t ancient. My symbols appear to be loaded properly as I can step through my driver just fine. I’m using WinDbg version 6.12.0002.633.

What’s a fella to do in a situation like this?

—
NTDEV is sponsored by OSR

Visit the list at: http://www.osronline.com/showlists.cfm?list=ntdev

OSR is HIRING!! See http://www.osr.com/careers

For our schedule of WDF, WDM, debugging and other seminars visit:
http://www.osr.com/seminars

To unsubscribe, visit the List Server section of OSR Online at http://www.osronline.com/page.cfm?name=ListServer