USB Audio Driver on Vista hangs PNP

PascalJedi · October 6, 2009, 2:36pm

Hi All,

I was wondering if anyone has any insight into why the USB Audio class
driver would be hanging PNP on Vista. I have tried everything I know to
figure it out why USBAudio is handing around… Any debugging techniques
that to address this type of hang? Below is the devnode, thread; one can
see the SURPRISE REMOVE irp which hasn’t been forwarded down the stack yet.

Any help, ideas, concerns, questions, WAGs?

Thanks,
-Randy

Devnode:
DevNode 0x8471e1c0 for PDO 0x846656f0
InstancePath is “USB\VID_0D8C&PID_0103\a&2ca75233&0&2”
ServiceName is “usbccgp”
State = DeviceNodeAwaitingQueuedDeletion (0x30e)
Previous State = DeviceNodeStarted (0x308)

DevNode 0x817ae8a8 for PDO 0x8461dc80
InstancePath is “USB\VID_0D8C&PID_0103&MI_00\b&17245a44&0&0000”
ServiceName is “usbaudio”
State = DeviceNodeStarted (0x308)
Previous State = DeviceNodeStarted (0x308)

Process:

THREAD 83f22020 Cid 0004.0044 Teb: 00000000 Win32Thread: 00000000
WAIT: (Executive) KernelMode Non-Alertable
8465c54c Mutant - owning thread 84449328
IRP List:
859dc2a0: (0006,0268) Flags: 00000000 Mdl: 00000000
84903270: (0006,0220) Flags: 00060000 Mdl: 00000000
8529cd28: (0006,0220) Flags: 00060000 Mdl: 00000000
Not impersonating
DeviceMap 87208dc8
Owning Process 83efcd90 Image: System
Attached Process N/A Image: N/A
Wait Start TickCount 4352704 Ticks: 118779
(0:00:30:52.964)
Context Switch Count 493139
UserTime 00:00:00.000
KernelTime 00:00:06.567
Win32 Start Address nt!ExpWorkerThread (0x8267e348)
Stack Init 8756c000 Current 8756ba18 Base 8756c000 Limit 87569000
Call 0
Priority 14 BasePriority 12 PriorityDecrement 2 IoPriority 2
PagePriority 5
ChildEBP RetAddr
8756ba30 826fd2ff nt!KiSwapContext+0x26 (FPO: [Uses EBP] [0,0,4])
8756ba74 8269acc8 nt!KiSwapThread+0x44f
8756bacc 8a61f9fd nt!KeWaitForSingleObject+0x492
8756bae8 9dcdb844 ks!KsAcquireControl+0x17 (FPO: [1,0,0])
8756bb08 8a61146a usbaudio!DeviceSurpriseRemoval+0x30 (FPO: [2,2,4])
8756bb28 82701fd3 ks!CKsDevice::DispatchPnp+0x2aa (FPO: [2,1,4])
8756bb40 827f7856 nt!IofCallDriver+0x63
8756bb74 828c1c8f nt!IopSynchronousCall+0xce
8756bbd0 828bb30f nt!IopRemoveDevice+0xd1
8756bbfc 828bb1cc nt!PnpSurpriseRemoveLockedDeviceNode+0xc4
8756bc10 828bb487 nt!PnpDeleteLockedDeviceNode+0x20
8756bc44 828bef33 nt!PnpDeleteLockedDeviceNodes+0x4c
8756bd04 827aae17 nt!PnpProcessQueryRemoveAndEject+0x594
8756bd1c 827d63c0 nt!PnpProcessTargetDeviceEvent+0x38
8756bd44 8267e445 nt!PnpDeviceEventWorker+0x201
8756bd7c 8281bb18 nt!ExpWorkerThread+0xfd
8756bdc0 82674a2e nt!PspSystemThreadStartup+0x9d
00000000 00000000 nt!KiThreadStartup+0x16

0: kd> !irp 0x859dc2a0 7
Irp is active with 14 stacks 14 is current (= 0x859dc4e4)
No Mdl: No System Buffer: Thread 83f22020: Irp stack trace.
Flags = 00000000
ThreadListEntry.Flink = 84903280
ThreadListEntry.Blink = 83f2224c
IoStatus.Status = c00000bb
IoStatus.Information = 00000000
RequestorMode = 00000000
Cancel = 00
CancelIrql = 0
ApcEnvironment = 00
UserIosb = 8756bb58
UserEvent = 8756bb60
Overlay.AsynchronousParameters.UserApcRoutine = 00000000
Overlay.AsynchronousParameters.UserApcContext = 00000000
Overlay.AllocationSize = 00000000 - 00000000
CancelRoutine = 00000000
UserBuffer = 00000000
&Tail.Overlay.DeviceQueueEntry = 859dc2e0
Tail.Overlay.Thread = 83f22020
Tail.Overlay.AuxiliaryBuffer = 00000000
Tail.Overlay.ListEntry.Flink = 00000000
Tail.Overlay.ListEntry.Blink = 00000000
Tail.Overlay.CurrentStackLocation = 859dc4e4
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 85700af0 00000000 00000000-00000000
\Driver\usbaudio
Args: 00000000 00000000 00000000 00000000
IO verifier information:
No information available - the verifier is probably disabled

0: kd> !pnpevent
Dumping PnP DeviceEvent Queue @ 0x83ec23a0
List = 0x9c98c180, 0x99f9f100

Dumping DeviceEventEntry @ 0x9c98c180
ListEntry = 0x9e041ea8, 0x83ec23e4, Argument = 0x00000000
CallerEvent = 0x87557acc, Callback = 0x00000000, Context = 0x00000000
VetoType = 0x00000000, VetoName = 0x00000000

Dumping PlugPlayEventBlock @ 0x9C98C1A0
EventGuid = GUID_DEVICE_NOOP
Category = TargetDeviceChangeEvent
Result = 0x87557adc, Flags = 0x00000000, TotalSize = 64
DeviceObject = 0x00000000
DeviceIds:

Dumping DeviceEventEntry @ 0x9e041ea8
ListEntry = 0x9de78c60, 0x9c98c180, Argument = 0x00000000
CallerEvent = 0x00000000, Callback = 0x00000000, Context = 0x00000000
VetoType = 0x00000000, VetoName = 0x00000000

