Mathias, Hello again! Any news on progress of upstreaming this patch? 2017-10-18 1:21 GMT+03:00 Yaroslav Isakov <yaroslav.isakov@xxxxxxxxx>: > Applied it to 4.13.7, and it helps! Thanks a lot! > > 2017-10-16 14:33 GMT+03:00 Mathias Nyman <mathias.nyman@xxxxxxxxxxxxxxx>: >> 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 >>> >> -- 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
