PM IRPs won't complete in KMDF bus driver

Hi,

I have a problem with a KMDF bus driver where the bus driver does not
transition its stack back to D0 upon receiving a request on its PDOs to
transition to D0 as a result of system entering S0. This problem happens
intermittently, only on some hosts and mainly on Vista (occasionally seen on
Win2k and XP).

This is the scenario: host is put in S1 state and awoken after 20s (using
WDTF) and this cycles through. After few cycles, screen comes up as either
blank or blank with the mouse pointer frozen. System is not responsive and
has to be cold-restarted. If I break into the debugger at this time, stack
backtrace shows CPUs (multiprocessor system) are idle and there doesn't seem
to be any deadlocks.

There are several power IRPs active in the system at this point, the ones of
my interest being child FDOs' SET_POWER S0s being pended on SET_POWER D0s it
had sent. SET_POWER D0s are then pending in the bus driver for unknown
reason. Looking at the KMDF logs, I can see that PDOs have received the
SET_POWER D0 IRP, but for some reason they are waiting for the parent
transition to D0 which never seems to happen.

I have included the results of !WDFDEVICE for child PDO and parent bus FDO
as well as last bits of KMDF logs.

Could this be due to a potential race condition in the Framework as problem
seems to occur more frequently when the number of childs is increased? As
power mangement is handled by the Framework, I couldn't think of a way to
take this any further. What else would you recommend to gather more
information on this?

Many thanks,
DaveH


//////////////////////// Child PDO

1: kd> !wdfdevice 0x77bf6900 fff

Dumping WDFDEVICE 0x77bf6900
=================================

WDM PDEVICE_OBJECTs: self 91ffe9a8

Pnp state: 119 ( WdfDevStatePnpStarted )
Power state: 32f ( WdfDevStatePowerWaitForParent )
Power Pol state: 571 ( WdfDevStatePwrPolDx )

Parent WDFDEVICE 701ff620
Parent states:
Pnp state: 119 ( WdfDevStatePnpStarted )
Power state: 31f ( WdfDevStatePowerDx )
Power Pol state: 515 (
WdfDevStatePwrPolSystemWakeDeviceWakeEnabledWakeCanceled )

Pended device power irp 0x95af2f00 (D0)

Pnp state history:
[0] WdfDevStatePnpObjectCreated (0x100)
[1] WdfDevStatePnpInit (0x105)
[2] WdfDevStatePnpInitStarting (0x106)
[3] WdfDevStatePnpHardwareAvailable (0x108)
[4] WdfDevStatePnpEnableInterfaces (0x109)
[5] WdfDevStatePnpStarted (0x119)

Power state history:
[0] WdfDevStatePowerStartSelfManagedIo (0x32b)
[1] WdfDevStatePowerD0BusWakeOwner (0x309)
[2] WdfDevStatePowerGotoDx (0x31a)
[3] WdfDevStatePowerGotoDxIoStopped (0x31c)
[4] WdfDevStatePowerDx (0x31f)
[5] WdfDevStatePowerCheckDeviceType (0x301)
[6] WdfDevStatePowerCheckParentState (0x303)
[7] WdfDevStatePowerWaitForParent (0x32f)

Power policy state history:
[0] WdfDevStatePwrPolGotoD0 (0x572)
[1] WdfDevStatePwrPolStartingSucceeded (0x502)
[2] WdfDevStatePwrPolGotoDx (0x56f)
[3] WdfDevStatePwrPolDx (0x571)
[4] WdfDevStatePwrPolGotoD0 (0x572)
[5] WdfDevStatePwrPolStartingSucceeded (0x502)
[6] WdfDevStatePwrPolGotoDx (0x56f)
[7] WdfDevStatePwrPolDx (0x571)

EvtDeviceEnableWakeAtBus: Mf!ChildEvtDeviceEnableWakeAtBus (8651be9a)
EvtDeviceDisableWakeAtBus: Mf!ChildEvtDeviceDisableWakeAtBus (8651bece)


Properties:
SynchronizationScope: WdfSynchronizationScopeNone
ExecutionLevel: WdfExecutionLevelDispatch
IoType: WdfDeviceIoBuffered
FileObjectClass: WdfFileObjectNotRequired
Exclusive: No
AutoForwardCleanupClose: No
DefaultIoPriorityBoot: 2


//////////////////////// Bus FDO

1: kd> !WDFDEVICE 0x701ff620 fff

Dumping WDFDEVICE 0x701ff620
=================================

WDM PDEVICE_OBJECTs:self 92c43c50, attached 8f5f9020, pdo 83c20030