Dumping PlugPlayEventBlock @ 0x9E041EC8
EventGuid = GUID_DEVICE_INTERFACE_REMOVAL
Category = DeviceClassChangeEvent
Result = 0x00000000, Flags = 0x00000000, TotalSize = 308
DeviceObject = 0x00000000
ClassGuid = 53F56307-B6BF-11D0-94F2-00A0C91EFB8B
SymbolicLinkName =
??\USBSTOR#Disk&Ven_JetFlash&Prod_TS1GJF110&Rev_0.00#b&16f10f7f&0&a1f070063bc07e&0#{53f56307-b6bf-11d0-94f2-00a0c91efb8b}

Dumping DeviceEventEntry @ 0x9de78c60
ListEntry = 0xa29ec228, 0x9e041ea8, Argument = 0x00000000
CallerEvent = 0x00000000, Callback = 0x00000000, Context = 0x00000000
VetoType = 0x00000000, VetoName = 0x00000000

Dumping PlugPlayEventBlock @ 0x9DE78C80
EventGuid = GUID_DEVICE_INTERFACE_REMOVAL
Category = DeviceClassChangeEvent
Result = 0x00000000, Flags = 0x00000000, TotalSize = 254
DeviceObject = 0x00000000
ClassGuid = 6994AD04-93EF-11D0-A3CC-00A0C9223196
SymbolicLinkName =
??\USB#VID_0D8C&PID_0103&MI_00#b&17245a44&0&0000#{6994ad04-93ef-11d0-a3cc-00a0c9223196}\GLOBAL

Dumping DeviceEventEntry @ 0xa29ec228
ListEntry = 0x9d3a86f8, 0x9de78c60, Argument = 0x00000000
CallerEvent = 0x00000000, Callback = 0x00000000, Context = 0x00000000
VetoType = 0x00000000, VetoName = 0x00000000

Dumping PlugPlayEventBlock @ 0xA29EC248
EventGuid = GUID_DEVICE_INTERFACE_REMOVAL
Category = DeviceClassChangeEvent
Result = 0x00000000, Flags = 0x00000000, TotalSize = 254
DeviceObject = 0x00000000
ClassGuid = 65E8773E-8F56-11D0-A3B9-00A0C9223196
SymbolicLinkName =
??\USB#VID_0D8C&PID_0103&MI_00#b&17245a44&0&0000#{65e8773e-8f56-11d0-a3b9-00a0c9223196}\GLOBAL

Dumping DeviceEventEntry @ 0x9d3a86f8
ListEntry = 0x9e018498, 0xa29ec228, Argument = 0x00000000
CallerEvent = 0x00000000, Callback = 0x00000000, Context = 0x00000000
VetoType = 0x00000000, VetoName = 0x00000000

Dumping PlugPlayEventBlock @ 0x9D3A8718
EventGuid = GUID_PNP_POWER_SETTING_CHANGE
Category = DeviceInstanceRemovalEvent
Result = 0x00000000, Flags = 0x00000000, TotalSize = 64
DeviceObject = 0x00000000
DeviceIds:
㇘兜ᘽﶠꀑ醌

腀蝖>

Tim_Roberts · October 6, 2009, 3:36pm

Randal Erman wrote:

I was wondering if anyone has any insight into why the USB Audio
class driver would be hanging PNP on Vista. I have tried everything I
know to figure it out why USBAudio is handing around… Any debugging
techniques that to address this type of hang? Below is the devnode,
thread; one can see the SURPRISE REMOVE irp which hasn’t been
forwarded down the stack yet.
…
0: kd> !irp 0x859dc2a0 7
Irp is active with 14 stacks 14 is current (= 0x859dc4e4)

14 devices in the stack, without the verifier??? Do you have a whole
bunch of lower filter drivers installed? Are you running a USB
sniffer? They could be involved.

–
Tim Roberts, xxxxx@probo.com
Providenza & Boekelheide, Inc.

PascalJedi · October 6, 2009, 4:17pm

Hi Tim,

Yes, there are several filter drivers, as well as tracing drivers in
the stack as well as a bus enumeration driver and hubs. Certainly they
could be involved…

-R

On Tue, Oct 6, 2009 at 12:35 PM, Tim Roberts wrote:

> Randal Erman wrote:
> >
> > I was wondering if anyone has any insight into why the USB Audio
> > class driver would be hanging PNP on Vista. I have tried everything I
> > know to figure it out why USBAudio is handing around… Any debugging
> > techniques that to address this type of hang? Below is the devnode,
> > thread; one can see the SURPRISE REMOVE irp which hasn’t been
> > forwarded down the stack yet.
> > …
> > 0: kd> !irp 0x859dc2a0 7
> > Irp is active with 14 stacks 14 is current (= 0x859dc4e4)
>
> 14 devices in the stack, without the verifier??? Do you have a whole
> bunch of lower filter drivers installed? Are you running a USB
> sniffer? They could be involved.
>
> –
> Tim Roberts, xxxxx@probo.com
> Providenza & Boekelheide, Inc.
>
>
> —
> NTDEV is sponsored by OSR
>
> For our schedule of WDF, WDM, debugging and other seminars visit:
> http://www.osr.com/seminars
>
> To unsubscribe, visit the List Server section of OSR Online at
> http://www.osronline.com/page.cfm?name=ListServer
>

Doron_Holan · October 6, 2009, 4:29pm

Usbaudio is trying to acquire a lock (probably a KEVENT), so my guess is that either the lock was abandoned or some other currently running thread is holding on to it and that other thread has not returned or is deadlocked.? You could dump all of the stacks with ks or usbaudio in them (see the help for !stacks on how to do that) and see if any of them look suspicious

d

PascalJedi · October 6, 2009, 5:48pm

Hi Doron,

Here are all stacks with USBAudio in it;

