usb HC busted?

[Mathias Nyman <mathias.nyman@linux.intel.com>]

Hi

On 24.05.2018 00:29, Sudip Mukherjee wrote:
> Hi Mathias,
> 
> On Fri, May 18, 2018 at 04:19:02PM +0300, Mathias Nyman wrote:
>> On 18.05.2018 16:04, Sudip Mukherjee wrote:
>>> Hi Mathias,
>>>
>>> On Fri, May 18, 2018 at 03:55:04PM +0300, Mathias Nyman wrote:
>>>> Hi,
>>>>
>>>> Looks like event for Transfer block (TRB) at 0x32a21060 was never completed,
>>>> or at least not handled by xhci driver.
>>>> (either the event was never issued by hw, or something got messed up in the driver along the way)
>>>>
>>>> HC doesn't look busted, it continues sending transfer completions events.
>>>> it is already at event 0x32a211d0, which is 23 TRBS later. (one TRB is 0x10)
>>>>
>>>> This small log sinppet doesnt' say much about the reasons.
>>>>
>>>> Can you enable tracing for xhci and send me the output.
>>>
> We have finally reproduced the error while traces were on. The trace and
> the relevant part of the dmesg (when the error starts) are in:
> https://drive.google.com/open?id=1PbcYwL1a9ndtHw1MNjE6uVqb0fFX9jV8
> 
> Will request you to have a look and suggest what might be going wrong here.
> 

Log show two rings having the same TRB segment dma address, this will completely mess up the transfer:

While allocating rigs the enque pointers for the two rings are the same:

461.859315: xhci_ring_alloc: ISOC efa4e580: enq 0x0000000033386000(0x0000000033386000) deq 0x0000000033386000(0x0000000033386000) segs 2 stream 0 ...bs
461.859320: xhci_ring_alloc: ISOC f0ce1f00: enq 0x0000000033386000(0x0000000033386000) deq 0x0000000033386000(0x0000000033386000) segs 2 stream 0 ...

URBs for ISOC IN transfers are queued on EP3 at enqueue address (33386000 to 33386140)

461.859998: xhci_urb_enqueue: ep3in-isoc: urb f0ec0e00 pipe 4294528 slot 8 length 0/170 sgs 0/0 stream 0 flags 00010302
461.860004: xhci_queue_trb: ISOC: Buffer 000000002b480240 length 17 TD size 0 intr 0 type 'Isoch' flags b:i:I:c:s:I:e:c
461.860006: xhci_inc_enq: ISOC f0ce1f00: enq 0x0000000033386010(0x0000000033386000) deq 0x0000000033386000(0x0000000033386000

Later URBs for ISOC OUT transfers are queued at the same address, this should not happen:

461.901175: xhci_urb_enqueue: ep3out-isoc: urb ecec2600 pipe 100096 slot 8 length 0/51 sgs 0/0 stream 0 flags 00010002
461.901180: xhci_queue_trb: ISOC: Buffer 000000002d9fa805 length 17 TD size 0 intr 0 type 'Isoch' flags b:i:I:c:s:i:e:c
461.901181: xhci_inc_enq: ISOC efa4e580: enq 0x0000000033386010(0x0000000033386000) deq 0x0000000033386000(0x0000000033386000)

So something goes really wrong when allocating or setting up the rings in one of these functions:
xhci_ring_alloc()
xhci_alloc_segments_for_ring()
xhci_initialize_ring_info()
xhci_segment_alloc()
xhci_link_segments()
dma_pool_zalloc()

To verify and rule out dma_pool_zalloc(), could you apply the attached patch and reproduce with new logs?

Thanks
-Mathias

From 7aee4db28204fddff6cbc1534b8d50f13fd0b141 Mon Sep 17 00:00:00 2001
From: Mathias Nyman <mathias.nyman@linux.intel.com>
Date: Thu, 24 May 2018 15:37:41 +0300
Subject: [PATCH] xhci: testpatch, add custom trace for ring segment alloc

for custom debugging only
---
 drivers/usb/host/xhci-mem.c   | 10 ++++++++++
 drivers/usb/host/xhci-trace.h |  5 +++++
 2 files changed, 15 insertions(+)

diff --git a/drivers/usb/host/xhci-mem.c b/drivers/usb/host/xhci-mem.c
index e5ace89..7d343ad 100644
--- a/drivers/usb/host/xhci-mem.c
+++ b/drivers/usb/host/xhci-mem.c
@@ -44,10 +44,15 @@ static struct xhci_segment *xhci_segment_alloc(struct xhci_hcd *xhci,
 		return NULL;
 	}
 
+	xhci_dbg_trace(xhci,  trace_xhci_ring_mem_detail,
+		       "MATTU xhci_segment_alloc dma @ %pad", &dma);
+
 	if (max_packet) {
 		seg->bounce_buf = kzalloc(max_packet, flags);
 		if (!seg->bounce_buf) {
 			dma_pool_free(xhci->segment_pool, seg->trbs, dma);
+			xhci_dbg_trace(xhci,  trace_xhci_ring_mem_detail,
+				       "MATTU xhci segment free dma @ %pad", &dma);
 			kfree(seg);
 			return NULL;
 		}
@@ -58,6 +63,9 @@ static struct xhci_segment *xhci_segment_alloc(struct xhci_hcd *xhci,
 			seg->trbs[i].link.control |= cpu_to_le32(TRB_CYCLE);
 	}
 	seg->dma = dma;
+	xhci_dbg_trace(xhci,  trace_xhci_ring_mem_detail,
+		       "MATTU xhci segment alloc seg->dma @ %pad", &seg->dma);
+
 	seg->next = NULL;
 
 	return seg;
@@ -67,6 +75,8 @@ static void xhci_segment_free(struct xhci_hcd *xhci, struct xhci_segment *seg)
 {
 	if (seg->trbs) {
 		dma_pool_free(xhci->segment_pool, seg->trbs, seg->dma);
+		xhci_dbg_trace(xhci,  trace_xhci_ring_mem_detail,
+			       "MATTU xhci segment free seg->dma @ %p", &seg->dma);
 		seg->trbs = NULL;
 	}
 	kfree(seg->bounce_buf);
diff --git a/drivers/usb/host/xhci-trace.h b/drivers/usb/host/xhci-trace.h
index 35bdd06..951e371 100644
--- a/drivers/usb/host/xhci-trace.h
+++ b/drivers/usb/host/xhci-trace.h
@@ -72,6 +72,11 @@ DEFINE_EVENT(xhci_log_msg, xhci_dbg_ring_expansion,
 	TP_ARGS(vaf)
 );
 
+DEFINE_EVENT(xhci_log_msg, xhci_ring_mem_detail,
+	TP_PROTO(struct va_format *vaf),
+	TP_ARGS(vaf)
+);
+
 DECLARE_EVENT_CLASS(xhci_log_ctx,
 	TP_PROTO(struct xhci_hcd *xhci, struct xhci_container_ctx *ctx,
 		 unsigned int ep_num),
-- 
2.7.4