Hello,
On Mon, Sep 09, 2024 at 06:24:23PM +0300, Mathias Nyman wrote:
> > [ 4808.165397] xhci_hcd 0000:01:00.0: Cancel URB 00000000bcd65caa, dev 1.1.1, ep 0x85, stream_id 6 starting at offset 0xd9964960
> > [ 4808.439706] xhci_hcd 0000:01:00.0: Cancel URB 000000000d48b0aa, dev 1.1.4, ep 0x85, stream_id 6 starting at offset 0x12c7ef0
> > [ 4808.439981] xhci_hcd 0000:01:00.0: WARN Set TR Deq Ptr cmd invalid because of stream ID configuration
> > [ 4808.439984] xhci_hcd 0000:01:00.0: MN: Set TR Dequeue Pointer Command: deq 00000000012c7f02 stream 6 slot 12 ep 11 flags c
> > [ 4808.450328] xhci_hcd 0000:01:00.0: ERROR Transfer event TRB DMA ptr not part of current TD ep_index 10 comp_code 3
> > [ 4808.450339] xhci_hcd 0000:01:00.0: Looking for event-dma 00000000012c7ef0 trb-start 00000000012c7f00 trb-end 0000000000000000 seg-start 00000000012c7000 seg-end 00000000012c7ff0
> > [ 4808.450342] xhci_hcd 0000:01:00.0: Looking for event-dma 00000000012c7ef0 trb-start 00000000012c6000 trb-end 00000000012c6700 seg-start 00000000012c6000 seg-end 00000000012c6ff0
> > [ 4808.450345] xhci_hcd 0000:01:00.0: MN: No TD found, fix halted ep
>
> Thanks.
>
> So the failed 'Set TR Deq' command is the start of the issue.
>
> xHC host fails to move the past that cancelled transfer, but xhci driver gives
> back the URB anyway. Once ring continues running it starts from that cancelled
> transfer, triggering a babble error, pointing to that given back TD.
>
> Still unclear why that 'Set TR Deq' command failed in the first place.
>
> The 'Set TR Deq' command TRB looks fine. Stream ID is ok, (6) and Stream Context
> type (SCT) which is bits 3:1 of dequeue 00000000012c7f02 is looks fine (=1, which
> means primary stream array with dequeue pointing to transfer ring)
> Maybe stream is dropped, or something else is messing with endpoint context
> MaxPSstream, or Linear Stream Address (LSA) fields before the 'Set TD Deq' command.
> That would trigger stream ID issues like this.
>
> Can I ask you to add some select traces on top of the patch?
> They should show content of endpoint context:
>
> as root:
I did that, however, even when mounting to /sys/kernel/debug/tracing, most of
the pseudo-files were actually at /sys/kernel/tracing and I had to fix the
path of the commands.
> Send content of /sys/kernel/debug/tracing/trace
root@video:~# more /tmp/a1
# tracer: nop
#
# entries-in-buffer/entries-written: 49/49 #P:8
#
# _-----=> irqs-off/BH-disabled
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / _-=> migrate-disable
# |||| / delay
# TASK-PID CPU# ||||| TIMESTAMP FUNCTION
# | | | ||||| | |
<idle>-0 [005] d.h2. 1209.080113: xhci_handle_command: CMD: Stop Ring Command: slot 7 sp 0 ep 11 flags C
<idle>-0 [005] d.h2. 1209.080300: xhci_handle_command: CMD: Set TR Dequeue Pointer Command: deq 00000000d99f6c12 stream 3 slot 7 ep 11 flags C
<idle>-0 [005] d.h2. 1209.080302: xhci_handle_cmd_set_deq: RS 00011 super-speed plus Ctx Entries 15 MEL 0 us Port# 1/0 [TT Slot 0 Port# 0 TTT 0 Intr 0] Addr 7 State configured
<idle>-0 [005] d.h2. 1209.080303: xhci_handle_cmd_set_deq_ep: State stopped mult 1 max P. Streams 3 LSA interval 125 us max ESIT payload 0 CErr 3 Type Bulk IN HIDburst 15 maxp 1024 deq 00000000d9933100 avg trb len 0
<idle>-0 [005] d.h2. 1209.210387: xhci_handle_command: CMD: Stop Ring Command: slot 12 sp 0 ep 11 flags C
<idle>-0 [005] d.h2. 1209.210558: xhci_handle_command: CMD: Set TR Dequeue Pointer Command: deq 0000000001296853 stream 4 slot 12 ep 11 flags C
<idle>-0 [005] d.h2. 1209.210560: xhci_handle_cmd_set_deq: RS 00041 super-speed plus Ctx Entries 15 MEL 0 us Port# 1/0 [TT Slot 0 Port# 0 TTT 0 Intr 0] Addr 12 State configured
<idle>-0 [005] d.h2. 1209.210561: xhci_handle_cmd_set_deq_ep: State stopped mult 1 max P. Streams 3 LSA interval 125 us max ESIT payload 0 CErr 3 Type Bulk IN HIDburst 15 maxp 1024 deq 00000000d9933a00 avg trb len 0
<idle>-0 [005] d.h2. 1209.222205: xhci_handle_command: CMD: Stop Ring Command: slot 11 sp 0 ep 11 flags C
<idle>-0 [005] d.h2. 1209.222374: xhci_handle_command: CMD: Set TR Dequeue Pointer Command: deq 0000000001251d63 stream 1 slot 11 ep 11 flags C
<idle>-0 [005] d.h2. 1209.222375: xhci_handle_cmd_set_deq: RS 00031 super-speed plus Ctx Entries 15 MEL 0 us Port# 1/0 [TT Slot 0 Port# 0 TTT 0 Intr 0] Addr 11 State configured
<idle>-0 [005] d.h2. 1209.222376: xhci_handle_cmd_set_deq_ep: State stopped mult 1 max P. Streams 3 LSA interval 125 us max ESIT payload 0 CErr 3 Type Bulk IN HIDburst 15 maxp 1024 deq 00000000d9933700 avg trb len 0
<idle>-0 [005] d.H2. 1209.229176: xhci_handle_command: CMD: Stop Ring Command: slot 11 sp 0 ep 11 flags C
<idle>-0 [005] d.H2. 1209.229344: xhci_handle_command: CMD: Set TR Dequeue Pointer Command: deq 0000000001251d73 stream 1 slot 11 ep 11 flags C
<idle>-0 [005] d.H2. 1209.229345: xhci_handle_cmd_set_deq: RS 00031 super-speed plus Ctx Entries 15 MEL 0 us Port# 1/0 [TT Slot 0 Port# 0 TTT 0 Intr 0] Addr 11 State configured
<idle>-0 [005] d.H2. 1209.229346: xhci_handle_cmd_set_deq_ep: State stopped mult 1 max P. Streams 3 LSA interval 125 us max ESIT payload 0 CErr 3 Type Bulk IN HIDburst 15 maxp 1024 deq 00000000d9933700 avg trb len 0
<idle>-0 [005] d.h2. 1209.365774: xhci_handle_command: CMD: Stop Ring Command: slot 9 sp 0 ep 11 flags C
<idle>-0 [005] d.h2. 1209.365941: xhci_handle_command: CMD: Set TR Dequeue Pointer Command: deq 0000000001218983 stream 4 slot 9 ep 11 flags C
<idle>-0 [005] d.h2. 1209.365943: xhci_handle_cmd_set_deq: RS 00021 super-speed plus Ctx Entries 15 MEL 0 us Port# 1/0 [TT Slot 0 Port# 0 TTT 0 Intr 0] Addr 9 State configured
<idle>-0 [005] d.h2. 1209.365943: xhci_handle_cmd_set_deq_ep: State stopped mult 1 max P. Streams 3 LSA interval 125 us max ESIT payload 0 CErr 3 Type Bulk IN HIDburst 15 maxp 1024 deq 00000000d9933400 avg trb len 0
<idle>-0 [005] d.h2. 1209.393909: xhci_handle_command: CMD: Stop Ring Command: slot 9 sp 0 ep 11 flags C
<idle>-0 [005] d.h2. 1209.394076: xhci_handle_command: CMD: Set TR Dequeue Pointer Command: deq 000000000121a1e2 stream 5 slot 9 ep 11 flags C
<idle>-0 [005] d.h2. 1209.394077: xhci_handle_cmd_set_deq: RS 00021 super-speed plus Ctx Entries 15 MEL 0 us Port# 1/0 [TT Slot 0 Port# 0 TTT 0 Intr 0] Addr 9 State configured
<idle>-0 [005] d.h2. 1209.394077: xhci_handle_cmd_set_deq_ep: State stopped mult 1 max P. Streams 3 LSA interval 125 us max ESIT payload 0 CErr 3 Type Bulk IN HIDburst 15 maxp 1024 deq 00000000d9933400 avg trb len 0
<idle>-0 [005] d.h2. 1809.115095: xhci_handle_command: CMD: Stop Ring Command: slot 7 sp 0 ep 11 flags C
<idle>-0 [005] d.h2. 1809.115264: xhci_handle_command: CMD: Set TR Dequeue Pointer Command: deq 00000000d99f2bc2 stream 1 slot 7 ep 11 flags C
<idle>-0 [005] d.h2. 1809.115265: xhci_handle_cmd_set_deq: RS 00011 super-speed plus Ctx Entries 15 MEL 0 us Port# 1/0 [TT Slot 0 Port# 0 TTT 0 Intr 0] Addr 7 State configured
<idle>-0 [005] d.h2. 1809.115266: xhci_handle_cmd_set_deq_ep: State stopped mult 1 max P. Streams 3 LSA interval 125 us max ESIT payload 0 CErr 3 Type Bulk IN HIDburst 15 maxp 1024 deq 00000000d9933100 avg trb len 0
<idle>-0 [005] d.h2. 1809.128672: xhci_handle_command: CMD: Stop Ring Command: slot 7 sp 0 ep 11 flags C
<idle>-0 [005] d.h2. 1809.128843: xhci_handle_command: CMD: Set TR Dequeue Pointer Command: deq 00000000d99f2bd2 stream 1 slot 7 ep 11 flags C
<idle>-0 [005] d.h2. 1809.128845: xhci_handle_cmd_set_deq: RS 00011 super-speed plus Ctx Entries 15 MEL 0 us Port# 1/0 [TT Slot 0 Port# 0 TTT 0 Intr 0] Addr 7 State configured
<idle>-0 [005] d.h2. 1809.128845: xhci_handle_cmd_set_deq_ep: State stopped mult 1 max P. Streams 3 LSA interval 125 us max ESIT payload 0 CErr 3 Type Bulk IN HIDburst 15 maxp 1024 deq 00000000d9933100 avg trb len 0
<idle>-0 [005] d.h2. 1809.303711: xhci_handle_command: CMD: Stop Ring Command: slot 12 sp 0 ep 11 flags C
<idle>-0 [005] d.h2. 1809.303917: xhci_handle_command: CMD: Set TR Dequeue Pointer Command: deq 0000000001296782 stream 4 slot 12 ep 11 flags C
<idle>-0 [005] d.h2. 1809.303919: xhci_handle_cmd_set_deq: RS 00041 super-speed plus Ctx Entries 15 MEL 0 us Port# 1/0 [TT Slot 0 Port# 0 TTT 0 Intr 0] Addr 12 State configured
<idle>-0 [005] d.h2. 1809.303920: xhci_handle_cmd_set_deq_ep: State stopped mult 1 max P. Streams 3 LSA interval 125 us max ESIT payload 0 CErr 3 Type Bulk IN HIDburst 15 maxp 1024 deq 00000000d9933a00 avg trb len 0
<idle>-0 [005] d.h2. 1809.375752: xhci_handle_command: CMD: Stop Ring Command: slot 11 sp 0 ep 11 flags C
<idle>-0 [005] d.h2. 1809.375937: xhci_handle_command: CMD: Set TR Dequeue Pointer Command: deq 000000000125b3a3 stream 6 slot 11 ep 11 flags C
<idle>-0 [005] d.h2. 1809.375939: xhci_handle_cmd_set_deq: RS 00031 super-speed plus Ctx Entries 15 MEL 0 us Port# 1/0 [TT Slot 0 Port# 0 TTT 0 Intr 0] Addr 11 State configured
<idle>-0 [005] d.h2. 1809.375940: xhci_handle_cmd_set_deq_ep: State stopped mult 1 max P. Streams 3 LSA interval 125 us max ESIT payload 0 CErr 3 Type Bulk IN HIDburst 15 maxp 1024 deq 00000000d9933700 avg trb len 0
<idle>-0 [005] d.H2. 1809.497074: xhci_handle_command: CMD: Stop Ring Command: slot 9 sp 0 ep 11 flags C
<idle>-0 [005] d.h2. 1809.497243: xhci_handle_command: CMD: Set TR Dequeue Pointer Command: deq 0000000001217d62 stream 4 slot 9 ep 11 flags C
<idle>-0 [005] d.h2. 1809.497245: xhci_handle_cmd_set_deq: RS 00021 super-speed plus Ctx Entries 15 MEL 0 us Port# 1/0 [TT Slot 0 Port# 0 TTT 0 Intr 0] Addr 9 State configured
<idle>-0 [005] d.h2. 1809.497245: xhci_handle_cmd_set_deq_ep: State stopped mult 1 max P. Streams 3 LSA interval 125 us max ESIT payload 0 CErr 3 Type Bulk IN HIDburst 15 maxp 1024 deq 00000000d9933400 avg trb len 0
<idle>-0 [005] d.h2. 1809.524165: xhci_handle_command: CMD: Stop Ring Command: slot 9 sp 0 ep 11 flags C
<idle>-0 [005] dNH2. 1809.524235: xhci_handle_command: CMD: Set TR Dequeue Pointer Command: deq 0000000001219f22 stream 5 slot 9 ep 11 flags C
<idle>-0 [005] dNH2. 1809.524236: xhci_handle_cmd_set_deq: RS 00021 super-speed plus Ctx Entries 15 MEL 0 us Port# 1/0 [TT Slot 0 Port# 0 TTT 0 Intr 0] Addr 9 State configured
<idle>-0 [005] dNH2. 1809.524237: xhci_handle_cmd_set_deq_ep: State stopped mult 1 max P. Streams 3 LSA interval 125 us max ESIT payload 0 CErr 3 Type Bulk IN HIDburst 15 maxp 1024 deq 00000000d9933400 avg trb len 0
kworker/5:1H-150 [005] d.h2. 1809.533666: xhci_handle_command: CMD: Reset Endpoint Command: ctx 0000000000000000 slot 9 ep 11 flags t:C
root@video:~#
> And then send me both the trace and dmesg of triggered case.
[ 1809.518429] xhci_hcd 0000:01:00.0: WARN Set TR Deq Ptr cmd invalid because of stream ID configuration
[ 1809.518434] xhci_hcd 0000:01:00.0: MN: Set TR Dequeue Pointer Command: deq 0000000001219f22 stream 5 slot 9 ep 11 flags C
[ 1809.527627] xhci_hcd 0000:01:00.0: ERROR Transfer event TRB DMA ptr not part of current TD ep_index 10 comp_code 3
[ 1809.527637] xhci_hcd 0000:01:00.0: Looking for event-dma 0000000001219f10 trb-start 0000000001219f20 trb-end 0000000000000000 seg-start 0000000001219000 seg-end 0000000001219ff0
[ 1809.527641] xhci_hcd 0000:01:00.0: Looking for event-dma 0000000001219f10 trb-start 000000000121a000 trb-end 000000000121a720 seg-start 000000000121a000 seg-end 000000000121aff0
[ 1809.527644] xhci_hcd 0000:01:00.0: MN: No TD found, fix halted ep
[ 1816.575134] sd 16:0:0:0: [sdc] tag#5 uas_eh_abort_handler 0 uas-tag 6 inflight: CMD
[ 1816.575151] sd 16:0:0:0: [sdc] tag#5 CDB: ATA command pass through(12)/Blank a1 06 20 da 00 00 4f c2 00 b0 00 00
[ 1828.638347] xhci_hcd 0000:01:00.0: Cancel URB 000000008009522e, dev 1.1.2, ep 0x85, stream_id 5 starting at offset 0x1219f20
[ 1828.638390] usb 3-1.1.2: stat urb: no pending cmd for uas-tag 6
[ 1828.731237] xhci_hcd 0000:01:00.0: WARN Event TRB for slot 9 ep 10 with no TDs queued?
[ 1840.227417] sd 16:0:0:0: [sdc] tag#4 uas_eh_abort_handler 0 uas-tag 2 inflight: IN
[ 1840.227426] sd 16:0:0:0: [sdc] tag#4 CDB: Read(16) 88 00 00 00 00 00 15 59 78 00 00 00 04 00 00 00
[ 1840.227433] xhci_hcd 0000:01:00.0: Cancel URB 0000000088ada5bf, dev 1.1.2, ep 0x85, stream_id 2 starting at offset 0x12134d0
[ 1840.228047] sd 16:0:0:0: [sdc] tag#2 uas_eh_abort_handler 0 uas-tag 4 inflight: CMD IN
[ 1840.228058] sd 16:0:0:0: [sdc] tag#2 CDB: Read(16) 88 00 00 00 00 00 15 59 98 00 00 00 04 00 00 00
[ 1840.228072] xhci_hcd 0000:01:00.0: Cancel URB 00000000498a4d69, dev 1.1.2, ep 0x85, stream_id 4 starting at offset 0x1218d70
[ 1840.236069] sd 16:0:0:0: [sdc] tag#1 uas_eh_abort_handler 0 uas-tag 3 inflight: CMD IN
[ 1840.236072] sd 16:0:0:0: [sdc] tag#1 CDB: Read(16) 88 00 00 00 00 00 15 59 90 00 00 00 04 00 00 00
[ 1840.236075] xhci_hcd 0000:01:00.0: Cancel URB 00000000ce78030e, dev 1.1.2, ep 0x85, stream_id 3 starting at offset 0x1216730
[ 1840.243820] sd 16:0:0:0: [sdc] tag#0 uas_eh_abort_handler 0 uas-tag 1 inflight: CMD IN
[ 1840.243823] sd 16:0:0:0: [sdc] tag#0 CDB: Read(16) 88 00 00 00 00 00 15 59 94 00 00 00 04 00 00 00
[ 1840.243836] xhci_hcd 0000:01:00.0: Cancel URB 000000006af8d826, dev 1.1.2, ep 0x85, stream_id 1 starting at offset 0x1211590
[ 1840.258742] xhci_hcd 0000:01:00.0: WARN Event TRB for slot 9 ep 10 with no TDs queued?
[ 1840.283445] scsi host16: uas_eh_device_reset_handler start
[ 1840.283455] xhci_hcd 0000:01:00.0: Cancel URB 00000000ab683c42, dev 1.1.2, ep 0x87, stream_id 4 starting at offset 0x12064c0
[ 1840.283906] xhci_hcd 0000:01:00.0: Cancel URB 0000000084685914, dev 1.1.2, ep 0x87, stream_id 1 starting at offset 0xd9959d80
[ 1840.284415] xhci_hcd 0000:01:00.0: Cancel URB 0000000045b3d678, dev 1.1.2, ep 0x87, stream_id 3 starting at offset 0x1204ee0
[ 1840.375427] usb 3-1.1.2: reset SuperSpeed Plus Gen 2x1 USB device number 7 using xhci_hcd
[ 1840.423055] scsi host16: uas_eh_device_reset_handler success
Have a nice evening.
