Hi
My Usb headset playback is not working on our emulated xhci host controller with windows 8.1 microsoft’s usb driver stack. After the SET_INTERFACE there are some isochronous transfers that are successful, but after that there seems to be no urbs. There is a log statement “Possible starvation of iscoh stream” during this time and then there is a client initiated recovery action which aborts and resets the endpoint. The same audio device works well when the intel xhci drivers are loaded against the controller in windows 7. The same device works well with the usb 2.0 driver stack. I have collected the etw traces of usbxhci, usbhub3, ucx01000.sys. The rcdrdump of usbxhci driver gave the same details. Please find the logs below. I wanted to seek some suggestions on how I can debug the reason for the scarcity of urbs/endpt abort/client recovery action. How to enable logging in usbaudio.sys? I followed the same instructions as given in http://support.microsoft.com/kb/314743 for winxp and win2000, but did not get any logs in windbg with checked build on windows 8.1.
Please find the the traces of usbxhci, usbucx, usbhub3.
13:34:26.7056685 0x5017A2D8 0x1 0x0 Out 1325 1:34:26 PM 12/19/2014 116.2623430 (2892) UsbUcx UsbUcx:Dispatch URB_FUNCTION_ISOCH_TRANSFER
13:34:26.7163048 0x5017A2D8 0x1 0x0 Out success 1326 1:34:26 PM 12/19/2014 116.2729793 (440) UsbUcx UsbUcx:Complete URB_FUNCTION_ISOCH_TRANSFER
13:34:26.7164959 0x5017A2D8 0x1 0x0 Out 1327 1:34:26 PM 12/19/2014 116.2731704 (2892) UsbUcx UsbUcx:Dispatch URB_FUNCTION_ISOCH_TRANSFER
13:34:26.7264252 0x5017A2D8 0x1 0x0 Out success 1328 1:34:26 PM 12/19/2014 116.2830997 (0) UsbUcx UsbUcx:Complete URB_FUNCTION_ISOCH_TRANSFER
13:34:26.7268191 0x5017A2D8 0x1 0x0 Out 1329 1:34:26 PM 12/19/2014 116.2834936 (2892) UsbUcx UsbUcx:Dispatch URB_FUNCTION_ISOCH_TRANSFER
13:34:26.7732444 0x5017A2D8 0x1 0x0 Out success 1330 1:34:26 PM 12/19/2014 116.3299189 (2892) UsbUcx UsbUcx:Complete URB_FUNCTION_ISOCH_TRANSFER
13:34:26.7732685 0x5017A2D8 0x1 0x0 Out success 1331 1:34:26 PM 12/19/2014 116.3299430 (2892) UsbUcx UsbUcx:Complete URB_FUNCTION_ISOCH_TRANSFER
13:34:26.7745122 0x1 0x0 1332 1:34:26 PM 12/19/2014 116.3311867 (2892) UsbUcx UsbUcx:Endpoint State Machine Event 13:34:26.7745146 0x1 0x0 1333 1:34:26 PM 12/19/2014 116.3311891 (2892) UsbUcx UsbUcx:Endpoint State Machine Transition UcxEndpointStateWaitingForAbortUrbToBeQueued 13:34:26.7745230 0x1 0x0 1334 1:34:26 PM 12/19/2014 116.3311975 (2892) UsbUcx UsbUcx:Endpoint State Machine Event 13:34:26.7745244 0x1 0x0 1335 1:34:26 PM 12/19/2014 116.3311989 (2892) UsbUcx UsbUcx:Endpoint State Machine Transition UcxEndpointStateAborting1 13:34:26.7745380 0x1 0x0 1336 1:34:26 PM 12/19/2014 116.3312125 (2892) UsbUcx UsbUcx:Endpoint State Machine Event 13:34:26.7745450 0x1 0x0 1337 1:34:26 PM 12/19/2014 116.3312195 (2892) UsbUcx UsbUcx:Endpoint State Machine Transition UcxEndpointStateCompletingAbortUrbIfNotAlreadyCancelled1 13:34:26.7745475 0x1 0x0 1338 1:34:26 PM 12/19/2014 116.3312220 (2892) UsbUcx UsbUcx:Endpoint State Machine Transition UcxEndpointStateStarting2 13:34:26.7745489 0x1 0x0 1339 1:34:26 PM 12/19/2014 116.3312234 (2892) UsbUcx UsbUcx:Endpoint State Machine Transition UcxEndpointStateEnabled 13:34:26.7745594 0x5017A2D8 0x0 1340 1:34:26 PM 12/19/2014 116.3312339 (2892) UsbHub3 UsbHub3:Start of IOCTL_INTERNAL_USB_SUBMIT_URB for USB Device 13:34:26.7745611 0x5017A2D8 0x0 1341 1:34:26 PM 12/19/2014 116.3312356 (2892) UsbHub3 UsbHub3:Start URB Client Request for USB Device 13:34:26.7745629 0x50989FD8 0x1 1342 1:34:26 PM 12/19/2014 116.3312374 (2892) UsbHub3 UsbHub3:Client Initiated Recovery Action 13:34:26.7745713 0x5017A2D8 0x0 1343 1:34:26 PM 12/19/2014 116.3312458 (2892) UsbHub3 UsbHub3:State Machine Transition DsmGettingMatchingPipeHandleOnClientResetPipe 13:34:26.7745772 0x5017A2D8 0x0 1344 1:34:26 PM 12/19/2014 116.3312517 (2892) UsbHub3 UsbHub3:State Machine Transition DsmCheckingForZeroBwPipeOnClientResetPipe 13:34:26.7745797 0x5017A2D8 0x0 1345 1:34:26 PM 12/19/2014 116.3312542 (2892) UsbHub3 UsbHub3:State Machine Transition DsmCheckingIfItIsIsochronousEndpoint 13:34:26.7745835 0x5017A2D8 0x0 1346 1:34:26 PM 12/19/2014 116.3312580 (2892) UsbHub3 UsbHub3:State Machine Transition DsmResettingPipeInUCXOnClientReset 13:34:26.7745930 0x1 0x0 1347 1:34:26 PM 12/19/2014 116.3312675 (2892) UsbUcx UsbUcx:Endpoint State Machine Event 13:34:26.7745944 0x1 0x0 1348 1:34:26 PM 12/19/2014 116.3312689 (2892) UsbUcx UsbUcx:Endpoint State Machine Transition UcxEndpointStateResettingEndpoint1 13:34:26.7746084 0x1 0x0 1349 1:34:26 PM 12/19/2014 116.3312829 (2892) UsbUcx UsbUcx:Endpoint State Machine Event 13:34:26.7746119 0x1 0x0 1350 1:34:26 PM 12/19/2014 116.3312864 (2892) UsbUcx UsbUcx:Endpoint State Machine Transition UcxEndpointStateCompletingEndpointResetIrp1 13:34:26.7746143 0x1 0x0 1351 1:34:26 PM 12/19/2014 116.3312888 (2892) UsbUcx UsbUcx:Endpoint State Machine Transition UcxEndpointStateEnabled 13:34:26.7746175 0x5017A2D8 0x0 1352 1:34:26 PM 12/19/2014 116.3312920 (2892) UsbHub3 UsbHub3:State Machine Transition DsmCompletingClientRequestInConfigured 13:34:26.7746189 0x5017A2D8 0x0 success 1353 1:34:26 PM 12/19/2014 116.3312934 (2892) UsbHub3 UsbHub3:Completion of URB Client Request for USB Device 13:34:26.7746199 0x5017A2D8 0x0 1354 1:34:26 PM 12/19/2014 116.3312944 (2892) UsbHub3 UsbHub3:Completion of IOCTL_INTERNAL_USB_SUBMIT_URB for USB Device 13:34:26.7746227 0x5017A2D8 0x0 1355 1:34:26 PM 12/19/2014 116.3312972 (2892) UsbHub3 UsbHub3:State Machine Transition DsmCheckingIfDeviceHasReceivedFirstStart 13:34:26.7746248 0x5017A2D8 0x0 1356 1:34:26 PM 12/19/2014 116.3312993 (2892) UsbHub3 UsbHub3:State Machine Transition DsmConfiguredInD0 13:34:26.7746325 0x5017A2D8 0x1 0x0 Out 1357 1:34:26 PM 12/19/2014 116.3313070 (2892) UsbUcx UsbUcx:Dispatch URB_FUNCTION_ISOCH_TRANSFER 13:34:26.7747367 0x5017A2D8 0x1 0x0 Out 1358 1:34:26 PM 12/19/2014 116.3314112 (2892) UsbUcx UsbUcx:Dispatch URB_FUNCTION_ISOCH_TRANSFER usbxhci trace: 00005555 driver 0 0 0 12\19\2014-13:34:26:717 [39] SlotId 5 EndpointId 2 ED 1 Pointer b63fd200080001 Length 176 0x1 0x20 00005556 driver 0 0 0 12\19\2014-13:34:26:717 [40] SlotId 5 EndpointId 2 ED 1 Pointer b63fd200090001 Length 176 0x1 0x20 00005557 driver 0 0 0 12\19\2014-13:34:26:717 5.2.0: WdfRequest 0x00001FFE508347F8 Stage 0xFFFFE001AF7CBA20 : Finished all 10 packets 00005558 driver 0 0 0 12\19\2014-13:34:26:717 5.2.0: WdfRequest 0x00001FFE508347F8 STATUS_SUCCESS StartFrame 0xB63FD2 Packets (Successful, Total) = (10, 10), BytesTransferred 1764 00005559 driver 2892 1140 0 12\19\2014-13:34:26:717 5.2.0: WdfRequest 0x00001FFE508347F8 packets 10, xhciFrame 0xB63FDE, StartFrame 0xB63FE6, NextStartFrame 0xB63FF0 00005560 driver 2892 1140 0 12\19\2014-13:34:26:717 5.2.0: WdfRequest 0x00001FFE508347F8, start mapping first stage 0xFFFFE001AF7CBA20 00005561 driver 2892 2704 0 12\19\2014-13:34:26:764 [41] SlotId 5 EndpointId 2 ED 1 Pointer b63fdc00000001 Length 176 0x1 0x20 00005562 driver 2892 2704 0 12\19\2014-13:34:26:764 [42] SlotId 5 EndpointId 2 ED 1 Pointer b63fdc00010001 Length 176 0x1 0x20 00005563 driver 2892 2704 0 12\19\2014-13:34:26:764 [43] SlotId 5 EndpointId 2 ED 1 Pointer b63fdc00020001 Length 176 0x1 0x20 00005564 driver 2892 2704 0 12\19\2014-13:34:26:764 [44] SlotId 5 EndpointId 2 ED 1 Pointer b63fdc00030001 Length 176 0x1 0x20 00005565 driver 2892 2704 0 12\19\2014-13:34:26:764 [45] SlotId 5 EndpointId 2 ED 1 Pointer b63fdc00040001 Length 176 0x1 0x20 00005566 driver 2892 2704 0 12\19\2014-13:34:26:764 [46] SlotId 5 EndpointId 2 ED 1 Pointer b63fdc00050001 Length 180 0x1 0x20 00005567 driver 2892 2704 0 12\19\2014-13:34:26:764 [47] SlotId 5 EndpointId 2 ED 1 Pointer b63fdc00060001 Length 176 0x1 0x20 00005568 driver 2892 2704 0 12\19\2014-13:34:26:764 [48] SlotId 5 EndpointId 2 ED 1 Pointer b63fdc00070001 Length 176 0x1 0x20 00005569 driver 2892 2704 0 12\19\2014-13:34:26:764 [49] SlotId 5 EndpointId 2 ED 1 Pointer b63fdc00080001 Length 176 0x1 0x20 00005570 driver 2892 2704 0 12\19\2014-13:34:26:764 [50] SlotId 5 EndpointId 2 ED 1 Pointer b63fdc00090001 Length 176 0x1 0x20 00005571 driver 2892 2704 0 12\19\2014-13:34:26:764 5.2.0: WdfRequest 0x00001FFE5085AB18 Stage 0xFFFFE001AF7A5700 : Finished all 10 packets 00005572 driver 2892 2704 0 12\19\2014-13:34:26:764 5.2.0: WdfRequest 0x00001FFE5085AB18 STATUS_SUCCESS StartFrame 0xB63FDC Packets (Successful, Total) = (10, 10), BytesTransferred 1764 00005573 driver 2892 2704 0 12\19\2014-13:34:26:764 [51] SlotId 5 EndpointId 2 ED 1 Pointer b63fe600000001 Length 176 0x1 0x20 00005574 driver 2892 2704 0 12\19\2014-13:34:26:764 [52] SlotId 5 EndpointId 2 ED 1 Pointer b63fe600010001 Length 176 0x1 0x20 00005575 driver 2892 2704 0 12\19\2014-13:34:26:764 [53] SlotId 5 EndpointId 2 ED 1 Pointer b63fe600020001 Length 176 0x1 0x20 00005576 driver 2892 2704 0 12\19\2014-13:34:26:764 [54] SlotId 5 EndpointId 2 ED 1 Pointer b63fe600030001 Length 176 0x1 0x20 00005577 driver 2892 2704 0 12\19\2014-13:34:26:764 [55] SlotId 5 EndpointId 2 ED 1 Pointer b63fe600040001 Length 176 0x1 0x20 00005578 driver 2892 2704 0 12\19\2014-13:34:26:764 [56] SlotId 5 EndpointId 2 ED 1 Pointer b63fe600050001 Length 180 0x1 0x20 00005579 driver 2892 2704 0 12\19\2014-13:34:26:764 [57] SlotId 5 EndpointId 2 ED 1 Pointer b63fe600060001 Length 176 0x1 0x20 00005580 driver 2892 2704 0 12\19\2014-13:34:26:764 [58] SlotId 5 EndpointId 2 ED 1 Pointer b63fe600070001 Length 176 0x1 0x20 00005581 driver 2892 2704 0 12\19\2014-13:34:26:764 [59] SlotId 5 EndpointId 2 ED 1 Pointer b63fe600080001 Length 176 0x1 0x20 00005582 driver 2892 2704 0 12\19\2014-13:34:26:764 [60] SlotId 5 EndpointId 2 ED 1 Pointer b63fe600090001 Length 176 0x1 0x20 00005583 driver 2892 2704 0 12\19\2014-13:34:26:764 5.2.0: WdfRequest 0x00001FFE508347F8 Stage 0xFFFFE001AF7CBA20 : Finished all 10 packets 00005584 driver 2892 2704 0 12\19\2014-13:34:26:764 5.2.0: WdfRequest 0x00001FFE508347F8 STATUS_SUCCESS StartFrame 0xB63FE6 Packets (Successful, Total) = (10, 10), BytesTransferred 1764 00005585 driver 2892 2704 0 12\19\2014-13:34:26:764 5.2.0: Possible starvation of Isoch stream - no outstanding URBs 00005586 driver 2892 1140 0 12\19\2014-13:34:26:765 5.2: Abort UcxEndpoint 0x00001FFE50A1AFD8 Start 00005587 driver 2892 1140 0 12\19\2014-13:34:26:765 5.2: Abort UcxEndpoint 0x00001FFE50A1AFD8 Complete 00005588 Unknown 2892 1140 0 00\00\ 0-00:00:00:00 Unknown( 11): GUID=90d574b2-5b75-7acc-7b4f-2bce10ddfcc6 (No Format Information found). 00005589 driver 2892 1140 0 12\19\2014-13:34:26:765 5.2.0: Setting IsochPure on client endpoint reset request 00005590 Unknown 2892 1140 0 00\00\ 0-00:00:00:00 Unknown( 11): GUID=90d574b2-5b75-7acc-7b4f-2bce10ddfcc6 (No Format Information found). 00005591 driver 2892 1140 0 12\19\2014-13:34:26:765 5.2: UcxEndpoint 0x00001FFE50A1AFD8 WdfRequest 0x00001FFE508347F8 Flags 0x0 00005592 Unknown 2892 1140 0 00\00\ 0-00:00:00:00 Unknown( 11): GUID=90d574b2-5b75-7acc-7b4f-2bce10ddfcc6 (No Format Information found). 00005593 driver 2892 1140 0 12\19\2014-13:34:26:765 5.2: WdfRequest 0x00001FFE508347F8 Endpoint reset completed with STATUS_SUCCESS 00005594 Unknown 2892 1140 0 00\00\ 0-00:00:00:00 Unknown( 11): GUID=90d574b2-5b75-7acc-7b4f-2bce10ddfcc6 (No Format Information found). 00005595 driver 2892 1140 0 12\19\2014-13:34:26:765 5.2.0: WdfRequest 0x00001FFE508347F8 packets 10, xhciFrame 0xB6400E, StartFrame 0xB64013, NextStartFrame 0xB6401D 00005596 driver 2892 1140 0 12\19\2014-13:34:26:765 5.2.0: WdfRequest 0x00001FFE508347F8, start mapping first stage 0xFFFFE001AF7CBA20 00005597 driver 2892 1140 0 12\19\2014-13:34:26:765 5.2.0: WdfRequest 0x00001FFE508347F8 Stage 0xFFFFE001AF7CBA20 Gap Detected. Stage StartFrame 0xb64013, FrameOfLastMappedTD 0xb63fef Thanks in advance for your time.
On Dec 29, 2014, at 3:13 PM, xxxxx@vmware.com wrote:
My Usb headset playback is not working on our emulated xhci host controller with windows 8.1 microsoft’s usb driver stack.
“Emulating” with what? Is there genuine hardware somewhere?
After the SET_INTERFACE there are some isochronous transfers that are successful, but after that there seems to be no urbs. There is a log statement “Possible starvation of iscoh stream” during this time and then there is a client initiated recovery action which aborts and resets the endpoint.
Did you look at the timing in the log? The URBs are all being completed after 10ms (which is correct), but the one submitted at 26.7268191 takes 50ms. That’s where starvation comes from. Why does it take 50ms?
—
Tim Roberts, xxxxx@probo.com
Providenza & Boekelheide, Inc.
wesley
December 30, 2014, 10:29pm
3
What your device speed when running on the USB3 stack?
I have never switch on the USBAudio.sys debug print.
But usually, I use the USB analyzer to root cause the bus stuck issue.
Thanks for your inputs Tim and Wesley. I appreciate the help.
It is a virtual host controller developed using the 1.0 spec. The device is a Sennheiser 1.1 headset.The requests in this xhci are interpreted and submitted to a physical controller and completed based on the results. While I am trying to debug the delay, I am hitting this error even if the requests complete in less than 20ms. Looking close at the timings, each isoch transfer is completed within 20 ms on an average. When an isoch transfer is being completed in the ucx, there is next dispatch at the same time. At the time where the error occurs there is no dispatch for a complete. Then there is a client initiated endpt reset and then abort of ucx endpt. Is there any time limit at the ucx level, on when the request has to complete after it is dispatched? Possible starvation of Isoch stream - no outstanding URBs was also reported initially before the isoch requests started but the I/O proceeded. When the audio stopped playing, there is a starvation reported for the second time accompanied by an IOCTL to reset the pipe(usbhub3) and then Abort endpt(ucx). When will UCX abort the endpoint? Based on the naming and timing in the logs, it is client initiated and so I was trying to get the usbaudio.sys logs. What the client is not happy with is what I want to investigate.
Please find the etw traces usbtrace from ucx, usbxhci, usbhub3 with request durations added.
Success 1764 of 1764 159044 (0x26D44) 10 (0xA) 19:17:14.3743346 0x9C2D8E8 0.021685 1764 (0x6E4) 1764 (0x6E4) 0x1 Out 3946 25.8686234 (0) UsbUcx UsbUcx:Complete URB_FUNCTION_ISOCH_TRANSFER
1764 0 (0x0) 10 (0xA) 19:17:14.3775199 0x9C2D8E8 1764 (0x6E4) 0x1 Out 3949 25.8718087 (2412) UsbUcx UsbUcx:Dispatch URB_FUNCTION_ISOCH_TRANSFER
Success 1764 of 1764 159054 (0x26D4E) 10 (0xA) 19:17:14.3833784 0x9C2D8E8 0.020364 1764 (0x6E4) 1764 (0x6E4) 0x1 Out 3950 25.8776672 (4) UsbUcx UsbUcx:Complete URB_FUNCTION_ISOCH_TRANSFER
1764 0 (0x0) 10 (0xA) 19:17:14.3870321 0x9C2D8E8 1764 (0x6E4) 0x1 Out 3953 25.8813209 (2412) UsbUcx UsbUcx:Dispatch URB_FUNCTION_ISOCH_TRANSFER
Success 1764 of 1764 159064 (0x26D58) 10 (0xA) 19:17:14.3965247 0x9C2D8E8 0.019005 1764 (0x6E4) 1764 (0x6E4) 0x1 Out 3954 25.8908135 (0) UsbUcx UsbUcx:Complete URB_FUNCTION_ISOCH_TRANSFER
1764 0 (0x0) 10 (0xA) 19:17:14.3966656 0x9C2D8E8 1764 (0x6E4) 0x1 Out 3955 25.8909544 (2412) UsbUcx UsbUcx:Dispatch URB_FUNCTION_ISOCH_TRANSFER
Success 1764 of 1764 159074 (0x26D62) 10 (0xA) 19:17:14.4047659 0x9C2D8E8 0.017734 1764 (0x6E4) 1764 (0x6E4) 0x1 Out 3960 25.8990547 (0) UsbUcx UsbUcx:Complete URB_FUNCTION_ISOCH_TRANSFER
1764 0 (0x0) 10 (0xA) 19:17:14.4049088 0x9C2D8E8 1764 (0x6E4) 0x1 Out 3961 25.8991976 (2412) UsbUcx UsbUcx:Dispatch URB_FUNCTION_ISOCH_TRANSFER
Success 1764 of 1764 159084 (0x26D6C) 10 (0xA) 19:17:14.4162701 0x9C2D8E8 0.019605 1764 (0x6E4) 1764 (0x6E4) 0x1 Out 3964 25.9105589 (904) UsbUcx UsbUcx:Complete URB_FUNCTION_ISOCH_TRANSFER
1764 0 (0x0) 10 (0xA) 19:17:14.4186295 0x9C2D8E8 1764 (0x6E4) 0x1 Out 3967 25.9129183 (2412) UsbUcx UsbUcx:Dispatch URB_FUNCTION_ISOCH_TRANSFER
Success 1764 of 1764 159094 (0x26D76) 10 (0xA) 19:17:14.4265932 0x9C2D8E8 0.021684 1764 (0x6E4) 1764 (0x6E4) 0x1 Out 3968 25.9208820 (0) UsbUcx UsbUcx:Complete URB_FUNCTION_ISOCH_TRANSFER
1764 0 (0x0) 10 (0xA) 19:17:14.4269591 0x9C2D8E8 1764 (0x6E4) 0x1 Out 3969 25.9212479 (2412) UsbUcx UsbUcx:Dispatch URB_FUNCTION_ISOCH_TRANSFER
Success 1764 of 1764 159104 (0x26D80) 10 (0xA) 19:17:14.4392998 0x9C2D8E8 0.020670 1764 (0x6E4) 1764 (0x6E4) 0x1 Out 3970 25.9335886 (0) UsbUcx UsbUcx:Complete URB_FUNCTION_ISOCH_TRANSFER
Success 1764 of 1764 159114 (0x26D8A) 10 (0xA) 19:17:14.4467810 0x9C2D8E8 0.019822 1764 (0x6E4) 1764 (0x6E4) 0x1 Out 3977 25.9410698 (0) UsbUcx UsbUcx:Complete URB_FUNCTION_ISOCH_TRANSFER
19:17:14.4511683 0x9C2D8E8 3988 25.9454571 (2412) UsbHub3 UsbHub3:Start of IOCTL_INTERNAL_USB_SUBMIT_URB for USB Device
19:17:14.4511695 0x9C2D8E8 3989 25.9454583 (2412) UsbHub3 UsbHub3:Start URB Client Request for USB Device
19:17:14.4511779 0x9C2D8E8 3991 25.9454667 (2412) UsbHub3 UsbHub3:State Machine Transition DsmGettingMatchingPipeHandleOnClientResetPipe 19:17:14.4511820 0x9C2D8E8 3992 25.9454708 (2412) UsbHub3 UsbHub3:State Machine Transition DsmCheckingForZeroBwPipeOnClientResetPipe 19:17:14.4511836 0x9C2D8E8 3993 25.9454724 (2412) UsbHub3 UsbHub3:State Machine Transition DsmCheckingIfItIsIsochronousEndpoint 19:17:14.4511851 0x9C2D8E8 3994 25.9454739 (2412) UsbHub3 UsbHub3:State Machine Transition DsmResettingPipeInUCXOnClientReset 19:17:14.4512372 0x9C2D8E8 4000 25.9455260 (2412) UsbHub3 UsbHub3:State Machine Transition DsmCompletingClientRequestInConfigured 19:17:14.4512384 0x9C2D8E8 4001 25.9455272 (2412) UsbHub3 UsbHub3:Completion of URB Client Request for USB Device Success 19:17:14.4512391 0x9C2D8E8 4002 25.9455279 (2412) UsbHub3 UsbHub3:Completion of IOCTL_INTERNAL_USB_SUBMIT_URB for USB Device 19:17:14.4512422 0x9C2D8E8 4003 25.9455310 (2412) UsbHub3 UsbHub3:State Machine Transition DsmCheckingIfDeviceHasReceivedFirstStart 19:17:14.4512434 0x9C2D8E8 4004 25.9455322 (2412) UsbHub3 UsbHub3:State Machine Transition DsmConfiguredInD0 1764 0 (0x0) 10 (0xA) 19:17:14.4512590 0x9C2D8E8 1764 (0x6E4) 0x1 Out 4005 25.9455478 (2412) UsbUcx UsbUcx:Dispatch URB_FUNCTION_ISOCH_TRANSFER 1764 0 (0x0) 10 (0xA) 19:17:14.4515444 0x9C2D8E8 1764 (0x6E4) 0x1 Out 4006 25.9458332 (2412) UsbUcx UsbUcx:Dispatch URB_FUNCTION_ISOCH_TRANSFER UsbXhci trace: 00014778 driver 0 0 0 01\07\2015-19:17:14:443 [24] SlotId 6 EndpointId 2 ED 1 Pointer 26d8000000001 Length 176 0x1 0x20 00014779 driver 0 0 0 01\07\2015-19:17:14:443 [25] SlotId 6 EndpointId 2 ED 1 Pointer 26d8000010001 Length 176 0x1 0x20 00014780 driver 0 0 0 01\07\2015-19:17:14:443 [26] SlotId 6 EndpointId 2 ED 1 Pointer 26d8000020001 Length 176 0x1 0x20 00014781 driver 0 0 0 01\07\2015-19:17:14:443 [27] SlotId 6 EndpointId 2 ED 1 Pointer 26d8000030001 Length 176 0x1 0x20 00014782 driver 0 0 0 01\07\2015-19:17:14:443 [28] SlotId 6 EndpointId 2 ED 1 Pointer 26d8000040001 Length 176 0x1 0x20 00014783 driver 0 0 0 01\07\2015-19:17:14:443 [29] SlotId 6 EndpointId 2 ED 1 Pointer 26d8000050001 Length 180 0x1 0x20 00014784 driver 0 0 0 01\07\2015-19:17:14:443 [30] SlotId 6 EndpointId 2 ED 1 Pointer 26d8000060001 Length 176 0x1 0x20 00014785 driver 0 0 0 01\07\2015-19:17:14:443 [31] SlotId 6 EndpointId 2 ED 1 Pointer 26d8000070001 Length 176 0x1 0x20 00014786 driver 0 0 0 01\07\2015-19:17:14:443 [32] SlotId 6 EndpointId 2 ED 1 Pointer 26d8000080001 Length 176 0x1 0x20 00014787 driver 0 0 0 01\07\2015-19:17:14:443 [33] SlotId 6 EndpointId 2 ED 1 Pointer 26d8000090001 Length 176 0x1 0x20 00014788 driver 0 0 0 01\07\2015-19:17:14:443 6.2.0: WdfRequest 0x00001FFE07201908 Stage 0xFFFFE001F8DFE910 : Finished all 10 packets 00014789 driver 0 0 0 01\07\2015-19:17:14:443 6.2.0: WdfRequest 0x00001FFE07201908 STATUS_SUCCESS StartFrame 0x26D80 Packets (Successful, Total) = (10, 10), BytesTransferred 1764 00014805 driver 0 0 0 01\07\2015-19:17:14:450 [37] SlotId 6 EndpointId 2 ED 1 Pointer 26d8a00000001 Length 176 0x1 0x20 00014806 driver 0 0 0 01\07\2015-19:17:14:450 [38] SlotId 6 EndpointId 2 ED 1 Pointer 26d8a00010001 Length 176 0x1 0x20 00014807 driver 0 0 0 01\07\2015-19:17:14:450 [39] SlotId 6 EndpointId 2 ED 1 Pointer 26d8a00020001 Length 176 0x1 0x20 00014808 driver 0 0 0 01\07\2015-19:17:14:450 [40] SlotId 6 EndpointId 2 ED 1 Pointer 26d8a00030001 Length 176 0x1 0x20 00014809 driver 0 0 0 01\07\2015-19:17:14:450 [41] SlotId 6 EndpointId 2 ED 1 Pointer 26d8a00040001 Length 176 0x1 0x20 00014810 driver 0 0 0 01\07\2015-19:17:14:450 [42] SlotId 6 EndpointId 2 ED 1 Pointer 26d8a00050001 Length 180 0x1 0x20 00014811 driver 0 0 0 01\07\2015-19:17:14:450 [43] SlotId 6 EndpointId 2 ED 1 Pointer 26d8a00060001 Length 176 0x1 0x20 00014812 driver 0 0 0 01\07\2015-19:17:14:450 [44] SlotId 6 EndpointId 2 ED 1 Pointer 26d8a00070001 Length 176 0x1 0x20 00014813 driver 0 0 0 01\07\2015-19:17:14:450 [45] SlotId 6 EndpointId 2 ED 1 Pointer 26d8a00080001 Length 176 0x1 0x20 00014814 driver 0 0 0 01\07\2015-19:17:14:450 [46] SlotId 6 EndpointId 2 ED 1 Pointer 26d8a00090001 Length 176 0x1 0x20 00014815 driver 0 0 0 01\07\2015-19:17:14:450 6.2.0: WdfRequest 0x00001FFE0A6625B8 Stage 0xFFFFE001F599DC60 : Finished all 10 packets 00014816 driver 0 0 0 01\07\2015-19:17:14:450 6.2.0: WdfRequest 0x00001FFE0A6625B8 STATUS_SUCCESS StartFrame 0x26D8A Packets (Successful, Total) = (10, 10), BytesTransferred 1764 00014817 driver 0 0 0 01\07\2015-19:17:14:451 6.2.0: Possible starvation of Isoch stream - no outstanding URBs 00014818 driver 0 0 0 01\07\2015-19:17:14:453 [47] SlotId 5 EndpointId 3 ED 1 Pointer ffffe001f599f923 Length 8 0x1 0x20 00014819 driver 0 0 0 01\07\2015-19:17:14:453 5.3.0: TransferEventTrb 0xFFFFF803BFABA7A0 0x1 Length 8 EventData 1 Pointer 0xffffe001f599f923 00014820 driver 0 0 0 01\07\2015-19:17:14:453 5.3.0: WdfRequest 0x00001FFE0A6608F8 transferData 0xFFFFE001F599F8A0 stageData 0xFFFFE001F599F920 00014821 driver 0 0 0 01\07\2015-19:17:14:453 5.3.0: WdfRequest 0x00001FFE0A6608F8 STATUS_SUCCESS BytesTransferred 8 00014822 driver 0 0 0 01\07\2015-19:17:14:453 5.3.0: WdfRequest 0x00001FFE0A6625B8, start mapping first stage 0xFFFFE001F599DC60 00014823 driver 2412 2936 0 01\07\2015-19:17:14:455 6.2: Abort UcxEndpoint 0x00001FFE0B1124E8 Start 00014824 driver 2412 2936 0 01\07\2015-19:17:14:455 6.2: Abort UcxEndpoint 0x00001FFE0B1124E8 Complete 00014825 Unknown 2412 2936 0 00\00\ 0-00:00:00:00 Unknown( 11): GUID=90d574b2-5b75-7acc-7b4f-2bce10ddfcc6 (No Format Information found). 00014826 driver 2412 2936 0 01\07\2015-19:17:14:455 6.2.0: Setting IsochPure on client endpoint reset request 00014827 Unknown 2412 2936 0 00\00\ 0-00:00:00:00 Unknown( 11): GUID=90d574b2-5b75-7acc-7b4f-2bce10ddfcc6 (No Format Information found). 00014828 driver 2412 2936 0 01\07\2015-19:17:14:455 6.2: UcxEndpoint 0x00001FFE0B1124E8 WdfRequest 0x00001FFE0A6608F8 Flags 0x0 00014829 Unknown 2412 2936 0 00\00\ 0-00:00:00:00 Unknown( 11): GUID=90d574b2-5b75-7acc-7b4f-2bce10ddfcc6 (No Format Information found). 00014830 driver 2412 2936 0 01\07\2015-19:17:14:455 6.2: WdfRequest 0x00001FFE0A6608F8 Endpoint reset completed with STATUS_SUCCESS 00014831 Unknown 2412 2936 0 00\00\ 0-00:00:00:00 Unknown( 11): GUID=90d574b2-5b75-7acc-7b4f-2bce10ddfcc6 (No Format Information found). 00014832 driver 2412 2936 0 01\07\2015-19:17:14:455 6.2.0: WdfRequest 0x00001FFE0A6608F8 packets 10, xhciFrame 0x26D9F, StartFrame 0x26DA4, NextStartFrame 0x26DAE 00014833 driver 2412 2936 0 01\07\2015-19:17:14:455 6.2.0: WdfRequest 0x00001FFE0A6608F8, start mapping first stage 0xFFFFE001F599F920 00014834 driver 2412 2936 0 01\07\2015-19:17:14:455 6.2.0: WdfRequest 0x00001FFE0A6608F8 Stage 0xFFFFE001F599F920 Gap Detected. Stage StartFrame 0x26da4, FrameOfLastMappedTD 0x26d93 Usbhub3 trace: 00000273 src 2412 2936 0 01\07\2015-19:17:14:455 Transition for 0xFFFFE001F7D840D0: DsmStateConfiguredInD0 --DsmEventClientRequestResetPipe–> DsmStateGettingMatchingPipeHandleOnClientResetPipe 00000274 src 2412 2936 0 01\07\2015-19:17:14:455 Transition for 0xFFFFE001F7D840D0: DsmStateGettingMatchingPipeHandleOnClientResetPipe --DsmEventOperationSuccess–> DsmStateCheckingForZeroBwPipeOnClientResetPipe 00000275 src 2412 2936 0 01\07\2015-19:17:14:455 Transition for 0xFFFFE001F7D840D0: DsmStateCheckingForZeroBwPipeOnClientResetPipe --DsmEventNo–> DsmStateCheckingIfItIsIsochronousEndpoint 00000276 src 2412 2936 0 01\07\2015-19:17:14:455 Transition for 0xFFFFE001F7D840D0: DsmStateCheckingIfItIsIsochronousEndpoint --DsmEventYes–> DsmStateResettingPipeInUCXOnClientReset 00000277 src 2412 2936 0 01\07\2015-19:17:14:455 Transition for 0xFFFFE001F7D840D0: DsmStateResettingPipeInUCXOnClientReset --DsmEventUCXIoctlSuccess–> DsmStateCompletingClientRequestInConfigured 00000278 src 2412 2936 0 01\07\2015-19:17:14:455 Transition for 0xFFFFE001F7D840D0: DsmStateCompletingClientRequestInConfigured --DsmEventOperationSuccess–> DsmStateCheckingIfDeviceHasReceivedFirstStart 00000279 src 2412 2936 0 01\07\2015-19:17:14:455 Transition for 0xFFFFE001F7D840D0: DsmStateCheckingIfDeviceHasReceivedFirstStart --DsmEventYes–> DsmStateConfiguredInD0
I missed to attach this portion of the logs…The event that triggered the abort is
UcxEndpointEventAbortUrbFromClient. Please let me know if there are any ways I can get more information about this event. If you have any recommendations about where I can read more info about interaction between usbucx, usbhub3, usbxhci kindly pass them to me.Thanks in advance for your time.
19:17:14.4510897 0x1 3980 25.9453785 (2412) UsbUcx UsbUcx:Endpoint State Machine Event 19:17:14.4510919 0x1 3981 25.9453807 (2412) UsbUcx UsbUcx:Endpoint State Machine Transition UcxEndpointStateWaitingForAbortUrbToBeQueued 19:17:14.4511103 0x1 3982 25.9453991 (2412) UsbUcx UsbUcx:Endpoint State Machine Event 19:17:14.4511115 0x1 3983 25.9454003 (2412) UsbUcx UsbUcx:Endpoint State Machine Transition UcxEndpointStateAborting1 19:17:14.4511352 0x1 3984 25.9454240 (2412) UsbUcx UsbUcx:Endpoint State Machine Event 19:17:14.4511380 0x1 3985 25.9454268 (2412) UsbUcx UsbUcx:Endpoint State Machine Transition UcxEndpointStateCompletingAbortUrbIfNotAlreadyCancelled1 19:17:14.4511483 0x1 3986 25.9454371 (2412) UsbUcx UsbUcx:Endpoint State Machine Transition UcxEndpointStateStarting2 19:17:14.4511502 0x1 3987 25.9454390 (2412) UsbUcx UsbUcx:Endpoint State Machine Transition UcxEndpointStateEnabled 19:17:14.4511683 0x9C2D8E8 3988 25.9454571 (2412) UsbHub3 UsbHub3:Start of IOCTL_INTERNAL_USB_SUBMIT_URB for USB Device 19:17:14.4511695 0x9C2D8E8 3989 25.9454583 (2412) UsbHub3 UsbHub3:Start URB Client Request for USB Device
xxxxx@vmware.com wrote:
It is a virtual host controller developed using the 1.0 spec. The device is a Sennheiser 1.1 headset.The requests in this xhci are interpreted and submitted to a physical controller and completed based on the results. While I am trying to debug the delay, I am hitting this error even if the requests complete in less than 20ms. Looking close at the timings, each isoch transfer is completed within 20 ms on an average.
Well, as I look at it, the times drift. The request times go:
19:17:14.3743346
3833784 10ms - 0.956
3965247 10ms + 3.146
4047659 10ms - 1.759
4162701 10ms + 1.504
4265932 10ms - 0.323
4392998 10ms + 2.707
4467810 10ms - 2.519
The AVERAGE time here is 10.35ms, which by itself is 3% too long.
Beyond that, however, that’s a large amount of jitter – you’re
averaging as much as 20%. The USB audio driver wants things to be
steady and reliable. It’s not impossible for me to believe they are
measuring the jitter and aborting/restarting the stream if the jitter is
too large.
Is there any time limit at the ucx level, on when the request has to complete after it is dispatched? Possible starvation of Isoch stream - no outstanding URBs was also reported initially before the isoch requests started but the I/O proceeded. When the audio stopped playing, there is a starvation reported for the second time accompanied by an IOCTL to reset the pipe(usbhub3) and then Abort endpt(ucx). When will UCX abort the endpoint? Based on the naming and timing in the logs, it is client initiated and so I was trying to get the usbaudio.sys logs. What the client is not happy with is what I want to investigate.
I’m not sure it is UCX aborting the request. There’s no inherent USB
requirement here. I would be more inclined to blame usbaudio.sys.
Please let me know if there are any ways I can get more information about this event. If you have any recommendations about where I can read more info about interaction between usbucx, usbhub3, usbxhci kindly pass them to me.
There is no such documentation. Those three drivers are considered to
be a unit, and their interdriver communication is internal and
undocumented. It’s possible you may have to pay for a Microsoft product
support incident and start talking to a developer.
–
Tim Roberts, xxxxx@probo.com
Providenza & Boekelheide, Inc.