THREAD 83f22020 Cid 0004.0044 Teb: 00000000 Win32Thread: 00000000
WAIT: (Executive) KernelMode Non-Alertable
8465c54c Mutant - owning thread 84449328
IRP List:
859dc2a0: (0006,0268) Flags: 00000000 Mdl: 00000000
84903270: (0006,0220) Flags: 00060000 Mdl: 00000000
8529cd28: (0006,0220) Flags: 00060000 Mdl: 00000000
Not impersonating
DeviceMap 87208dc8
Owning Process 83efcd90 Image: System
Attached Process N/A Image: N/A
Wait Start TickCount 4352704 Ticks: 118779
(0:00:30:52.964)
Context Switch Count 493139
UserTime 00:00:00.000
KernelTime 00:00:06.567
Win32 Start Address nt!ExpWorkerThread (0x8267e348)
Stack Init 8756c000 Current 8756ba18 Base 8756c000 Limit 87569000
Call 0
Priority 14 BasePriority 12 PriorityDecrement 2 IoPriority 2
PagePriority 5
ChildEBP RetAddr Args to Child
8756ba30 826fd2ff 83f22020 83f220a8 8274813c nt!KiSwapContext+0x26
(FPO: [Uses EBP] [0,0,4])
8756ba74 8269acc8 83f22020 00000000 8465c514 nt!KiSwapThread+0x44f
8756bacc 8a61f9fd 8465c54c 00000000 00000000
nt!KeWaitForSingleObject+0x492
8756bae8 9dcdb844 8465c514 859dc2a0 85765008
ks!KsAcquireControl+0x17 (FPO: [1,0,0])
8756bb08 8a61146a 85765074 859dc2a0 859dc508
usbaudio!DeviceSurpriseRemoval+0x30 (FPO: [2,2,4])
8756bb28 82701fd3 85700af0 859dc2a0 8756bbcc
ks!CKsDevice::DispatchPnp+0x2aa (FPO: [2,1,4])
8756bb40 827f7856 8461dc80 8461dc80 817ae8a8 nt!IofCallDriver+0x63
8756bb74 828c1c8f 8461dc80 8756bba8 00000000
nt!IopSynchronousCall+0xce
8756bbd0 828bb30f 8461dc80 00000017 a08d5088 nt!IopRemoveDevice+0xd1
8756bbfc 828bb1cc 00000308 00000000 8461dfc0
nt!PnpSurpriseRemoveLockedDeviceNode+0xc4
8756bc10 828bb487 00000003 00000000 00000000
nt!PnpDeleteLockedDeviceNode+0x20
8756bc44 828bef33 8455d6f0 a08d5088 00000003
nt!PnpDeleteLockedDeviceNodes+0x4c
8756bd04 827aae17 8756bd34 00000000 a09bca30
nt!PnpProcessQueryRemoveAndEject+0x594
8756bd1c 827d63c0 00000000 8274813c 83f22020
nt!PnpProcessTargetDeviceEvent+0x38
8756bd44 8267e445 856e92a8 00000000 83f22020
nt!PnpDeviceEventWorker+0x201
8756bd7c 8281bb18 856e92a8 64399c6a 00000000 nt!ExpWorkerThread+0xfd
8756bdc0 82674a2e 8267e348 00000001 00000000
nt!PspSystemThreadStartup+0x9d
00000000 00000000 00000000 00000000 00000000 nt!KiThreadStartup+0x16

WARNING: Frame IP not in any known module. Following frames may be wrong.
0113f6c4 00000000 00000000 00000000 00000000 0x777d9a94

THREAD 84449328 Cid 0470.1254 Teb: 7ffd8000 Win32Thread: 00000000
WAIT: (Executive) KernelMode Non-Alertable
85980048 NotificationEvent
IRP List:
845dd660: (0006,0268) Flags: 00060030 Mdl: 00000000
Not impersonating
DeviceMap 93155e88
Owning Process 95df8d90 Image: audiodg.exe
Attached Process N/A Image: N/A
Wait Start TickCount 1058292 Ticks: 3413191
(0:14:47:26.120)
Context Switch Count 4
UserTime 00:00:00.000
KernelTime 00:00:00.000
Win32 Start Address 0x774d4f4e
Stack Init a2d50000 Current a2d4f978 Base a2d50000 Limit a2d4d000
Call 0
Priority 8 BasePriority 8 PriorityDecrement 0 IoPriority 2
PagePriority 5
ChildEBP RetAddr Args to Child
a2d4f990 826fd2ff 84449328 844493b0 95ed4620 nt!KiSwapContext+0x26
(FPO: [Uses EBP] [0,0,4])
a2d4f9d4 8269acc8 84449328 00000000 85980048 nt!KiSwapThread+0x44f
a2d4fa28 9dcdc277 85980048 00000000 00000000
nt!KeWaitForSingleObject+0x492
a2d4fa50 9dce56f9 006d7da0 00000002 856d7d10
usbaudio!PinWaitForStarvation+0x45 (FPO: [1,0,4])
a2d4fa70 9dcdc149 856d7da0 00000003 00000002
usbaudio!USBType1StateChangePin+0x9b (FPO: [3,2,4])
a2d4fa84 8a60fe12 856d7da0 00000002 00000003
usbaudio!PinSetDeviceState+0x1b (FPO: [3,0,0])
a2d4faa4 8a6100a7 856d7d10 00000002 00000003
ks!CKsPin::ClientSetDeviceState+0x56 (FPO: [3,0,4])
a2d4fac8 8a610182 856f0090 00000002 00000003
ks!CKsPipeSection::DistributeStateChangeToPins+0x28 (FPO: [3,1,4])
a2d4fae8 8a610045 8571a5d8 00000002 00000003
ks!CKsQueue::SetDeviceState+0x25 (FPO: [4,0,4])
a2d4fb0c 8a610396 8571a5d8 00000002 00000003
ks!CKsPipeSection::DistributeDeviceStateChange+0x1f (FPO: [3,1,0])
a2d4fb34 8a60ff27 856d7d10 856d7d10 00000002
ks!CKsPipeSection::SetDeviceState+0xb2 (FPO: [3,2,4])
a2d4fb54 8a60ef8f 845dd660 846a34c0 856d7da0
ks!CKsPin::Property_ConnectionState+0xdc (FPO: [3,0,4])
a2d4fba4 8a60f174 845dd660 00000003 9d28d06c
ks!KspPropertyHandler+0x66f (FPO: [SEH])
a2d4fbd0 8a60f377 845dd660 9d28d008 856d7d94
ks!KspHandleAutomationIoControl+0x174 (FPO: [6,0,0])
a2d4fc04 8a60f246 85700af0 845dd660 a2d4fc2c
ks!CKsPin::DispatchDeviceIoControl+0xa7 (FPO: [2,2,4])
a2d4fc14 8a6010f1 85700af0 845dd660 85700af0 ks!KsDispatchIrp+0xa5
(FPO: [2,0,0])
a2d4fc2c 82701fd3 85700af0 845dd660 845dd660
ks!CKsDevice::PassThroughIrp+0x4f (FPO: [2,0,0])
a2d4fc44 828925e5 84478a38 845dd660 845dd8a4 nt!IofCallDriver+0x63
a2d4fc64 82892d8a 85700af0 84478a38 01fcef00
nt!IopSynchronousServiceTail+0x1d9
a2d4fd00 8287ca5d 85700af0 845dd660 00000000
nt!IopXxxControlFile+0x6b7
a2d4fd34 8269da1a 00000678 000006b5 00000000
nt!NtDeviceIoControlFile+0x2a
a2d4fd34 777d9a94 00000678 000006b5 00000000
nt!KiFastCallEntry+0x12a (FPO: [0,3] TrapFrame @ a2d4fd64)
WARNING: Frame IP not in any known module. Following frames may be wrong.
01fcef3c 00000000 00000000 00000000 00000000 0x777d9a94

