xhci-hcd errors with Qualcomm based modem and Asmedia ASM1042A

xhci-hcd errors with Qualcomm based modem and Asmedia ASM1042A

[Daniele Palmas]

Hello all,

I've a system with kernel 4.14.127 that is showing unexpected xhci-hcd
(ASM1042A) errors with a Qualcomm based modem, when running the
following test:

- signal strength qmi requests looping every few seconds on
/dev/cdc-wdm (driver qmi_wwan)
- iperf tcp data connection test on the modem network interface

The issue is showing also with kernel 5.0

The issues is showing in three different ways:

First one:

2019-07-24 15:17:45.495293 kern.err kernel:xhci_hcd 0000:03:00.0:
ERROR Transfer event TRB DMA ptr not part of current TD ep_index 28
comp_code 13
2019-07-24 15:17:45.495392 kern.warning kernel:xhci_hcd 0000:03:00.0:
Looking for event-dma 000000007725b420 trb-start 000000007725b400
trb-end 000000007725b400 seg-start 000000007725b000 seg-end
000000007725bff0

The full kernel log is available at
https://drive.google.com/open?id=1FBjGhnc65vYks4MeOjliwmxA3FmCNbKw

usb devices list is availabe at
https://drive.google.com/open?id=1UgtwOaxGBcMc71CeOrlhxzPiHIADu1Cr

Second one:

2019-07-24 17:24:09.588826 kern.debug kernel:xhci_hcd 0000:03:00.0:
Set TR Deq Ptr cmd, new deq seg = ffff95c865e4e340 (0x77729000 dma),
new deq ptr = ffff95c877729fc0 (0x77729fc0 dma), new cycle = 0
2019-07-24 17:24:09.588838 kern.warning kernel:xhci_hcd 0000:03:00.0:
WARN Cannot submit Set TR Deq Ptr
2019-07-24 17:24:09.588847 kern.warning kernel:xhci_hcd 0000:03:00.0:
A Set TR Deq Ptr command is pending.
2019-07-24 17:24:09.588855 kern.debug kernel:xhci_hcd 0000:03:00.0: //
Ding dong!
2019-07-24 17:24:09.588863 kern.debug kernel:xhci_hcd 0000:03:00.0:
Giveback URB ffff95c84f01e900, len = 0, expected = 1500, status = -71
2019-07-24 17:24:09.650800 kern.debug kernel:xhci_hcd 0000:03:00.0:
WARN halted endpoint, queueing URB anyway.
2019-07-24 17:24:09.650861 kern.debug kernel:xhci_hcd 0000:03:00.0:
WARN halted endpoint, queueing URB anyway.
2019-07-24 17:24:09.653715 kern.debug kernel:xhci_hcd 0000:03:00.0:
Transfer error for slot 3 ep 29 on endpoint
2019-07-24 17:24:09.653774 kern.debug kernel:xhci_hcd 0000:03:00.0:
Cleaning up stalled endpoint ring
2019-07-24 17:24:09.653786 kern.debug kernel:xhci_hcd 0000:03:00.0:
Finding endpoint context
2019-07-24 17:24:09.653794 kern.debug kernel:xhci_hcd 0000:03:00.0:
Cycle state = 0x0
2019-07-24 17:24:09.653802 kern.debug kernel:xhci_hcd 0000:03:00.0:
New dequeue segment = ffff95c865e4e340 (virtual)
2019-07-24 17:24:09.653812 kern.debug kernel:xhci_hcd 0000:03:00.0:
New dequeue pointer = 0x77729fd0 (DMA)
2019-07-24 17:24:09.653822 kern.debug kernel:xhci_hcd 0000:03:00.0:
Queueing new dequeue state
2019-07-24 17:24:09.653863 kern.debug kernel:xhci_hcd 0000:03:00.0:
Set TR Deq Ptr cmd, new deq seg = ffff95c865e4e340 (0x77729000 dma),
new deq ptr = ffff95c877729fd0 (0x77729fd0 dma), new cycle = 0

The full kernel log is available at
https://drive.google.com/open?id=1zNQa-nGLA3F_5yka8c0-syUBcTe4L8W2

usb devices list is availabe at
https://drive.google.com/open?id=19bfAUfgF-jtiF--7eHgTo00mfwnLWMyf

Third one:

2019-07-24 17:41:45.233364 kern.debug kernel:xhci_hcd 0000:03:00.0: //
Ding dong!
2019-07-24 17:41:45.233372 kern.debug kernel:xhci_hcd 0000:03:00.0:
Giveback URB ffff95c84d46ce40, len = 0, expected = 1514, status = -71
2019-07-24 17:41:45.234647 kern.debug kernel:xhci_hcd 0000:03:00.0:
Ignoring reset ep completion code of 1
2019-07-24 17:41:45.237145 kern.debug kernel:xhci_hcd 0000:03:00.0:
Successful Set TR Deq Ptr cmd, deq = @777e7350
2019-07-24 17:41:45.242662 kern.debug kernel:xhci_hcd 0000:03:00.0:
Transfer error for slot 3 ep 28 on endpoint
2019-07-24 17:41:45.242698 kern.debug kernel:xhci_hcd 0000:03:00.0:
Cleaning up stalled endpoint ring
2019-07-24 17:41:45.242705 kern.debug kernel:xhci_hcd 0000:03:00.0:
Finding endpoint context
2019-07-24 17:41:45.242709 kern.debug kernel:xhci_hcd 0000:03:00.0:
Cycle state = 0x1
2019-07-24 17:41:45.242712 kern.debug kernel:xhci_hcd 0000:03:00.0:
New dequeue segment = ffff95c84f01dcc0 (virtual)
2019-07-24 17:41:45.242717 kern.debug kernel:xhci_hcd 0000:03:00.0:
New dequeue pointer = 0x777e7360 (DMA)
2019-07-24 17:41:45.242721 kern.debug kernel:xhci_hcd 0000:03:00.0:
Queueing new dequeue state
2019-07-24 17:41:45.242726 kern.debug kernel:xhci_hcd 0000:03:00.0:
Set TR Deq Ptr cmd, new deq seg = ffff95c84f01dcc0 (0x777e7000 dma),
new deq ptr = ffff95c8777e7360 (0x777e7360 dma), new cycle = 1

