Hallo All,
When running the WLK 1.5 CHAOS ? Concurrent Hardware And OS Test on a Mobile broadband driver on Win7, we encounter a BSOD DRIVER_POWER_STATE_FAILURE (9f) probably caused by pnpfiltr.
Arg1 equals 4 indicating that some threads were hung in the kernel during power transition (hibernate, etc) while still holding the PnP lock, which is explained at http://social.msdn.microsoft.com/Forums/en-US/isvwindowserrors/thread/1f4a8876-df97-415e-b913-cc02e92fe289.
A very similar problem can be found on thread http://www.osronline.com/ShowThread.cfm?link=168190 entered by Skaramush
Doing some analysis we see that the surprise removal irp is still active is causing the BSOD 9F.
I would like to know how we can analysis in order to overcome the problem.
Thanks in advance for any hints,
Eric
!Analyze ?v
DRIVER_POWER_STATE_FAILURE (9f)
A driver is causing an inconsistent power state.
Arguments:
Arg1: 0000000000000004, The power transition timed out waiting to synchronize with the Pnp
subsystem.
Arg2: 0000000000000258, Timeout in seconds.
Arg3: fffffa8000ce3b60, The thread currently holding on to the Pnp lock.
Arg4: fffff80000b9c510
Debugging Details:
DRVPOWERSTATE_SUBCODE: 4
FAULTING_THREAD: fffffa8000ce3b60
DEFAULT_BUCKET_ID: VISTA_DRIVER_FAULT
BUGCHECK_STR: 0x9F
PROCESS_NAME: System
CURRENT_IRQL: 2
LAST_CONTROL_TRANSFER: from fffff80002ac5052 to fffff80002ac3dda
STACK_TEXT:
fffff880031dd410 fffff80002ac5052 : fffffa8000ce3b60 fffffa8000ce3b60 0000000000000000 000000000000000c : nt!KiSwapContext+0x7a
fffff880031dd550 fffff80002ac71af : fffffa80052451a0 fffffa8005245000 fffff88000000000 0000000000000000 : nt!KiCommitThreadWait+0x1d2
fffff880031dd5e0 fffff8800151d6f2 : fffffa8005245100 0000000000000000 fffff98004e4ce00 fffffa8005245100 : nt!KeWaitForSingleObject+0x19f
fffff880031dd680 fffff88001578299 : 0000000000000000 fffffa80052451a0 fffff98004e4ce50 0000000000000017 : ndis!ndisPnPRemoveDeviceEx+0x112
fffff880031dd6e0 fffff80002f63c16 : fffff98004e4ce50 fffff98004e4ce50 fffffa8005245050 0000000000000000 : ndis! ?? ::LNCPHCLB::string'+0x75c8 fffff880031dd780 fffff8800569f9bc : fffffa80020606f0 fffff98004e4ce50 fffffa8001bec8f0 fffffa8002824560 : nt!IovCallDriver+0x566 fffff880031dd7e0 fffff880056a62b9 : fffffa80020606f0 fffff98004e4ce50 fffffa8000005a0c fffffa8001bec8f0 : pnpfiltr+0x19bc fffff880031dd810 fffff880056a55c8 : fffff98004e4ce50 fffff8800569e000 fffffa8001bec8f0 fffffa8001a95010 : pnpfiltr+0x82b9 fffff880031dd840 fffff80002f63c16 : fffff98004e4ce50 0000000000000002 fffffa8001bec8f0 fffff880031dd988 : pnpfiltr+0x75c8 fffff880031dd870 fffff80002d29419 : fffffa8001bec8f0 00000000c00000bb fffff880031dd988 fffffa8001a95010 : nt!IovCallDriver+0x566 fffff880031dd8d0 fffff80002ea7391 : fffffa8003e649c0 0000000000000000 fffffa8003e4e790 0000000000000000 : nt!IopSynchronousCall+0xc5 fffff880031dd940 fffff80002ea1e08 : 0000000000000010 fffffa8003e649c0 000000000000030a 0000000000000308 : nt!IopRemoveDevice+0x101 fffff880031dda00 fffff80002ea6ed7 : fffffa8003e4e790 0000000000000000 0000000000000003 0000000000010246 : nt!PnpSurpriseRemoveLockedDeviceNode+0x128 fffff880031dda40 fffff80002ea6ff0 : 0000000000000000 fffff8a002a1b000 fffff8a002a42ed0 000000004e706e50 : nt!PnpDeleteLockedDeviceNode+0x37 fffff880031dda70 fffff80002f36f6f : 0000000000000002 0000000000000000 fffffa8003e4e790 fffff8a002a1b0c0 : nt!PnpDeleteLockedDeviceNodes+0xa0 fffff880031ddae0 fffff80002f37b2c : fffff880031ddcb8 0000000000000000 fffff8a002f4e700 fffffa8000000000 : nt!PnpProcessQueryRemoveAndEject+0x6cf fffff880031ddc20 fffff80002e22c48 : 0000000000000000 fffffa8003d97500 fffff8a002a1b0c0 0000000000000001 : nt!PnpProcessTargetDeviceEvent+0x4c fffff880031ddc50 fffff80002acb161 : fffff80002d28fc0 fffff8a002a1b0c0 fffff80002c615f8 0000000000000000 : nt! ?? ::NNGAKEGL::string’+0x5abab
fffff880031ddcb0 fffff80002d61166 : 66292062261e5e23 fffffa8000ce3b60 0000000000000080 fffffa8000cc6040 : nt!ExpWorkerThread+0x111
fffff880031ddd40 fffff80002a9c486 : fffff880009e3180 fffffa8000ce3b60 fffff880009edf40 4799654899654899 : nt!PspSystemThreadStartup+0x5a
fffff880031ddd80 0000000000000000 : fffff880031de000 fffff880031d8000 fffff880031dcf90 0000000000000000 : nt!KxStartSystemThread+0x16
STACK_COMMAND: .thread 0xfffffa8000ce3b60 ; kb
FOLLOWUP_IP:
pnpfiltr+19bc
fffff880`0569f9bc 8bd8 mov ebx,eax
SYMBOL_STACK_INDEX: 6
SYMBOL_NAME: pnpfiltr+19bc
FOLLOWUP_NAME: MachineOwner
MODULE_NAME: pnpfiltr
IMAGE_NAME: pnpfiltr.sys
DEBUG_FLR_IMAGE_TIMESTAMP: 4b079fff
FAILURE_BUCKET_ID: X64_0x9F_VRF_pnpfiltr+19bc
BUCKET_ID: X64_0x9F_VRF_pnpfiltr+19bc
Followup: MachineOwner
After receiving NdisDevicePnPEventSurpriseRemoved, the Mobile Broadband driver executes the PauseHandler and then HaltHandlerEx. HaltHandlerEx stops all threads, frees all memory completes or cancels all irps so that all references to the driver are removed.
The issue seems to be timing related because from time to time we pass the test when a debug driver is loaded. A release drivers seems to fail always.
When the test passes the UnloadHandler is called almost immediately after finishing the HaltHandlerEx.
We suspect that a pnp irp is hanging and prohibits the unloadhandler from being called.
!locks
**** DUMP OF ALL RESOURCE OBJECTS ****
KD: Scanning for held locks…
Resource @ nt!IopDeviceTreeLock (0xfffff80002cc0500) Shared 1 owning threads
Threads: fffffa8000ce3b60-01<*>
KD: Scanning for held locks.
Resource @ nt!PiEngineLock (0xfffff80002cc0400) Exclusively owned
Contention Count = 54
NumberOfExclusiveWaiters = 1
Threads: fffffa8000ce3b60-01<*>
Threads Waiting On Exclusive Access:
fffffa8000ce2040
KD: Scanning for held locks…
9708 total locks, 2 locks currently held
0: kd> !thread fffffa8000ce3b60
THREAD fffffa8000ce3b60 Cid 0004.0044 Teb: 0000000000000000 Win32Thread: 0000000000000000 WAIT: (Executive) KernelMode Non-Alertable
fffff880031dd6b0 NotificationEvent
IRP List:
fffff98004e4ce50: (0006,01a8) Flags: 40000000 Mdl: 00000000
Not impersonating
DeviceMap fffff8a000007e40
Owning Process fffffa8000cc6040 Image: System
Attached Process N/A Image: N/A
Wait Start TickCount 40644 Ticks: 38463 (0:00:10:00.026)
Context Switch Count 2948 NoStackSwap
UserTime 00:00:00.000
KernelTime 00:00:01.107
Win32 Start Address nt!ExpWorkerThread (0xfffff80002acb050)
Stack Init fffff880031dddb0 Current fffff880031dd3d0
Base fffff880031de000 Limit fffff880031d8000 Call 0
Priority 15 BasePriority 12 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5
Child-SP RetAddr : Args to Child : Call Site
fffff880031dd410 fffff80002ac5052 : fffffa8000ce3b60 fffffa8000ce3b60 0000000000000000 000000000000000c : nt!KiSwapContext+0x7a
fffff880031dd550 fffff80002ac71af : fffffa80052451a0 fffffa8005245000 fffff88000000000 0000000000000000 : nt!KiCommitThreadWait+0x1d2
fffff880031dd5e0 fffff8800151d6f2 : fffffa8005245100 0000000000000000 fffff98004e4ce00 fffffa8005245100 : nt!KeWaitForSingleObject+0x19f
fffff880031dd680 fffff88001578299 : 0000000000000000 fffffa80052451a0 fffff98004e4ce50 0000000000000017 : ndis!ndisPnPRemoveDeviceEx+0x112
fffff880031dd6e0 fffff80002f63c16 : fffff98004e4ce50 fffff98004e4ce50 fffffa8005245050 0000000000000000 : ndis! ?? ::LNCPHCLB::string'+0x75c8 fffff880031dd780 fffff8800569f9bc : fffffa80020606f0 fffff98004e4ce50 fffffa8001bec8f0 fffffa8002824560 : nt!IovCallDriver+0x566 fffff880031dd7e0 fffff880056a62b9 : fffffa80020606f0 fffff98004e4ce50 fffffa8000005a0c fffffa8001bec8f0 : pnpfiltr+0x19bc fffff880031dd810 fffff880056a55c8 : fffff98004e4ce50 fffff8800569e000 fffffa8001bec8f0 fffffa8001a95010 : pnpfiltr+0x82b9 fffff880031dd840 fffff80002f63c16 : fffff98004e4ce50 0000000000000002 fffffa8001bec8f0 fffff880031dd988 : pnpfiltr+0x75c8 fffff880031dd870 fffff80002d29419 : fffffa8001bec8f0 00000000c00000bb fffff880031dd988 fffffa8001a95010 : nt!IovCallDriver+0x566 fffff880031dd8d0 fffff80002ea7391 : fffffa8003e649c0 0000000000000000 fffffa8003e4e790 0000000000000000 : nt!IopSynchronousCall+0xc5 fffff880031dd940 fffff80002ea1e08 : 0000000000000010 fffffa8003e649c0 000000000000030a 0000000000000308 : nt!IopRemoveDevice+0x101 fffff880031dda00 fffff80002ea6ed7 : fffffa8003e4e790 0000000000000000 0000000000000003 0000000000010246 : nt!PnpSurpriseRemoveLockedDeviceNode+0x128 fffff880031dda40 fffff80002ea6ff0 : 0000000000000000 fffff8a002a1b000 fffff8a002a42ed0 000000004e706e50 : nt!PnpDeleteLockedDeviceNode+0x37 fffff880031dda70 fffff80002f36f6f : 0000000000000002 0000000000000000 fffffa8003e4e790 fffff8a002a1b0c0 : nt!PnpDeleteLockedDeviceNodes+0xa0 fffff880031ddae0 fffff80002f37b2c : fffff880031ddcb8 0000000000000000 fffff8a002f4e700 fffffa8000000000 : nt!PnpProcessQueryRemoveAndEject+0x6cf fffff880031ddc20 fffff80002e22c48 : 0000000000000000 fffffa8003d97500 fffff8a002a1b0c0 0000000000000001 : nt!PnpProcessTargetDeviceEvent+0x4c fffff880031ddc50 fffff80002acb161 : fffff80002d28fc0 fffff8a002a1b0c0 fffff80002c615f8 0000000000000000 : nt! ?? ::NNGAKEGL::string’+0x5abab
fffff880031ddcb0 fffff80002d61166 : 66292062261e5e23 fffffa8000ce3b60 0000000000000080 fffffa8000cc6040 : nt!ExpWorkerThread+0x111
fffff880031ddd40 fffff80002a9c486 : fffff880009e3180 fffffa8000ce3b60 fffff880009edf40 4799654899654899 : nt!PspSystemThreadStartup+0x5a
fffff880031ddd80 0000000000000000 : fffff880031de000 fffff880031d8000 fffff880031dcf90 0000000000000000 : nt!KxStartSystemThread+0x16
0: kd> !irp fffff98004e4ce50 7
Irp is active with 3 stacks 3 is current (= 0xfffff98004e4cfb0)
No Mdl: No System Buffer: Thread fffffa8000ce3b60: Irp stack trace.
Flags = 40000000
ThreadListEntry.Flink = fffffa8000ce3f48
ThreadListEntry.Blink = fffffa8000ce3f48
IoStatus.Status = 00000000
IoStatus.Information = 00000000
RequestorMode = 00000000
Cancel = 00
CancelIrql = 0
ApcEnvironment = 00
UserIosb = fffff880031dd900
UserEvent = fffff880031dd910
Overlay.AsynchronousParameters.UserApcRoutine = 00000000
Overlay.AsynchronousParameters.UserApcContext = 00000000
Overlay.AllocationSize = 00000000 - 00000000
CancelRoutine = 00000000
UserBuffer = 00000000
&Tail.Overlay.DeviceQueueEntry = fffff98004e4cec8
Tail.Overlay.Thread = fffffa8000ce3b60
Tail.Overlay.AuxiliaryBuffer = 00000000
Tail.Overlay.ListEntry.Flink = 00000000
Tail.Overlay.ListEntry.Blink = 00000000
Tail.Overlay.CurrentStackLocation = fffff98004e4cfb0
Tail.Overlay.OriginalFileObject = 00000000
Tail.Apc = 00000000
Tail.CompletionKey = 00000000
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
[1b,17] 0 0 fffffa8005245050 00000000 00000000-00000000
\Driver\GTNDIS62
Args: 00000000 00000000 00000000 00000000
IO verifier information:
A problem occured reading memory
0: kd> !locks -v fffff80002cc0500
Resource @ nt!IopDeviceTreeLock (0xfffff80002cc0500) Shared 1 owning threads
Threads: fffffa8000ce3b60-01<*>
THREAD fffffa8000ce3b60 Cid 0004.0044 Teb: 0000000000000000 Win32Thread: 0000000000000000 WAIT: (Executive) KernelMode Non-Alertable
fffff880031dd6b0 NotificationEvent
IRP List:
fffff98004e4ce50: (0006,01a8) Flags: 40000000 Mdl: 00000000
Not impersonating
DeviceMap fffff8a000007e40
Owning Process fffffa8000cc6040 Image: System
Attached Process N/A Image: N/A
Wait Start TickCount 40644 Ticks: 38463 (0:00:10:00.026)
Context Switch Count 2948 NoStackSwap
UserTime 00:00:00.000
KernelTime 00:00:01.107
Win32 Start Address nt!ExpWorkerThread (0xfffff80002acb050)
Stack Init fffff880031dddb0 Current fffff880031dd3d0
Base fffff880031de000 Limit fffff880031d8000 Call 0
Priority 15 BasePriority 12 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5
Child-SP RetAddr Call Site
fffff880031dd410 fffff80002ac5052 nt!KiSwapContext+0x7a
fffff880031dd550 fffff80002ac71af nt!KiCommitThreadWait+0x1d2
fffff880031dd5e0 fffff8800151d6f2 nt!KeWaitForSingleObject+0x19f
fffff880031dd680 fffff88001578299 ndis!ndisPnPRemoveDeviceEx+0x112
fffff880031dd6e0 fffff80002f63c16 ndis! ?? ::LNCPHCLB::string'+0x75c8 fffff880031dd780 fffff8800569f9bc nt!IovCallDriver+0x566 fffff880031dd7e0 fffff880056a62b9 pnpfiltr+0x19bc fffff880031dd810 fffff880056a55c8 pnpfiltr+0x82b9 fffff880031dd840 fffff80002f63c16 pnpfiltr+0x75c8 fffff880031dd870 fffff80002d29419 nt!IovCallDriver+0x566 fffff880031dd8d0 fffff80002ea7391 nt!IopSynchronousCall+0xc5 fffff880031dd940 fffff80002ea1e08 nt!IopRemoveDevice+0x101 fffff880031dda00 fffff80002ea6ed7 nt!PnpSurpriseRemoveLockedDeviceNode+0x128 fffff880031dda40 fffff80002ea6ff0 nt!PnpDeleteLockedDeviceNode+0x37 fffff880031dda70 fffff80002f36f6f nt!PnpDeleteLockedDeviceNodes+0xa0 fffff880031ddae0 fffff80002f37b2c nt!PnpProcessQueryRemoveAndEject+0x6cf fffff880031ddc20 fffff80002e22c48 nt!PnpProcessTargetDeviceEvent+0x4c fffff880031ddc50 fffff80002acb161 nt! ?? ::NNGAKEGL::string’+0x5abab
fffff880031ddcb0 fffff80002d61166 nt!ExpWorkerThread+0x111
fffff880031ddd40 fffff80002a9c486 nt!PspSystemThreadStartup+0x5a
fffff880031ddd80 0000000000000000 nt!KxStartSystemThread+0x16
1 total locks, 1 locks currently held
We see that a surpriseremoval irp which is in the stack of the Mobile Broadband driver (GTNDIS62.sys) is still active.