WARNING: Frame IP not in any known module. Following frames may be wrong.
01a4f770 00000000 00000000 00000000 00000000 0x777d9a94

THREAD 8597c758 Cid 0470.1608 Teb: 7ffd5000 Win32Thread: 00000000
WAIT: (Executive) KernelMode Non-Alertable
8465c54c Mutant - owning thread 84449328
IRP List:
856d4a90: (0006,0268) Flags: 00060030 Mdl: 00000000
Not impersonating
DeviceMap 93155e88
Owning Process 95df8d90 Image: audiodg.exe
Attached Process N/A Image: N/A
Wait Start TickCount 1058419 Ticks: 3413064
(0:14:47:24.139)
Context Switch Count 8902
UserTime 00:00:00.015
KernelTime 00:00:00.015
Win32 Start Address 0x740f82b3
Stack Init 980e6000 Current 980e5a78 Base 980e6000 Limit 980e3000
Call 0
Priority 22 BasePriority 5 PriorityDecrement 0 IoPriority 2
PagePriority 5
ChildEBP RetAddr Args to Child
980e5a90 826fd2ff 8597c758 8597c7e0 00000000 nt!KiSwapContext+0x26
(FPO: [Uses EBP] [0,0,4])
980e5ad4 8269acc8 8597c758 8b0662b8 856d7d10 nt!KiSwapThread+0x44f
980e5b2c 8a60fee6 8465c54c 00000000 00000000
nt!KeWaitForSingleObject+0x492
980e5b54 8a60ef8f 856d4a90 8b0662c0 856d7da0
ks!CKsPin::Property_ConnectionState+0x9b (FPO: [3,0,4])
980e5ba4 8a60f174 856d4a90 00000003 9d28d06c
ks!KspPropertyHandler+0x66f (FPO: [SEH])
980e5bd0 8a60f377 856d4a90 9d28d008 856d7d94
ks!KspHandleAutomationIoControl+0x174 (FPO: [6,0,0])
980e5c04 8a60f246 85700af0 856d4a90 980e5c2c
ks!CKsPin::DispatchDeviceIoControl+0xa7 (FPO: [2,2,4])
980e5c14 8a6010f1 85700af0 856d4a90 85700af0 ks!KsDispatchIrp+0xa5
(FPO: [2,0,0])
980e5c2c 82701fd3 85700af0 856d4a90 856d4a90
ks!CKsDevice::PassThroughIrp+0x4f (FPO: [2,0,0])
980e5c44 828925e5 84478a38 856d4a90 856d4cd4 nt!IofCallDriver+0x63
980e5c64 82892d8a 85700af0 84478a38 0113f700
nt!IopSynchronousServiceTail+0x1d9
980e5d00 8287ca5d 85700af0 856d4a90 00000000
nt!IopXxxControlFile+0x6b7
980e5d34 8269da1a 00000678 000005d1 00000000
nt!NtDeviceIoControlFile+0x2a
980e5d34 777d9a94 00000678 000005d1 00000000
nt!KiFastCallEntry+0x12a (FPO: [0,3] TrapFrame @ 980e5d64)

Here is everything that came up with USBAudio in irpfind.

859dc2a0 [83f22020] irpStack: (1b,17) 85700af0 [\Driver\usbaudio]
856d4a90 [8597c758] irpStack: ( e, 0) 85700af0 [\Driver\usbaudio]
84c23820 [8594cd78] irpStack: ( e, 0) 85700af0 [\Driver\usbaudio]
0x95df8d90
845dd660 [84449328] irpStack: ( e, 0) 85700af0 [\Driver\usbaudio]

