On Tue, 2017-05-09 at 11:34 +0300, Felipe Balbi wrote:
> Hi,
>
> Maël Lavault <[email protected]> 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 [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html
