Hi
On 23.02.2018 04:55, Cyril Roelandt wrote:
Hello,
On 02/21/18 17:04, Mathias Nyman wrote:
could you change one flag in the xhci driver and take the same
set of logs? It will add more details about the URB and xHC hw position check.
diff --git a/drivers/usb/host/xhci-ring.c b/drivers/usb/host/xhci-ring.c
index cc368ad..f1b73e6 100644
--- a/drivers/usb/host/xhci-ring.c
+++ b/drivers/usb/host/xhci-ring.c
@@ -772,7 +772,7 @@ static void xhci_handle_cmd_stop_ep(struct xhci_hcd *xhci, int slot_id,
hw_deq &= ~0xf;
if (trb_in_td(xhci, cur_td->start_seg, cur_td->first_trb,
- cur_td->last_trb, hw_deq, false)) {
+ cur_td->last_trb, hw_deq, true)) {
xhci_find_new_dequeue_state(xhci, slot_id, ep_index,
cur_td->urb->stream_id,
cur_td, &deq_state);
OK, so I tried this patch on top of 4.13. I'll post the logs at the end of this
message.
Another thing not related to xhci is that the serial number seems to be changing
for this device after reset.
This causes the "usb 4-2: device firmware changed" messages, and usb core will
try to logically disconnect the device.
Can you also plug in and out the device a few times without changing the
drives in the enclosure, and check if the serial number really is changing.
This behaviour can be seen on a machine running 4.11 (a version of the kernel
with which the enclosure works well):
# dmesg -T | grep "SerialNumber:"
[Fri Feb 23 02:43:20 2018] usb 2-2: SerialNumber: RANDOM__7758C4668BE7
[Fri Feb 23 02:43:38 2018] usb 2-2: SerialNumber: RANDOM__D6BA993A16EF
[Fri Feb 23 02:43:57 2018] usb 2-2: SerialNumber: RANDOM__DA02D6BA993A
[Fri Feb 23 02:55:45 2018] usb 2-2: SerialNumber: RANDOM__BB3BB6A08401
Thanks for your help, I'm leaving the (huge) logs below.
Cyril Roelandt.
Thanks for the logs, They clearly show that there is a issue in getting the
position where the second stream stopped.
When reading the stopped position for URB2 on stream 2 we get stream1 position,
in fact stream 2 never starts again after this, and when re-reading the stopped
position of stream 2 it keeps giving stream 1 position.
One possible cause is that a xhci command accidentally writes a "0" to "Max Primary Streams"
while configuring some other endpoint value, this would limit streams to 1.
Current tracing has a bug in displaying "Max Primaty streams" and always showed zero.
I have a series of even more custom debugging patches.
attached patches apply on 4.13, but seris for both 4.13 and 4.15 can be found in the
streams-debug-4.13 and streams-debug-4.15 branches at
git://git.kernel.org/pub/scm/linux/kernel/git/mnyman/xhci.git
https://git.kernel.org/pub/scm/linux/kernel/git/mnyman/xhci.git
Can I ask you to do take logs with these?
no need for the previous diff, it's included
Thanks
Mathias
>From 1b6dc2f3d4a2d6a4b110858da27b69ae1182bc05 Mon Sep 17 00:00:00 2001
From: Mathias Nyman <mathias.nyman@xxxxxxxxxxxxxxx>
Date: Tue, 27 Feb 2018 16:01:48 +0200
Subject: [PATCH 1/3] xhci: fix endpoint context tracer output
Fix incorrent values showed for max Primary stream and
Linear stream array (LSA) values in the endpoint context
decoder.
Fixes: 19a7d0d65c4a ("usb: host: xhci: add Slot and EP Context tracers")
Cc: <stable@xxxxxxxxxxxxxxx> # v4.12+
Signed-off-by: Mathias Nyman <mathias.nyman@xxxxxxxxxxxxxxx>
---
drivers/usb/host/xhci.h | 22 ++++++++++++----------
1 file changed, 12 insertions(+), 10 deletions(-)
diff --git a/drivers/usb/host/xhci.h b/drivers/usb/host/xhci.h
index e3e9352..77b3fa1 100644
--- a/drivers/usb/host/xhci.h
+++ b/drivers/usb/host/xhci.h
@@ -721,11 +721,12 @@ struct xhci_ep_ctx {
/* bits 10:14 are Max Primary Streams */
/* bit 15 is Linear Stream Array */
/* Interval - period between requests to an endpoint - 125u increments. */
-#define EP_INTERVAL(p) (((p) & 0xff) << 16)
-#define EP_INTERVAL_TO_UFRAMES(p) (1 << (((p) >> 16) & 0xff))
-#define CTX_TO_EP_INTERVAL(p) (((p) >> 16) & 0xff)
-#define EP_MAXPSTREAMS_MASK (0x1f << 10)
-#define EP_MAXPSTREAMS(p) (((p) << 10) & EP_MAXPSTREAMS_MASK)
+#define EP_INTERVAL(p) (((p) & 0xff) << 16)
+#define EP_INTERVAL_TO_UFRAMES(p) (1 << (((p) >> 16) & 0xff))
+#define CTX_TO_EP_INTERVAL(p) (((p) >> 16) & 0xff)
+#define EP_MAXPSTREAMS_MASK (0x1f << 10)
+#define EP_MAXPSTREAMS(p) (((p) << 10) & EP_MAXPSTREAMS_MASK)
+#define CTX_TO_EP_MAXPSTREAMS(p) (((p) & EP_MAXPSTREAMS_MASK) >> 10)
/* Endpoint is set up with a Linear Stream Array (vs. Secondary Stream Array) */
#define EP_HAS_LSA (1 << 15)
@@ -2449,21 +2450,22 @@ static inline const char *xhci_decode_ep_context(u32 info, u32 info2, u64 deq,
u8 burst;
u8 cerr;
u8 mult;
- u8 lsa;
- u8 hid;
+
+ bool lsa;
+ bool hid;
esit = EP_MAX_ESIT_PAYLOAD_HI(info) << 16 |
EP_MAX_ESIT_PAYLOAD_LO(tx_info);
ep_state = info & EP_STATE_MASK;
- max_pstr = info & EP_MAXPSTREAMS_MASK;
+ max_pstr = CTX_TO_EP_MAXPSTREAMS(info);
interval = CTX_TO_EP_INTERVAL(info);
mult = CTX_TO_EP_MULT(info) + 1;
- lsa = info & EP_HAS_LSA;
+ lsa = !!(info & EP_HAS_LSA);
cerr = (info2 & (3 << 1)) >> 1;
ep_type = CTX_TO_EP_TYPE(info2);
- hid = info2 & (1 << 7);
+ hid = !!(info2 & (1 << 7));
burst = CTX_TO_MAX_BURST(info2);
maxp = MAX_PACKET_DECODED(info2);
--
2.7.4
>From a0703ede3c76b76fa4db55e51fb1ae5dbcc2a280 Mon Sep 17 00:00:00 2001
From: Mathias Nyman <mathias.nyman@xxxxxxxxxxxxxxx>
Date: Wed, 28 Feb 2018 10:07:48 +0200
Subject: [PATCH 2/3] xhci: add control context tracer
Signed-off-by: Mathias Nyman <mathias.nyman@xxxxxxxxxxxxxxx>
---
drivers/usb/host/xhci-ring.c | 16 ++++++++++++++++
drivers/usb/host/xhci-trace.h | 21 +++++++++++++++++++++
drivers/usb/host/xhci.c | 1 +
drivers/usb/host/xhci.h | 18 ++++++++++++++++++
4 files changed, 56 insertions(+)
diff --git a/drivers/usb/host/xhci-ring.c b/drivers/usb/host/xhci-ring.c
index cc368ad..f8a09b1 100644
--- a/drivers/usb/host/xhci-ring.c
+++ b/drivers/usb/host/xhci-ring.c
@@ -1367,6 +1367,20 @@ void xhci_handle_command_timeout(struct work_struct *work)
return;
}
+static void xhci_trace_dump_ep_ctx(struct xhci_hcd *xhci, int slot_id)
+{
+ struct xhci_virt_device *vdev;
+ struct xhci_ep_ctx *ep_ctx;
+ int i;
+
+ vdev = xhci->devs[slot_id];
+
+ for(i = 0; i < 32; i++) {
+ ep_ctx = xhci_get_ep_ctx(xhci, vdev->out_ctx, i);
+ trace_xhci_handle_cmd_config_ep(ep_ctx);
+ }
+}
+
static void handle_cmd_completion(struct xhci_hcd *xhci,
struct xhci_event_cmd *event)
{
@@ -1437,11 +1451,13 @@ static void handle_cmd_completion(struct xhci_hcd *xhci,
xhci_handle_cmd_disable_slot(xhci, slot_id);
break;
case TRB_CONFIG_EP:
+ xhci_trace_dump_ep_ctx(xhci, slot_id);
if (!cmd->completion)
xhci_handle_cmd_config_ep(xhci, slot_id, event,
cmd_comp_code);
break;
case TRB_EVAL_CONTEXT:
+ xhci_trace_dump_ep_ctx(xhci, slot_id);
break;
case TRB_ADDR_DEV:
xhci_handle_cmd_addr_dev(xhci, slot_id);
diff --git a/drivers/usb/host/xhci-trace.h b/drivers/usb/host/xhci-trace.h
index 8ce96de..262140e 100644
--- a/drivers/usb/host/xhci-trace.h
+++ b/drivers/usb/host/xhci-trace.h
@@ -388,6 +388,27 @@ DEFINE_EVENT(xhci_log_slot_ctx, xhci_handle_cmd_set_deq,
TP_ARGS(ctx)
);
+DECLARE_EVENT_CLASS(xhci_log_ctrl_ctx,
+ TP_PROTO(struct xhci_input_control_ctx *ctrl_ctx),
+ TP_ARGS(ctrl_ctx),
+ TP_STRUCT__entry(
+ __field(u32, drop)
+ __field(u32, add)
+ ),
+ TP_fast_assign(
+ __entry->drop = le32_to_cpu(ctrl_ctx->drop_flags);
+ __entry->add = le32_to_cpu(ctrl_ctx->add_flags);
+ ),
+ TP_printk("%s", xhci_decode_in_ctrl_context(__entry->drop,
+ __entry->add)
+ )
+);
+
+DEFINE_EVENT(xhci_log_ctrl_ctx, xhci_configure_endpoint_ctrl_ctx,
+ TP_PROTO(struct xhci_input_control_ctx *ctrl_ctx),
+ TP_ARGS(ctrl_ctx)
+);
+
DECLARE_EVENT_CLASS(xhci_log_ring,
TP_PROTO(struct xhci_ring *ring),
TP_ARGS(ring),
diff --git a/drivers/usb/host/xhci.c b/drivers/usb/host/xhci.c
index b2ff1ff..7e889a7 100644
--- a/drivers/usb/host/xhci.c
+++ b/drivers/usb/host/xhci.c
@@ -2591,6 +2591,7 @@ static int xhci_configure_endpoint(struct xhci_hcd *xhci,
xhci_warn(xhci, "Not enough bandwidth\n");
return -ENOMEM;
}
+ trace_xhci_configure_endpoint_ctrl_ctx(ctrl_ctx);
if (!ctx_change)
ret = xhci_queue_configure_endpoint(xhci, command,
diff --git a/drivers/usb/host/xhci.h b/drivers/usb/host/xhci.h
index 77b3fa1..bf920d0 100644
--- a/drivers/usb/host/xhci.h
+++ b/drivers/usb/host/xhci.h
@@ -2393,6 +2393,24 @@ static inline const char *xhci_decode_slot_context(u32 info, u32 info2,
return str;
}
+static inline const char *xhci_decode_in_ctrl_context(unsigned long drop,
+ unsigned long add)
+{
+ static char str[1024];
+ int bitnr;
+ int ret = 0;
+
+ ret = sprintf(str, "Drop context flags:");
+ for_each_set_bit(bitnr, &drop, 32) {
+ ret += sprintf(str + ret, " D%d", bitnr);
+ }
+ ret += sprintf(str + ret, " Add context flags:");
+ for_each_set_bit(bitnr, &add, 32) {
+ ret += sprintf(str + ret, " A%d", bitnr);
+ }
+ return str;
+}
+
static inline const char *xhci_ep_state_string(u8 state)
{
switch (state) {
--
2.7.4
>From b6dcdf0302e839555e8e1c884c919a3c9d775b92 Mon Sep 17 00:00:00 2001
From: Mathias Nyman <mathias.nyman@xxxxxxxxxxxxxxx>
Date: Mon, 26 Feb 2018 11:07:15 +0200
Subject: [PATCH 3/3] xhci: TEMP DEBUG, add more custom streams debugging
For testing missing stream on uas
---
drivers/usb/host/xhci-ring.c | 15 +++++++++++++--
drivers/usb/host/xhci-trace.h | 5 +++++
2 files changed, 18 insertions(+), 2 deletions(-)
diff --git a/drivers/usb/host/xhci-ring.c b/drivers/usb/host/xhci-ring.c
index f8a09b1..8fb25a8 100644
--- a/drivers/usb/host/xhci-ring.c
+++ b/drivers/usb/host/xhci-ring.c
@@ -498,9 +498,20 @@ static u64 xhci_get_hw_deq(struct xhci_hcd *xhci, struct xhci_virt_device *vdev,
if (ep->ep_state & EP_HAS_STREAMS) {
st_ctx = &ep->stream_info->stream_ctx_array[stream_id];
- return le64_to_cpu(st_ctx->stream_ring);
+ xhci_dbg_trace(xhci, trace_xhci_get_hw_deq,
+ "ep_index %d stream_id %d deq %016llx\n",
+ ep_index,
+ stream_id,
+ le64_to_cpu(st_ctx->stream_ring));
+
+ return le64_to_cpu(st_ctx->stream_ring);
}
ep_ctx = xhci_get_ep_ctx(xhci, vdev->out_ctx, ep_index);
+ xhci_dbg_trace(xhci, trace_xhci_get_hw_deq,
+ "ep_index %d No stream, deq %016llx\n",
+ ep_index,
+ le64_to_cpu(ep_ctx->deq));
+
return le64_to_cpu(ep_ctx->deq);
}
@@ -772,7 +783,7 @@ static void xhci_handle_cmd_stop_ep(struct xhci_hcd *xhci, int slot_id,
hw_deq &= ~0xf;
if (trb_in_td(xhci, cur_td->start_seg, cur_td->first_trb,
- cur_td->last_trb, hw_deq, false)) {
+ cur_td->last_trb, hw_deq, true)) {
xhci_find_new_dequeue_state(xhci, slot_id, ep_index,
cur_td->urb->stream_id,
cur_td, &deq_state);
diff --git a/drivers/usb/host/xhci-trace.h b/drivers/usb/host/xhci-trace.h
index 262140e..c3c5801 100644
--- a/drivers/usb/host/xhci-trace.h
+++ b/drivers/usb/host/xhci-trace.h
@@ -39,6 +39,11 @@ DECLARE_EVENT_CLASS(xhci_log_msg,
TP_printk("%s", __get_str(msg))
);
+DEFINE_EVENT(xhci_log_msg, xhci_get_hw_deq,
+ TP_PROTO(struct va_format *vaf),
+ TP_ARGS(vaf)
+);
+
DEFINE_EVENT(xhci_log_msg, xhci_dbg_address,
TP_PROTO(struct va_format *vaf),
TP_ARGS(vaf)
--
2.7.4
