[Bug 208327] New: xhci_hcd issue transfer event - usb3.0

[Bug 208327] New: xhci_hcd issue transfer event - usb3.0

[bugzilla-daemon]

https://bugzilla.kernel.org/show_bug.cgi?id=208327

            Bug ID: 208327
           Summary: xhci_hcd issue transfer event - usb3.0
           Product: Drivers
           Version: 2.5
    Kernel Version: 4.14.170
          Hardware: x86-64
                OS: Linux
              Tree: Mainline
            Status: NEW
          Severity: high
          Priority: P1
         Component: USB
          Assignee: drivers_usb@kernel-bugs.kernel.org
          Reporter: ionut_n2001@yahoo.com
        Regression: No

Hi Kernel Team,

With compile vanilla kernel 4.14.170, observe this issue with
connect/disconnect usb device (mouse and keyboard).


usb xhci_hcd issue, USB3.0

[  146.924776] usb 1-2: USB disconnect, device number 2
[  146.926153] xhci_hcd 0000:00:14.0: ERROR Transfer event TRB DMA ptr not part
of current TD ep_index 1 comp_code 1
[  146.926163] xhci_hcd 0000:00:14.0: Looking for event-dma 00000000ffee2350
trb-start 00000000ffee2360 trb-end 00000000ffee2360 seg-start 00000000ffee2000
seg-end 00000000ffee2ff0
[  146.927151] xhci_hcd 0000:00:14.0: ERROR Transfer event TRB DMA ptr not part
of current TD ep_index 1 comp_code 1
[  146.927160] xhci_hcd 0000:00:14.0: Looking for event-dma 00000000ffee2360
trb-start 00000000ffee2370 trb-end 00000000ffee2370 seg-start 00000000ffee2000
seg-end 00000000ffee2ff0
[  146.928153] xhci_hcd 0000:00:14.0: ERROR Transfer event TRB DMA ptr not part
of current TD ep_index 1 comp_code 1
[  146.928163] xhci_hcd 0000:00:14.0: Looking for event-dma 00000000ffee2370
trb-start 00000000ffee2380 trb-end 00000000ffee2380 seg-start 00000000ffee2000
seg-end 00000000ffee2ff0
[  146.929150] xhci_hcd 0000:00:14.0: ERROR Transfer event TRB DMA ptr not part
of current TD ep_index 1 comp_code 1
[  146.929159] xhci_hcd 0000:00:14.0: Looking for event-dma 00000000ffee2380
trb-start 00000000ffee2390 trb-end 00000000ffee2390 seg-start 00000000ffee2000
seg-end 00000000ffee2ff0
[  146.930150] xhci_hcd 0000:00:14.0: ERROR Transfer event TRB DMA ptr not part
of current TD ep_index 1 comp_code 1
[  146.930158] xhci_hcd 0000:00:14.0: Looking for event-dma 00000000ffee2390
trb-start 00000000ffee23a0 trb-end 00000000ffee23a0 seg-start 00000000ffee2000
seg-end 00000000ffee2ff0

-- 
You are receiving this mail because:
You are watching the assignee of the bug.

[Bug 208327] xhci_hcd issue transfer event - usb3.0

[bugzilla-daemon]

https://bugzilla.kernel.org/show_bug.cgi?id=208327

Mathias Nyman (mathias.nyman@linux.intel.com) changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |mathias.nyman@linux.intel.c
                   |                            |om

--- Comment #1 from Mathias Nyman (mathias.nyman@linux.intel.com) ---
Can this issue be reproduced with 5.7 kernel or later?

If yes, then logs and traces with a more recent kernel would help:

mount -t debugfs none /sys/kernel/debug
echo 'module xhci_hcd =p' >/sys/kernel/debug/dynamic_debug/control
echo 'module usbcore =p' >/sys/kernel/debug/dynamic_debug/control
echo 81920 > /sys/kernel/debug/tracing/buffer_size_kb
echo 1 > /sys/kernel/debug/tracing/events/xhci-hcd/enable
< trigger the issue >
Send output of dmesg
Send content of /sys/kernel/debug/tracing/trace

-- 
You are receiving this mail because:
You are watching the assignee of the bug.

[Bug 208327] xhci_hcd issue transfer event - usb3.0

[bugzilla-daemon]

https://bugzilla.kernel.org/show_bug.cgi?id=208327

--- Comment #5 from Mathias Nyman (mathias.nyman@linux.intel.com) ---
Thanks

Logs show we get double (duplicate) events for some ISOC transfers.
Driver expects only one event per TRB and warns when we get a second event for
the same TRB

A wild guess is that this is somehow related to the soft retry of transaction
errors seen on another endpoint on the same device.
Driver tries to recover from the transaction error with a soft retry
three times. the duplicate events seen on the other endpoint occur close to the
soft retries, almost like this ISOC enpoint is being retried as well.

