Re: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 1 ep 2 with no TDs queued?

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



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



[Index of Archives]     [Linux Media]     [Linux Input]     [Linux Audio Users]     [Yosemite News]     [Linux Kernel]     [Linux SCSI]     [Old Linux USB Devel Archive]

  Powered by Linux