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
