Hello, Mathias! Did you get a chance to look into this bug? 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