driver will ignore the duplicate events after warning about it, so there
shouldn't be any functional impact, but this isn't how it's supposed to
behave.

-- 
You are receiving this mail because:
You are watching the assignee of the bug.

[Bug 208327] xhci_hcd issue transfer event - usb3.0

[bugzilla-daemon]

https://bugzilla.kernel.org/show_bug.cgi?id=208327

--- Comment #6 from Mathias Nyman (mathias.nyman@linux.intel.com) ---
Could you please dump the event ring ringht after seeing the 
"Transfer event TRB DMA ptr not part of current TD.." message. 
Just to verify hardware actually writes duplicate events on the ring buffer.

This can be done by:
mount -t debugfs none /sys/kernel/debug
cat /sys/kernel/debug/usb/xhci/0000:00:14.0/event-ring/trbs

-- 
You are receiving this mail because:
You are watching the assignee of the bug.

[Bug 208327] xhci_hcd issue transfer event - usb3.0

[bugzilla-daemon]

https://bugzilla.kernel.org/show_bug.cgi?id=208327

--- Comment #7 from Mathias Nyman (mathias.nyman@linux.intel.com) ---
To check if this is related to the soft retry of the transaction errors
we could prevent soft retry with the following change:

diff --git a/drivers/usb/host/xhci-ring.c b/drivers/usb/host/xhci-ring.c
index 2c255d0620b0..964cacc1092e 100644
--- a/drivers/usb/host/xhci-ring.c
+++ b/drivers/usb/host/xhci-ring.c
@@ -2302,6 +2302,7 @@ static int process_bulk_intr_td(struct xhci_hcd *xhci,
struct xhci_td *td,
                remaining       = 0;
                break;
        case COMP_USB_TRANSACTION_ERROR:
+               break;
                if ((ep_ring->err_count++ > MAX_SOFT_RETRY) ||
                    le32_to_cpu(slot_ctx->tt_info) & TT_SLOT)
                        break;


Does that help?
After this chagen you should still see the Transactio errors, but not the
"Transfer event TRB DMA ptr not part of current TD.." message.

-- 
You are receiving this mail because:
You are watching the assignee of the bug.

[Bug 208327] xhci_hcd issue transfer event - usb3.0

[bugzilla-daemon]

https://bugzilla.kernel.org/show_bug.cgi?id=208327

--- Comment #10 from sander44 (ionut_n2001@yahoo.com) ---
I tried with this change:

diff --git a/drivers/usb/host/xhci-ring.c b/drivers/usb/host/xhci-ring.c
index 2c255d0620b0..964cacc1092e 100644
--- a/drivers/usb/host/xhci-ring.c
+++ b/drivers/usb/host/xhci-ring.c
@@ -2302,6 +2302,7 @@ static int process_bulk_intr_td(struct xhci_hcd *xhci,
struct xhci_td *td,
                remaining       = 0;
                break;
        case COMP_USB_TRANSACTION_ERROR:
+               break;
                if ((ep_ring->err_count++ > MAX_SOFT_RETRY) ||
                    le32_to_cpu(slot_ctx->tt_info) & TT_SLOT)
                        break;

And it doesn't help.
Error messages still appear.

[  245.472838] xhci_hcd 0000:00:14.0: ERROR Transfer event TRB DMA ptr not part
of current TD ep_index 1 comp_code 1
[  245.473676] xhci_hcd 0000:00:14.0: Looking for event-dma 000000035ae0cea0
trb-start 000000035ae0ceb0 trb-end 000000035ae0ceb0 seg-start 000000035ae0c000
seg-end 000000035ae0cff0
[  245.473828] xhci_hcd 0000:00:14.0: ERROR Transfer event TRB DMA ptr not part
of current TD ep_index 1 comp_code 1
[  245.474575] xhci_hcd 0000:00:14.0: Looking for event-dma 000000035ae0ceb0
trb-start 000000035ae0cec0 trb-end 000000035ae0cec0 seg-start 000000035ae0c000
seg-end 000000035ae0cff0
[  245.474829] xhci_hcd 0000:00:14.0: ERROR Transfer event TRB DMA ptr not part
of current TD ep_index 1 comp_code 1
[  245.475710] xhci_hcd 0000:00:14.0: Looking for event-dma 000000035ae0cec0
trb-start 000000035ae0ced0 trb-end 000000035ae0ced0 seg-start 000000035ae0c000
seg-end 000000035ae0cff0
[  245.475828] xhci_hcd 0000:00:14.0: ERROR Transfer event TRB DMA ptr not part
of current TD ep_index 1 comp_code 1
[  245.476706] xhci_hcd 0000:00:14.0: Looking for event-dma 000000035ae0ced0
trb-start 000000035ae0cee0 trb-end 000000035ae0cee0 seg-start 000000035ae0c000
seg-end 000000035ae0cff0

-- 
You are receiving this mail because:
You are watching the assignee of the bug.