NetBSD-Bugs archive

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index][Old Index]

kern/57518: usb keyboard causes host controller to miss microframe



>Number:         57518
>Category:       kern
>Synopsis:       usb keyboard causes host controller to miss microframe
>Confidential:   no
>Severity:       serious
>Priority:       medium
>Responsible:    kern-bug-people
>State:          open
>Class:          sw-bug
>Submitter-Id:   net
>Arrival-Date:   Mon Jul 10 16:45:00 +0000 2023
>Originator:     Andreas Hecht
>Release:        NetBSD 10.99.5
>Organization:
N/A
>Environment:
NetBSD pc.domain.home 10.99.5 NetBSD 10.99.5 (MYKERNEL) #15: Sat Jul 8 12:50:37 CEST 2023 andreas%pc.domain.home@localhost:/home/andreas/git/netbsd/src/sys/arch/amd64/compile/obj/MYKERNEL amd64
>Description:
My USB keyboard (Leopold FC750R PD) causes the USB 2.0 host controller to miss
a required complete-split transaction. 

These are the system messages (-> dmesg) which occur when the keyboard gets
plugged in:

[    35.554780] uhidev1 at uhub2 port 6 configuration 1 interface 0
[    35.554780] uhidev1: HID Keyboard (0x4b4) HID Keyboard (0x510), rev 2.00/2.01, addr 4, iclass 3/1
[    35.554780] ukbd0 at uhidev1
[    35.965206] wskbd1 at ukbd0 mux 1
[    35.965206] wskbd1: connecting to wsdisplay0
[    35.965206] uhidev2 at uhub2 port 6 configuration 1 interface 1
[    35.965206] uhidev2: HID Keyboard (0x4b4) HID Keyboard (0x510), rev 2.00/2.01, addr 4, iclass 3/1
[    35.965206] uhidev2: 8 report ids
[    35.975217] uhid1 at uhidev2 reportid 1: input=2, output=0, feature=0
[    35.975217] ukbd1 at uhidev2 reportid 8
[    36.385643] wskbd2 at ukbd1 mux 1
[    36.385643] wskbd2: connecting to wsdisplay0

This is the error message (-> dmesg) which occurs when a key is pressed:

[    44.093653] ehci1: missed microframe, TT reset not implemented, hub might be inoperational

Here is the usbhist debug output (-> vmstat -u usbhist) of a single 'key press
and release event' of the affected keyboard generated with a kernel compiled
with USB_DEBUG and EHCI_DEBUG and hw.ehci.debug set to '1':

