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
