On 01.04.2018 15:16, ljoublanc@xxxxxxxxx wrote:
Hi Again Mathias,
I did a system update yesterday (using gentoo, so I build everything
with distcc), and managed to get it to crash.
[48292.615897] xhci_hcd 0000:01:00.0: ERROR Transfer event TRB DMA ptr
not part of current TD ep_index 2 comp_code 13
[48292.615902] xhci_hcd 0000:01:00.0: Looking for event-dma
00000001d91f5050 trb-start 00000001d91f5030 trb-end 00000001d91f5030
seg-start 00000001d91f5000 seg-end 00000001d91f5ff0
I'm suspecting that this happens when I use a combination of USB
devices; this happened when I was browsing the web while compiling.
Also it happened _after_ I'd finished compiling all packages, while I
was running something over NFS - I don't believe the network
throughput was very high at that point.
The trace file compresses to about 30 Meg (800 compressed), so I will
send you a link directly.
Luciano
Thanks,
Logs show there is no transfer event for the URB queued at 5030.
We queue URBs on TRBs at 5020, 5030, 5040 etc, with the same flags for each.
Wnd get transfer event for all others except 5030. Normal events continue for
transfers after 5030 so ring seems to be running properly.
I wrote a quick patch that dumps event ring once this is hit. Can you apply
test with it?. Traces shouldn't be necessary, dmesg is enough.
Patch attached
From the event ring we can see if hardware failed to write the event, or driver
failed to read it/skipped it.
Relevant parts from your traces below :
Queue URB 1299c7900 at 5010
ksoftirqd/0-7 [000] ..s. 48292.835744: xhci_urb_enqueue: ep1in-bulk: urb ffff8801299c7900 pipe 3221258880 slot 1 length 0/16384 sgs 0/0 stream 0 flags 00010200
ksoftirqd/0-7 [000] d.s. 48292.835744: xhci_queue_trb: BULK: Buffer 0000000080960000 length 16384 TD size 0 intr 0 type 'Normal' flags b:i:I:c:s:I:e:C
ksoftirqd/0-7 [000] d.s. 48292.835744: xhci_inc_enq: BULK ffff88010dfdee80: enq 0x00000001d91f5020(0x00000001d91f5000) deq 0x000000011a343f70(0x000000011a343000) segs 2 stream 0 free_trbs 499 bounce 1024 cycle 0
Queue URB 1299c7f00 at 5020
<idle>-0 [002] .Ns. 48292.835954: xhci_urb_enqueue: ep1in-bulk: urb ffff8801299c7f00 pipe 3221258880 slot 1 length 0/16384 sgs 0/0 stream 0 flags 00010200
<idle>-0 [002] dNs. 48292.835954: xhci_queue_trb: BULK: Buffer 0000000080958000 length 16384 TD size 0 intr 0 type 'Normal' flags b:i:I:c:s:I:e:C
<idle>-0 [002] dNs. 48292.835954: xhci_inc_enq: BULK ffff88010dfdee80: enq 0x00000001d91f5030(0x00000001d91f5000) deq 0x000000011a343f80(0x000000011a343000) segs 2 stream 0 free_trbs 499 bounce 1024 cycle 0
Queue URB 1299c7c00 at 5030
<idle>-0 [002] .Ns. 48292.836162: xhci_urb_enqueue: ep1in-bulk: urb ffff8801299c7c00 pipe 3221258880 slot 1 length 0/16384 sgs 0/0 stream 0 flags 00010200
<idle>-0 [002] dNs. 48292.836163: xhci_queue_trb: BULK: Buffer 0000000080934000 length 16384 TD size 0 intr 0 type 'Normal' flags b:i:I:c:s:I:e:C
<idle>-0 [002] dNs. 48292.836163: xhci_inc_enq: BULK ffff88010dfdee80: enq 0x00000001d91f5040(0x00000001d91f5000) deq 0x000000011a343f90(0x000000011a343000) segs 2 stream 0 free_trbs 499 bounce 1024 cycle 0
Queue URB 139dcccc0 at 5040
<idle>-0 [002] .Ns. 48292.836381: xhci_urb_enqueue: ep1in-bulk: urb ffff880139dcccc0 pipe 3221258880 slot 1 length 0/16384 sgs 0/0 stream 0 flags 00010200
<idle>-0 [002] dNs. 48292.836382: xhci_queue_trb: BULK: Buffer 0000000080900000 length 16384 TD size 0 intr 0 type 'Normal' flags b:i:I:c:s:I:e:C
<idle>-0 [002] dNs. 48292.836382: xhci_inc_enq: BULK ffff88010dfdee80: enq 0x00000001d91f5050(0x00000001d91f5000) deq 0x000000011a343fa0(0x000000011a343000) segs 2 stream 0 free_trbs 499 bounce 1024 cycle 0
Queue URB 139dccb40 at 5050
<idle>-0 [002] .Ns. 48292.836620: xhci_urb_enqueue: ep1in-bulk: urb ffff880139dccb40 pipe 3221258880 slot 1 length 0/16384 sgs 0/0 stream 0 flags 00010200
<idle>-0 [002] dNs. 48292.836620: xhci_queue_trb: BULK: Buffer 00000000808d0000 length 16384 TD size 0 intr 0 type 'Normal' flags b:i:I:c:s:I:e:C
<idle>-0 [002] dNs. 48292.836621: xhci_inc_enq: BULK ffff88010dfdee80: enq 0x00000001d91f5060(0x00000001d91f5000) deq 0x000000011a343fb0(0x000000011a343000) segs 2 stream 0 free_trbs 499 bounce 1024 cycle 0
<..queueing more URBs/TRBs >
Event for 5020 (short packet), give back URB 1299c7f00
<idle>-0 [002] d.h. 48292.838156: xhci_handle_event: EVENT: TRB 00000001d91f5020 status 'Short Packet' len 13496 slot 1 ep 3 type 'Transfer Event' flags e:c
<idle>-0 [002] d.h. 48292.838157: xhci_handle_transfer: BULK: Buffer 0000000080958000 length 16384 TD size 0 intr 0 type 'Normal' flags b:i:I:c:s:I:e:c
<idle>-0 [002] d.h. 48292.838157: xhci_inc_deq: BULK ffff88010dfdee80: enq 0x00000001d91f50c0(0x00000001d91f5000) deq 0x00000001d91f5030(0x00000001d91f5000) segs 2 stream 0 free_trbs 500 bounce 1024 cycle 0
<idle>-0 [002] d.h. 48292.838157: xhci_urb_giveback: ep1in-bulk: urb ffff8801299c7f00 pipe 3221258880 slot 1 length 2888/16384 sgs 0/0 stream 0 flags 00010200
Event for 5040 (short packet) Event for 5030 missing!!
<idle>-0 [002] d.h. 48292.838579: xhci_handle_event: EVENT: TRB 00000001d91f5040 status 'Short Packet' len 14120 slot 1 ep 3 type 'Transfer Event' flags e:c
-Mathias
>From a988fa837b4cd7af083774b715ffc647a6dabc02 Mon Sep 17 00:00:00 2001
From: Mathias Nyman <mathias.nyman@xxxxxxxxxxxxxxx>
Date: Tue, 10 Apr 2018 14:47:28 +0300
Subject: [PATCH] xhci: dump event ring, testpatch for Luciano
dump event ring if we get a event we don't expect
Signed-off-by: Mathias Nyman <mathias.nyman@xxxxxxxxxxxxxxx>
---
drivers/usb/host/xhci-ring.c | 20 ++++++++++++++++++++
1 file changed, 20 insertions(+)
diff --git a/drivers/usb/host/xhci-ring.c b/drivers/usb/host/xhci-ring.c
index daa94c3..4afe791 100644
--- a/drivers/usb/host/xhci-ring.c
+++ b/drivers/usb/host/xhci-ring.c
@@ -2263,6 +2263,21 @@ static int process_bulk_intr_td(struct xhci_hcd *xhci, struct xhci_td *td,
return finish_td(xhci, td, ep_trb, event, ep, status);
}
+static void xhci_dump_ev_ring(struct xhci_hcd *xhci)
+{
+ int i;
+ struct xhci_segment *seg = xhci->event_ring->first_seg;
+
+ for (i = 0; i < TRBS_PER_SEGMENT; i++) {
+ xhci_warn(xhci, "%llx: %s\n", seg->dma + (i * sizeof(union xhci_trb)),
+ xhci_decode_trb(seg->trbs[i].generic.field[0],
+ seg->trbs[i].generic.field[1],
+ seg->trbs[i].generic.field[2],
+ seg->trbs[i].generic.field[3]));
+ }
+ xhci_warn(xhci, "dequeue: %llx\n", xhci_trb_virt_to_dma(seg, xhci->event_ring->dequeue));
+}
+
/*
* If this function returns an error condition, it means it got a Transfer
* event with a corrupted Slot ID, Endpoint ID, or TRB DMA address.
@@ -2286,6 +2301,7 @@ static int handle_tx_event(struct xhci_hcd *xhci,
u32 trb_comp_code;
int td_num = 0;
bool handling_skipped_tds = false;
+ static bool dumped;
slot_id = TRB_TO_SLOT_ID(le32_to_cpu(event->flags));
ep_index = TRB_TO_EP_ID(le32_to_cpu(event->flags)) - 1;
@@ -2546,6 +2562,10 @@ static int handle_tx_event(struct xhci_hcd *xhci,
trb_in_td(xhci, ep_ring->deq_seg,
ep_ring->dequeue, td->last_trb,
ep_trb_dma, true);
+ if (!dumped) {
+ xhci_dump_ev_ring(xhci);
+ dumped = true;
+ }
return -ESHUTDOWN;
}
--
2.7.4
