Power management deadlock

NTDEV
1

I have a crashdump created manually on customer’s deadlocked computer. Deadlock occured during system suspend and it was my USB driver which blocked S3 query IRP. It has a reason: it tried to cancel selective suspend before and sent D0 IRP to UsbHub driver. This IRP was never completed and I’d like to know why. From the dump it seems as the order of events was following:

  • driver passed idle IRP down to the stack
  • idle callback was called, driver successfully set device to D2
  • later an event occured and driver decided to turn device on; it sent D0 IRP down the stack
  • system sent S3 query to the driver
  • driver started waiting until both D0 and idle IRPs are completed but below driver never did it -> deadlock

Unfortunately, I’m unable to reproduce the problem. It occured under high system and selective suspend stress test (driver counters in the dump show 121 system and 6595 device suspends) and it was probably caused by some kind of race conditions. It seems as the problem could be in the UsbHub driver but it is hard to decide. Anyway, there is something wrong:

Windows XP Kernel Version 2600 (Service Pack 2) UP Free x86 compatible
Product: WinNt, suite: TerminalServer SingleUserTS
Built by: 2600.xpsp_sp2_rtm.040803-2158

kd> !poreqlist
All active Power Irps from PoRequestPowerIrp
PopReqestedPowerIrpList
FieldOffset = 00000004
Irp 86768718 DevObj 867e4290 \Driver\ACPI Ctx 00000005 * Wait Wake S4
Irp 85297008 DevObj 8659e618 \Driver\usbuhci Ctx 00000001 Wait Wake S0
Irp 864095d8 DevObj 86370030 \Driver\usbuhci Ctx 00000001 Wait Wake S0
Irp 85644e48 DevObj 85851de8 \Driver\usbhub Ctx 00000001 Wait Wake S0
Irp 8661be48 DevObj 0000000000000000: Could not read device object or _DEVICE_OBJECT not found
Ctx 00000002 [blocked]
Irp 867284d0 DevObj 85851de8 \Driver\usbhub Ctx 00000003 Set Power D0 ShutdownType 2
Irp 863fca50 DevObj 0000000000000000: Could not read device object or _DEVICE_OBJECT not found
Ctx 00000002 [blocked]

The D0 IRP I mentioned before is IRP 867284d0. There are two strange IRPs marked as [blocked] above:

