On Tue, 2017-05-09 at 11:34 +0300, Felipe Balbi wrote: > Hi, > > Maël Lavault <mael.lavault@xxxxxxxxxxxxxxxxxxx> writes: > > Le 28 avr. 2017 15:57, "Maël Lavault" <mael.lavault@universalavenue > > .com > > > a écrit : > > > > On Fri, 2017-04-28 at 16:58 +0300, Mathias Nyman wrote: > > > On 21.04.2017 11:08, Maël Lavault wrote: > > > > On Tue, 2017-04-18 at 16:58 +0200, Maël Lavault wrote: > > > > > Hi, > > > > > > > > > > I can't find how to reply to an old thread with majordomo, > > > > > sorry > > > > > for > > > > > the inconvenience it might cause. > > > > > > > > > > I'm reposting an issue [0] that has been inactive for a few > > > > > month > > > > > but > > > > > still present in kernel 4.10.10 on a Macbook pro 12,1. > > > > > > > > > > I can provide more informations if needed but the issue is > > > > > explained > > > > > in > > > > > details in the bugzilla issue. > > > > > > > > > > Thanks. > > > > > > > > > > --------------- > > > > > Hi list, > > > > > > > > > > I have a Apple Inc. MacBookPro11,1 (with the most recent > > > > > 'bios': > > > > > BIOS > > > > > MBP111.88Z.0138.B16.1509081438 09/08/2015). > > > > > > > > > > At the beginning, USB worked normally. After a while (and > > > > > after > > > > > newer > > > > > kernel versions released by debian?) things started to act > > > > > strangely. > > > > > For > > > > > one, the bios/efi boot takes a very long time (probably due > > > > > to > > > > > the > > > > > same > > > > > reason I describe later) just to get to the bootloader/grub. > > > > > Likley > > > > > resetting and probing for USB ports/mass storage. When grub > > > > > finally > > > > > pops > > > > > up, I can use the (internal USB based keyboard) normally to > > > > > select a > > > > > grub > > > > > entry etc. > > > > > > > > > > Booting the kernel then works reasonably fine, until it loads > > > > > the > > > > > xhci > > > > > module. > > > > > It spews some messages in dmesg (taking some 15 seconds) and > > > > > only > > > > > then, > > > > > the > > > > > keyboard starts to work again. > > > > > > > > > > The log is filled with messages like: > > > > > [ 7.248479] xhci_hcd 0000:00:14.0: Command completion > > > > > event > > > > > does > > > > > not > > > > > match command > > > > > [ 7.248495] xhci_hcd 0000:00:14.0: Timeout while waiting > > > > > for > > > > > setup > > > > > device command > > > > > [ 12.256347] xhci_hcd 0000:00:14.0: Timeout while waiting > > > > > for > > > > > setup > > > > > device command > > > > > [ 12.256363] usb 1-2: hub failed to enable device, error > > > > > -62 > > > > > [ 17.264166] xhci_hcd 0000:00:14.0: Timeout while waiting > > > > > for > > > > > setup > > > > > device command > > > > > (followed by USB hub/device enumeration) > > > > > > > > > > I've tried several combinations and quirks, updating to the > > > > > latest rc > > > > > kernels since 3.16 (am on 4.5.0 right now) and it only seems > > > > > to > > > > > get > > > > > worse. > > > > > > > > > > Last year, on the 3.x series of kernels occasionally after a > > > > > reboot > > > > > the > > > > > 'bios' would go through quickly and fine and also no problems > > > > > loading > > > > > the > > > > > module and logging in. But now it always fails. > > > > > > > > > > Additionally it (may or may not) seems to cause the internal > > > > > usb > > > > > card > > > > > reader to not even show up almost all of the time, though > > > > > under > > > > > OSX > > > > > it > > > > > works fine. There is/was a known issue with this cardreader > > > > > where > > > > > it > > > > > would > > > > > disappear after a suspend. > > > > > > > > > > Adding various seemingly related intel usb3 quirks I had no > > > > > change, > > > > > as > > > > > I > > > > > think all of them are already applied to this chipset. > > > > > > > > > > I'm guessing that somehow the usb chipset has some > > > > > configuration > > > > > option > > > > > miss-set (which persists over reboots/power down) and the > > > > > driver > > > > > doesn't > > > > > quite understand it. > > > > > > > > > > Unfortunately it seems that this chipset does not work in > > > > > pure > > > > > USB2.0 > > > > > (ehci) mode and needs the xhci module to work at all, so even > > > > > falling > > > > > to > > > > > USB2 is no option. Also disconnecting all USB perhipials is > > > > > nearly > > > > > impossible as the touchpad, bluetooth cardreader and keyboard > > > > > are > > > > > internally all wired to USB. > > > > > > > > > > I'm attaching 3 dmesg logs with various kernels and levels of > > > > > debugging > > > > > information. I tried to google for errors from these logs, > > > > > but to > > > > > no > > > > > avail. > > > > > > > > > > I have attached some log files on the bugzilla issue tracker > > > > > [1] > > > > > (they > > > > > are > > > > > to big for the ML I think). > > > > > > > > > > [1] https://bugzilla.kernel.org/show_bug.cgi?id=115741 > > > > > > > > > > > > > > > Olliver > > > > > > > > > > > > > > > > > > > > [0] http://thread.gmane.org/gmane.linux.usb.general/139697 > > > > > > > > I updated to fedora 26 with kernel 4.11.0-rc7 and the issue is > > > > still > > > > present. > > > > > > 4.11-rc7 should have xhci tracepoints installed. > > > Could you take some traces at boot with most recent kernel you > > > got. > > > > > > xhci traces for boot can be enabled by adding "trace_event=xhci- > > > hcd" > > > to > > > your kernel cmdline > > > > > > Traces should then appear in /sys/kernel/debug/tracing/trace > > > > > > -Mathias > > > > Thanks ! I'll try to do that, but it's utterly difficult since each > > keypress takes between 5 and 10 seconds due to this bug ... > > > > So I tried it and I cannot access the trace. Are the trace > > persisted > > across reboot ? Since all 4.11 kernel freeze on the login page I > > have > > no other choice but rebooting on a old 4.10 kernel to look at the > > trace. > > You could SSH from a different machine, no? tracepoints don't persist > across reboots, AFAICT. > Thanks, it did work. Here is the trace: # tracer: nop # # entries-in-buffer/entries-written: 78/78 #P:4 # # _-----=> irqs-off # / _----=> need-resched # | / _---=> hardirq/softirq # || / _--=> preempt-depth # ||| / delay # TASK-PID CPU# |||| TIMESTAMP FUNCTION # | | | |||| | | swapper/0-1 [003] .... 1.131059: xhci_dbg_init: // Halt the HC swapper/0-1 [003] .... 1.131063: xhci_dbg_init: // Reset the HC swapper/0-1 [003] .... 1.132066: xhci_dbg_init: Wait for controller to be ready for doorbell rings swapper/0-1 [003] .... 1.132067: xhci_dbg_init: xhci_init swapper/0-1 [003] .... 1.132067: xhci_dbg_init: xHCI doesn't need link TRB QUIRK swapper/0-1 [003] .... 1.132068: xhci_dbg_init: Supported page size register = 0x1 swapper/0-1 [003] .... 1.132068: xhci_dbg_init: Supported page size of 4K swapper/0-1 [003] .... 1.132069: xhci_dbg_init: HCD page size set to 4K swapper/0-1 [003] .... 1.132070: xhci_dbg_init: // xHC can handle at most 32 device slots. swapper/0-1 [003] .... 1.132071: xhci_dbg_init: // Setting Max device slots reg = 0x20. swapper/0-1 [003] .... 1.132072: xhci_dbg_init: // Device context base array address = 0x25c47a000 (DMA), ffff91079c47a000 (virt) swapper/0-1 [003] .... 1.132075: xhci_dbg_init: Allocated command ring at ffff91079c47bb80 swapper/0-1 [003] .... 1.132075: xhci_dbg_init: First segment DMA is 0x25c47c000 swapper/0-1 [003] .... 1.132078: xhci_dbg_init: // Setting command ring address to 0x20 swapper/0-1 [003] .... 1.132082: xhci_dbg_init: // Doorbell array is located at offset 0x3000 from cap regs base addr swapper/0-1 [003] .... 1.132095: xhci_dbg_init: // Allocating event ring swapper/0-1 [003] .... 1.132097: xhci_dbg_init: // Allocated event ring segment table at 0x25c47f000 swapper/0-1 [003] .... 1.132097: xhci_dbg_init: Set ERST to 0; private num segs = 1, virt addr = ffff91079c47f000, dma addr = 0x25c47f000 swapper/0-1 [003] .... 1.132098: xhci_dbg_init: // Write ERST size = 1 to ir_set 0 (some bits preserved) swapper/0-1 [003] .... 1.132098: xhci_dbg_init: // Set ERST entries to point to event ring. swapper/0-1 [003] .... 1.132099: xhci_dbg_init: // Set ERST base address for ir_set 0 = 0x25c47f000 swapper/0-1 [003] .... 1.132102: xhci_dbg_init: // Write event ring dequeue pointer, preserving EHB bit swapper/0-1 [003] .... 1.132103: xhci_dbg_init: Wrote ERST address to ir_set 0. swapper/0-1 [003] .... 1.132105: xhci_dbg_init: Allocating 16 scratchpad buffers swapper/0-1 [003] .... 1.132122: xhci_dbg_init: Ext Cap ffffb90001238000, port offset = 1, count = 11, revision = 0x2 swapper/0-1 [003] .... 1.132124: xhci_dbg_init: xHCI 1.0: support USB2 software lpm swapper/0-1 [003] .... 1.132125: xhci_dbg_init: xHCI 1.0: support USB2 hardware lpm swapper/0-1 [003] .... 1.132127: xhci_dbg_init: Ext Cap ffffb90001238020, port offset = 12, count = 4, revision = 0x3 swapper/0-1 [003] .... 1.132128: xhci_dbg_init: Found 11 USB 2.0 ports and 4 USB 3.0 ports. swapper/0-1 [003] .... 1.132129: xhci_dbg_init: USB 2.0 port at index 0, addr = ffffb90001230480 swapper/0-1 [003] .... 1.132129: xhci_dbg_init: USB 2.0 port at index 1, addr = ffffb90001230490 swapper/0-1 [003] .... 1.132129: xhci_dbg_init: USB 2.0 port at index 2, addr = ffffb900012304a0 swapper/0-1 [003] .... 1.132129: xhci_dbg_init: USB 2.0 port at index 3, addr = ffffb900012304b0 swapper/0-1 [003] .... 1.132130: xhci_dbg_init: USB 2.0 port at index 4, addr = ffffb900012304c0 swapper/0-1 [003] .... 1.132130: xhci_dbg_init: USB 2.0 port at index 5, addr = ffffb900012304d0 swapper/0-1 [003] .... 1.132130: xhci_dbg_init: USB 2.0 port at index 6, addr = ffffb900012304e0 swapper/0-1 [003] .... 1.132131: xhci_dbg_init: USB 2.0 port at index 7, addr = ffffb900012304f0 swapper/0-1 [003] .... 1.132131: xhci_dbg_init: USB 2.0 port at index 8, addr = ffffb90001230500 swapper/0-1 [003] .... 1.132131: xhci_dbg_init: USB 2.0 port at index 9, addr = ffffb90001230510 swapper/0-1 [003] .... 1.132132: xhci_dbg_init: USB 2.0 port at index 10, addr = ffffb90001230520 swapper/0-1 [003] .... 1.132132: xhci_dbg_init: USB 3.0 port at index 11, addr = ffffb90001230530 swapper/0-1 [003] .... 1.132133: xhci_dbg_init: USB 3.0 port at index 12, addr = ffffb90001230540 swapper/0-1 [003] .... 1.132133: xhci_dbg_init: USB 3.0 port at index 13, addr = ffffb90001230550 swapper/0-1 [003] .... 1.132133: xhci_dbg_init: USB 3.0 port at index 14, addr = ffffb90001230560 swapper/0-1 [003] .... 1.132134: xhci_dbg_init: Finished xhci_init swapper/0-1 [003] .... 1.132140: xhci_dbg_init: xhci_run swapper/0-1 [003] .... 1.132140: xhci_dbg_init: Failed to enable MSI-X swapper/0-1 [003] .... 1.132176: xhci_dbg_init: ERST deq = 64'h25c47e000 swapper/0-1 [003] .... 1.132177: xhci_dbg_init: // Set the interrupt modulation register swapper/0-1 [003] .... 1.132179: xhci_dbg_init: // Enable interrupts, cmd = 0x4. swapper/0-1 [003] .... 1.132180: xhci_dbg_init: // Enabling event ring interrupter ffffb90001232020 by writing 0x2 to irq_pending swapper/0-1 [003] .... 1.132186: xhci_dbg_init: Finished xhci_run for USB2 roothub swapper/0-1 [003] .... 1.132559: xhci_dbg_init: // Turn on HC, cmd = 0x5. swapper/0-1 [003] .... 1.132561: xhci_dbg_init: Finished xhci_run for USB3 roothub <idle>-0 [000] d.h. 1.152105: xhci_handle_event: EVENT: TRB 0000000001000000 status 'Success' len 0 slot 0 ep 0 type 'Port Status Change Event' flags e:C <idle>-0 [000] d.h. 1.152116: xhci_handle_event: EVENT: TRB 0000000003000000 status 'Success' len 0 slot 0 ep 0 type 'Port Status Change Event' flags e:C <idle>-0 [000] d.h. 1.152125: xhci_handle_event: EVENT: TRB 0000000005000000 status 'Success' len 0 slot 0 ep 0 type 'Port Status Change Event' flags e:C kworker/3:0-35 [003] d... 1.234029: xhci_queue_trb: CMD: Enable Slot Command: flags C <idle>-0 [002] d.h. 1.234042: xhci_handle_event: EVENT: TRB 000000025c47c000 status 'Success' len 0 slot 1 ep 0 type 'Command Completion Event' flags e:C <idle>-0 [002] d.h. 1.234043: xhci_handle_command: CMD: Enable Slot Command: flags C kworker/3:0-35 [003] .... 1.234058: xhci_alloc_virt_device: vdev ffff9107a1ee4000 ctx 25c5cd000 | 25c5cc000 num 0 state 0 speed 0 port 0 level 0 slot 0 <idle>-0 [002] d.h. 1.239014: xhci_handle_event: EVENT: TRB 000000000e000000 status 'Success' len 0 slot 0 ep 0 type 'Port Status Change Event' flags e:C kworker/3:0-35 [003] .... 1.337988: xhci_setup_addressable_virt_device: vdev ffff9107a1ee4000 ctx 25c5cd000 | 25c5cc000 num 0 state 5 speed 5 port 3 level 1 slot 1 kworker/3:0-35 [003] .... 1.337990: xhci_address_ctx: ctx_64=0, ctx_type=2, ctx_dma=@25c5cd000, ctx_va=@ffff91079c5cd000 kworker/3:0-35 [003] d... 1.337990: xhci_setup_device: vdev ffff9107a1ee4000 ctx 25c5cd000 | 25c5cc000 num 0 state 5 speed 5 port 3 level 1 slot 1 kworker/3:0-35 [003] d... 1.337992: xhci_queue_trb: CMD: Address Device Command: ctx 000000025c5cd000 slot 1 flags b:C <idle>-0 [001] d.h. 6.633956: xhci_handle_event: EVENT: TRB 000000025c47c010 status 'Command Aborted' len 0 slot 1 ep 0 type 'Command Completion Event' flags e:C <idle>-0 [001] d.h. 6.633959: xhci_handle_command: CMD: Address Device Command: ctx 000000025c5cd000 slot 1 flags b:C <idle>-0 [001] d.h. 6.633964: xhci_handle_event: EVENT: TRB 000000025c47c020 status 'Command Ring Stopped' len 0 slot 1 ep 0 type 'Command Completion Event' flags e:C <idle>-0 [001] d.h. 6.633964: xhci_handle_command: CMD: type 'UNKNOWN' -> raw 00000000 00000000 00000000 00000000 kworker/3:2-163 [003] d... 6.634066: xhci_queue_trb: CMD: Enable Slot Command: flags C kworker/3:0-35 [003] .... 8.682073: xhci_address_ctx: ctx_64=0, ctx_type=2, ctx_dma=@25c5cd000, ctx_va=@ffff91079c5cd000 kworker/3:0-35 [003] d... 8.682075: xhci_setup_device: vdev ffff9107a1ee4000 ctx 25c5cd000 | 25c5cc000 num 0 state 5 speed 5 port 3 level 1 slot 1 kworker/3:0-35 [003] d... 8.682079: xhci_queue_trb: CMD: Address Device Command: ctx 000000025c5cd000 slot 1 flags b:C <idle>-0 [001] d.h. 13.801929: xhci_handle_event: EVENT: TRB 000000025c47c020 status 'Success' len 0 slot 2 ep 0 type 'Command Completion Event' flags e:C <idle>-0 [001] d.h. 13.801932: xhci_handle_command: CMD: Enable Slot Command: flags C <idle>-0 [001] dNh. 13.802010: xhci_handle_event: EVENT: TRB 000000025c47c030 status 'Success' len 0 slot 0 ep 0 type 'Command Completion Event' flags e:C <idle>-0 [001] dNh. 13.802010: xhci_handle_command: CMD: Enable Slot Command: flags C -- 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