0: kd> !stacks
Proc.Thread .Thread Ticks ThreadState Blocker
[83efcd90 System]
4.000030 83f21d78 001d000 Blocked
nt!PnpSynchronizeDeviceEventQueue+0x72
4.000034 83f21ad0 00000dc Blocked nt!PpDevNodeLockTree+0x7a
4.000044 83f22020 001cffb Blocked ks!KsAcquireControl+0x17
4.000048 83f22d78 0000000 RUNNING nt!KeBugCheck+0x14
4.000060 83f93d78 000e39e GATEWAIT nt!MiModifiedPageWriter+0x3e
4.000070 83f92c50 0000016 Blocked nt!CcQueueLazyWriteScanThread+0x42
4.000080 83ed0d18 0000037 Blocked nt!EtwpLogger+0xc7
4.000084 83ed06b0 0000029 Blocked nt!EtwpLogger+0xc7
4.000088 83f1f918 0000030 Blocked nt!EtwpLogger+0xc7
4.00008c 83f1f370 0000029 Blocked nt!EtwpLogger+0xc7
4.000090 8439fd78 0443aa2 Blocked nt!EtwpLogger+0x66
4.000094 8439f7d0 0443aa2 Blocked nt!EtwpLogger+0x66
4.000098 84424020 0443aa2 Blocked nt!EtwpLogger+0x66
4.0000a0 84c31d78 00018e5 Blocked nt!EtwpLogger+0xc7
4.0000a4 84c36d78 00008bb Blocked nt!WdipSemCheckTimeout+0x226
4.0000a8 84c53d50 00001e6 Blocked acpi!ACPIWorkerThread+0x47
4.0000b0 842df3a0 0443a99 Blocked
acpi!PciRootBusBiosMethodDispatcherOnResume+0x30
4.0000b4 84c85240 0443a99 Blocked
pci!ExpressRootComplexPmeEventDispatcher+0x34
4.0000bc 850d45e0 0000097 Blocked ndis!ndisCmWaitThread+0x5b
4.0000d0 85182680 0442707 Blocked ecache!EcCacheIoWorker+0x42
4.0000d4 84c38640 044270a Blocked ecache!EcCacheIoWatchdog+0x2c1
4.0000e0 85199538 043a7e3 Blocked volsnap!VspWorkerThread+0x90
4.0000e4 85199218 000000f Blocked volsnap!VspWorkerThread+0x90
4.0000e8 85c7b020 000000f Blocked volsnap!VspWorkerThread+0x90
4.0000ec 85c7bd78 0440311 Blocked volsnap!VspWorkerThread+0x90
4.0000f0 85c7bad0 0440812 Blocked volsnap!VspWorkerThread+0x90
4.0000f4 85d743b8 000000e Blocked
Ntfs!TxfPrivateThreadWorkerRoutine+0x2f
4.0000fc 85da8020 0443929 Blocked rimmptsk+0x61d0
4.000100 85da8758 0443929 Blocked rimsptsk+0x67f9
4.000104 85d98a48 0443928 Blocked rixdptsk+0x6899
4.000110 85ebdb18 04438a9 Blocked rimmptsk+0x66c4
4.000114 85eab020 04438a8 Blocked rimmptsk+0x6c02
4.000118 85ea71f0 04438a6 Blocked rimsptsk+0x660c
4.00011c 85ebd5b0 04438a6 Blocked rimsptsk+0x70bc
4.000120 85ea8ca8 04438a4 Blocked rixdptsk+0x669e
4.000124 85ea8408 04438a4 Blocked rixdptsk+0x708e
4.000150 8b0233d0 044361f Blocked CHDRT32+0x14c0a
4.000154 8b025578 0443841 Blocked CHDRT32+0xee36
4.00015c 85d51a58 044350b Blocked bthport!HCI_ThreadFunction+0xc9
4.00019c 8b146c38 0000c92 Blocked nt!AlpcpReceiveMessagePort+0x221
4.0001f0 8b08b538 04436df Blocked watchdog!SMgrGdiCalloutThread+0x35
4.000228 8d856530 0000064 Blocked nt!IoRemoveIoCompletion+0x23
4.000264 8b1e8ad0 0000c92 Blocked nt!EtwpLogger+0xc7
4.000324 8d9a0238 000000c Blocked luafv!SynchronousFsControl+0xa3
4.000328 8d9b3458 00000b7 Blocked ino_fltr+0x8a8b
4.00032c 95ec3568 04432ff Blocked ino_fltr+0x527b
4.0004fc 95f02d78 0443609 Blocked spsys+0x5c0e8
4.000554 8163cd10 0002214 Blocked nt!EtwpLogger+0xc7
4.00068c 81688d78 0000245 Blocked HTTP!UlpScavengerThread+0x5e
4.000714 816b6320 0000ff9 Blocked mpsdrv!AuditSuccessEvent+0x19b
4.000780 816fbc40 04434c1 Blocked srv2!SrvProcWorkerThread+0x6c
4.000784 816fa258 04434bf Blocked srv2!SrvProcWorkerThread+0x6c
4.000788 816fb998 04434bf Blocked srv2!SrvProcWorkerThread+0x6c
4.00078c 816fb6f0 04434be Blocked srv2!SrvProcWorkerThread+0x6c
4.000790 816fb448 04434bc Blocked srv2!SrvProcWorkerThread+0x6c
4.0009d8 97ca9110 0001bd7 Blocked nt!EtwpLogger+0xc7
4.000c30 97ce4430 0000005 RUNNING nt!PfTEntryInfoLookup+0xc4
4.000d48 95ffe030 044272e Blocked nt!EtwpLogger+0xc7
4.000ed0 844f2720 000001f Blocked nt!EtwpLogger+0xc7
4.000efc 84502600 04425fb Blocked nt!EtwpLogger+0xc7
4.001720 84c8b270 001db10 Blocked nt!EtwpLogger+0x66
4.001464 8574a020 0405896 Blocked nt!IoRemoveIoCompletion+0x23
4.001580 84675570 0405873 Blocked nt!IoRemoveIoCompletion+0x23

[95df8d90 audiodg.exe]
470.001608 8597c758 0341448 Blocked
ks!CKsPin::Property_ConnectionState+0x9b
470.001254 84449328 03414c7 Blocked usbaudio!PinWaitForStarvation+0x45
470.000968 85a3b760 0000c52 Blocked nt!KiFastCallEntry+0x12a
470.001950 85a8b4f0 00004cf Blocked nt!IoRemoveIoCompletion+0x23

-R

On Tue, Oct 6, 2009 at 1:28 PM, wrote:

> Usbaudio is trying to acquire a lock (probably a KEVENT), so my guess is
> that either the lock was abandoned or some other currently running thread is
> holding on to it and that other thread has not returned or is deadlocked.?
> You could dump all of the stacks with ks or usbaudio in them (see the help
> for !stacks on how to do that) and see if any of them look suspicious
>
> d
>
>
> —
> NTDEV is sponsored by OSR
>
> For our schedule of WDF, WDM, debugging and other seminars visit:
> http://www.osr.com/seminars
>
> To unsubscribe, visit the List Server section of OSR Online at
> http://www.osronline.com/page.cfm?name=ListServer
>

Doron_Holan · October 6, 2009, 7:32pm

You have another 8597c758 waiting on the same dispatcher object, outside of that who knows. You need to start digging yourself and see what is there

d

From: xxxxx@lists.osr.com [mailto:xxxxx@lists.osr.com] On Behalf Of Randal Erman
Sent: Tuesday, October 06, 2009 2:48 PM
To: Windows System Software Devs Interest List
Subject: Re: [ntdev] USB Audio Driver on Vista hangs PNP

Hi Doron,

Here are all stacks with USBAudio in it;