Pnp state: 119 ( WdfDevStatePnpStarted )
Power state: 31f ( WdfDevStatePowerDx )
Power Pol state: 515 (
WdfDevStatePwrPolSystemWakeDeviceWakeEnabledWakeCanceled )

Default WDFIOTARGET: 6d3d4438

No pended pnp or power irps
Device is the power policy owner for the stack

Pnp state history:
[0] WdfDevStatePnpObjectCreated (0x100)
[1] WdfDevStatePnpInit (0x105)
[2] WdfDevStatePnpInitStarting (0x106)
[3] WdfDevStatePnpHardwareAvailable (0x108)
[4] WdfDevStatePnpEnableInterfaces (0x109)
[5] WdfDevStatePnpStarted (0x119)

Power state history:
[0] WdfDevStatePowerWaking (0x333)
[1] WdfDevStatePowerWakingConnectInterrupt (0x335)
[2] WdfDevStatePowerWakingDmaEnable (0x339)
[3] WdfDevStatePowerStartSelfManagedIo (0x32b)
[4] WdfDevStatePowerD0 (0x307)
[5] WdfDevStatePowerGotoDx (0x31a)
[6] WdfDevStatePowerGotoDxIoStopped (0x31c)
[7] WdfDevStatePowerDx (0x31f)

Power policy state history:
[0] WdfDevStatePwrPolSleeping (0x526)
[1] WdfDevStatePwrPolSleepingWakePowerDown (0x52a)
[2] WdfDevStatePwrPolSleepingSendWake (0x52b)
[3] WdfDevStatePwrPolCheckPowerPageable (0x510)
[4] WdfDevStatePwrPolSleepingWakeWakeArrived (0x511)
[5] WdfDevStatePwrPolSystemAsleepWakeArmed (0x513)
[6] WdfDevStatePwrPolSystemWakeDeviceWakeEnabled (0x514)
[7] WdfDevStatePwrPolSystemWakeDeviceWakeEnabledWakeCanceled (0x515)

EvtDeviceD0Entry: Mf!BusEvtDeviceD0Entry (8651acc8)
EvtDevicePrepareHardware: Mf!BusEvtDevicePrepareHardware (8651b83a)
EvtDeviceReleaseHardware: Mf!BusEvtDeviceReleaseHardware (8651b5e0)
EvtDeviceArmWakeFromS0: Mf!BusEvtDeviceArmWake (8651acf8)
EvtDeviceDisarmWakeFromS0: Mf!BusEvtDeviceDisarmWake (8651b638)
EvtDeviceArmWakeFromSx: Mf!BusEvtDeviceArmWake (8651acf8)
EvtDeviceDisarmWakeFromSx: Mf!BusEvtDeviceDisarmWake (8651b638)

WDFCHILDLIST Handles:
!WDFCHILDLIST 0x701566f8 (static PDO list)

Properties:
SynchronizationScope: WdfSynchronizationScopeNone
ExecutionLevel: WdfExecutionLevelDispatch
IoType: WdfDeviceIoBuffered
FileObjectClass: WdfFileObjectNotRequired
Exclusive: No
AutoForwardCleanupClose: No
DefaultIoPriorityBoot: 0


//////////////////////// KMDF log

