On 13.10.2017 14:46, Yaroslav Isakov wrote:
Hello, Mathias! Did you get a chance to look into this bug?
Other things came up and this got a bit delayed.
Attached is a patch to test
-Mathias
2017-07-20 19:15 GMT+03:00 Yaroslav Isakov <yaroslav.isakov@xxxxxxxxx>:
Yes, I can definitely test the patch
2017-07-20 19:16 GMT+03:00 Mathias Nyman <mathias.nyman@xxxxxxxxxxxxxxx>:
On 20.07.2017 18:07, Yaroslav Isakov wrote:
Here it is
2017-07-20 18:06 GMT+03:00 Mathias Nyman <mathias.nyman@xxxxxxxxxxxxxxx>:
On 20.07.2017 17:43, Yaroslav Isakov wrote:
Hello everyone! I saw this thread some months ago, but do not know how
to properly reply to it. I have the same problem, and it's just not
few messages - it was about 40k messages in 10 minutes. No functional
of my USB device (which is CCID USB token) is broken, just enormous
amount of spam in the logs. I'm on 4.12 kernel, but I've seen this
error on 4.11 and 4.9. Could this problem be caused by a bug in e.g.
libusb, not a device itself?
--
I'd start by looking at xhci, can you take xhci traces of this?
mount -t debugfs none /sys/kernel/debug
echo 81920 > /sys/kernel/debug/tracing/buffer_size_kb
echo 1 > /sys/kernel/debug/tracing/events/xhci-hcd/enable
and then send me the content of
/sys/kernel/debug/tracing/trace
I'll be away for a couple of weeks, so next response might take some time
-Mathias
Think I found something. (details mostly for myself in to remember this)
A short transfer response on a bulk in transfer which is not the last TRB of
a TD
According to specs xhci will issue short transfer events both on the short
TRB, _and_
on the last TRB of the TD in case any previous TRB in the TD was short
(see xhci 4.11.3.1)
After the first short transfer event the driver fast forward past this TD.
(and the last TRB)
when we get the second short transfer event there are no TRBs queued and you
see the
warning.
Warning should be harmless in this case, but annoying.
If I write a patch can you try it out?
As a reference, a snippet when log when a 65556 byte transfer is queued,
split into 5 pieces (TRBS),
and we get short transfer events for first and last TRB
* A URB asking for 65556 bytes is queues:
2369.450362: xhci_urb_enqueue: ep1in-bulk: urb ffff8801398f6540 pipe
3221258880 slot 1 length 0/65556 sgs 5/5 stream 0 flags 00040200
* split into 5 pieces ( TRBs at 0x00000002169cb520, ..530, ..540, ..550 and
..560)
2369.450363: xhci_queue_trb: BULK: Buffer 000000010a7dc000 length 16384 TD
size 31 intr 0 type 'Normal' flags b:i:i:C:s:I:e:C
2369.450363: xhci_inc_enq: BULK ffff88021726c780: enq
0x00000002169cb530(0x00000002169cb000) deq
0x00000002169cb520(0x00000002169cb000) segs 2 stream 0 free_trbs 508 bounce
6\
2369.450363: xhci_queue_trb: BULK: Buffer 000000011e970000 length 16384 TD
size 31 intr 0 type 'Normal' flags b:i:i:C:s:I:e:c
2369.450363: xhci_inc_enq: BULK ffff88021726c780: enq
0x00000002169cb540(0x00000002169cb000) deq
0x00000002169cb520(0x00000002169cb000) segs 2 stream 0 free_trbs 507 bounce
6\
2369.450363: xhci_queue_trb: BULK: Buffer 00000001b63ac000 length 16384 TD
size 31 intr 0 type 'Normal' flags b:i:i:C:s:I:e:c
2369.450363: xhci_inc_enq: BULK ffff88021726c780: enq
0x00000002169cb550(0x00000002169cb000) deq
0x00000002169cb520(0x00000002169cb000) segs 2 stream 0 free_trbs 506 bounce
6\
2369.450364: xhci_queue_trb: BULK: Buffer 000000010a7ac000 length 16384 TD
size 1 intr 0 type 'Normal' flags b:i:i:C:s:I:e:c
2369.450364: xhci_inc_enq: BULK ffff88021726c780: enq
0x00000002169cb560(0x00000002169cb000) deq
0x00000002169cb520(0x00000002169cb000) segs 2 stream 0 free_trbs 505 bounce
6\
2369.450364: xhci_queue_trb: BULK: Buffer 00000001a26adf40 length 20 TD size
0 intr 0 type 'Normal' flags b:i:I:c:s:I:e:c
2369.450364: xhci_inc_enq: BULK ffff88021726c780: enq
0x00000002169cb570(0x00000002169cb000) deq
0x00000002169cb520(0x00000002169cb000) segs 2 stream 0 free_trbs 504 bounce
6\
* short packet event for first TRB at ..520
2369.450505: xhci_handle_event: EVENT: TRB 00000002169cb520 status 'Short
Packet' len 16334 slot 1 ep 3 type 'Transfer Event' flags e:c
2369.450506: xhci_handle_transfer: BULK: Buffer 000000010a7dc000 length
16384 TD size 31 intr 0 type 'Normal' flags b:i:i:C:s:I:e:c
* fast forward past this TD, move dequeue to ..570)
2369.450506: xhci_inc_deq: BULK ffff88021726c780: enq
0x00000002169cb570(0x00000002169cb000) deq
0x00000002169cb530(0x00000002169cb000) segs 2 stream 0 free_trbs 505 bounce
6\
2369.450506: xhci_inc_deq: BULK ffff88021726c780: enq
0x00000002169cb570(0x00000002169cb000) deq
0x00000002169cb540(0x00000002169cb000) segs 2 stream 0 free_trbs 506 bounce
6\
2369.450506: xhci_inc_deq: BULK ffff88021726c780: enq
0x00000002169cb570(0x00000002169cb000) deq
0x00000002169cb550(0x00000002169cb000) segs 2 stream 0 free_trbs 507 bounce
6\
2369.450506: xhci_inc_deq: BULK ffff88021726c780: enq
0x00000002169cb570(0x00000002169cb000) deq
0x00000002169cb560(0x00000002169cb000) segs 2 stream 0 free_trbs 508 bounce
6\
2369.450506: xhci_inc_deq: BULK ffff88021726c780: enq
0x00000002169cb570(0x00000002169cb000) deq
0x00000002169cb570(0x00000002169cb000) segs 2 stream 0 free_trbs 509 bounce
6\
2369.450506: xhci_urb_giveback: ep1in-bulk: urb ffff8801398f6540 pipe
3221258880 slot 1 length 50/65556 sgs 5/5 stream 0 flags 00040200
* short transfer event for last TRB in TD at ..560
2369.450507: xhci_handle_event: EVENT: TRB 00000002169cb560 status 'Short
Packet' len 20 slot 1 ep 3 type 'Transfer Event' flags e:c
we are already past 560, we are at 570 with a empty ring, not expecting
events for this ring
-Mathias
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
>From 8caafc429a111550c379b8cb217918335d54fb42 Mon Sep 17 00:00:00 2001
From: Mathias Nyman <mathias.nyman@xxxxxxxxxxxxxxx>
Date: Mon, 16 Oct 2017 14:06:08 +0300
Subject: [PATCH] xhci: Don't show incorrect WARN message about events for
empty rings
xHC will generate events for short transfer both on the TRB that was
short, and for the last TRB in the TD. This means that for TDs with
several TRBs we can get two transfer events for the same TD.
The driver will handle the TD after the first short event, and remove
it from its internal list. Driver then incorrectly prints a warning
for the second event:
WARN Event TRB for slot x ep y with no TDs queued
Fix this by not printing a warning if we get a event on a empty list
if the previous event was a short event.
Signed-off-by: Mathias Nyman <mathias.nyman@xxxxxxxxxxxxxxx>
---
drivers/usb/host/xhci-ring.c | 11 ++++++++---
1 file changed, 8 insertions(+), 3 deletions(-)
diff --git a/drivers/usb/host/xhci-ring.c b/drivers/usb/host/xhci-ring.c
index fb25c10..87158a9 100644
--- a/drivers/usb/host/xhci-ring.c
+++ b/drivers/usb/host/xhci-ring.c
@@ -2485,12 +2485,17 @@ static int handle_tx_event(struct xhci_hcd *xhci,
*/
if (list_empty(&ep_ring->td_list)) {
/*
+ * Don't print wanings in the following cases:
* A stopped endpoint may generate an extra completion
- * event if the device was suspended. Don't print
- * warnings.
+ * event if the device was suspended. Or,
+ * a second event for a TD is generated for the last
+ * TRB if the previous event was a short event mid TD.
+ * TD is alrady removed from list.
*/
+
if (!(trb_comp_code == COMP_STOPPED ||
- trb_comp_code == COMP_STOPPED_LENGTH_INVALID)) {
+ trb_comp_code == COMP_STOPPED_LENGTH_INVALID ||
+ ep_ring->last_td_was_short)) {
xhci_warn(xhci, "WARN Event TRB for slot %d ep %d with no TDs queued?\n",
TRB_TO_SLOT_ID(le32_to_cpu(event->flags)),
ep_index);
--
2.7.4
