Re: Windows 7 USB lockup after selective suspend resume
- From: "Philip Ries [MSFT]" <phries@xxxxxxxxxxxxx>
- Date: Thu, 17 Dec 2009 18:27:19 -0800
Hi Michael,
You can send me a USB ETW trace and I'll see if it shows anything interesting. Instructions here: http://blogs.msdn.com/usbcoreblog/archive/2009/12/04/etw-in-the-windows-7-usb-core-stack.aspx
You can also look through the trace yourself using the latter part of the instructions.
I'd also be interested to see the DbgView output like below for a successful resume from selective suspend for a write and then return to selective suspend.
Philip
dhmot wrote:
I have a KMDF USB driver for a network device that supports selective suspend (this is a two piece driver, as recommended in Doron Holan's blog). This driver passes WHQL for XP and 7. I am having problems with the x86 (x64 untested with this scenario) Windows 7/WDF 1009 version of the driver under scenarios where a request is received in a power managed queue within 2-3 milliseconds of the WDF USB driver completing its EvtDeviceD0Exit routine. The selective suspend timeout is set to 5 seconds. The timeline looks something like this (per output from DbgView):.
119.872 Last read event received
124.866 EvtDeviceSelfManagedIoSuspend routine entered
- Continuous readers stopped (3 pipes)
- Read request cancelled (1 pipe)
124.867 EvtDeviceSelfManagedIoSuspend exited
124.867 EvtDeviceD0Exit entered
124.867 EvtDeviceD0Exit exited
< Driver in selected suspend state at this point>
124.868 Write request sent to power management queue
124.973 Power management write queue handler entered
124.973 Write request forwarded to USB pipe IO target
124.973 Power management write queue handler exited
124.973 EvtDeviceSelfManagedIoRestart entered
124.973 Reader for pipe #1 restarted
124.973 Write completion callback entered with result of 0xc0000001
124.973 Write completion callback completes request
124.973 Write completion callback exited
124.974 Reader for pipe #2 restarted
124.974 Reader for pipe #3 restarted
124.974 Read request posted to pipe #4
124.974 EvtDeviceSelfManagedIoRestart exited
< Driver out of selected suspend state at this point>
124.974 Read completion callback entered with result of 0xc0000001 for pipe #4
124.974 Read completion callback exited
124.974 Reader for pipe #1 fail callback entered with error code 0xc0000001.
124.974 Reader for pipe #1 fail callback exited with TRUE to restart reader.
124.974 Reader for pipe #2 fail callback entered with error code 0xc0000001.
124.974 Reader for pipe #2 fail callback exited with TRUE to restart reader.
124.974 Reader for pipe #3 fail callback entered with error code 0xc0000001.
124.974 Reader for pipe #3 fail callback exited with TRUE to restart reader.
129.971 EvtDeviceSelfManagedIoSuspend routine entered
- Continuous readers stopped (3 pipes)
129.971 EvtDeviceSelfManagedIoSuspend exited
129.971 EvtDeviceD0Exit entered
129.971 EvtDeviceD0Exit exited
< Driver in selected suspend state at this point>
130.381 Write request sent to power management queue
130.518 Power management write queue handler entered
130.518 Request forwarded to USB pipe IO target
130.518 Power management write queue handler exited
130.518 EvtDeviceSelfManagedIoRestart entered
130.518 Reader for pipe #1 restarted
130.519 Reader for pipe #2 restarted
130.519 Reader for pipe #3 restarted
130.519 Read request posted to pipe #4, but returns error of 0xc0000120
130.519 EvtDeviceSelfManagedIoRestart exited
The write that was posted on 130.381 never completes, nor does any subsequent write request. Eventually the driver runs out of transmit buffers. When the device is unplugged, all pending write requests are comleted with a status of 0xc0000120.
I connected an Ellisys USB analyzer to confirm that the issue was not with my device. I did notice a bit of an oddity on the USB side which seems to correspond with the above failure. The timestamps here don't match up exactly with the above, as I started DbgView a few seconds after the USB analyzer:
110.811 Bulk transfer
115.805 SetFeature(RemoteWakeup) sent to device
<15.5 milliseconds of selective suspend>
115.960 ClearFeature(RemoteWakeup) sent to device
115.961 Bulk transfer
.....
126.034 Bulk transfer
131.032 SetFeature(RemoteWakeup) sent to device
<5.5 seconds of selective suspend>
136.684 ClearFeature(RemoteWakeup) sent to device
After the last "ClearFeature", there is no further read or write requests made on any endpoint, i.e. the readers are not doing their job and the writes are never sent (no NAKs are present). At this point, the only recovery is to unplug the USB device and re-insert the USB device. A reboot is not necessary to recover from this situation. This scenario is very easy to reproduce and is not simply some corner scenario.
The data rate is very low when this occurs, a six packet burst of 30 bytes or so every five seconds. It is a USB 2.0 device and enumerates as such. If I shut off selective suspend, I do not run into any issues. I have also downloaded the latest updates from the Microsoft web site for Windows 7.
What is the problem here? Is there a solution, short of disabling selective suspend?
Thanks,
Michael
- Follow-Ups:
- References:
- Prev by Date: Re: Ndis protocol driver and windows 7
- Next by Date: Re: NDIS intermediate driver under Windows 7
- Previous by thread: Windows 7 USB lockup after selective suspend resume
- Next by thread: Re: Windows 7 USB lockup after selective suspend resume
- Index(es):
Relevant Pages
|