3234: FxPkgPnp::Dispatch - WDFDEVICE 0x701FF620 !devobj 0x92C43C50
IRP_MJ_POWER, Minor 0x2 IRP 0x972EAED8
3235: FxPkgPnp::Dispatch - WDFDEVICE 0x77BF6900 !devobj 0x91FFE9A8
IRP_MJ_POWER, Minor 0x2 IRP 0x9721EF00
3236: FxPkgPnp::Dispatch - WDFDEVICE 0x6E0C75D8 !devobj 0x92C1A480
IRP_MJ_POWER, Minor 0x2 IRP 0x9926AF00
3237: FxPkgPnp::Dispatch - WDFDEVICE 0x7BC2D768 !devobj 0x92C51530
IRP_MJ_POWER, Minor 0x2 IRP 0x97358F00
3238: FxPkgPnp::Dispatch - WDFDEVICE 0x6D3C1748 !devobj 0x91F39030
IRP_MJ_POWER, Minor 0x2 IRP 0x99388F00
3239: FxPkgPnp::Dispatch - WDFDEVICE 0x6E0C6E48 !devobj 0x92C5ACD0
IRP_MJ_POWER, Minor 0x2 IRP 0x992BEF00
3240: FxPkgPnp::Dispatch - WDFDEVICE 0x762E57C0 !devobj 0x89CB5A48
IRP_MJ_POWER, Minor 0x2 IRP 0x973E6F00
3241: FxPkgPnp::Dispatch - WDFDEVICE 0x6D398480 !devobj 0x84382AD8
IRP_MJ_POWER, Minor 0x2 IRP 0x993BEF00
3242: FxPkgPnp::Dispatch - WDFDEVICE 0x6D39E210 !devobj 0x92C56C50
IRP_MJ_POWER, Minor 0x2 IRP 0x95ADCF00
3243: FxPkgPnp::Dispatch - WDFDEVICE 0x77BF6900 !devobj 0x91FFE9A8
IRP_MJ_POWER, Minor 0x2 IRP 0x95AF2F00
3244: FxPkgPnp::PowerEnterNewState - WDFDEVICE 0x77BF6900 !devobj 0x91FFE9A8
entering Power State WdfDevStatePowerCheckDeviceType from WdfDevStatePowerDx
3245: FxPkgPnp::PowerEnterNewState - WDFDEVICE 0x77BF6900 !devobj 0x91FFE9A8
entering Power State WdfDevStatePowerCheckParentState from
WdfDevStatePowerCheckDeviceType
3246: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE 0x701FF620 !devobj
0x92C43C50 entering power idle state FxIdleInDxIoIncrement from FxIdleInDx
3247: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE 0x701FF620 !devobj
0x92C43C50 entering power idle state FxIdleInDx from FxIdleInDxIoIncrement
3248: FxPkgPnp::PowerEnterNewState - WDFDEVICE 0x77BF6900 !devobj 0x91FFE9A8
entering Power State WdfDevStatePowerWaitForParent from
WdfDevStatePowerCheckParentState
3249: FxPkgPnp::Dispatch - WDFDEVICE 0x6E0C75D8 !devobj 0x92C1A480
IRP_MJ_POWER, Minor 0x2 IRP 0x99272F00
3250: FxPkgPnp::PowerEnterNewState - WDFDEVICE 0x6E0C75D8 !devobj 0x92C1A480
entering Power State WdfDevStatePowerCheckDeviceType from WdfDevStatePowerDx
3251: FxPkgPnp::PowerEnterNewState - WDFDEVICE 0x6E0C75D8 !devobj 0x92C1A480
entering Power State WdfDevStatePowerCheckParentState from
WdfDevStatePowerCheckDeviceType
3252: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE 0x701FF620 !devobj
0x92C43C50 entering power idle state FxIdleInDxIoIncrement from FxIdleInDx
3253: FxPowerIdleMachine::InDxIoIncrement - WDFDEVICE 701FF620 idle (in Dx)
not sending io present event (already sent)
3254: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE 0x701FF620 !devobj
0x92C43C50 entering power idle state FxIdleInDx from FxIdleInDxIoIncrement
3255: FxPkgPnp::PowerEnterNewState - WDFDEVICE 0x6E0C75D8 !devobj 0x92C1A480
entering Power State WdfDevStatePowerWaitForParent from
WdfDevStatePowerCheckParentState
3256: FxPkgPnp::PowerPolicyEnterNewState - WDFDEVICE 0x701FF620 !devobj
0x92C43C50 entering power policy state
WdfDevStatePwrPolSystemWakeDeviceWakeEnabled from
WdfDevStatePwrPolSystemAsleepWakeArmed
3257: FxPkgPnp::PowerPolicyCancelWaitWake - Successfully got WaitWake irp
99246ED8 for cancelling
3258: FxPkgPnp::_PowerPolicyWaitWakeCompletionRoutine - Completion of
WaitWake irp 99246ED8, 0xc0000120(STATUS_CANCELLED)
3259: FxPkgPnp::_PowerPolicyWaitWakeCompletionRoutine - Not completing
WaitWake irp 99246ED8 in completion routine
3260: FxPkgPnp::PowerPolicyCancelWaitWake - Cancel of irp 99246ED8 returned 1
3261: FxPkgPnp::PowerPolicyEnterNewState - WDFDEVICE 0x701FF620 !devobj
0x92C43C50 entering power policy state
WdfDevStatePwrPolSystemWakeDeviceWakeEnabledWakeCanceled from
WdfDevStatePwrPolSystemWakeDeviceWakeEnabled
3262: FxPkgPnp::PowerPolicySendDevicePowerRequest - Requesting D0 irp,
0x00000103(STATUS_PENDING)
3263: FxPkgPnp::Dispatch - WDFDEVICE 0x7BC2D768 !devobj 0x92C51530
IRP_MJ_POWER, Minor 0x2 IRP 0x993C0F00
3264: FxPkgPnp::PowerEnterNewState - WDFDEVICE 0x7BC2D768 !devobj 0x92C51530
entering Power State WdfDevStatePowerCheckDeviceType from WdfDevStatePowerDx
3265: FxPkgPnp::PowerEnterNewState - WDFDEVICE 0x7BC2D768 !devobj 0x92C51530
entering Power State WdfDevStatePowerCheckParentState from
WdfDevStatePowerCheckDeviceType
3266: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE 0x701FF620 !devobj
0x92C43C50 entering power idle state FxIdleInDxIoIncrement from FxIdleInDx
3267: FxPowerIdleMachine::InDxIoIncrement - WDFDEVICE 701FF620 idle (in Dx)
not sending io present event (already sent)
3268: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE 0x701FF620 !devobj
0x92C43C50 entering power idle state FxIdleInDx from FxIdleInDxIoIncrement
3269: FxPkgPnp::PowerEnterNewState - WDFDEVICE 0x7BC2D768 !devobj 0x92C51530
entering Power State WdfDevStatePowerWaitForParent from
WdfDevStatePowerCheckParentState
3270: FxPkgPnp::Dispatch - WDFDEVICE 0x6D3C1748 !devobj 0x91F39030
IRP_MJ_POWER, Minor 0x2 IRP 0x8B2AEF00
3271: FxPkgPnp::PowerEnterNewState - WDFDEVICE 0x6D3C1748 !devobj 0x91F39030
entering Power State WdfDevStatePowerCheckDeviceType from WdfDevStatePowerDx
3272: FxPkgPnp::PowerEnterNewState - WDFDEVICE 0x6D3C1748 !devobj 0x91F39030
entering Power State WdfDevStatePowerCheckParentState from
WdfDevStatePowerCheckDeviceType
3273: FxPkgPnp::Dispatch - WDFDEVICE 0x6E0C6E48 !devobj 0x92C5ACD0
IRP_MJ_POWER, Minor 0x2 IRP 0x95ACCF00
3274: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE 0x701FF620 !devobj
0x92C43C50 entering power idle state FxIdleInDxIoIncrement from FxIdleInDx
3275: FxPowerIdleMachine::InDxIoIncrement - WDFDEVICE 701FF620 idle (in Dx)
not sending io present event (already sent)
3276: FxPkgPnp::PowerEnterNewState - WDFDEVICE 0x6E0C6E48 !devobj 0x92C5ACD0
entering Power State WdfDevStatePowerCheckDeviceType from WdfDevStatePowerDx
3277: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE 0x701FF620 !devobj
0x92C43C50 entering power idle state FxIdleInDx from FxIdleInDxIoIncrement
3278: FxPkgPnp::PowerEnterNewState - WDFDEVICE 0x6E0C6E48 !devobj 0x92C5ACD0
entering Power State WdfDevStatePowerCheckParentState from
WdfDevStatePowerCheckDeviceType
3279: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE 0x701FF620 !devobj
0x92C43C50 entering power idle state FxIdleInDxIoIncrement from FxIdleInDx
3280: FxPowerIdleMachine::InDxIoIncrement - WDFDEVICE 701FF620 idle (in Dx)
not sending io present event (already sent)
3281: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE 0x701FF620 !devobj
0x92C43C50 entering power idle state FxIdleInDx from FxIdleInDxIoIncrement
3282: FxPkgPnp::PowerEnterNewState - WDFDEVICE 0x6D3C1748 !devobj 0x91F39030
entering Power State WdfDevStatePowerWaitForParent from
WdfDevStatePowerCheckParentState
3283: FxPkgPnp::PowerEnterNewState - WDFDEVICE 0x6E0C6E48 !devobj 0x92C5ACD0
entering Power State WdfDevStatePowerWaitForParent from
WdfDevStatePowerCheckParentState
3284: FxPkgPnp::Dispatch - WDFDEVICE 0x762E57C0 !devobj 0x89CB5A48
IRP_MJ_POWER, Minor 0x2 IRP 0x9709CF00
3285: FxPkgPnp::PowerEnterNewState - WDFDEVICE 0x762E57C0 !devobj 0x89CB5A48
entering Power State WdfDevStatePowerCheckDeviceType from WdfDevStatePowerDx
3286: FxPkgPnp::PowerEnterNewState - WDFDEVICE 0x762E57C0 !devobj 0x89CB5A48
entering Power State WdfDevStatePowerCheckParentState from
WdfDevStatePowerCheckDeviceType
3287: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE 0x701FF620 !devobj
0x92C43C50 entering power idle state FxIdleInDxIoIncrement from FxIdleInDx
3288: FxPowerIdleMachine::InDxIoIncrement - WDFDEVICE 701FF620 idle (in Dx)
not sending io present event (already sent)
3289: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE 0x701FF620 !devobj
0x92C43C50 entering power idle state FxIdleInDx from FxIdleInDxIoIncrement
3290: FxPkgPnp::PowerEnterNewState - WDFDEVICE 0x762E57C0 !devobj 0x89CB5A48
entering Power State WdfDevStatePowerWaitForParent from
WdfDevStatePowerCheckParentState
3291: FxPkgPnp::Dispatch - WDFDEVICE 0x6D398480 !devobj 0x84382AD8
IRP_MJ_POWER, Minor 0x2 IRP 0x993F8F00
3292: FxPkgPnp::PowerEnterNewState - WDFDEVICE 0x6D398480 !devobj 0x84382AD8
entering Power State WdfDevStatePowerCheckDeviceType from WdfDevStatePowerDx
3293: FxPkgPnp::PowerEnterNewState - WDFDEVICE 0x6D398480 !devobj 0x84382AD8
entering Power State WdfDevStatePowerCheckParentState from
WdfDevStatePowerCheckDeviceType
3294: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE 0x701FF620 !devobj
0x92C43C50 entering power idle state FxIdleInDxIoIncrement from FxIdleInDx
3295: FxPowerIdleMachine::InDxIoIncrement - WDFDEVICE 701FF620 idle (in Dx)
not sending io present event (already sent)
3296: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE 0x701FF620 !devobj
0x92C43C50 entering power idle state FxIdleInDx from FxIdleInDxIoIncrement
3297: FxPkgPnp::PowerEnterNewState - WDFDEVICE 0x6D398480 !devobj 0x84382AD8
entering Power State WdfDevStatePowerWaitForParent from
WdfDevStatePowerCheckParentState
3298: FxPkgPnp::Dispatch - WDFDEVICE 0x6D39E210 !devobj 0x92C56C50
IRP_MJ_POWER, Minor 0x2 IRP 0x993DAF00
3299: FxPkgPnp::PowerEnterNewState - WDFDEVICE 0x6D39E210 !devobj 0x92C56C50
entering Power State WdfDevStatePowerCheckDeviceType from WdfDevStatePowerDx
3300: FxPkgPnp::PowerEnterNewState - WDFDEVICE 0x6D39E210 !devobj 0x92C56C50
entering Power State WdfDevStatePowerCheckParentState from
WdfDevStatePowerCheckDeviceType
3301: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE 0x701FF620 !devobj
0x92C43C50 entering power idle state FxIdleInDxIoIncrement from FxIdleInDx
3302: FxPowerIdleMachine::InDxIoIncrement - WDFDEVICE 701FF620 idle (in Dx)
not sending io present event (already sent)
3303: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE 0x701FF620 !devobj
0x92C43C50 entering power idle state FxIdleInDx from FxIdleInDxIoIncrement
3304: FxPkgPnp::PowerEnterNewState - WDFDEVICE 0x6D39E210 !devobj 0x92C56C50
entering Power State WdfDevStatePowerWaitForParent from
WdfDevStatePowerCheckParentState