THREAD 83f22020 Cid 0004.0044 Teb: 00000000 Win32Thread: 00000000 WAIT: (Executive) KernelMode Non-Alertable
8465c54c Mutant - owning thread 84449328
IRP List:
859dc2a0: (0006,0268) Flags: 00000000 Mdl: 00000000
84903270: (0006,0220) Flags: 00060000 Mdl: 00000000
8529cd28: (0006,0220) Flags: 00060000 Mdl: 00000000
Not impersonating
DeviceMap 87208dc8
Owning Process 83efcd90 Image: System
Attached Process N/A Image: N/A
Wait Start TickCount 4352704 Ticks: 118779 (0:00:30:52.964)
Context Switch Count 493139
UserTime 00:00:00.000
KernelTime 00:00:06.567
Win32 Start Address nt!ExpWorkerThread (0x8267e348)
Stack Init 8756c000 Current 8756ba18 Base 8756c000 Limit 87569000 Call 0
Priority 14 BasePriority 12 PriorityDecrement 2 IoPriority 2 PagePriority 5
ChildEBP RetAddr Args to Child
8756ba30 826fd2ff 83f22020 83f220a8 8274813c nt!KiSwapContext+0x26 (FPO: [Uses EBP] [0,0,4])
8756ba74 8269acc8 83f22020 00000000 8465c514 nt!KiSwapThread+0x44f
8756bacc 8a61f9fd 8465c54c 00000000 00000000 nt!KeWaitForSingleObject+0x492
8756bae8 9dcdb844 8465c514 859dc2a0 85765008 ks!KsAcquireControl+0x17 (FPO: [1,0,0])
8756bb08 8a61146a 85765074 859dc2a0 859dc508 usbaudio!DeviceSurpriseRemoval+0x30 (FPO: [2,2,4])
8756bb28 82701fd3 85700af0 859dc2a0 8756bbcc ks!CKsDevice::DispatchPnp+0x2aa (FPO: [2,1,4])
8756bb40 827f7856 8461dc80 8461dc80 817ae8a8 nt!IofCallDriver+0x63
8756bb74 828c1c8f 8461dc80 8756bba8 00000000 nt!IopSynchronousCall+0xce
8756bbd0 828bb30f 8461dc80 00000017 a08d5088 nt!IopRemoveDevice+0xd1
8756bbfc 828bb1cc 00000308 00000000 8461dfc0 nt!PnpSurpriseRemoveLockedDeviceNode+0xc4
8756bc10 828bb487 00000003 00000000 00000000 nt!PnpDeleteLockedDeviceNode+0x20
8756bc44 828bef33 8455d6f0 a08d5088 00000003 nt!PnpDeleteLockedDeviceNodes+0x4c
8756bd04 827aae17 8756bd34 00000000 a09bca30 nt!PnpProcessQueryRemoveAndEject+0x594
8756bd1c 827d63c0 00000000 8274813c 83f22020 nt!PnpProcessTargetDeviceEvent+0x38
8756bd44 8267e445 856e92a8 00000000 83f22020 nt!PnpDeviceEventWorker+0x201
8756bd7c 8281bb18 856e92a8 64399c6a 00000000 nt!ExpWorkerThread+0xfd
8756bdc0 82674a2e 8267e348 00000001 00000000 nt!PspSystemThreadStartup+0x9d
00000000 00000000 00000000 00000000 00000000 nt!KiThreadStartup+0x16

WARNING: Frame IP not in any known module. Following frames may be wrong.
0113f6c4 00000000 00000000 00000000 00000000 0x777d9a94

THREAD 84449328 Cid 0470.1254 Teb: 7ffd8000 Win32Thread: 00000000 WAIT: (Executive) KernelMode Non-Alertable
85980048 NotificationEvent
IRP List:
845dd660: (0006,0268) Flags: 00060030 Mdl: 00000000
Not impersonating
DeviceMap 93155e88
Owning Process 95df8d90 Image: audiodg.exe
Attached Process N/A Image: N/A
Wait Start TickCount 1058292 Ticks: 3413191 (0:14:47:26.120)
Context Switch Count 4
UserTime 00:00:00.000
KernelTime 00:00:00.000
Win32 Start Address 0x774d4f4e
Stack Init a2d50000 Current a2d4f978 Base a2d50000 Limit a2d4d000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0 IoPriority 2 PagePriority 5
ChildEBP RetAddr Args to Child
a2d4f990 826fd2ff 84449328 844493b0 95ed4620 nt!KiSwapContext+0x26 (FPO: [Uses EBP] [0,0,4])
a2d4f9d4 8269acc8 84449328 00000000 85980048 nt!KiSwapThread+0x44f
a2d4fa28 9dcdc277 85980048 00000000 00000000 nt!KeWaitForSingleObject+0x492
a2d4fa50 9dce56f9 006d7da0 00000002 856d7d10 usbaudio!PinWaitForStarvation+0x45 (FPO: [1,0,4])
a2d4fa70 9dcdc149 856d7da0 00000003 00000002 usbaudio!USBType1StateChangePin+0x9b (FPO: [3,2,4])
a2d4fa84 8a60fe12 856d7da0 00000002 00000003 usbaudio!PinSetDeviceState+0x1b (FPO: [3,0,0])
a2d4faa4 8a6100a7 856d7d10 00000002 00000003 ks!CKsPin::ClientSetDeviceState+0x56 (FPO: [3,0,4])
a2d4fac8 8a610182 856f0090 00000002 00000003 ks!CKsPipeSection::DistributeStateChangeToPins+0x28 (FPO: [3,1,4])
a2d4fae8 8a610045 8571a5d8 00000002 00000003 ks!CKsQueue::SetDeviceState+0x25 (FPO: [4,0,4])
a2d4fb0c 8a610396 8571a5d8 00000002 00000003 ks!CKsPipeSection::DistributeDeviceStateChange+0x1f (FPO: [3,1,0])
a2d4fb34 8a60ff27 856d7d10 856d7d10 00000002 ks!CKsPipeSection::SetDeviceState+0xb2 (FPO: [3,2,4])
a2d4fb54 8a60ef8f 845dd660 846a34c0 856d7da0 ks!CKsPin::Property_ConnectionState+0xdc (FPO: [3,0,4])
a2d4fba4 8a60f174 845dd660 00000003 9d28d06c ks!KspPropertyHandler+0x66f (FPO: [SEH])
a2d4fbd0 8a60f377 845dd660 9d28d008 856d7d94 ks!KspHandleAutomationIoControl+0x174 (FPO: [6,0,0])
a2d4fc04 8a60f246 85700af0 845dd660 a2d4fc2c ks!CKsPin::DispatchDeviceIoControl+0xa7 (FPO: [2,2,4])
a2d4fc14 8a6010f1 85700af0 845dd660 85700af0 ks!KsDispatchIrp+0xa5 (FPO: [2,0,0])
a2d4fc2c 82701fd3 85700af0 845dd660 845dd660 ks!CKsDevice::PassThroughIrp+0x4f (FPO: [2,0,0])
a2d4fc44 828925e5 84478a38 845dd660 845dd8a4 nt!IofCallDriver+0x63
a2d4fc64 82892d8a 85700af0 84478a38 01fcef00 nt!IopSynchronousServiceTail+0x1d9
a2d4fd00 8287ca5d 85700af0 845dd660 00000000 nt!IopXxxControlFile+0x6b7
a2d4fd34 8269da1a 00000678 000006b5 00000000 nt!NtDeviceIoControlFile+0x2a
a2d4fd34 777d9a94 00000678 000006b5 00000000 nt!KiFastCallEntry+0x12a (FPO: [0,3] TrapFrame @ a2d4fd64)
WARNING: Frame IP not in any known module. Following frames may be wrong.
01fcef3c 00000000 00000000 00000000 00000000 0x777d9a94

