> >> On 22 May 2017, at 14:37, Mathias Nyman <mathias.ny...@linux.intel.com> >> wrote: >> >> On 22.05.2017 11:48, Christoph Gohle wrote: >>> Hey Mathias, >>> >>> >>>> On 19 May 2017, at 09:58, Mathias Nyman <mathias.ny...@linux.intel.com> >>>> wrote: >>>> >>>>> >>>> >>>> 4.11 kernel has xhci traces enabled, could you try to reproduce it with >>>> 4.11? >>>> xhci traces can be enabled with: >>>> >>>> echo 1 > /sys/kernel/debug/tracing/events/xhci-hcd/enable >>>> >>>> If you know how to reliably reproduce this then please enable tracing just >>>> before >>>> triggering this. It generates a lot of data. >>>> >>>> -Mathias >>> I would be able to do xhci traces with a 4.10 kernel (4.10.0-21-generic >>> #23~16.04.1-Ubuntu SMP). Don’t really want to go to 4.11. . Still >>> interested? >> >> xhci got more useful tracing support in 4.11, >> Sure, you can try if there's something in 4.10 OK. Now I managed (had to update-initramfs, stupid…)
So I triggered the failiure with xhci-hcd tracing enabled. I can’t make much
sense out of the trace. Maybe you can? The trace is as follows (I removed
repeating ‘Removing canceled TD...':
# tracer: nop
#
# entries-in-buffer/entries-written: 1536/1536 #P:4
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
device 1 sectio-3419 [002] d... 326.179876: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc6f68f800, dev 5.2, ep 0x84, starting at offset 0x209e5c320
<idle>-0 [002] d.h. 326.179952: xhci_cmd_completion:
trb_dma=@26e01a820, trb_va=@ffff8dcc6e01a820, status=01000000, flags=04008400
<idle>-0 [002] d.h. 326.179959: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x209e5c320 (dma).
.
.
.
<idle>-0 [002] d.h. 326.180141: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x209e5c710 (dma).
device 1 sectio-3419 [002] d... 326.180198: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc6f68c000, dev 5.2, ep 0x84, starting at offset 0x209e5c720
<idle>-0 [002] d.h. 326.180243: xhci_cmd_completion:
trb_dma=@26e01a830, trb_va=@ffff8dcc6e01a830, status=01000000, flags=04008400
<idle>-0 [002] d.h. 326.180248: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x209e5c720 (dma).
.
.
.
<idle>-0 [002] d.h. 326.180420: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x209e5cb10 (dma).
device 1 sectio-3419 [002] d... 326.180465: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc6f68c800, dev 5.2, ep 0x84, starting at offset 0x1ebb11730
<idle>-0 [002] d.h. 326.180504: xhci_cmd_completion:
trb_dma=@26e01a840, trb_va=@ffff8dcc6e01a840, status=01000000, flags=04008400
<idle>-0 [002] d.h. 326.180507: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x1ebb11730 (dma).
<idle>-0 [002] d.h. 326.180511: xhci_dbg_cancel_urb: Finding
endpoint context
<idle>-0 [002] d.h. 326.180515: xhci_dbg_cancel_urb: Cycle
state = 0x1
<idle>-0 [002] d.h. 326.180517: xhci_dbg_cancel_urb: New
dequeue segment = ffff8dcc040c7b40 (virtual)
<idle>-0 [002] d.h. 326.180523: xhci_dbg_cancel_urb: New
dequeue pointer = 0x1ebb11740 (DMA)
<idle>-0 [002] d.h. 326.180528: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x1ebb11740 (dma).
.
.
.
<idle>-0 [002] d.h. 326.180697: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x1ebb11b00 (dma).
<idle>-0 [002] d.h. 326.180700: xhci_dbg_cancel_urb: Set TR Deq
Ptr cmd, new deq seg = ffff8dcc040c7b40 (0x1ebb11000 dma), new deq ptr =
ffff8dcbebb11740 (0x1ebb11740 dma), new cycle = 1
<idle>-0 [002] dNh. 326.180738: xhci_cmd_completion:
trb_dma=@26e01a850, trb_va=@ffff8dcc6e01a850, status=01000000, flags=04008400
<idle>-0 [002] dNh. 326.180741: xhci_dbg_cancel_urb: Successful
Set TR Deq Ptr cmd, deq = @1ebb11740
device 1 sectio-3419 [002] d... 326.180847: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc6f689800, dev 5.2, ep 0x84, starting at offset 0x1ebb11b10
<idle>-0 [003] d.H. 326.180918: xhci_cmd_completion:
trb_dma=@26e01a860, trb_va=@ffff8dcc6e01a860, status=01000000, flags=04008400
<idle>-0 [003] d.H. 326.180924: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x1ebb11b10 (dma).
<idle>-0 [003] d.H. 326.180931: xhci_dbg_cancel_urb: Finding
endpoint context
<idle>-0 [003] d.H. 326.180936: xhci_dbg_cancel_urb: Cycle
state = 0x1
<idle>-0 [003] d.H. 326.180941: xhci_dbg_cancel_urb: New
dequeue segment = ffff8dcc040c7b40 (virtual)
<idle>-0 [003] d.H. 326.180945: xhci_dbg_cancel_urb: New
dequeue pointer = 0x1ebb11b20 (DMA)
<idle>-0 [003] d.H. 326.180948: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x1ebb11b20 (dma).
.
.
.
<idle>-0 [003] d.H. 326.181129: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x1ebb11f00 (dma).
<idle>-0 [003] d.H. 326.181132: xhci_dbg_cancel_urb: Set TR Deq
Ptr cmd, new deq seg = ffff8dcc040c7b40 (0x1ebb11000 dma), new deq ptr =
ffff8dcbebb11b20 (0x1ebb11b20 dma), new cycle = 1
<idle>-0 [003] d.H. 326.181188: xhci_cmd_completion:
trb_dma=@26e01a870, trb_va=@ffff8dcc6e01a870, status=01000000, flags=04008400
<idle>-0 [003] d.H. 326.181191: xhci_dbg_cancel_urb: Successful
Set TR Deq Ptr cmd, deq = @1ebb11b20
device 1 sectio-3419 [002] d... 326.181205: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc6f688800, dev 5.2, ep 0x84, starting at offset 0x1ebb11f10
<idle>-0 [002] d.h. 326.181247: xhci_cmd_completion:
trb_dma=@26e01a880, trb_va=@ffff8dcc6e01a880, status=01000000, flags=04008400
<idle>-0 [002] d.h. 326.181252: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x1ebb11f10 (dma).
.
.
.
<idle>-0 [002] d.h. 326.181435: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x209e5c310 (dma).
<idle>-0 [002] d.h. 327.288291: xhci_cmd_completion:
trb_dma=@26e01a890, trb_va=@ffff8dcc6e01a890, status=01000000, flags=04008401
device 1 sectio-3419 [002] .... 327.288342: xhci_dbg_context_change:
Successful Endpoint Configure command
<idle>-0 [002] d.h. 327.313000: xhci_dbg_ring_expansion: ERROR
no room on ep ring, try ring expansion
<idle>-0 [002] d.h. 327.313045: xhci_dbg_ring_expansion: ring
expansion succeed, now has 4 segments
device 1 sectio-3419 [000] d... 347.177471: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc6f68f800, dev 5.2, ep 0x84, starting at offset 0x20eb42f00
<idle>-0 [002] dNh. 347.177530: xhci_cmd_completion:
trb_dma=@26e01a8a0, trb_va=@ffff8dcc6e01a8a0, status=01000000, flags=04008400
<idle>-0 [002] dNh. 347.177538: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x20eb42f00 (dma).
.
.
.
<idle>-0 [002] dNh. 347.177660: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x2549c9300 (dma).
device 1 sectio-3419 [000] d... 347.177897: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc6f68c000, dev 5.2, ep 0x84, starting at offset 0x26d92ef40
<idle>-0 [002] dNh. 347.177953: xhci_cmd_completion:
trb_dma=@26e01a8b0, trb_va=@ffff8dcc6e01a8b0, status=01000000, flags=04008400
<idle>-0 [002] dNh. 347.177957: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x26d92ef50 (dma).
<idle>-0 [002] dNh. 347.177961: xhci_dbg_cancel_urb: Finding
endpoint context
<idle>-0 [002] dNh. 347.177962: xhci_dbg_cancel_urb: Cycle
state = 0x0
<idle>-0 [002] dNh. 347.177964: xhci_dbg_cancel_urb: New
dequeue segment = ffff8dcbdefeee00 (virtual)
<idle>-0 [002] dNh. 347.177968: xhci_dbg_cancel_urb: New
dequeue pointer = 0x26d92ef60 (DMA)
<idle>-0 [002] dNh. 347.177970: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x26d92ef60 (dma).
.
.
.
<idle>-0 [002] dNh. 347.178075: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x20eb422f0 (dma).
<idle>-0 [002] dNh. 347.178078: xhci_dbg_cancel_urb: Set TR Deq
Ptr cmd, new deq seg = ffff8dcbdefeee00 (0x26d92e000 dma), new deq ptr =
ffff8dcc6d92ef60 (0x26d92ef60 dma), new cycle = 0
<idle>-0 [002] dNh. 347.178102: xhci_cmd_completion:
trb_dma=@26e01a8c0, trb_va=@ffff8dcc6e01a8c0, status=01000000, flags=04008400
<idle>-0 [002] dNh. 347.178104: xhci_dbg_cancel_urb: Successful
Set TR Deq Ptr cmd, deq = @26d92ef60
device 1 sectio-3419 [000] d... 347.178242: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc6f68c800, dev 5.2, ep 0x84, starting at offset 0x20eb42300
<idle>-0 [002] d.h. 347.178295: xhci_cmd_completion:
trb_dma=@26e01a8d0, trb_va=@ffff8dcc6e01a8d0, status=01000000, flags=04008400
<idle>-0 [002] d.h. 347.178298: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x20eb42300 (dma).
<idle>-0 [002] d.h. 347.178302: xhci_dbg_cancel_urb: Finding
endpoint context
<idle>-0 [002] d.h. 347.178306: xhci_dbg_cancel_urb: Cycle
state = 0x1
<idle>-0 [002] d.h. 347.178308: xhci_dbg_cancel_urb: New
dequeue segment = ffff8dcbdefeef80 (virtual)
<idle>-0 [002] d.h. 347.178310: xhci_dbg_cancel_urb: New
dequeue pointer = 0x20eb42310 (DMA)
<idle>-0 [002] d.h. 347.178312: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x20eb42310 (dma).
.
.
.
<idle>-0 [002] d.h. 347.178429: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x20eb426f0 (dma).
<idle>-0 [002] d.h. 347.178432: xhci_dbg_cancel_urb: Set TR Deq
Ptr cmd, new deq seg = ffff8dcbdefeef80 (0x20eb42000 dma), new deq ptr =
ffff8dcc0eb42310 (0x20eb42310 dma), new cycle = 1
<idle>-0 [002] dNh. 347.178465: xhci_cmd_completion:
trb_dma=@26e01a8e0, trb_va=@ffff8dcc6e01a8e0, status=01000000, flags=04008400
<idle>-0 [002] dNh. 347.178468: xhci_dbg_cancel_urb: Successful
Set TR Deq Ptr cmd, deq = @20eb42310
device 1 sectio-3419 [000] d... 347.178595: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc6f689800, dev 5.2, ep 0x84, starting at offset 0x20eb42700
<idle>-0 [002] d.h. 347.178641: xhci_cmd_completion:
trb_dma=@26e01a8f0, trb_va=@ffff8dcc6e01a8f0, status=01000000, flags=04008400
<idle>-0 [002] d.h. 347.178644: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x20eb42700 (dma).
<idle>-0 [002] d.h. 347.178647: xhci_dbg_cancel_urb: Finding
endpoint context
<idle>-0 [002] d.h. 347.178651: xhci_dbg_cancel_urb: Cycle
state = 0x1
<idle>-0 [002] d.h. 347.178653: xhci_dbg_cancel_urb: New
dequeue segment = ffff8dcbdefeef80 (virtual)
<idle>-0 [002] d.h. 347.178655: xhci_dbg_cancel_urb: New
dequeue pointer = 0x20eb42710 (DMA)
<idle>-0 [002] d.h. 347.178657: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x20eb42710 (dma).
.
.
.
<idle>-0 [002] d.h. 347.178774: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x20eb42af0 (dma).
<idle>-0 [002] d.h. 347.178776: xhci_dbg_cancel_urb: Set TR Deq
Ptr cmd, new deq seg = ffff8dcbdefeef80 (0x20eb42000 dma), new deq ptr =
ffff8dcc0eb42710 (0x20eb42710 dma), new cycle = 1
<idle>-0 [002] dNh. 347.178820: xhci_cmd_completion:
trb_dma=@26e01a900, trb_va=@ffff8dcc6e01a900, status=01000000, flags=04008400
<idle>-0 [002] dNh. 347.178822: xhci_dbg_cancel_urb: Successful
Set TR Deq Ptr cmd, deq = @20eb42710
device 1 sectio-3419 [000] d... 347.178936: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc6f688800, dev 5.2, ep 0x84, starting at offset 0x20eb42b00
<idle>-0 [002] d.h. 347.178994: xhci_cmd_completion:
trb_dma=@26e01a910, trb_va=@ffff8dcc6e01a910, status=01000000, flags=04008400
<idle>-0 [002] d.h. 347.178997: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x20eb42b00 (dma).
<idle>-0 [002] d.h. 347.179001: xhci_dbg_cancel_urb: Finding
endpoint context
<idle>-0 [002] d.h. 347.179004: xhci_dbg_cancel_urb: Cycle
state = 0x1
<idle>-0 [002] d.h. 347.179009: xhci_dbg_cancel_urb: New
dequeue segment = ffff8dcbdefeef80 (virtual)
<idle>-0 [002] d.h. 347.179011: xhci_dbg_cancel_urb: New
dequeue pointer = 0x20eb42b10 (DMA)
<idle>-0 [002] d.h. 347.179013: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x20eb42b10 (dma).
.
.
.
<idle>-0 [002] d.h. 347.179130: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x20eb42ef0 (dma).
<idle>-0 [002] d.h. 347.179132: xhci_dbg_cancel_urb: Set TR Deq
Ptr cmd, new deq seg = ffff8dcbdefeef80 (0x20eb42000 dma), new deq ptr =
ffff8dcc0eb42b10 (0x20eb42b10 dma), new cycle = 1
<idle>-0 [002] dNh. 347.179177: xhci_cmd_completion:
trb_dma=@26e01a920, trb_va=@ffff8dcc6e01a920, status=01000000, flags=04008400
<idle>-0 [002] dNh. 347.179179: xhci_dbg_cancel_urb: Successful
Set TR Deq Ptr cmd, deq = @20eb42b10
<idle>-0 [002] d.h. 348.287092: xhci_cmd_completion:
trb_dma=@26e01a930, trb_va=@ffff8dcc6e01a930, status=01000000, flags=04008401
device 1 sectio-3419 [000] .... 348.287299: xhci_dbg_context_change:
Successful Endpoint Configure command
<idle>-0 [002] d.h. 348.312308: xhci_dbg_ring_expansion: ERROR
no room on ep ring, try ring expansion
<idle>-0 [002] d.h. 348.312385: xhci_dbg_ring_expansion: ring
expansion succeed, now has 4 segments
kworker/u8:5-234 [000] d... 355.356495: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc759950c0, dev 2, ep 0x83, starting at offset 0x26da57540
<idle>-0 [003] d.h. 355.356547: xhci_cmd_completion:
trb_dma=@26e01a940, trb_va=@ffff8dcc6e01a940, status=01000000, flags=02008401
<idle>-0 [003] d.h. 355.356561: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x26da57540 (dma).
<idle>-0 [003] d.h. 355.356571: xhci_dbg_cancel_urb: Finding
endpoint context
<idle>-0 [003] d.h. 355.356576: xhci_dbg_cancel_urb: Cycle
state = 0x1
<idle>-0 [003] d.h. 355.356579: xhci_dbg_cancel_urb: New
dequeue segment = ffff8dcc6da4a780 (virtual)
<idle>-0 [003] d.h. 355.356585: xhci_dbg_cancel_urb: New
dequeue pointer = 0x26da57740 (DMA)
<idle>-0 [003] d.h. 355.356590: xhci_dbg_cancel_urb: Set TR Deq
Ptr cmd, new deq seg = ffff8dcc6da4a780 (0x26da57000 dma), new deq ptr =
ffff8dcc6da57740 (0x26da57740 dma), new cycle = 1
<idle>-0 [003] dNh. 355.356656: xhci_cmd_completion:
trb_dma=@26e01a950, trb_va=@ffff8dcc6e01a950, status=01000000, flags=02008401
<idle>-0 [003] dNh. 355.356661: xhci_dbg_cancel_urb: Successful
Set TR Deq Ptr cmd, deq = @26da57740
kworker/u8:5-234 [003] d... 355.356797: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc5aceacc0, dev 2, ep 0x83, starting at offset 0x26d99b220
<idle>-0 [002] d.h. 355.356865: xhci_cmd_completion:
trb_dma=@26e01a960, trb_va=@ffff8dcc6e01a960, status=01000000, flags=02008401
<idle>-0 [002] d.h. 355.356872: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x26d99b220 (dma).
kworker/u8:5-234 [002] d... 355.357006: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc5a86e540, dev 2, ep 0x83, starting at offset 0x26da53500
<idle>-0 [002] d.h. 355.357059: xhci_cmd_completion:
trb_dma=@26e01a970, trb_va=@ffff8dcc6e01a970, status=01000000, flags=02008400
<idle>-0 [002] d.h. 355.357063: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x26da53500 (dma).
scsi_eh_2-231 [002] d... 357.392425: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc5a86ea80, dev 2, ep 0x4, starting at offset 0x26e350e90
scsi_eh_2-231 [002] d.h. 357.392470: xhci_cmd_completion:
trb_dma=@26e01a980, trb_va=@ffff8dcc6e01a980, status=13000000, flags=02008401
scsi_eh_2-231 [002] d.h. 357.392474: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x26e350e90 (dma).
scsi_eh_2-231 [002] d... 357.392549: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc5a86e840, dev 2, ep 0x82, starting at offset 0x26d9d0190
scsi_eh_2-231 [002] d.h. 357.392582: xhci_cmd_completion:
trb_dma=@26e01a990, trb_va=@ffff8dcc6e01a990, status=01000000, flags=02008401
scsi_eh_2-231 [002] d.h. 357.392588: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x26d9d0190 (dma).
scsi_eh_2-231 [002] d.h. 357.392592: xhci_dbg_cancel_urb: Finding
endpoint context
scsi_eh_2-231 [002] d.h. 357.392599: xhci_dbg_cancel_urb: Cycle
state = 0x1
scsi_eh_2-231 [002] d.h. 357.392602: xhci_dbg_cancel_urb: New
dequeue segment = ffff8dcc6d93f780 (virtual)
scsi_eh_2-231 [002] d.h. 357.392606: xhci_dbg_cancel_urb: New
dequeue pointer = 0x26d9d01a0 (DMA)
scsi_eh_2-231 [002] d.h. 357.392613: xhci_dbg_cancel_urb: Set TR Deq
Ptr cmd, new deq seg = ffff8dcc6d93f780 (0x26d9d0000 dma), new deq ptr =
ffff8dcc6d9d01a0 (0x26d9d01a0 dma), new cycle = 1
scsi_eh_2-231 [002] d.h. 357.392637: xhci_cmd_completion:
trb_dma=@26e01a9a0, trb_va=@ffff8dcc6e01a9a0, status=01000000, flags=02008401
scsi_eh_2-231 [002] d.h. 357.392642: xhci_dbg_cancel_urb: Successful
Set TR Deq Ptr cmd, deq = @26d9d01a0
scsi_eh_2-231 [002] d... 357.392673: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc596770c0, dev 2, ep 0x82, starting at offset 0x26da40570
<idle>-0 [003] d.h. 357.392779: xhci_cmd_completion:
trb_dma=@26e01a9b0, trb_va=@ffff8dcc6e01a9b0, status=01000000, flags=02008401
<idle>-0 [003] d.h. 357.392786: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x26da40570 (dma).
scsi_eh_2-231 [002] d... 357.392846: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc5aceac00, dev 2, ep 0x82, starting at offset 0x26da5e2f0
<idle>-0 [002] d.h. 357.392892: xhci_cmd_completion:
trb_dma=@26e01a9c0, trb_va=@ffff8dcc6e01a9c0, status=01000000, flags=02008400
<idle>-0 [002] d.h. 357.392897: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x26da5e2f0 (dma).
scsi_eh_2-231 [002] d... 357.392962: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc5acead80, dev 2, ep 0x82, starting at offset 0x26da3e570
<idle>-0 [002] d.h. 357.393002: xhci_cmd_completion:
trb_dma=@26e01a9d0, trb_va=@ffff8dcc6e01a9d0, status=01000000, flags=02008400
<idle>-0 [002] d.h. 357.393007: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x26da3e570 (dma).
scsi_eh_2-231 [002] d... 357.393047: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc5acea180, dev 2, ep 0x82, starting at offset 0x26d9d7650
<idle>-0 [003] d.h. 357.393197: xhci_cmd_completion:
trb_dma=@26e01a9e0, trb_va=@ffff8dcc6e01a9e0, status=01000000, flags=02008400
<idle>-0 [003] d.h. 357.393208: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x26d9d7650 (dma).
scsi_eh_2-231 [002] d... 357.393266: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc5acea540, dev 2, ep 0x82, starting at offset 0x26d9ce1f0
<idle>-0 [002] d.h. 357.393304: xhci_cmd_completion:
trb_dma=@26e01a9f0, trb_va=@ffff8dcc6e01a9f0, status=01000000, flags=02008400
<idle>-0 [002] d.h. 357.393309: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x26d9ce1f0 (dma).
scsi_eh_2-231 [002] d... 357.393364: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc5acea300, dev 2, ep 0x82, starting at offset 0x26da47450
<idle>-0 [002] d.h. 357.393402: xhci_cmd_completion:
trb_dma=@26e01aa00, trb_va=@ffff8dcc6e01aa00, status=01000000, flags=02008400
<idle>-0 [002] d.h. 357.393407: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x26da47450 (dma).
scsi_eh_2-231 [002] d... 357.393469: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc5aceaa80, dev 2, ep 0x82, starting at offset 0x26da49430
<idle>-0 [003] d.h. 357.393637: xhci_cmd_completion:
trb_dma=@26e01aa10, trb_va=@ffff8dcc6e01aa10, status=01000000, flags=02008400
<idle>-0 [003] d.h. 357.393648: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x26da49430 (dma).
scsi_eh_2-231 [002] d... 357.393704: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc59677300, dev 2, ep 0x82, starting at offset 0x26d9d5b80
<idle>-0 [002] d.h. 357.393742: xhci_cmd_completion:
trb_dma=@26e01aa20, trb_va=@ffff8dcc6e01aa20, status=01000000, flags=02008400
<idle>-0 [002] d.h. 357.393746: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x26d9d5b80 (dma).
scsi_eh_2-231 [002] d... 357.393788: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc59677840, dev 2, ep 0x82, starting at offset 0x26d9d3e70
<idle>-0 [002] d.h. 357.393824: xhci_cmd_completion:
trb_dma=@26e01aa30, trb_va=@ffff8dcc6e01aa30, status=01000000, flags=02008400
<idle>-0 [002] d.h. 357.393829: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x26d9d3e70 (dma).
scsi_eh_2-231 [002] d... 357.393882: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc5a86eb40, dev 2, ep 0x82, starting at offset 0x26da60d60
<idle>-0 [002] d.h. 357.393920: xhci_cmd_completion:
trb_dma=@26e01aa40, trb_va=@ffff8dcc6e01aa40, status=01000000, flags=02008400
<idle>-0 [002] d.h. 357.393931: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x26da60d60 (dma).
scsi_eh_2-231 [002] d... 357.393988: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc6ded3c00, dev 2, ep 0x82, starting at offset 0x26da45470
<idle>-0 [003] d.h. 357.394092: xhci_cmd_completion:
trb_dma=@26e01aa50, trb_va=@ffff8dcc6e01aa50, status=01000000, flags=02008400
<idle>-0 [003] d.h. 357.394098: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x26da45470 (dma).
scsi_eh_2-231 [002] d... 357.394164: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc5a86ef00, dev 2, ep 0x82, starting at offset 0x26da43480
<idle>-0 [002] d.h. 357.394206: xhci_cmd_completion:
trb_dma=@26e01aa60, trb_va=@ffff8dcc6e01aa60, status=01000000, flags=02008400
<idle>-0 [002] d.h. 357.394212: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x26da43480 (dma).
scsi_eh_2-231 [002] d... 357.394263: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc5a86e600, dev 2, ep 0x82, starting at offset 0x26d9d1eb0
<idle>-0 [002] d.h. 357.394306: xhci_cmd_completion:
trb_dma=@26e01aa70, trb_va=@ffff8dcc6e01aa70, status=01000000, flags=02008400
<idle>-0 [002] d.h. 357.394310: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x26d9d1eb0 (dma).
scsi_eh_2-231 [002] d... 357.394370: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc59677240, dev 2, ep 0x4, starting at offset 0x26e26b9d0
<idle>-0 [002] d.h. 357.394409: xhci_cmd_completion:
trb_dma=@26e01aa80, trb_va=@ffff8dcc6e01aa80, status=13000000, flags=02008400
<idle>-0 [002] d.h. 357.394418: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x26e26b9d0 (dma).
scsi_eh_2-231 [002] d... 357.394476: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc5acea240, dev 2, ep 0x4, starting at offset 0x26d9af310
<idle>-0 [003] d.h. 357.394675: xhci_cmd_completion:
trb_dma=@26e01aa90, trb_va=@ffff8dcc6e01aa90, status=13000000, flags=02008400
<idle>-0 [003] d.h. 357.394682: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x26d9af310 (dma).
scsi_eh_2-231 [002] d... 357.394742: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc5aceaf00, dev 2, ep 0x4, starting at offset 0x26e357e70
<idle>-0 [002] d.h. 357.394787: xhci_cmd_completion:
trb_dma=@26e01aaa0, trb_va=@ffff8dcc6e01aaa0, status=13000000, flags=02008400
<idle>-0 [002] d.h. 357.394793: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x26e357e70 (dma).
scsi_eh_2-231 [002] d... 357.394846: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc5acea6c0, dev 2, ep 0x4, starting at offset 0x26d9b37a0
<idle>-0 [002] d.h. 357.394883: xhci_cmd_completion:
trb_dma=@26e01aab0, trb_va=@ffff8dcc6e01aab0, status=13000000, flags=02008400
<idle>-0 [002] d.h. 357.394886: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x26d9b37a0 (dma).
scsi_eh_2-231 [002] d... 357.394928: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc5acea900, dev 2, ep 0x4, starting at offset 0x1ebb17240
scsi_eh_2-231 [002] d.h. 357.394954: xhci_cmd_completion:
trb_dma=@26e01aac0, trb_va=@ffff8dcc6e01aac0, status=13000000, flags=02008400
scsi_eh_2-231 [002] d.h. 357.394960: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x1ebb17240 (dma).
scsi_eh_2-231 [002] d... 357.394999: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc5acea480, dev 2, ep 0x4, starting at offset 0x1ebb34e50
<idle>-0 [003] d.h. 357.395045: xhci_cmd_completion:
trb_dma=@26e01aad0, trb_va=@ffff8dcc6e01aad0, status=13000000, flags=02008400
<idle>-0 [003] d.h. 357.395050: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x1ebb34e50 (dma).
scsi_eh_2-231 [002] d... 357.395129: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc59677780, dev 2, ep 0x4, starting at offset 0x26e333700
mopidy-5773 [002] d.h. 357.395177: xhci_cmd_completion:
trb_dma=@26e01aae0, trb_va=@ffff8dcc6e01aae0, status=13000000, flags=02008400
mopidy-5773 [002] d.h. 357.395183: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x26e333700 (dma).
scsi_eh_2-231 [002] d... 357.395266: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc59677cc0, dev 2, ep 0x4, starting at offset 0x26e267590
mopidy-5773 [002] d.h. 357.395307: xhci_cmd_completion:
trb_dma=@26e01aaf0, trb_va=@ffff8dcc6e01aaf0, status=13000000, flags=02008400
mopidy-5773 [002] d.h. 357.395312: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x26e267590 (dma).
scsi_eh_2-231 [002] d... 357.395378: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc6ded3240, dev 2, ep 0x4, starting at offset 0x1ebb505e0
mopidy-5773 [002] d.h. 357.395417: xhci_cmd_completion:
trb_dma=@26e01ab00, trb_va=@ffff8dcc6e01ab00, status=13000000, flags=02008400
mopidy-5773 [002] d.h. 357.395424: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x1ebb505e0 (dma).
scsi_eh_2-231 [002] d... 357.395480: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc5a86e780, dev 2, ep 0x4, starting at offset 0x1ebb681b0
<idle>-0 [003] d.h. 357.395565: xhci_cmd_completion:
trb_dma=@26e01ab10, trb_va=@ffff8dcc6e01ab10, status=13000000, flags=02008400
<idle>-0 [003] d.h. 357.395573: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x1ebb681b0 (dma).
in:imklog-3272 [002] d.h. 357.396744: xhci_cmd_completion:
trb_dma=@26e01ab20, trb_va=@ffff8dcc6e01ab20, status=01000000, flags=02008400
scsi_eh_2-231 [002] .... 357.396790: xhci_dbg_context_change:
Successful Endpoint Configure command
scsi_eh_2-231 [002] .... 357.397837: xhci_dbg_context_change: Set up
evaluate context for LPM MEL change.
in:imklog-3272 [002] d.h. 357.397874: xhci_cmd_completion:
trb_dma=@26e01ab30, trb_va=@ffff8dcc6e01ab30, status=01000000, flags=02008400
scsi_eh_2-231 [002] .... 357.397903: xhci_dbg_context_change:
Successful evaluate context command
rcu_sched-7 [003] d.h. 357.516327: xhci_cmd_completion:
trb_dma=@26e01ab40, trb_va=@ffff8dcc6e01ab40, status=01000000, flags=02008400
scsi_eh_2-231 [002] .... 357.516384: xhci_address_ctx:
ctx_64=0, ctx_type=2, ctx_dma=@26e1ed000, ctx_va=@ffff8dcc6e1ed000
<idle>-0 [002] d.h. 357.516442: xhci_cmd_completion:
trb_dma=@26e01ab50, trb_va=@ffff8dcc6e01ab50, status=01000000, flags=02008400
scsi_eh_2-231 [002] .... 357.516482: xhci_dbg_address: Successful
setup address command
scsi_eh_2-231 [002] .... 357.516495: xhci_dbg_address: Op regs DCBAA
ptr = 0x0000026e019000
scsi_eh_2-231 [002] .... 357.516505: xhci_dbg_address: Slot ID 2
dcbaa entry @ffff8dcc6e019010 = 0x0000026e1de000
scsi_eh_2-231 [002] .... 357.516513: xhci_dbg_address: Output
Context DMA address = 0x26e1de000
scsi_eh_2-231 [002] .... 357.516523: xhci_address_ctx:
ctx_64=0, ctx_type=2, ctx_dma=@26e1ed000, ctx_va=@ffff8dcc6e1ed000
scsi_eh_2-231 [002] .... 357.516527: xhci_address_ctx:
ctx_64=0, ctx_type=1, ctx_dma=@26e1de000, ctx_va=@ffff8dcc6e1de000
scsi_eh_2-231 [002] .... 357.516528: xhci_dbg_address: Internal
device address = 2
<idle>-0 [003] d.h. 357.537947: xhci_cmd_completion:
trb_dma=@26e01ab60, trb_va=@ffff8dcc6e01ab60, status=01000000, flags=02008400
scsi_eh_2-231 [002] .... 357.537989: xhci_dbg_context_change:
Successful Endpoint Configure command
<idle>-0 [002] d.h. 357.538530: xhci_cmd_completion:
trb_dma=@26e01ab70, trb_va=@ffff8dcc6e01ab70, status=01000000, flags=02008400
scsi_eh_2-231 [002] .... 357.538582: xhci_dbg_context_change:
Successful Endpoint Configure command
scsi_eh_2-231 [002] .... 357.538963: xhci_dbg_context_change: Set up
evaluate context for LPM MEL change.
<idle>-0 [003] d.h. 357.539002: xhci_cmd_completion:
trb_dma=@26e01ab80, trb_va=@ffff8dcc6e01ab80, status=01000000, flags=02008400
scsi_eh_2-231 [002] .... 357.539039: xhci_dbg_context_change:
Successful evaluate context command
scsi_eh_2-231 [002] .... 357.539351: xhci_dbg_context_change: Set up
evaluate context for LPM MEL change.
<idle>-0 [003] d.h. 357.539454: xhci_cmd_completion:
trb_dma=@26e01ab90, trb_va=@ffff8dcc6e01ab90, status=01000000, flags=02008400
scsi_eh_2-231 [002] .... 357.539495: xhci_dbg_context_change:
Successful evaluate context command
scsi_eh_2-231 [002] .... 357.541030: xhci_dbg_context_change:
Setting number of stream ctx array entries to 32
scsi_eh_2-231 [002] .... 357.541042: xhci_dbg_context_change:
Setting number of stream ctx array entries to 32
scsi_eh_2-231 [002] .... 357.541045: xhci_dbg_context_change:
Setting number of stream ctx array entries to 32
<idle>-0 [003] d.h. 357.541353: xhci_cmd_completion:
trb_dma=@26e01aba0, trb_va=@ffff8dcc6e01aba0, status=01000000, flags=02008400
scsi_eh_2-231 [002] .... 357.541389: xhci_dbg_context_change:
Successful Endpoint Configure command
device 1 sectio-3419 [002] d... 368.184484: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc6f68f800, dev 5.2, ep 0x84, starting at offset 0x1ebb0df00
device 1 sectio-3419 [002] d.h. 368.184539: xhci_cmd_completion:
trb_dma=@26e01abb0, trb_va=@ffff8dcc6e01abb0, status=01000000, flags=04008400
device 1 sectio-3419 [002] d.h. 368.184545: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x1ebb0df00 (dma).
.
.
.
device 1 sectio-3419 [002] d.h. 368.184828: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x213968300 (dma).
device 1 sectio-3419 [002] d... 368.184871: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc6f68c000, dev 5.2, ep 0x84, starting at offset 0x213968310
<idle>-0 [002] d.h. 368.184920: xhci_cmd_completion:
trb_dma=@26e01abc0, trb_va=@ffff8dcc6e01abc0, status=01000000, flags=04008400
<idle>-0 [002] d.h. 368.184924: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x213968310 (dma).
.
.
.
<idle>-0 [002] d.h. 368.185233: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x213968700 (dma).
device 1 sectio-3419 [002] d... 368.185316: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc6f68c800, dev 5.2, ep 0x84, starting at offset 0x1ebb0d320
<idle>-0 [002] d.h. 368.185366: xhci_cmd_completion:
trb_dma=@26e01abd0, trb_va=@ffff8dcc6e01abd0, status=01000000, flags=04008400
<idle>-0 [002] d.h. 368.185370: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x1ebb0d320 (dma).
<idle>-0 [002] d.h. 368.185375: xhci_dbg_cancel_urb: Finding
endpoint context
<idle>-0 [002] d.h. 368.185380: xhci_dbg_cancel_urb: Cycle
state = 0x1
<idle>-0 [002] d.h. 368.185387: xhci_dbg_cancel_urb: New
dequeue segment = ffff8dcbde530980 (virtual)
<idle>-0 [002] d.h. 368.185391: xhci_dbg_cancel_urb: New
dequeue pointer = 0x1ebb0d330 (DMA)
<idle>-0 [002] d.h. 368.185394: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x1ebb0d330 (dma).
.
.
.
<idle>-0 [002] d.h. 368.185663: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x1ebb0d6f0 (dma).
<idle>-0 [002] d.h. 368.185669: xhci_dbg_cancel_urb: Set TR Deq
Ptr cmd, new deq seg = ffff8dcbde530980 (0x1ebb0d000 dma), new deq ptr =
ffff8dcbebb0d330 (0x1ebb0d330 dma), new cycle = 1
<idle>-0 [002] dNh. 368.185716: xhci_cmd_completion:
trb_dma=@26e01abe0, trb_va=@ffff8dcc6e01abe0, status=01000000, flags=04008400
<idle>-0 [002] dNh. 368.185720: xhci_dbg_cancel_urb: Successful
Set TR Deq Ptr cmd, deq = @1ebb0d330
device 1 sectio-3419 [002] d... 368.185774: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc6f689800, dev 5.2, ep 0x84, starting at offset 0x1ebb0d700
<idle>-0 [003] d.h. 368.185893: xhci_cmd_completion:
trb_dma=@26e01abf0, trb_va=@ffff8dcc6e01abf0, status=01000000, flags=04008400
<idle>-0 [003] d.h. 368.185899: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x1ebb0d700 (dma).
<idle>-0 [003] d.h. 368.185907: xhci_dbg_cancel_urb: Finding
endpoint context
<idle>-0 [003] d.h. 368.185916: xhci_dbg_cancel_urb: Cycle
state = 0x1
<idle>-0 [003] d.h. 368.185921: xhci_dbg_cancel_urb: New
dequeue segment = ffff8dcbde530980 (virtual)
<idle>-0 [003] d.h. 368.185928: xhci_dbg_cancel_urb: New
dequeue pointer = 0x1ebb0d710 (DMA)
<idle>-0 [003] d.h. 368.185931: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x1ebb0d710 (dma).
.
.
.
<idle>-0 [003] d.h. 368.186192: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x1ebb0daf0 (dma).
<idle>-0 [003] d.h. 368.186197: xhci_dbg_cancel_urb: Set TR Deq
Ptr cmd, new deq seg = ffff8dcbde530980 (0x1ebb0d000 dma), new deq ptr =
ffff8dcbebb0d710 (0x1ebb0d710 dma), new cycle = 1
device 1 sectio-3419 [002] d... 368.186266: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc6f688800, dev 5.2, ep 0x84, starting at offset 0x1ebb0db00
<idle>-0 [003] dNh. 368.186289: xhci_cmd_completion:
trb_dma=@26e01ac00, trb_va=@ffff8dcc6e01ac00, status=01000000, flags=04008400
<idle>-0 [003] dNh. 368.186295: xhci_dbg_cancel_urb: Successful
Set TR Deq Ptr cmd, deq = @1ebb0d710
<idle>-0 [003] dNh. 368.186309: xhci_cmd_completion:
trb_dma=@26e01ac10, trb_va=@ffff8dcc6e01ac10, status=13000000, flags=04008400
<idle>-0 [003] dNh. 368.186314: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x1ebb0db00 (dma).
.
.
.
<idle>-0 [003] dNh. 368.186569: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x1ebb0def0 (dma).
<idle>-0 [002] d.h. 369.294121: xhci_cmd_completion:
trb_dma=@26e01ac20, trb_va=@ffff8dcc6e01ac20, status=01000000, flags=04008401
device 1 sectio-3419 [002] .... 369.294178: xhci_dbg_context_change:
Successful Endpoint Configure command
<idle>-0 [002] dNh. 369.318878: xhci_dbg_ring_expansion: ERROR
no room on ep ring, try ring expansion
<idle>-0 [002] dNh. 369.318941: xhci_dbg_ring_expansion: ring
expansion succeed, now has 4 segments
device 1 sectio-3419 [002] d... 389.255045: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc6f68f800, dev 5.2, ep 0x84, starting at offset 0x1f6e22330
device 1 sectio-3419 [002] d.h. 389.255092: xhci_cmd_completion:
trb_dma=@26e01ac30, trb_va=@ffff8dcc6e01ac30, status=01000000, flags=04008401
device 1 sectio-3419 [002] d.h. 389.255096: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x1f6e22340 (dma).
device 1 sectio-3419 [002] d.h. 389.255105: xhci_dbg_cancel_urb: Finding
endpoint context
device 1 sectio-3419 [002] d.h. 389.255108: xhci_dbg_cancel_urb: Cycle
state = 0x1
device 1 sectio-3419 [002] d.h. 389.255111: xhci_dbg_cancel_urb: New
dequeue segment = ffff8dcbe159a140 (virtual)
device 1 sectio-3419 [002] d.h. 389.255115: xhci_dbg_cancel_urb: New
dequeue pointer = 0x1f6e22350 (DMA)
device 1 sectio-3419 [002] d.h. 389.255118: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x1f6e22350 (dma).
.
.
.
device 1 sectio-3419 [002] d.h. 389.255395: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x1f6e22710 (dma).
device 1 sectio-3419 [002] d.h. 389.255405: xhci_dbg_cancel_urb: Set TR Deq
Ptr cmd, new deq seg = ffff8dcbe159a140 (0x1f6e22000 dma), new deq ptr =
ffff8dcbf6e22350 (0x1f6e22350 dma), new cycle = 1
device 1 sectio-3419 [002] d.h. 389.255443: xhci_cmd_completion:
trb_dma=@26e01ac40, trb_va=@ffff8dcc6e01ac40, status=01000000, flags=04008401
device 1 sectio-3419 [002] d.h. 389.255446: xhci_dbg_cancel_urb: Successful
Set TR Deq Ptr cmd, deq = @1f6e22350
device 1 sectio-3419 [002] d... 389.255620: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc6f68c000, dev 5.2, ep 0x84, starting at offset 0x1f6e22720
<idle>-0 [002] d.h. 389.255725: xhci_cmd_completion:
trb_dma=@26e01ac50, trb_va=@ffff8dcc6e01ac50, status=01000000, flags=04008401
<idle>-0 [002] d.h. 389.255734: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x1f6e22720 (dma).
<idle>-0 [002] d.h. 389.255740: xhci_dbg_cancel_urb: Finding
endpoint context
<idle>-0 [002] d.h. 389.255747: xhci_dbg_cancel_urb: Cycle
state = 0x1
<idle>-0 [002] d.h. 389.255751: xhci_dbg_cancel_urb: New
dequeue segment = ffff8dcbe159a140 (virtual)
<idle>-0 [002] d.h. 389.255755: xhci_dbg_cancel_urb: New
dequeue pointer = 0x1f6e22730 (DMA)
<idle>-0 [002] d.h. 389.255758: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x1f6e22730 (dma).
.
.
.
<idle>-0 [002] d.h. 389.256044: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x1f6e22b10 (dma).
<idle>-0 [002] d.h. 389.256048: xhci_dbg_cancel_urb: Set TR Deq
Ptr cmd, new deq seg = ffff8dcbe159a140 (0x1f6e22000 dma), new deq ptr =
ffff8dcbf6e22730 (0x1f6e22730 dma), new cycle = 1
<idle>-0 [002] dNh. 389.256102: xhci_cmd_completion:
trb_dma=@26e01ac60, trb_va=@ffff8dcc6e01ac60, status=01000000, flags=04008401
<idle>-0 [002] dNh. 389.256106: xhci_dbg_cancel_urb: Successful
Set TR Deq Ptr cmd, deq = @1f6e22730
device 1 sectio-3419 [002] d... 389.256137: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc6f68c800, dev 5.2, ep 0x84, starting at offset 0x1f6e22b20
<idle>-0 [002] d.h. 389.256187: xhci_cmd_completion:
trb_dma=@26e01ac70, trb_va=@ffff8dcc6e01ac70, status=01000000, flags=04008401
<idle>-0 [002] d.h. 389.256190: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x1f6e22b20 (dma).
.
.
.
<idle>-0 [002] d.h. 389.256363: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x1f6e22f10 (dma).
device 1 sectio-3419 [002] d... 389.256408: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc6f689800, dev 5.2, ep 0x84, starting at offset 0x1f6e22f20
<idle>-0 [003] d.h. 389.256623: xhci_cmd_completion:
trb_dma=@26e01ac80, trb_va=@ffff8dcc6e01ac80, status=01000000, flags=04008400
<idle>-0 [003] d.h. 389.256629: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x1f6e22f20 (dma).
<idle>-0 [003] d.h. 389.256636: xhci_dbg_cancel_urb: Finding
endpoint context
<idle>-0 [003] d.h. 389.256645: xhci_dbg_cancel_urb: Cycle
state = 0x1
<idle>-0 [003] d.h. 389.256649: xhci_dbg_cancel_urb: New
dequeue segment = ffff8dcbe159a140 (virtual)
<idle>-0 [003] d.h. 389.256653: xhci_dbg_cancel_urb: New
dequeue pointer = 0x1f6e22f30 (DMA)
<idle>-0 [003] d.h. 389.256662: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x1f6e22f30 (dma).
.
.
.
<idle>-0 [003] d.h. 389.256841: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x1f4167320 (dma).
<idle>-0 [003] d.h. 389.256846: xhci_dbg_cancel_urb: Set TR Deq
Ptr cmd, new deq seg = ffff8dcbe159a140 (0x1f6e22000 dma), new deq ptr =
ffff8dcbf6e22f30 (0x1f6e22f30 dma), new cycle = 1
<idle>-0 [003] d.h. 389.256894: xhci_cmd_completion:
trb_dma=@26e01ac90, trb_va=@ffff8dcc6e01ac90, status=01000000, flags=04008400
<idle>-0 [003] d.h. 389.256898: xhci_dbg_cancel_urb: Successful
Set TR Deq Ptr cmd, deq = @1f6e22f30
device 1 sectio-3419 [002] d... 389.256913: xhci_dbg_cancel_urb: Cancel URB
ffff8dcc6f688800, dev 5.2, ep 0x84, starting at offset 0x1f4167330
<idle>-0 [002] d.h. 389.257010: xhci_cmd_completion:
trb_dma=@26e01aca0, trb_va=@ffff8dcc6e01aca0, status=01000000, flags=04008400
<idle>-0 [002] d.h. 389.257014: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x1f4167330 (dma).
<idle>-0 [002] d.h. 389.257018: xhci_dbg_cancel_urb: Finding
endpoint context
<idle>-0 [002] d.h. 389.257024: xhci_dbg_cancel_urb: Cycle
state = 0x1
<idle>-0 [002] d.h. 389.257030: xhci_dbg_cancel_urb: New
dequeue segment = ffff8dcbe159a440 (virtual)
<idle>-0 [002] d.h. 389.257033: xhci_dbg_cancel_urb: New
dequeue pointer = 0x1f4167340 (DMA)
<idle>-0 [002] d.h. 389.257036: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x1f4167340 (dma).
.
.
. <idle>-0 [002] d.h. 389.257232: xhci_dbg_cancel_urb: Removing
canceled TD starting at 0x1f4167720 (dma).
<idle>-0 [002] d.h. 389.257236: xhci_dbg_cancel_urb: Set TR Deq
Ptr cmd, new deq seg = ffff8dcbe159a440 (0x1f4167000 dma), new deq ptr =
ffff8dcbf4167340 (0x1f4167340 dma), new cycle = 1
<idle>-0 [002] dNh. 389.257275: xhci_cmd_completion:
trb_dma=@26e01acb0, trb_va=@ffff8dcc6e01acb0, status=01000000, flags=04008400
<idle>-0 [002] dNh. 389.257278: xhci_dbg_cancel_urb: Successful
Set TR Deq Ptr cmd, deq = @1f4167340
<idle>-0 [002] d.h. 390.364871: xhci_cmd_completion:
trb_dma=@26e01acc0, trb_va=@ffff8dcc6e01acc0, status=01000000, flags=04008401
device 1 sectio-3419 [002] .... 390.364947: xhci_dbg_context_change:
Successful Endpoint Configure command
<idle>-0 [002] d.h. 390.389754: xhci_dbg_ring_expansion: ERROR
no room on ep ring, try ring expansion
<idle>-0 [002] d.h. 390.389820: xhci_dbg_ring_expansion: ring
expansion succeed, now has 4 segments
the accompaining kernel messages are:
May 24 20:34:11 gserv kernel: [ 324.868069] xhci_hcd 0000:00:14.0: ERROR
Transfer event for disabled endpoint or incorrect stream ring
May 24 20:34:11 gserv kernel: [ 324.868193] xhci_hcd 0000:00:14.0:
@000000026e01ce90 00000000 00000000 04000000 02088000
May 24 20:34:42 gserv kernel: [ 355.356457] sd 2:0:0:0: [sdb] tag#12
uas_eh_abort_handler 0 uas-tag 4 inflight: CMD IN
May 24 20:34:42 gserv kernel: [ 355.356478] sd 2:0:0:0: [sdb] tag#12 CDB:
Read(16) 88 00 00 00 00 00 74 e7 9f e0 00 00 01 00 00 00
May 24 20:34:42 gserv kernel: [ 355.356763] sd 2:0:0:0: [sdb] tag#8
uas_eh_abort_handler 0 uas-tag 8 inflight: CMD IN
May 24 20:34:42 gserv kernel: [ 355.356784] sd 2:0:0:0: [sdb] tag#8 CDB:
Read(16) 88 00 00 00 00 00 74 e7 9e e0 00 00 01 00 00 00
May 24 20:34:42 gserv kernel: [ 355.356970] sd 2:0:0:0: [sdb] tag#13
uas_eh_abort_handler 0 uas-tag 2 inflight: CMD IN
May 24 20:34:42 gserv kernel: [ 355.356989] sd 2:0:0:0: [sdb] tag#13 CDB:
Read(16) 88 00 00 00 00 00 74 e7 9d e0 00 00 01 00 00 00
May 24 20:34:44 gserv kernel: [ 357.392211] sd 2:0:0:2: [sdd] tag#4
uas_eh_abort_handler 0 uas-tag 5 inflight: CMD OUT
May 24 20:34:44 gserv kernel: [ 357.392233] sd 2:0:0:2: [sdd] tag#4 CDB:
Write(16) 8a 00 00 00 00 00 e8 10 25 f8 00 00 01 00 00 00
May 24 20:34:44 gserv kernel: [ 357.392535] scsi host2:
uas_eh_bus_reset_handler start
May 24 20:34:44 gserv kernel: [ 357.395671] sd 2:0:0:1: [sdc] tag#3
uas_zap_pending 0 uas-tag 1 inflight: CMD
May 24 20:34:44 gserv kernel: [ 357.395693] sd 2:0:0:1: [sdc] tag#3 CDB:
Write(16) 8a 00 00 00 00 00 e8 10 27 f8 00 00 02 00 00 00
May 24 20:34:44 gserv kernel: [ 357.395714] sd 2:0:0:1: [sdc] tag#1
uas_zap_pending 0 uas-tag 3 inflight: CMD
May 24 20:34:44 gserv kernel: [ 357.395726] sd 2:0:0:1: [sdc] tag#1 CDB:
Write(16) 8a 00 00 00 00 00 e8 10 26 f8 00 00 01 00 00 00
May 24 20:34:44 gserv kernel: [ 357.395741] sd 2:0:0:1: [sdc] tag#6
uas_zap_pending 0 uas-tag 6 inflight: CMD
May 24 20:34:44 gserv kernel: [ 357.395753] sd 2:0:0:1: [sdc] tag#6 CDB:
Write(16) 8a 00 00 00 00 00 e8 10 24 f8 00 00 01 00 00 00
May 24 20:34:44 gserv kernel: [ 357.395771] sd 2:0:0:2: [sdd] tag#2
uas_zap_pending 0 uas-tag 7 inflight: CMD
May 24 20:34:44 gserv kernel: [ 357.395783] sd 2:0:0:2: [sdd] tag#2 CDB:
Write(16) 8a 00 00 00 00 00 e8 10 27 f8 00 00 01 00 00 00
May 24 20:34:44 gserv kernel: [ 357.395798] sd 2:0:0:2: [sdd] tag#9
uas_zap_pending 0 uas-tag 9 inflight: CMD
May 24 20:34:44 gserv kernel: [ 357.395809] sd 2:0:0:2: [sdd] tag#9 CDB:
Write(16) 8a 00 00 00 00 00 e8 10 2b f8 00 00 01 00 00 00
May 24 20:34:44 gserv kernel: [ 357.395825] sd 2:0:0:2: [sdd] tag#11
uas_zap_pending 0 uas-tag 10 inflight: CMD
May 24 20:34:44 gserv kernel: [ 357.395837] sd 2:0:0:2: [sdd] tag#11 CDB:
Write(16) 8a 00 00 00 00 00 e8 10 2c f8 00 00 01 00 00 00
May 24 20:34:44 gserv kernel: [ 357.395854] sd 2:0:0:1: [sdc] tag#10
uas_zap_pending 0 uas-tag 11 inflight: CMD
May 24 20:34:44 gserv kernel: [ 357.395866] sd 2:0:0:1: [sdc] tag#10 CDB:
Write(16) 8a 00 00 00 00 00 e8 10 23 f8 00 00 01 00 00 00
May 24 20:34:44 gserv kernel: [ 357.395881] sd 2:0:0:2: [sdd] tag#7
uas_zap_pending 0 uas-tag 12 inflight: CMD
May 24 20:34:44 gserv kernel: [ 357.395893] sd 2:0:0:2: [sdd] tag#7 CDB:
Write(16) 8a 00 00 00 00 00 e8 10 26 f8 00 00 01 00 00 00
May 24 20:34:44 gserv kernel: [ 357.395908] sd 2:0:0:2: [sdd] tag#5
uas_zap_pending 0 uas-tag 13 inflight: CMD
May 24 20:34:44 gserv kernel: [ 357.395919] sd 2:0:0:2: [sdd] tag#5 CDB:
Write(16) 8a 00 00 00 00 00 e8 10 28 f8 00 00 03 00 00 00
May 24 20:34:44 gserv kernel: [ 357.395937] sd 2:0:0:1: [sdc] tag#0
uas_zap_pending 0 uas-tag 14 inflight: CMD
May 24 20:34:44 gserv kernel: [ 357.395948] sd 2:0:0:1: [sdc] tag#0 CDB:
Write(16) 8a 00 00 00 00 00 e8 10 25 f8 00 00 01 00 00 00
May 24 20:34:44 gserv kernel: [ 357.516558] usb 2-2: reset SuperSpeed USB
device number 2 using xhci_hcd
May 24 20:34:44 gserv kernel: [ 357.541482] scsi host2:
uas_eh_bus_reset_handler success
May 24 20:34:44 gserv kernel: [ 357.542678] sd 2:0:0:2: [sdd] tag#4 FAILED
Result: hostbyte=DID_TIME_OUT driverbyte=DRIVER_OK
May 24 20:34:44 gserv kernel: [ 357.542720] sd 2:0:0:2: [sdd] tag#4 CDB:
Write(16) 8a 00 00 00 00 00 e8 10 25 f8 00 00 01 00 00 00
May 24 20:34:44 gserv kernel: [ 357.542736] blk_update_request: I/O error, dev
sdd, sector 3893372408
May 24 20:34:49 gserv kernel: [ 363.136196] xhci_hcd 0000:00:14.0: ERROR
Transfer event for disabled endpoint or incorrect stream ring
May 24 20:34:49 gserv kernel: [ 363.136468] xhci_hcd 0000:00:14.0:
@000000026e01cb00 00000000 00000000 04000000 02088001
…
does that tell anything?
Cheers,
Christoph
--
Christoph Gohle
christ...@gohle.org
signature.asc
Description: Message signed with OpenPGP using GPGMail
