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
