Re: Windows 7 USB lockup after selective suspend resume

Tech-Archive recommends: Repair Windows Errors & Optimize Windows Performance

The device didn't come out of suspend successfully the third time. I would try to repro with the device behind an external hub. If you can't repro there then it may be a known issue with the EHCI driver. This issue has a QFE (fix) under consideration.

If you'd like to get the QFE as soon as possible, please contact Microsoft support (some instructions pasted below). The KB number for this issue will be 978258, you can refer to this number in the support case.

Thanks,
Philip

For more information on how to open a Windows Driver Kit (WDK) service request in order to receive USB driver development support, please click or copy the below link:

http://support.microsoft.com/select/?LN=en-us&target=assistance&x=13&y=9

In the “Quick product finder” field, type “Windows Driver Kit” as the product and select that product

dhmot wrote:
Philip,

I've emailed you the USB trace. One odd thing is that I noticed is that none of my power management callbacks were invoked this time, or at least none showed up in DbgView this time. But the result is the same - the USB driver hangs on the send requests and does not request data from the USB device. However, it does appear from the trace that there was an attempt to enter selective suspend at 188.505.

One other point I did not mention, but the driver's execution level (ExecutionLevel) is set to WdfExecutionLevelPassive. I do not know if this is pertinent.

Here's the output of a good selective suspend under Windows 7. FYI, I do hand-edit for clarity:
------------------------
5.783 Last read event received
10.783 EvtDeviceSelfManagedIoSuspend routine entered
- Continuous readers stopped (3 pipes)
- Read request cancelled (1 pipe) 10.785 EvtDeviceSelfManagedIoSuspend routine exited
10.785 EvtDeviceD0Exit routine entered
10.785 EvtDeviceD0Exit routine exited

< Driver in selected suspend state at this point>

21.938 Write request sent to power management queue 22.057 Power management write queue handler entered 22.057 Write request forwarded to USB pipe IO target
22.057 Power management write queue handler exited 22.057 EvtDeviceSelfManagedIoRestart routine entered
22.058 Reader for pipe #1 restarted 22.058 Write completion callback entered with no error
22.058 Write completion callback completes request
22.058 Write completion callback exited
22.058 Reader for pipe #2 restarted
22.058 Reader for pipe #3 restarted
22.058 Read request posted to pipe #4
22.058 EvtDeviceSelfManagedIoRestart routine exited

< Driver out of selected suspend state at this point>

22.153 Read completion callback entered with no error
22.153 Read completion callback exited
23.018 Last read event received
28.018 EvtDeviceSelfManagedIoSuspend routine entered
- Continuous readers stopped (3 pipes)
- Read request cancelled (1 pipe)
28.019 EvtDeviceSelfManagedIoSuspend routine exited
28.019 EvtDeviceD0Exit routine entered
28.019 EvtDeviceD0Exit routine exited

< Driver in selected suspend state at this point>
------------------------

Let me know if you want any further information. Note that I will be on vacation starting tomorrow until the end of December or beginning of January.

Thanks,
Michael


"Philip Ries [MSFT]" wrote:

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
.

.

Relevant Pages

  • Re: Windows 7 USB lockup after selective suspend resume
    ... driver hangs on the send requests and does not request data from the USB ... EvtDeviceSelfManagedIoSuspend routine entered ... Write request forwarded to USB pipe IO target ... Reader for pipe #1 restarted ...
    (microsoft.public.development.device.drivers)
  • Re: Windows 7 USB lockup after selective suspend resume
    ... But the result is the same - the USB driver hangs on the send requests and does not request data from the USB device. ... EvtDeviceSelfManagedIoSuspend routine entered ... Write request forwarded to USB pipe IO target ... Reader for pipe #1 restarted ...
    (microsoft.public.development.device.drivers)
  • Re: Windows 7 USB lockup after selective suspend resume
    ... driver hangs on the send requests and does not request data from the USB ... EvtDeviceSelfManagedIoSuspend routine entered ... Write request forwarded to USB pipe IO target ... Reader for pipe #1 restarted ...
    (microsoft.public.development.device.drivers)
  • Re: Windows 7 USB lockup after selective suspend resume
    ... external, powered USB hub. ... EvtDeviceSelfManagedIoSuspend routine entered ... Write request forwarded to USB pipe IO target ... Reader for pipe #1 restarted ...
    (microsoft.public.development.device.drivers)
  • Re: Windows 7 USB lockup after selective suspend resume
    ... When I moved the device to a powered external USB hub, ... EvtDeviceSelfManagedIoSuspend routine entered ... Write request forwarded to USB pipe IO target ... Reader for pipe #1 restarted ...
    (microsoft.public.development.device.drivers)