The full kernel log is available at
https://drive.google.com/file/d/1r4lyF6mcXJXwaAKb2dxIptMTsWCbxALg/view?usp=sharing

I'm not expert enough to understand if this is an xhci host issue or a
device one. Can someone help on this?

Thanks in advance,
Daniele

Re: xhci-hcd errors with Qualcomm based modem and Asmedia ASM1042A

[Mathias Nyman]

On 24.7.2019 22.09, Daniele Palmas wrote:
> Hello all,
> 
> I've a system with kernel 4.14.127 that is showing unexpected xhci-hcd
> (ASM1042A) errors with a Qualcomm based modem, when running the
> following test:
> 
> - signal strength qmi requests looping every few seconds on
> /dev/cdc-wdm (driver qmi_wwan)
> - iperf tcp data connection test on the modem network interface
> 
> The issue is showing also with kernel 5.0
> 
> The issues is showing in three different ways:
> 
> First one:
> 
> 2019-07-24 15:17:45.495293 kern.err kernel:xhci_hcd 0000:03:00.0:
> ERROR Transfer event TRB DMA ptr not part of current TD ep_index 28
> comp_code 13


> 2019-07-24 15:17:45.495392 kern.warning kernel:xhci_hcd 0000:03:00.0:
> Looking for event-dma 000000007725b420 trb-start 000000007725b400
> trb-end 000000007725b400 seg-start 000000007725b000 seg-end
> 000000007725bff0

The xhci driver expects events for transfers in the same order they were
queued. For some reason we get an event for the transfer block queued at
address b420 before we get events for transfers at b400 and b410.

xhci traces of a 5.0 kernel would show in more detail what's going on.
can be taken with:

mount -t debugfs none /sys/kernel/debug
echo 'module xhci_hcd =p' >/sys/kernel/debug/dynamic_debug/control
echo 'module usbcore =p' >/sys/kernel/debug/dynamic_debug/control
echo 81920 > /sys/kernel/debug/tracing/buffer_size_kb
echo 1 > /sys/kernel/debug/tracing/events/xhci-hcd/enable
< reproduce the issue >
Send output of dmesg
Send content of /sys/kernel/debug/tracing/trace

Note that the trace file can be huge

-Mathias

Re: xhci-hcd errors with Qualcomm based modem and Asmedia ASM1042A

[Daniele Palmas]

Hi Mathias,

Il giorno ven 26 lug 2019 alle ore 10:50 Mathias Nyman
<mathias.nyman@linux.intel.com> ha scritto:
>
> On 24.7.2019 22.09, Daniele Palmas wrote:
> > Hello all,
> >
> > I've a system with kernel 4.14.127 that is showing unexpected xhci-hcd
> > (ASM1042A) errors with a Qualcomm based modem, when running the
> > following test:
> >
> > - signal strength qmi requests looping every few seconds on
> > /dev/cdc-wdm (driver qmi_wwan)
> > - iperf tcp data connection test on the modem network interface
> >
> > The issue is showing also with kernel 5.0
> >
> > The issues is showing in three different ways:
> >
> > First one:
> >
> > 2019-07-24 15:17:45.495293 kern.err kernel:xhci_hcd 0000:03:00.0:
> > ERROR Transfer event TRB DMA ptr not part of current TD ep_index 28
> > comp_code 13
>
>
> > 2019-07-24 15:17:45.495392 kern.warning kernel:xhci_hcd 0000:03:00.0:
> > Looking for event-dma 000000007725b420 trb-start 000000007725b400
> > trb-end 000000007725b400 seg-start 000000007725b000 seg-end
> > 000000007725bff0
>
> The xhci driver expects events for transfers in the same order they were
> queued. For some reason we get an event for the transfer block queued at
> address b420 before we get events for transfers at b400 and b410.
>
> xhci traces of a 5.0 kernel would show in more detail what's going on.
> can be taken with:
>
> mount -t debugfs none /sys/kernel/debug
> echo 'module xhci_hcd =p' >/sys/kernel/debug/dynamic_debug/control
> echo 'module usbcore =p' >/sys/kernel/debug/dynamic_debug/control
> echo 81920 > /sys/kernel/debug/tracing/buffer_size_kb
> echo 1 > /sys/kernel/debug/tracing/events/xhci-hcd/enable
> < reproduce the issue >
> Send output of dmesg
> Send content of /sys/kernel/debug/tracing/trace
>
> Note that the trace file can be huge
>

thanks for the explanation.

For 4.14.127 I already gathered traces related to that dmesg (you can
find them at https://drive.google.com/open?id=1c-vjusa44UgMzrIjAvpz6HKbxEk1Trw1),
but I'll try to get the same info for 5.

Thanks,
Daniele

> -Mathias