WARNING: Frame IP not in any known module. Following frames may be wrong.
01a4f770 00000000 00000000 00000000 00000000 0x777d9a94

THREAD 8597c758 Cid 0470.1608 Teb: 7ffd5000 Win32Thread: 00000000 WAIT: (Executive) KernelMode Non-Alertable
8465c54c Mutant - owning thread 84449328
IRP List:
856d4a90: (0006,0268) Flags: 00060030 Mdl: 00000000
Not impersonating
DeviceMap 93155e88
Owning Process 95df8d90 Image: audiodg.exe
Attached Process N/A Image: N/A
Wait Start TickCount 1058419 Ticks: 3413064 (0:14:47:24.139)
Context Switch Count 8902
UserTime 00:00:00.015
KernelTime 00:00:00.015
Win32 Start Address 0x740f82b3
Stack Init 980e6000 Current 980e5a78 Base 980e6000 Limit 980e3000 Call 0
Priority 22 BasePriority 5 PriorityDecrement 0 IoPriority 2 PagePriority 5
ChildEBP RetAddr Args to Child
980e5a90 826fd2ff 8597c758 8597c7e0 00000000 nt!KiSwapContext+0x26 (FPO: [Uses EBP] [0,0,4])
980e5ad4 8269acc8 8597c758 8b0662b8 856d7d10 nt!KiSwapThread+0x44f
980e5b2c 8a60fee6 8465c54c 00000000 00000000 nt!KeWaitForSingleObject+0x492
980e5b54 8a60ef8f 856d4a90 8b0662c0 856d7da0 ks!CKsPin::Property_ConnectionState+0x9b (FPO: [3,0,4])
980e5ba4 8a60f174 856d4a90 00000003 9d28d06c ks!KspPropertyHandler+0x66f (FPO: [SEH])
980e5bd0 8a60f377 856d4a90 9d28d008 856d7d94 ks!KspHandleAutomationIoControl+0x174 (FPO: [6,0,0])
980e5c04 8a60f246 85700af0 856d4a90 980e5c2c ks!CKsPin::DispatchDeviceIoControl+0xa7 (FPO: [2,2,4])
980e5c14 8a6010f1 85700af0 856d4a90 85700af0 ks!KsDispatchIrp+0xa5 (FPO: [2,0,0])
980e5c2c 82701fd3 85700af0 856d4a90 856d4a90 ks!CKsDevice::PassThroughIrp+0x4f (FPO: [2,0,0])
980e5c44 828925e5 84478a38 856d4a90 856d4cd4 nt!IofCallDriver+0x63
980e5c64 82892d8a 85700af0 84478a38 0113f700 nt!IopSynchronousServiceTail+0x1d9
980e5d00 8287ca5d 85700af0 856d4a90 00000000 nt!IopXxxControlFile+0x6b7
980e5d34 8269da1a 00000678 000005d1 00000000 nt!NtDeviceIoControlFile+0x2a
980e5d34 777d9a94 00000678 000005d1 00000000 nt!KiFastCallEntry+0x12a (FPO: [0,3] TrapFrame @ 980e5d64)

Here is everything that came up with USBAudio in irpfind.

859dc2a0 [83f22020] irpStack: (1b,17) 85700af0 [\Driver\usbaudio]
856d4a90 [8597c758] irpStack: ( e, 0) 85700af0 [\Driver\usbaudio]
84c23820 [8594cd78] irpStack: ( e, 0) 85700af0 [\Driver\usbaudio] 0x95df8d90
845dd660 [84449328] irpStack: ( e, 0) 85700af0 [\Driver\usbaudio]