50000 entries, next is 113
1685992014.561408 ehci_intr#1@0: called!
1685992014.561409 ehci_intr1#1@0: called!
1685992014.561410 ehci_intr1#1@0: sc=0xffff82d6f556d000 intrs=0xb(0xc00b) eintrs=0x3
1685992014.561411 ehci_intr1#1@0: INT=1  ERRINT=1
1685992014.561412 ehci_softintr#1@0: called!
1685992014.561413 ehci_check_qh_intr#1@0: called!
1685992014.561414 ehci_dump_sqtds#1@0: called!
1685992014.561414 ehci_dump_sqtd#1@0: called!
1685992014.561415 ehci_dump_qtd#1@0: called!
1685992014.561415 ehci_check_qh_intr#2@0: called!
1685992014.561416 ehci_dump_sqtds#2@0: called!
1685992014.561416 ehci_dump_sqtd#2@0: called!
1685992014.561416 ehci_dump_qtd#2@0: called!
1685992014.561416 ehci_check_qh_intr#3@0: called!
1685992014.561416 ehci_dump_sqtds#3@0: called!
1685992014.561417 ehci_dump_sqtd#3@0: called!
1685992014.561417 ehci_dump_qtd#3@0: called!
1685992014.561417 ehci_check_qh_intr#4@0: called!
1685992014.561417 ehci_idone#1@0: called!
1685992014.561418 ehci_idone#1@0: ex=0xffff82d6f57b1328
1685992014.561418 ehci_idone#1@0: xfer=0xffff82d6f57b1328, pipe=0xffff82d724667e00 ready
1685992014.561419 ehci_dump_sqtds#4@0: called!
1685992014.561419 ehci_dump_sqtd#4@0: called!
1685992014.561419 ehci_dump_qtd#4@0: called!
1685992014.561419 ehci_idone#1@0: toggle update status=0x00088d4e nstatus=0x00088d4e
1685992014.561420 ehci_idone#1@0: len=8 actlen=0 status=0x00088d4e
1685992014.561420 ehci_idone#1@0: halted addr=4 endpt=0x81
1685992014.561420 ehci_idone#1@0: cerr=3 pid=1
1685992014.561420 ehci_idone#1@0: active =0 halted=1 buferr=0 babble=0
1685992014.561421 ehci_idone#1@0: xacterr=1 missed=1 split =1 ping  =0
1685992014.561421 ehci_dump_sqh#1@0: called!
1685992014.561421 ehci_dump_sqh#1@0:     link 0x00000001 (T = 1):
1685992014.561421 ehci_dump_sqh#1@0:         ITD  = 1  QH   = 0  SITD = 0  FSTN = 0
1685992014.561422 ehci_dump_sqh#1@0:     link 0xcad98f80 (T = 0):
1685992014.561422 ehci_dump_qtd#5@0: called!
1685992014.561422 ehci_dump_sqtds#5@0: called!
1685992014.561422 ehci_dump_sqtd#5@0: called!
1685992014.561422 ehci_dump_qtd#6@0: called!
1685992014.561448 ehci_idone#1@0: ex=0xffff82d6f57b1328 done
1685992014.561449 ehci_device_intr_done#1@0: called!
1685992014.561449 ehci_device_intr_done#1@0: xfer=0xffff82d6f57b1328, actlen=0
1685992014.561452 ehci_device_intr_start#1@0: called!
1685992014.561453 ehci_device_intr_start#1@0: xfer=0xffff82d6f57b1328 len=8 flags=4
1685992014.561453 ehci_reset_sqtd_chain#1@0: called!
1685992014.561454 ehci_reset_sqtd_chain#1@0: xfer=0xffff82d6f57b1328 len 8 isread 1 toggle 0
1685992014.561454 ehci_reset_sqtd_chain#1@0:     VA 0xffffb9023a92ef80
1685992014.561454 ehci_reset_sqtd_chain#1@0: sqtd[1]=0xffffb90238f76f80 prev 0
1685992014.561454 ehci_reset_sqtd_chain#1@0:     len=8 curlen=8 curoffs=0
1685992014.561455 ehci_reset_sqtd_chain#1@0:       buffer[0/1] 0x00000001 0x1d725000
1685992014.561455 ehci_reset_sqtd_chain#1@0:     va 0xffffb9023a92ef80 pa 0x11d725f80 len 8
1685992014.561455 ehci_dump_sqh#2@0: called!
1685992014.561456 ehci_dump_sqh#2@0:     link 0x00000001 (T = 1):
1685992014.561456 ehci_dump_sqh#2@0:         ITD  = 1  QH   = 0  SITD = 0  FSTN = 0
1685992014.561456 ehci_dump_sqh#2@0:     link 0xcad98f80 (T = 0):
1685992014.561456 ehci_dump_qtd#7@0: called!
1685992014.561456 ehci_dump_sqtds#6@0: called!
1685992014.561456 ehci_dump_sqtd#6@0: called!
1685992014.561456 ehci_dump_qtd#8@0: called!
1685992014.561460 ehci_device_clear_toggle#1@0: called!
1685992014.561460 ehci_device_clear_toggle#1@0: epipe=0xffff82d724667e00 status=0x00000000
1685992014.561462 ehci_alloc_sqtd#1@0: called!
1685992014.561463 ehci_alloc_sqtd#2@0: called!
1685992014.561464 ehci_device_ctrl_start#1@0: called!
1685992014.561464 ehci_device_ctrl_start#1@0: type=0x02, request=0x01, wValue=0x0000, wIndex=0x0081
1685992014.561464 ehci_device_ctrl_start#1@0: len=0, addr=4, endpt=0
1685992014.561464 ehci_device_ctrl_start#1@0: setup 0xffffb90238f76d80 status 0xffffb90238f76c80 data 0
1685992014.561465 ehci_dump_sqh#3@0: called!
1685992014.561465 ehci_dump_sqh#3@0:     link 0xcad96e82 (T = 0):
1685992014.561465 ehci_dump_sqh#3@0:         ITD  = 0  QH   = 1  SITD = 0  FSTN = 0
1685992014.561465 ehci_dump_sqh#3@0:     link 0xcad98d80 (T = 0):
1685992014.561465 ehci_dump_qtd#9@0: called!
1685992014.561465 ehci_dump_sqtds#7@0: called!
1685992014.561466 ehci_dump_sqtd#7@0: called!
1685992014.561466 ehci_dump_qtd#10@0: called!
1685992014.561466 ehci_dump_sqtd#8@0: called!
1685992014.561466 ehci_dump_qtd#11@0: called!
1685992014.561908 ehci_intr#2@0: called!
1685992014.561908 ehci_intr1#2@0: called!
1685992014.561909 ehci_intr1#2@0: sc=0xffff82d6f556d000 intrs=0x1(0xc001) eintrs=0x1
1685992014.561910 ehci_intr1#2@0: INT=1  ERRINT=0
1685992014.561911 ehci_softintr#2@0: called!
1685992014.561911 ehci_check_qh_intr#5@0: called!
1685992014.561912 ehci_dump_sqtds#8@0: called!
1685992014.561912 ehci_dump_sqtd#9@0: called!
1685992014.561912 ehci_dump_qtd#12@0: called!
1685992014.561912 ehci_check_qh_intr#6@0: called!
1685992014.561913 ehci_dump_sqtds#9@0: called!
1685992014.561913 ehci_dump_sqtd#10@0: called!
1685992014.561913 ehci_dump_qtd#13@0: called!
1685992014.561913 ehci_check_qh_intr#7@0: called!
1685992014.561913 ehci_dump_sqtds#10@0: called!
1685992014.561913 ehci_dump_sqtd#11@0: called!
1685992014.561914 ehci_dump_qtd#14@0: called!
1685992014.561914 ehci_check_qh_intr#8@0: called!
1685992014.561914 ehci_dump_sqtds#11@0: called!
1685992014.561914 ehci_dump_sqtd#12@0: called!
1685992014.561914 ehci_dump_qtd#15@0: called!
1685992014.561914 ehci_check_qh_intr#9@0: called!
1685992014.561915 ehci_idone#2@0: called!
1685992014.561915 ehci_idone#2@0: ex=0xffff82d6f57b1908
1685992014.561916 ehci_idone#2@0: xfer=0xffff82d6f57b1908, pipe=0xffff82d71cde0500 ready
1685992014.561916 ehci_dump_sqtds#12@0: called!
1685992014.561916 ehci_dump_sqtd#13@0: called!
1685992014.561916 ehci_dump_qtd#16@0: called!
1685992014.561916 ehci_dump_sqtd#14@0: called!
1685992014.561917 ehci_dump_qtd#17@0: called!
1685992014.561917 ehci_idone#2@0: len=0 actlen=0 status=0x00008d00
1685992014.561917 ehci_idone#2@0: ex=0xffff82d6f57b1908 done
1685992014.561918 ehci_device_ctrl_done#1@0: called!
1685992014.561918 ehci_device_ctrl_done#1@0: xfer=0xffff82d6f57b1908
1685992014.561918 ehci_device_ctrl_done#1@0: length=0
1685992014.561921 ehci_free_sqtds#1@0: called!
1685992014.561921 ehci_free_sqtds#1@0: exfer=0xffff82d6f57b1908

