Alan Stern said:
> It might be that the problem is triggered by a particular pattern of URBs
> being unlinked and completed. The exact timing may matter as well.
> Anyway, this bug shouldn't occur no matter what hardware or firmware you
> use.
Definitely timing related-- the extra printks seem to make the kernel
panic no matter whether the ep2 firmware is loaded or not. I also tried
bumping the serial console speed up to 57600, at which point an occasional
character was dropped, but this also seemed to affect the kernel's
reaction to testusb.
> The patch below will log some additional debugging information. It might
> help pinpoint where things go wrong during your test. Unfortunately, it
> will generate a good deal of output even when things go right. Try to
> run just the test that produced the error messages above and post the
> corresponding part of the kernel log.
Following David's suggestion, here are the kernel logs for "testusb -t10
-g3 -c5000" and "testusb -t10 -g4 -c5000". The maximum seems to be 3
queued requests before the kernel panics, but even -g2 causes messages
similar to those in the -g3 log.
I also tried -g1, which worked fine. (I gather that it only queues one
request at a time, so it's not entirely surprising that it works.) Using
-g{5,6,7} all fail similarly to -g4.
David: perhaps I'm overlooking something, since what I found doesn't quite
correlate with your predicted failure between -g6 and -g7. Do you want to
see full logs for -g6 as well?
--
Charles Lepple <[EMAIL PROTECTED]>
http://www.ghz.cc/charles/uhci: added urbp c5ac753c to complete_list
uhci: took urbp c5ac753c off complete_list
uhci: freed urbp c5ac753c
drivers/usb/misc/usbtest.c: 0000:00:02.2-1:0 TEST 10: queue 3 control calls, 5000
times
uhci: added urbp c5ac753c to complete_list
uhci: added urbp c5ac74f4 to complete_list
drivers/usb/host/uhci-hcd.c: uhci_result_control() failed with status 0
[c7e532a0] link (07e531e2) element (00000001)
Element != First TD
0: [c7e54150] link (07e54180) e3 Length=7 MaxLen=7 DT0 EndPt=0 Dev=2, PID=2d(SETUP)
(buf=07e460c0)
1: [c7e54180] link (07e541b0) e3 SPD Length=7ff MaxLen=0 DT1 EndPt=0 Dev=2,
PID=69(IN) (buf=07e460a0)
2: [c7e541b0] link (00000001) e3 IOC Length=7ff MaxLen=7ff DT0 EndPt=0 Dev=2,
PID=e1(OUT) (buf=00000000)
uhci: added urbp c5ac74ac to complete_list
uhci: took urbp c5ac753c off complete_list
uhci: freed urbp c5ac753c
uhci: took urbp c5ac74f4 off complete_list
uhci: freed urbp c5ac74f4
uhci: took urbp c5ac74ac off complete_list
uhci: freed urbp c5ac74ac
drivers/usb/misc/usbtest.c: subtest 2 error, status -121
drivers/usb/misc/usbtest.c: control queue 81.0a, err -121, 14997 left
uhci: added urbp c5ac753c to remove_list
uhci: added urbp c5ac74f4 to remove_list
uhci: took urbp c5ac74f4 off remove_list
uhci: added urbp c5ac74f4 to complete_list
uhci: took urbp c5ac753c off remove_list
uhci: added urbp c5ac753c to complete_list
uhci: took urbp c5ac74f4 off complete_list
uhci: freed urbp c5ac74f4
drivers/usb/misc/usbtest.c: subcase 1 completed out of order, last 2
uhci: took urbp c5ac753c off complete_list
uhci: freed urbp c5ac753c
uhci: added urbp c5ac753c to complete_list
uhci: took urbp c5ac753c off complete_list
uhci: freed urbp c5ac753c
drivers/usb/misc/usbtest.c: 0000:00:02.2-1:0 TEST 10: queue 3 control calls, 5000
times
uhci: added urbp c5ac753c to complete_list
uhci: added urbp c5ac74f4 to complete_list
drivers/usb/host/uhci-hcd.c: uhci_result_control() failed with status 0
[c7e532a0] link (07e531e2) element (00000001)
Element != First TD
0: [c7e54150] link (07e54180) e3 Length=7 MaxLen=7 DT0 EndPt=0 Dev=2, PID=2d(SETUP)
(buf=07e460c0)
1: [c7e54180] link (07e541b0) e3 SPD Length=7ff MaxLen=0 DT1 EndPt=0 Dev=2,
PID=69(IN) (buf=07e460a0)
2: [c7e541b0] link (00000001) e3 IOC Length=7ff MaxLen=7ff DT0 EndPt=0 Dev=2,
PID=e1(OUT) (buf=00000000)
uhci: added urbp c5ac74ac to complete_list
uhci: took urbp c5ac753c off complete_list
uhci: freed urbp c5ac753c
uhci: took urbp c5ac74f4 off complete_list
uhci: freed urbp c5ac74f4
uhci: took urbp c5ac74ac off complete_list
uhci: freed urbp c5ac74ac
drivers/usb/misc/usbtest.c: subtest 2 error, status -121
drivers/usb/misc/usbtest.c: control queue 81.0a, err -121, 14997 left
uhci: added urbp c5ac753c to remove_list
uhci: added urbp c5ac74f4 to remove_list
uhci: took urbp c5ac74f4 off remove_list
uhci: added urbp c5ac74f4 to complete_list
uhci: took urbp c5ac753c off remove_list
uhci: added urbp c5ac753c to complete_list
uhci: took urbp c5ac74f4 off complete_list
uhci: freed urbp c5ac74f4
drivers/usb/misc/usbtest.c: subcase 1 completed out of order, last 2
uhci: took urbp c5ac753c off complete_list
uhci: freed urbp c5ac753c
uhci: added urbp c5ac753c to complete_list
uhci: took urbp c5ac753c off complete_list
uhci: freed urbp c5ac753c
drivers/usb/misc/usbtest.c: 0000:00:02.2-1:0 TEST 10: queue 3 control calls, 5000
times
uhci: added urbp c5ac753c to complete_list
uhci: added urbp c5ac74f4 to complete_list
drivers/usb/host/uhci-hcd.c: uhci_result_control() failed with status 0
[c7e532a0] link (07e531e2) element (00000001)
Element != First TD
0: [c7e54150] link (07e54180) e3 Length=7 MaxLen=7 DT0 EndPt=0 Dev=2, PID=2d(SETUP)
(buf=07e460c0)
1: [c7e54180] link (07e541b0) e3 SPD Length=7ff MaxLen=0 DT1 EndPt=0 Dev=2,
PID=69(IN) (buf=07e460a0)
2: [c7e541b0] link (00000001) e3 IOC Length=7ff MaxLen=7ff DT0 EndPt=0 Dev=2,
PID=e1(OUT) (buf=00000000)
uhci: added urbp c5ac74ac to complete_list
uhci: took urbp c5ac753c off complete_list
uhci: freed urbp c5ac753c
uhci: took urbp c5ac74f4 off complete_list
uhci: freed urbp c5ac74f4
uhci: took urbp c5ac74ac off complete_list
uhci: freed urbp c5ac74ac
drivers/usb/misc/usbtest.c: subtest 2 error, status -121
drivers/usb/misc/usbtest.c: control queue 81.0a, err -121, 14997 left
uhci: added urbp c5ac753c to remove_list
uhci: added urbp c5ac74f4 to remove_list
uhci: took urbp c5ac74f4 off remove_list
uhci: added urbp c5ac74f4 to complete_list
uhci: took urbp c5ac753c off remove_list
uhci: added urbp c5ac753c to complete_list
uhci: took urbp c5ac74f4 off complete_list
uhci: freed urbp c5ac74f4
drivers/usb/misc/usbtest.c: subcase 1 completed out of order, last 2
uhci: took urbp c5ac753c off complete_list
uhci: freed urbp c5ac753c
uhci: added urbp c5ac753c to complete_list
uhci: took urbp c5ac753c off complete_list
uhci: freed urbp c5ac753c
drivers/usb/misc/usbtest.c: 0000:00:02.2-1:0 TEST 10: queue 3 control calls, 5000
times
uhci: added urbp c5ac753c to complete_list
uhci: added urbp c5ac7584 to complete_list
drivers/usb/host/uhci-hcd.c: uhci_result_control() failed with status 0
[c7e532a0] link (07e531e2) element (00000001)
Element != First TD
0: [c7e54150] link (07e54180) e3 Length=7 MaxLen=7 DT0 EndPt=0 Dev=2, PID=2d(SETUP)
(buf=07e460c0)
1: [c7e54180] link (07e541b0) e3 SPD Length=7ff MaxLen=0 DT1 EndPt=0 Dev=2,
PID=69(IN) (buf=07e460a0)
2: [c7e541b0] link (00000001) e3 IOC Length=7ff MaxLen=7ff DT0 EndPt=0 Dev=2,
PID=e1(OUT) (buf=00000000)
uhci: added urbp c5ac7104 to complete_list
uhci: took urbp c5ac753c off complete_list
uhci: freed urbp c5ac753c
uhci: took urbp c5ac7584 off complete_list
uhci: freed urbp c5ac7584
uhci: took urbp c5ac7104 off complete_list
uhci: freed urbp c5ac7104
drivers/usb/misc/usbtest.c: subtest 2 error, status -121
drivers/usb/misc/usbtest.c: control queue 81.0a, err -121, 14997 left
uhci: added urbp c5ac753c to remove_list
uhci: added urbp c5ac7584 to remove_list
uhci: took urbp c5ac7584 off remove_list
uhci: added urbp c5ac7584 to complete_list
uhci: took urbp c5ac753c off remove_list
uhci: added urbp c5ac753c to complete_list
uhci: took urbp c5ac7584 off complete_list
uhci: freed urbp c5ac7584
drivers/usb/misc/usbtest.c: subcase 1 completed out of order, last 2
uhci: took urbp c5ac753c off complete_list
uhci: freed urbp c5ac753c
uhci: added urbp c5ac753c to complete_list
uhci: took urbp c5ac753c off complete_list
uhci: freed urbp c5ac753c
drivers/usb/misc/usbtest.c: 0000:00:02.2-1:0 TEST 10: queue 3 control calls, 5000
times
uhci: added urbp c5ac753c to complete_list
uhci: added urbp c5ac7584 to complete_list
drivers/usb/host/uhci-hcd.c: uhci_result_control() failed with status 0
[c7e532a0] link (07e531e2) element (00000001)
Element != First TD
0: [c7e54150] link (07e54180) e3 Length=7 MaxLen=7 DT0 EndPt=0 Dev=2, PID=2d(SETUP)
(buf=07e460c0)
1: [c7e54180] link (07e541b0) e3 SPD Length=7ff MaxLen=0 DT1 EndPt=0 Dev=2,
PID=69(IN) (buf=07e460a0)
2: [c7e541b0] link (00000001) e3 IOC Length=7ff MaxLen=7ff DT0 EndPt=0 Dev=2,
PID=e1(OUT) (buf=00000000)
uhci: added urbp c5ac7104 to complete_list
uhci: took urbp c5ac753c off complete_list
uhci: freed urbp c5ac753c
uhci: took urbp c5ac7584 off complete_list
uhci: freed urbp c5ac7584
uhci: took urbp c5ac7104 off complete_list
uhci: freed urbp c5ac7104
drivers/usb/misc/usbtest.c: subtest 2 error, status -121
drivers/usb/misc/usbtest.c: control queue 81.0a, err -121, 14997 left
uhci: added urbp c5ac753c to remove_list
uhci: added urbp c5ac7584 to remove_list
uhci: took urbp c5ac7584 off remove_list
uhci: added urbp c5ac7584 to complete_list
uhci: took urbp c5ac753c off remove_list
uhci: added urbp c5ac753c to complete_list
uhci: took urbp c5ac7584 off complete_list
uhci: freed urbp c5ac7584
drivers/usb/misc/usbtest.c: subcase 1 completed out of order, last 2
uhci: took urbp c5ac753c off complete_list
uhci: freed urbp c5ac753c
uhci: added urbp c540a53c to complete_list
uhci: took urbp c540a53c off complete_list
uhci: freed urbp c540a53c
drivers/usb/misc/usbtest.c: 0000:00:02.2-1:0 TEST 10: queue 4 control calls, 5000
times
uhci: added urbp c540a53c to complete_list
uhci: added urbp c540a4f4 to complete_list
drivers/usb/host/uhci-hcd.c: uhci_result_control() failed with status 0
[c7e532a0] link (07e531e2) element (07e532d2)
Element points to QH (bug?)
Element != First TD
0: [c7e54150] link (07e54180) e3 Length=7 MaxLen=7 DT0 EndPt=0 Dev=3, PID=2d(SETUP)
(buf=07e460c0)
1: [c7e54180] link (07e541b0) e3 SPD Length=7ff MaxLen=0 DT1 EndPt=0 Dev=3,
PID=69(IN) (buf=07e460a0)
2: [c7e541b0] link (07e532d2) e3 IOC Length=7ff MaxLen=7ff DT0 EndPt=0 Dev=3,
PID=e1(OUT) (buf=00000000)
--Queued QH's:
[c7e532d0] link (07e531e2) element (00000001)
Element != First TD
0: [c7e541e0] link (07e54210) e3 Length=7 MaxLen=7 DT1 EndPt=0 Dev=3, PID=2d(SETUP)
(buf=07e46100)
1: [c7e54210] link (07e54240) e3 Length=1 MaxLen=1 DT0 EndPt=0 Dev=3, PID=69(IN)
(buf=07e460e0)
2: [c7e54240] link (00000001) e3 IOC Length=7ff MaxLen=7ff DT1 EndPt=0 Dev=3,
PID=e1(OUT) (buf=00000000)
uhci: added urbp c540a4ac to complete_list
uhci: added urbp c540a464 to complete_list
uhci: took urbp c540a53c off complete_list
uhci: freed urbp c540a53c
uhci: took urbp c540a4f4 off complete_list
uhci: freed urbp c540a4f4
uhci: took urbp c540a4ac off complete_list
uhci: freed urbp c540a4ac
drivers/usb/misc/usbtest.c: subtest 2 error, status -121
drivers/usb/misc/usbtest.c: control queue 81.0a, err -121, 19997 left
uhci: added urbp c540a53c to remove_list
uhci: added urbp c540a4f4 to remove_list
uhci: added urbp c540a464 to remove_list
uhci: took urbp c540a464 off complete_list
drivers/usb/host/uhci-hcd.c: uhci_destroy_urb_priv: urb c7e34ae4 still on
uhci->urb_list or uhci->remove_list
uhci: freed urbp c540a464
Unable to handle kernel paging request at virtual address 6b6b6b6f
printing eip:
c025b87b
*pde = 00000000
Oops: 0002 [#1]
CPU: 0
EIP: 0060:[<c025b87b>] Not tainted
EFLAGS: 00010092
EIP is at uhci_remove_pending_qhs+0x4b/0xf0
eax: c7ecbb38 ebx: c540a464 ecx: c7ecbb30 edx: 6b6b6b6b
esi: 6b6b6b6b edi: c0380000 ebp: 6b6b6b6b esp: c0381e90
ds: 007b es: 007b ss: 0068
Process swapper (pid: 0, threadinfo=c0380000 task=c03111c0)
Stack: c7ecbb28 00000292 c7ecbb38 00000286 c7ecbb30 00000000 0000fce0 c7ecb94c
c0381f2c c025b9c3 c7ecb94c c7e34ae4 c7ecb94c 00000003 00000000 c0381f2c
c024edaf c7ecb94c c0381f2c c7e72d08 04000001 c010c919 0000000a c7ecb94c
Call Trace:
[<c025b9c3>] uhci_irq+0xa3/0x160
[<c024edaf>] usb_hcd_irq+0x2f/0x60
[<c010c919>] handle_IRQ_event+0x49/0x80
[<c010cca9>] do_IRQ+0xa9/0x170
[<c010b048>] common_interrupt+0x18/0x20
[<c011f4ce>] do_softirq+0x3e/0xa0
[<c010cd17>] do_IRQ+0x117/0x170
[<c0108b70>] default_idle+0x0/0x40
[<c0108b70>] default_idle+0x0/0x40
[<c010b048>] common_interrupt+0x18/0x20
[<c0108b70>] default_idle+0x0/0x40
[<c0108b70>] default_idle+0x0/0x40
[<c0108b94>] default_idle+0x24/0x40
[<c0108c2a>] cpu_idle+0x3a/0x50
[<c0105000>] rest_init+0x0/0x60
[<c038273d>] start_kernel+0x16d/0x1a0
[<c0382470>] unknown_bootoption+0x0/0x120
Code: 89 55 04 89 2a 89 5b 04 89 1b 89 5c 24 04 c7 04 24 20 b6 2f
<0>Kernel panic: Fatal exception in interrupt
In interrupt handler - not syncing
<0>Rebooting in 10 seconds..
