Hello,
I'm debugging a problem with USB audio CODECs that only occurs when
using EHCI. This is a custom board with a NXP EHCI/OHCI controller.
The two ports are connected to USB hubs, and the downstream ports are
connected to USB audio CODECs.
If I enable only the OHCI driver, I can use the CODECs properly (via the
usbaudio driver and ALSA interface). If I use the EHCI driver, I get
the following messages in the kernel log after I attempt to playback
audio:
ehci_hcd 0000:07:0c.2: fatal error
ehci_hcd 0000:07:0c.2: force halt; handhake c10ee024 00004000 00004000 -> -110
ehci_hcd 0000:07:0c.2: HC died; cleaning up
The only thing I have to do to produce this error is play back audio on
one of the CODECs two times, e.g.:
$ dd if=/dev/zero bs=8000 count=24 | aplay -D hw:0,0 -B 10000 -f S16_LE -r 48000
Playing raw data 'stdin' : Signed 16 bit Little Endian, Rate 48000 Hz, Mono
24+0 records in
24+0 records out
$ dd if=/dev/zero bs=8000 count=24 | aplay -D hw:0,0 -B 10000 -f S16_LE
-r 48000
<error happens, HC dies>
Playback the first time usually works OK, but readily fails the second
time I run the above command.
I added a dump_stack() call just after the first EHCI error, and also
enabled DEBUG in the ehci driver::
$ dd if=/dev/zero bs=8000 count=24 | aplay -D front:CARD=W681308,DEV=0 -B 10000 -f S16_LE -r 48000
Playing raw data 'stdin' : Signed 16 bit Little Endian, Rate 48000 Hz, Mono
24+0 records in
24+0 records out
Call Trace:
[bf83bd40] [80008c60] show_stack+0x48/0x15c (unreliable)
[bf83bd80] [802c7140] ehci_irq+0x27c/0x3d4
[bf83be20] [802ab8cc] usb_hcd_irq+0x50/0xa8
[bf83be40] [80060948] handle_IRQ_event+0xa4/0x1c0
[bf83be80] [80062d10] handle_fasteoi_irq+0x8c/0x128
[bf83bea0] [80006aa4] do_IRQ+0xcc/0x104
[bf83bed0] [800136e4] ret_from_except+0x0/0x14
--- Exception: 501 at cpu_idle+0xb4/0xe0
LR = cpu_idle+0xd0/0xe0
[bf83bf90] [80009d1c] cpu_idle+0x60/0xe0 (unreliable)
[bf83bfb0] [803fff84] start_secondary+0x2e8/0x300
[bf83bff0] [000034e0] 0x34e0
ehci_hcd 0000:07:0c.1: fatal error
ehci_hcd 0000:07:0c.1: fatal command 010018 (park)=0 ithresh=1 Periodic period=256 HALT
ehci_hcd 0000:07:0c.1: fatal status 4018 Periodic FATAL FLR
ehci_hcd 0000:07:0c.1: reset command 01001a (park)=0 ithresh=1 Periodic period=256 Reset HALT
usb 1-1: unlink qh256-0001/bf186180 start 255 [1/0 us]
ehci_hcd 0000:07:0c.1: reused qh bf186180 schedule
usb 1-1: link qh256-0001/bf186180 start 255 [1/0 us]
usb 1-1: unlink qh256-0001/bf186180 start 255 [1/0 us]
usb 1-2: unlink qh256-0001/bf186200 start 255 [1/0 us]
ehci_hcd 0000:07:0c.1: force halt; handhake c10f2024 00004000 00004000 -> -110
ehci_hcd 0000:07:0c.1: reused qh bf186200 schedule
usb 1-2: link qh256-0001/bf186200 start 255 [1/0 us]
usb 1-2: unlink qh256-0001/bf186200 start 255 [1/0 us]
ehci_hcd 0000:07:0c.1: force halt; handhake c10f2024 00004000 00004000 -> -110
ehci_hcd 0000:07:0c.1: HC died; cleaning up
I collected a usbmon trace for the error case and here is the tail end
of it:
bf0df700 136558571 C Zo:1:004:2 0:1:161:0 1 0:0:96 0
bf0df700 136558574 S Zo:1:004:2 -115:1:161 1 -18:0:96 96 D
bf214900 136560572 C Zo:1:004:2 0:1:162:0 2 0:0:96 0:96:96 0
bf214900 136560577 S Zo:1:004:2 -115:1:162 1 -18:0:96 96 D
bf0df700 136561571 C Zo:1:004:2 0:1:164:0 1 0:0:96 0
bf0df700 136561574 S Zo:1:004:2 -115:1:164 1 -18:0:96 96 D
bf214900 136562571 C Zo:1:004:2 0:1:165:0 1 0:0:96 0
bf214900 136562584 S Zo:1:004:2 -115:1:165 2 -18:0:96 -18:96:96 192 D
bf0df700 136563572 C Zo:1:004:2 -104:1:166:0 1 0:0:96 0
bf214900 136565572 C Zo:1:004:2 0:1:167:0 2 0:0:96 0:96:96 0
bf0df780 136608830 C Zi:1:004:6 -104:64:211:0 1 0:0:3 0
bf0df800 136608833 C Zi:1:004:6 -104:64:211:0 1 0:0:3 0
bf0df900 136672837 C Zi:1:004:6 -104:64:19:0 1 0:0:3 0
bf0df880 136672839 C Zi:1:004:6 -104:64:19:0 1 0:0:3 0
bf05d080 136763823 C Ii:1:002:1 -108:2048 0
bf05d280 136782772 C Ii:1:003:1 -108:2048 0
bfa15c00 137120913 C Ii:1:001:1 -2:2048 0
Device 004: The USB audio CODEC that I'm playing audio through
Device 001: EHCI host controller / root hub
Device 002: Hub #1
Device 003: Hub #2
In the usbmon trace, I basically see a bunch of isochronous output
events as expected, and then at the end I see a few isochronous input
events (even though I'm not recording?) followed by these interrupt
input callback events. If I capture the first run where the EHCI
controller doesn't die, I do not see those interrupt input events at the
end; instead I see a control output submission/callback event pair.
e.g.:
(first run: this doesn't die)
bf2136c0 115084046 S Zo:1:004:2 -115:1:190 2 -18:0:96 -18:96:96 192 D
bf0df780 115085041 C Zo:1:004:2 0:1:191:0 1 0:0:96 0
bf0df780 115085044 S Zo:1:004:2 -115:1:191 1 -18:0:96 96 D
bf2136c0 115087041 C Zo:1:004:2 0:1:192:0 2 0:0:96 0:96:96 0
bf2136c0 115087046 S Zo:1:004:2 -115:1:192 1 -18:0:96 96 D
bf0df780 115088041 C Zo:1:004:2 0:1:194:0 1 0:0:96 0
bf0df780 115088044 S Zo:1:004:2 -115:1:194 1 -18:0:96 96 D
bf2136c0 115089041 C Zo:1:004:2 0:1:195:0 1 0:0:96 0
bf2136c0 115089054 S Zo:1:004:2 -115:1:195 2 -18:0:96 -18:96:96 192 D
bf0df780 115090041 C Zo:1:004:2 -104:1:196:0 1 0:0:96 0
bf2136c0 115092041 C Zo:1:004:2 0:1:197:0 2 0:0:96 0:96:96 0
bf0df980 115135300 C Zi:1:004:6 -104:64:241:0 1 0:0:3 0
bf0df900 115135303 C Zi:1:004:6 -104:64:241:0 1 0:0:3 0
bf0df800 115199307 C Zi:1:004:6 -104:64:49:0 1 0:0:3 0
bf0df880 115199309 C Zi:1:004:6 -104:64:49:0 1 0:0:3 0
bf0df980 115200047 S Co:1:004:0 s 01 0b 0000 0002 0000 0
bf0df980 115200289 C Co:1:004:0 0 0
Any debugging clues/guidance would be greatly appreciated.
- Nate Case <ncase@xxxxxxxxxxx>
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