0: kd> !stacks
Proc.Thread .Thread Ticks ThreadState Blocker
[83efcd90 System]
4.000030 83f21d78 001d000 Blocked nt!PnpSynchronizeDeviceEventQueue+0x72
4.000034 83f21ad0 00000dc Blocked nt!PpDevNodeLockTree+0x7a
4.000044 83f22020 001cffb Blocked ks!KsAcquireControl+0x17
4.000048 83f22d78 0000000 RUNNING nt!KeBugCheck+0x14
4.000060 83f93d78 000e39e GATEWAIT nt!MiModifiedPageWriter+0x3e
4.000070 83f92c50 0000016 Blocked nt!CcQueueLazyWriteScanThread+0x42
4.000080 83ed0d18 0000037 Blocked nt!EtwpLogger+0xc7
4.000084 83ed06b0 0000029 Blocked nt!EtwpLogger+0xc7
4.000088 83f1f918 0000030 Blocked nt!EtwpLogger+0xc7
4.00008c 83f1f370 0000029 Blocked nt!EtwpLogger+0xc7
4.000090 8439fd78 0443aa2 Blocked nt!EtwpLogger+0x66
4.000094 8439f7d0 0443aa2 Blocked nt!EtwpLogger+0x66
4.000098 84424020 0443aa2 Blocked nt!EtwpLogger+0x66
4.0000a0 84c31d78 00018e5 Blocked nt!EtwpLogger+0xc7
4.0000a4 84c36d78 00008bb Blocked nt!WdipSemCheckTimeout+0x226
4.0000a8 84c53d50 00001e6 Blocked acpi!ACPIWorkerThread+0x47
4.0000b0 842df3a0 0443a99 Blocked acpi!PciRootBusBiosMethodDispatcherOnResume+0x30
4.0000b4 84c85240 0443a99 Blocked pci!ExpressRootComplexPmeEventDispatcher+0x34
4.0000bc 850d45e0 0000097 Blocked ndis!ndisCmWaitThread+0x5b
4.0000d0 85182680 0442707 Blocked ecache!EcCacheIoWorker+0x42
4.0000d4 84c38640 044270a Blocked ecache!EcCacheIoWatchdog+0x2c1
4.0000e0 85199538 043a7e3 Blocked volsnap!VspWorkerThread+0x90
4.0000e4 85199218 000000f Blocked volsnap!VspWorkerThread+0x90
4.0000e8 85c7b020 000000f Blocked volsnap!VspWorkerThread+0x90
4.0000ec 85c7bd78 0440311 Blocked volsnap!VspWorkerThread+0x90
4.0000f0 85c7bad0 0440812 Blocked volsnap!VspWorkerThread+0x90
4.0000f4 85d743b8 000000e Blocked Ntfs!TxfPrivateThreadWorkerRoutine+0x2f
4.0000fc 85da8020 0443929 Blocked rimmptsk+0x61d0
4.000100 85da8758 0443929 Blocked rimsptsk+0x67f9
4.000104 85d98a48 0443928 Blocked rixdptsk+0x6899
4.000110 85ebdb18 04438a9 Blocked rimmptsk+0x66c4
4.000114 85eab020 04438a8 Blocked rimmptsk+0x6c02
4.000118 85ea71f0 04438a6 Blocked rimsptsk+0x660c
4.00011c 85ebd5b0 04438a6 Blocked rimsptsk+0x70bc
4.000120 85ea8ca8 04438a4 Blocked rixdptsk+0x669e
4.000124 85ea8408 04438a4 Blocked rixdptsk+0x708e
4.000150 8b0233d0 044361f Blocked CHDRT32+0x14c0a
4.000154 8b025578 0443841 Blocked CHDRT32+0xee36
4.00015c 85d51a58 044350b Blocked bthport!HCI_ThreadFunction+0xc9
4.00019c 8b146c38 0000c92 Blocked nt!AlpcpReceiveMessagePort+0x221
4.0001f0 8b08b538 04436df Blocked watchdog!SMgrGdiCalloutThread+0x35
4.000228 8d856530 0000064 Blocked nt!IoRemoveIoCompletion+0x23
4.000264 8b1e8ad0 0000c92 Blocked nt!EtwpLogger+0xc7
4.000324 8d9a0238 000000c Blocked luafv!SynchronousFsControl+0xa3
4.000328 8d9b3458 00000b7 Blocked ino_fltr+0x8a8b
4.00032c 95ec3568 04432ff Blocked ino_fltr+0x527b
4.0004fc 95f02d78 0443609 Blocked spsys+0x5c0e8
4.000554 8163cd10 0002214 Blocked nt!EtwpLogger+0xc7
4.00068c 81688d78 0000245 Blocked HTTP!UlpScavengerThread+0x5e
4.000714 816b6320 0000ff9 Blocked mpsdrv!AuditSuccessEvent+0x19b
4.000780 816fbc40 04434c1 Blocked srv2!SrvProcWorkerThread+0x6c
4.000784 816fa258 04434bf Blocked srv2!SrvProcWorkerThread+0x6c
4.000788 816fb998 04434bf Blocked srv2!SrvProcWorkerThread+0x6c
4.00078c 816fb6f0 04434be Blocked srv2!SrvProcWorkerThread+0x6c
4.000790 816fb448 04434bc Blocked srv2!SrvProcWorkerThread+0x6c
4.0009d8 97ca9110 0001bd7 Blocked nt!EtwpLogger+0xc7
4.000c30 97ce4430 0000005 RUNNING nt!PfTEntryInfoLookup+0xc4
4.000d48 95ffe030 044272e Blocked nt!EtwpLogger+0xc7
4.000ed0 844f2720 000001f Blocked nt!EtwpLogger+0xc7
4.000efc 84502600 04425fb Blocked nt!EtwpLogger+0xc7
4.001720 84c8b270 001db10 Blocked nt!EtwpLogger+0x66
4.001464 8574a020 0405896 Blocked nt!IoRemoveIoCompletion+0x23
4.001580 84675570 0405873 Blocked nt!IoRemoveIoCompletion+0x23

[95df8d90 audiodg.exe]
470.001608 8597c758 0341448 Blocked ks!CKsPin::Property_ConnectionState+0x9b
470.001254 84449328 03414c7 Blocked usbaudio!PinWaitForStarvation+0x45
470.000968 85a3b760 0000c52 Blocked nt!KiFastCallEntry+0x12a
470.001950 85a8b4f0 00004cf Blocked nt!IoRemoveIoCompletion+0x23

-R

On Tue, Oct 6, 2009 at 1:28 PM, > wrote:
Usbaudio is trying to acquire a lock (probably a KEVENT), so my guess is that either the lock was abandoned or some other currently running thread is holding on to it and that other thread has not returned or is deadlocked.? You could dump all of the stacks with ks or usbaudio in them (see the help for !stacks on how to do that) and see if any of them look suspicious

d

—
NTDEV is sponsored by OSR

For our schedule of WDF, WDM, debugging and other seminars visit:
http://www.osr.com/seminars

To unsubscribe, visit the List Server section of OSR Online at http://www.osronline.com/page.cfm?name=ListServer

— NTDEV is sponsored by OSR For our schedule of WDF, WDM, debugging and other seminars visit: http://www.osr.com/seminars To unsubscribe, visit the List Server section of OSR Online at http://www.osronline.com/page.cfm?name=ListServer