kd> !irp 8661be48
Irp is active with 6 stacks 5 is current (= 0x8661bf48)
No Mdl Thread 00000000: Irp stack trace.
cmd flg cl Device File Completion-Context
[0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000
[0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000
[0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000
[16, 2] 0 e1 8637ac98 00000000 805094ff-f7a13e16 Success Error Cancel pending
\Driver\usbhub nt!PopCompleteRequestIrp
Args: 00000003 00000001 00000001 00000002

[0, 0] 0 0 8637ac98 00000000 00000000-00000000
\Driver\usbhub
Args: 8624c030 00000002 00000001 8637ad50
[0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 867285f8 85644f70 8661be48 00000000
kd> !irp 863fca50
Irp is active with 6 stacks 5 is current (= 0x863fcb50)
No Mdl Thread 00000000: Irp stack trace.
cmd flg cl Device File Completion-Context
[0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000
[0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000
[0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000
[16, 2] 0 e0 8637ac98 00000000 805094ff-f7a143e6 Success Error Cancel
\Driver\usbhub nt!PopCompleteRequestIrp
Args: 00000003 00000001 00000001 00000002

[0, 0] 0 0 8637ac98 00000000 00000000-00000000
\Driver\usbhub
Args: 8624c030 00000002 00000001 86316c90
[0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 80560660 867285f8 863fca50 00000000

Both IRPs seem as already completed and they are both set D0 IRPs. I wonder if it is UsbHub problem or if my driver could cause it some way and I’m not sure how to continue with analysis. Ideas welcome.

Best regards,

Michal Vodicka
UPEK, Inc.
[xxxxx@upek.com, http://www.upek.com]

2

Use \Callback\PowerState to cancel selective suspend instead of the
QueryPower IRP.

–
Jake Oshins
Windows Kernel Group

This posting is provided “AS IS” with no warranties, and confers no rights.

“Michal Vodicka” wrote in message
news:xxxxx@ntdev…
I have a crashdump created manually on customer’s deadlocked computer.
Deadlock occured during system suspend and it was my USB driver which
blocked S3 query IRP. It has a reason: it tried to cancel selective suspend
before and sent D0 IRP to UsbHub driver. This IRP was never completed and
I’d like to know why. From the dump it seems as the order of events was
following:

- driver passed idle IRP down to the stack
- idle callback was called, driver successfully set device to D2
- later an event occured and driver decided to turn device on; it sent D0
IRP down the stack
- system sent S3 query to the driver
- driver started waiting until both D0 and idle IRPs are completed but below
driver never did it -> deadlock

Unfortunately, I’m unable to reproduce the problem. It occured under high
system and selective suspend stress test (driver counters in the dump show
121 system and 6595 device suspends) and it was probably caused by some kind
of race conditions. It seems as the problem could be in the UsbHub driver
but it is hard to decide. Anyway, there is something wrong:

Windows XP Kernel Version 2600 (Service Pack 2) UP Free x86 compatible
Product: WinNt, suite: TerminalServer SingleUserTS
Built by: 2600.xpsp_sp2_rtm.040803-2158

kd> !poreqlist
All active Power Irps from PoRequestPowerIrp
PopReqestedPowerIrpList
FieldOffset = 00000004
Irp 86768718 DevObj 867e4290 \Driver\ACPI Ctx 00000005 * Wait Wake S4
Irp 85297008 DevObj 8659e618 \Driver\usbuhci Ctx 00000001 Wait Wake S0
Irp 864095d8 DevObj 86370030 \Driver\usbuhci Ctx 00000001 Wait Wake S0
Irp 85644e48 DevObj 85851de8 \Driver\usbhub Ctx 00000001 Wait Wake S0
Irp 8661be48 DevObj 0000000000000000: Could not read device object or
_DEVICE_OBJECT not found
Ctx 00000002 [blocked]
Irp 867284d0 DevObj 85851de8 \Driver\usbhub Ctx 00000003 Set Power D0
ShutdownType 2
Irp 863fca50 DevObj 0000000000000000: Could not read device object or
_DEVICE_OBJECT not found
Ctx 00000002 [blocked]

The D0 IRP I mentioned before is IRP 867284d0. There are two strange IRPs
marked as [blocked] above:

kd> !irp 8661be48
Irp is active with 6 stacks 5 is current (= 0x8661bf48)
No Mdl Thread 00000000: Irp stack trace.
cmd flg cl Device File Completion-Context
[0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000
[0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000
[0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000
[16, 2] 0 e1 8637ac98 00000000 805094ff-f7a13e16 Success Error Cancel
pending
\Driver\usbhub nt!PopCompleteRequestIrp
Args: 00000003 00000001 00000001 00000002
>[0, 0] 0 0 8637ac98 00000000 00000000-00000000
\Driver\usbhub
Args: 8624c030 00000002 00000001 8637ad50
[0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 867285f8 85644f70 8661be48 00000000
kd> !irp 863fca50
Irp is active with 6 stacks 5 is current (= 0x863fcb50)
No Mdl Thread 00000000: Irp stack trace.
cmd flg cl Device File Completion-Context
[0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000
[0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000
[0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000
[16, 2] 0 e0 8637ac98 00000000 805094ff-f7a143e6 Success Error Cancel
\Driver\usbhub nt!PopCompleteRequestIrp
Args: 00000003 00000001 00000001 00000002
>[0, 0] 0 0 8637ac98 00000000 00000000-00000000
\Driver\usbhub
Args: 8624c030 00000002 00000001 86316c90
[0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 80560660 867285f8 863fca50 00000000

Both IRPs seem as already completed and they are both set D0 IRPs. I wonder
if it is UsbHub problem or if my driver could cause it some way and I’m not
sure how to continue with analysis. Ideas welcome.

Best regards,

Michal Vodicka
UPEK, Inc.
[xxxxx@upek.com, http://www.upek.com]

3

Yes, I use it now. The problem occurs with older driver version just before this change. I’m concerned about it because it doesn’t seems related to QueryPower IRP; block there is a consequence and the real problem is blocked D0 IRP in UsbHub driver. Currently, our customer reprocuded it again and I just started next crashdump analysis; at first sigth it seems exactly as the previous one.

To be clear: it seems as there is UsbHub driver bug and using \Callback\PowerState only conceals its manifestation. I do worry about it because of bad past experience. Such bugs are usually race conditions and very rare problem can become frequent after an unrelated sw or hw change. That’s why I want to find the real reason now, until the driver is installed on tens thousands computers.

If you want to see the crashdump, it is available.

Best regards,

Michal Vodicka
UPEK, Inc.
[xxxxx@upek.com, http://www.upek.com]

From: xxxxx@lists.osr.com[SMTP:xxxxx@lists.osr.com] on behalf of Jake Oshins[SMTP:xxxxx@windows.microsoft.com]
Reply To: Windows System Software Devs Interest List
Sent: Thursday, September 23, 2004 6:57 PM
To: Windows System Software Devs Interest List
Subject: Re:[ntdev] Power management deadlock

Use \Callback\PowerState to cancel selective suspend instead of the
QueryPower IRP.

–
Jake Oshins
Windows Kernel Group

This posting is provided “AS IS” with no warranties, and confers no rights.

“Michal Vodicka” wrote in message
> news:xxxxx@ntdev…
> I have a crashdump created manually on customer’s deadlocked computer.
> Deadlock occured during system suspend and it was my USB driver which
> blocked S3 query IRP. It has a reason: it tried to cancel selective suspend
> before and sent D0 IRP to UsbHub driver. This IRP was never completed and
> I’d like to know why. From the dump it seems as the order of events was
> following:
>
> - driver passed idle IRP down to the stack
> - idle callback was called, driver successfully set device to D2
> - later an event occured and driver decided to turn device on; it sent D0
> IRP down the stack
> - system sent S3 query to the driver
> - driver started waiting until both D0 and idle IRPs are completed but below
> driver never did it -> deadlock
>
> Unfortunately, I’m unable to reproduce the problem. It occured under high
> system and selective suspend stress test (driver counters in the dump show
> 121 system and 6595 device suspends) and it was probably caused by some kind
> of race conditions. It seems as the problem could be in the UsbHub driver
> but it is hard to decide. Anyway, there is something wrong:
>
> Windows XP Kernel Version 2600 (Service Pack 2) UP Free x86 compatible
> Product: WinNt, suite: TerminalServer SingleUserTS
> Built by: 2600.xpsp_sp2_rtm.040803-2158
>
> kd> !poreqlist
> All active Power Irps from PoRequestPowerIrp
> PopReqestedPowerIrpList
> FieldOffset = 00000004
> Irp 86768718 DevObj 867e4290 \Driver\ACPI Ctx 00000005 * Wait Wake S4
> Irp 85297008 DevObj 8659e618 \Driver\usbuhci Ctx 00000001 Wait Wake S0
> Irp 864095d8 DevObj 86370030 \Driver\usbuhci Ctx 00000001 Wait Wake S0
> Irp 85644e48 DevObj 85851de8 \Driver\usbhub Ctx 00000001 Wait Wake S0
> Irp 8661be48 DevObj 0000000000000000: Could not read device object or
> _DEVICE_OBJECT not found
> Ctx 00000002 [blocked]
> Irp 867284d0 DevObj 85851de8 \Driver\usbhub Ctx 00000003 Set Power D0
> ShutdownType 2
> Irp 863fca50 DevObj 0000000000000000: Could not read device object or
> _DEVICE_OBJECT not found
> Ctx 00000002 [blocked]
>
> The D0 IRP I mentioned before is IRP 867284d0. There are two strange IRPs
> marked as [blocked] above:
>
> kd> !irp 8661be48
> Irp is active with 6 stacks 5 is current (= 0x8661bf48)
> No Mdl Thread 00000000: Irp stack trace.
> cmd flg cl Device File Completion-Context
> [0, 0] 0 0 00000000 00000000 00000000-00000000
>
> Args: 00000000 00000000 00000000 00000000
> [0, 0] 0 0 00000000 00000000 00000000-00000000
>
> Args: 00000000 00000000 00000000 00000000
> [0, 0] 0 0 00000000 00000000 00000000-00000000
>
> Args: 00000000 00000000 00000000 00000000
> [16, 2] 0 e1 8637ac98 00000000 805094ff-f7a13e16 Success Error Cancel
> pending
> \Driver\usbhub nt!PopCompleteRequestIrp
> Args: 00000003 00000001 00000001 00000002
> >[0, 0] 0 0 8637ac98 00000000 00000000-00000000
> \Driver\usbhub
> Args: 8624c030 00000002 00000001 8637ad50
> [0, 0] 0 0 00000000 00000000 00000000-00000000
>
> Args: 867285f8 85644f70 8661be48 00000000
> kd> !irp 863fca50
> Irp is active with 6 stacks 5 is current (= 0x863fcb50)
> No Mdl Thread 00000000: Irp stack trace.
> cmd flg cl Device File Completion-Context
> [0, 0] 0 0 00000000 00000000 00000000-00000000
>
> Args: 00000000 00000000 00000000 00000000
> [0, 0] 0 0 00000000 00000000 00000000-00000000
>
> Args: 00000000 00000000 00000000 00000000
> [0, 0] 0 0 00000000 00000000 00000000-00000000
>
> Args: 00000000 00000000 00000000 00000000
> [16, 2] 0 e0 8637ac98 00000000 805094ff-f7a143e6 Success Error Cancel
> \Driver\usbhub nt!PopCompleteRequestIrp
> Args: 00000003 00000001 00000001 00000002
> >[0, 0] 0 0 8637ac98 00000000 00000000-00000000
> \Driver\usbhub
> Args: 8624c030 00000002 00000001 86316c90
> [0, 0] 0 0 00000000 00000000 00000000-00000000
>
> Args: 80560660 867285f8 863fca50 00000000
>
> Both IRPs seem as already completed and they are both set D0 IRPs. I wonder
> if it is UsbHub problem or if my driver could cause it some way and I’m not
> sure how to continue with analysis. Ideas welcome.
>
> Best regards,
>
> Michal Vodicka
> UPEK, Inc.
> [xxxxx@upek.com, http://www.upek.com]
>
>
>
>
>
> —
> Questions? First check the Kernel Driver FAQ at http://www.osronline.com/article.cfm?id=256
>
> You are currently subscribed to ntdev as: xxxxx@upek.com
> To unsubscribe send a blank email to xxxxx@lists.osr.com
>