This keyboard (Leopold FC750R PD) works nice with Linux and OpenBSD, but does
*not* work under NetBSD.
>How-To-Repeat:
1. Plug in Leopold FC750R PD keyboard via USB
2. Press a key
3. Observe system message buffer (dmesg)
>Fix:
USB 1.1 devices interact with the USB 2.0 host controller through a transaction
translator (implemented in a USB 2.0 hub) which converts low-/full-speed
transactions into high-speed split transactions. The bug described above is
caused by the EHCI driver incorrectly scheduling split transactions for
full-/low-speed interrupt transactions. ehci_open function schedules
start-split to micro-frame Y1, the full-/low-speed transaction to micro-frame
Y2 and *one* complete-split to micro-frame Y3. (One H-Frame has 8 micro-frames
indexed Y0 to Y7.) USB 2.0 specifies (section 11.8.4; paragraph 3.b) that a
compete-split must be scheduled for each of the 3 micro-frames following the
micro-frame the low-/full-speed transaction is scheduled for:

"For interrupt IN/OUT full-/low-speed transactions, the host must schedule a
complete-split transaction in each of the two microframes following the first
microframe in which the full-/low-speed transaction is budgeted. An additional
complete-split must also be scheduled in the third following microframe unless
the full-/low-speed transaction was budgeted to start in microframe Y6."

As the current implementation has the full-/low-speed transaction scheduled to
micro-frame Y2 (and *not* micro-frame Y6), complete-splits should be scheduled
for micro-frames Y3, Y4 and Y5.

This fixes my keyboard:

--- a/sys/dev/usb/ehci.c
+++ b/sys/dev/usb/ehci.c
@@ -2039,7 +2039,7 @@ ehci_open(struct usbd_pipe *pipe)
 			    EHCI_QH_SET_PORT(hshubport) |
 			    EHCI_QH_SET_HUBA(hshubaddr) |
 			    (xfertype == UE_INTERRUPT ?
-				 EHCI_QH_SET_CMASK(0x08) : 0)
+				 EHCI_QH_SET_CMASK(0x38) : 0)
 			);
 		sqh->qh.qh_curqtd = EHCI_NULL;
 		/* Fill the overlay qTD */



Home | Main Index | Thread Index | Old Index