Windows 7 USB lockup after selective suspend resume

[dhmot]

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

[Philip Ries [MSFT]]

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]

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:

> .
>

[Philip Ries [MSFT]]

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]

Philip,

I was unable to reproduce the problem after placing the device in an
external, powered USB hub. It seems then that the problem is related to
KB978258. I will work through Microsoft support based on your information
below.

Thanks,
Michael

"Philip Ries [MSFT]" wrote:

> .
>

[dhmot]

Philip,

When I moved the device to a powered external USB hub, the problem no longer
occurred. I will attempt to get information on the KB through support.

Thanks,
Michael

"Philip Ries [MSFT]" wrote:

> .
>

[dhmot]

Philip,

Sorry for the duplicate replies earlier.

Following the link you provided requires an access ID and a contract ID. I
assume my access ID is the same as my MSDN ID (or one of the numbers
associated with it). However, I am unable to get a a contract ID. Whenever
I call the 800 number to get a contract ID, I get the runaround when I
mention the information I'm looking for (details concerning KB 978258). The
lady who answered the phone would not provide a contract ID because I was not
running an official release of Windows 7.

In the end, I was told to return to the forums and ask for further
information concerning this issue.

Is there some magic phrase I have to use to get a contract number when I
call? I should have at least two technical support incidents available to
me. Or do I need to restart the whole technical support question series from
scratch, describing the problem as if I had never heard of KB 978258?

Thanks,
Michael

"Philip Ries [MSFT]" wrote:

> .
>

[Philip Ries [MSFT]]

> The lady who answered the phone would not provide a contract ID because I was not running an official release of Windows 7.

You're not running Win7 RTM?

[Pavel A.]

"dhmot" <dh...@discussions.microsoft.com> wrote in message
news:92D55AAA-E1CA-408F...@microsoft.com...

> lady who answered the phone would not provide a contract ID because I was
> not
> running an official release of Windows 7.

??? Then test on the official release:
http://technet.microsoft.com/en-us/evalcenter/cc442495.aspx

--pa

[dhmot]

Pavel,

Thanks. I did. Same results.

Michael

[dhmot]

I don't know what "Win7 RTM" is, but yesterday I downloaded Windows 7
Professional (dated 11/12/09) from the MSDN site. The problem still occurs
with that version.

Michael

"Philip Ries [MSFT]" wrote:

> .
>

[dhmot]

Pavel,

Actually, I should say I tested with the version on MSDN dated 11/12/09,
with all the updates downloaded from the Microsoft web site. Same results.

Michael