.

Relevant Pages

  • RE: PM IRPs wont complete in KMDF bus driver
    ... entering Power State WdfDevStatePowerCheckDeviceType from WdfDevStatePowerDx ... 0x92C43C50 entering power idle state FxIdleInDxIoIncrement from FxIdleInDx ...
    (microsoft.public.development.device.drivers)
  • Re: PM IRPs wont complete in KMDF bus driver
    ... IRP to transition to D0, but for some reason it hasn't received that IRP yet ... WdfDevStatePowerCheckDeviceType ... entering Power State WdfDevStatePowerCheckParentState from ...
    (microsoft.public.development.device.drivers)
  • Re: PM IRPs wont complete in KMDF bus driver
    ... IRP to transition to D0, but for some reason it hasn't received that IRP yet ... WdfDevStatePowerCheckDeviceType ... entering Power State WdfDevStatePowerCheckParentState from ...
    (microsoft.public.development.device.drivers)
  • Re: PM IRPs wont complete in KMDF bus driver
    ... I have included the results of!WDFDEVICE for child PDO and parent bus FDO ... entering Power State WdfDevStatePowerCheckDeviceType from WdfDevStatePowerDx ... 0x92C43C50 entering power idle state FxIdleInDxIoIncrement from FxIdleInDx ...
    (microsoft.public.development.device.drivers)