Re: PM IRPs won't complete in KMDF bus driver

Tech-Archive recommends: Fix windows errors by optimizing your registry

">> 3262: FxPkgPnp::PowerPolicySendDevicePowerRequest - Requesting D0 irp,
0x00000103(STATUS_PENDING)"

From the above line in the log, it seems that the parent did request a D0
IRP to transition to D0, but for some reason it hasn't received that IRP yet
(at least on the D0 IRP's way up the stack). Unfortunately, the IRP pointer
is not getting logged, otherwise a !irp on the pointer would have given us
its status.
One thing you could try is running !WDFDEVICE device on every device object
in the parent's stack and see if a D0 IRP is pended on one of those.

"DaveH" <DaveH@xxxxxxxxxxxxxxxxxxxxxxxxx> wrote in message
news:C5635312-5299-41F7-8D62-9C5F630EFAEB@xxxxxxxxxxxxxxxx
One other thing which I just noticed is that at least in one failing case,
EvtInterruptEnable callback has been called without EvtDeviceD0Entry ever
being called (note when the host wakes after about 5 secs):

[1]0004.0C74::01/01/2001-00:09:18.197 [wdf]Entering BusEvtDeviceD0Exit
[1]0004.0C74::01/01/2001-00:09:18.197 [wdf]D0 exit to 0x4
[1]0004.0C74::01/01/2001-00:09:18.197 [wdf]Leaving BusEvtDeviceD0Exit
[1]0004.04F4::01/01/2001-00:09:23.103 [wdf]Entering BusEvtInterruptEnable
[1]0004.04F4::01/01/2001-00:09:23.103 [wdf]MEM WR 32: 0x00000001
@0x00000000F5600000 offset 0xC
[1]0004.04F4::01/01/2001-00:09:23.103 [wdf]Interrupt 0, mask 0x00000001
enabled
[1]0004.04F4::01/01/2001-00:09:23.103 [wdf]Leaving BusEvtInterruptEnable


"DaveH" wrote:

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


.

Relevant Pages

  • Re: PM IRPs wont complete in KMDF bus driver
    ... Allocated power irps ... and then dump each irp with "IRP: ... > entering Power State WdfDevStatePowerCheckDeviceType from ... > entering Power State WdfDevStatePowerCheckParentState from ...
    (microsoft.public.development.device.drivers)
  • 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
    ... 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 ... I have included the results of!WDFDEVICE for child PDO and parent bus FDO ... entering Power State WdfDevStatePowerCheckDeviceType from WdfDevStatePowerDx ...
    (microsoft.public.development.device.drivers)