andrum99
Posts: 778
Joined: Fri Jul 20, 2012 2:41 pm

USB problem on Pi 4B

Fri Jul 19, 2019 4:34 pm

I've got a strange problem with my Pi 4B. I am powering it with the official type C power supply with a single monitor attached via HDMI 0 and an HDMI to VGA adaptor. I've also got an official Raspberry Pi keyboard in one USB 2 socket, and an official mouse in the other USB 2 socket. I have a USB 3.0 hub connected to one of the USB 3.0 sockets on the Pi. Attached to the USB 3.0 hub are two hard disks in USB 3.0 enclosures, which I have previously used successfully with my Pi 3B and Pi 3B+. The problem I have encountered is that the Pi 4B did odd things when I typed on the keyboard, but only for a short period of time. It was working fine, went wonky for about 15 seconds, then started working fine again. In the log I see this:

Code: Select all

Jul 19 16:21:03 pi4b kernel: [   74.246901] xhci_hcd 0000:01:00.0: ERROR unknown event type 37
Jul 19 16:21:07 pi4b kernel: [   75.881403] xhci_hcd 0000:01:00.0: ERROR unknown event type 37
Jul 19 16:21:07 pi4b kernel: [   77.004496] xhci_hcd 0000:01:00.0: ERROR unknown event type 37
Jul 19 16:21:08 pi4b kernel: [   79.446641] xhci_hcd 0000:01:00.0: ERROR unknown event type 37
Jul 19 16:21:11 pi4b kernel: [   80.982340] xhci_hcd 0000:01:00.0: ERROR unknown event type 37
Jul 19 16:21:11 pi4b kernel: [   82.081034] xhci_hcd 0000:01:00.0: ERROR unknown event type 37
Jul 19 16:21:13 pi4b kernel: [   83.720325] xhci_hcd 0000:01:00.0: ERROR unknown event type 37
Jul 19 16:21:13 pi4b kernel: [   84.330990] xhci_hcd 0000:01:00.0: ERROR unknown event type 37
Jul 19 16:21:16 pi4b kernel: [   85.784313] xhci_hcd 0000:01:00.0: ERROR unknown event type 37
Jul 19 16:21:16 pi4b kernel: [   86.815015] xhci_hcd 0000:01:00.0: ERROR unknown event type 37
Jul 19 16:21:19 pi4b kernel: [   89.667696] xhci_hcd 0000:01:00.0: ERROR unknown event type 37
Jul 19 16:21:19 pi4b kernel: [   90.218486] xhci_hcd 0000:01:00.0: ERROR unknown event type 37
Jul 19 16:21:22 pi4b kernel: [   91.323935] xhci_hcd 0000:01:00.0: ERROR unknown event type 37
Jul 19 16:21:22 pi4b kernel: [   92.452037] xhci_hcd 0000:01:00.0: ERROR unknown event type 37
Jul 19 16:21:22 pi4b kernel: [   93.313910] xhci_hcd 0000:01:00.0: ERROR unknown event type 37
Jul 19 16:21:28 pi4b kernel: [   96.431742] xhci_hcd 0000:01:00.0: ERROR unknown event type 37
Jul 19 16:21:28 pi4b kernel: [   97.454892] xhci_hcd 0000:01:00.0: ERROR unknown event type 37
Jul 19 16:21:28 pi4b kernel: [   98.567170] xhci_hcd 0000:01:00.0: ERROR unknown event type 37
Jul 19 16:21:33 pi4b kernel: [  103.807832] xhci_hcd 0000:01:00.0: ERROR unknown event type 37
While I was typing on the keyboard, I was also writing to the two hard disks - they're set up as a RAID 1 array using mdadm. I was writing quite a lot of data - a DVD ISO image, although it was coming across the network so should not have been anywhere near saturating the USB 3.0 bus. Is this a known problem? The USB 3.0 hub is a D-Link DUB-1340 4-port hub with a 4A PSU. I've been using a different D-Link hub successfully with my Pi 3B+ and these hard disks, and before that my Pi 3B, without any issues, hence why I went for a D-Link for the new one. My Pi runs Raspbian Buster and is fully up-to-date with the latest packages.

jdb
Raspberry Pi Engineer & Forum Moderator
Raspberry Pi Engineer & Forum Moderator
Posts: 2076
Joined: Thu Jul 11, 2013 2:37 pm

Re: USB problem on Pi 4B

Fri Jul 19, 2019 5:41 pm

The error message is actually specified in the xHCI spec, the linux xhci-hcd driver just doesn't handle it. It means "xHC tried to write to the event ring buffer but the event ring buffer was full".

The event ring buffer is a proxy for interrupts - if a bunch of stuff happens on USB then the hardware will write several entries to the ring buffer and then interrupt the host processor after the interrupt ratelimit timeout of 40 microseconds. If more events happen in the 40us than there are free slots in the ring, then you drop events. You also drop events if the kernel doesn't service the ring and fails to advance the "dequeue pointer" which points to the last event serviced.

Can you try migrating the xHCI interrupt to a different core? echo 4 | sudo tee /proc/irq/55/smp_affinity?
Rockets are loud.
https://astro-pi.org

andrum99
Posts: 778
Joined: Fri Jul 20, 2012 2:41 pm

Re: USB problem on Pi 4B

Fri Jul 19, 2019 6:20 pm

jdb wrote:
Fri Jul 19, 2019 5:41 pm
Can you try migrating the xHCI interrupt to a different core? echo 4 | sudo tee /proc/irq/55/smp_affinity?
I don't have an IRQ 55. How can I determine which IRQ the USB controller is using?

trejan
Posts: 526
Joined: Tue Jul 02, 2019 2:28 pm

Re: USB problem on Pi 4B

Fri Jul 19, 2019 6:41 pm

andrum99 wrote:
Fri Jul 19, 2019 6:20 pm
I don't have an IRQ 55. How can I determine which IRQ the USB controller is using?
"grep xhci /proc/interrupts"

andrum99
Posts: 778
Joined: Fri Jul 20, 2012 2:41 pm

Re: USB problem on Pi 4B

Fri Jul 19, 2019 6:44 pm

Echoing 2 to the correct IRQ seems to have fixed it, or perhaps it fixed itself.

andrum99
Posts: 778
Joined: Fri Jul 20, 2012 2:41 pm

Re: USB problem on Pi 4B

Tue Aug 06, 2019 11:59 am

Changing the core affinity seems to make no difference - I'm getting the same errors randomly on average about once every second or 2 writing a load of large files continuously to the hard discs attached to the Pi. I will try blacklisting it for UAS and see if that is any better. There doesn't seem to be any other problem - I'm no seeing ext4 complain, although I did see a couple of errors in the log from a few days ago for ext4.

I've also installed irqbalance but again, that made no difference. I'm on a 4GB Pi if that makes a difference. At the moment there is nothing except the powered USB 3 hub connected to the USB ports on the Pi - it's also running mostly headless for occasional Kodi use.
Last edited by andrum99 on Sat Aug 10, 2019 4:32 pm, edited 1 time in total.

jdb
Raspberry Pi Engineer & Forum Moderator
Raspberry Pi Engineer & Forum Moderator
Posts: 2076
Joined: Thu Jul 11, 2013 2:37 pm

Re: USB problem on Pi 4B

Sat Aug 10, 2019 2:47 pm

What's the output from vmstat 2 when the dmesg log spam is occurring? I would expect a high number of hardware interrupts per second.
Rockets are loud.
https://astro-pi.org

andrum99
Posts: 778
Joined: Fri Jul 20, 2012 2:41 pm

Re: USB problem on Pi 4B

Sat Aug 10, 2019 4:14 pm

jdb wrote:
Sat Aug 10, 2019 2:47 pm
What's the output from vmstat 2 when the dmesg log spam is occurring? I would expect a high number of hardware interrupts per second.
vmstat 2 shows this:

Code: Select all

procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 2  1 101940 104848  35740 3613932    0   84     4 72063 31924 2225  1 30 60  8  0
 1  0 102004  56596  35616 3662260    0   32     6 32803 33260 2191  1 33 62  5  0
 1  0 102152  80672  35500 3635212    0   74     4 57423 34441 2166  1 39 60  1  0
 0  2 102244  85812  35256 3633188    0   46     4 51853 18339 1750  1 30 43 26  0
 1  0 102396  90280  34612 3629032    0   76     4 49245 45854 2676  2 40 53  5  0
 0  1 102396  74828  34172 3636184    0    0     6 57121 29778 1691  0 30 61  8  0
 2  0 102396  84268  32900 3633208    2    2     8 48149 37004 1889  1 34 63  2  0
 2  0 102396  89096  32288 3631236    0    0     4 57394 34738 1977  1 29 69  0  0
 2  1 102396  76888  30900 3644252    0    0     4 68182 34500 2119  1 33 53 13  0
 1  0 102396  87592  29892 3636936    0    0     2 40963 28979 1633  1 27 70  3  0
 1  0 102396  84576  29052 3639644    0    0     4 57402 40020 2557  1 33 62  4  0
 3  0 102396  87256  28096 3637752    0    0    14 48035 33954 1853  1 29 59 11  0
 3  0 102396  64340  27216 3657996    0    0     6 57359 27448 1692  0 31 67  2  0
 1  1 102396  81436  26500 3640448    2    0     6 72298 27344 1859  1 31 52 16  0
 1  0 102396  77164  25612 3650924    0    2     2 32837 35158 1795  0 31 66  3  0
 2  0 102396  71888  23952 3657460    0    0     8 65581 38544 2760  1 38 51 10  0
 2  0 102396  83776  23092 3647096    0    0     4 52513 39396 2300  0 30 57 13  0
 2  0 102396  74568  22312 3653836    0    0     4 57382 30249 1930  0 33 65  2  0
 2  0 102396  86176  21512 3645012    0    0    54 61216 28917 1759  1 30 60  9  0
As well as samba transfers over the network, I'm also seeing this problem when doing local transfers that don't touch the network. I have a backup job that runs overnight, the first step of which uses tar and pigz to compress various files into one big tarball. Both the files being backed up, and the tarball itself, are stored on the RAID 1 array - the 2 USB 3.0 attached drives. The log spam only occurs when the tarball is being built, not when the resultant tarball is slowly uploaded to Google Drive using rclone over a broadband (VDSL2) line.

So it seems like any time there is high IO activity involving the USB 3 controller I get this spam in the logs.

andrum99
Posts: 778
Joined: Fri Jul 20, 2012 2:41 pm

Re: USB problem on Pi 4B

Sat Aug 10, 2019 4:31 pm

Here's the output of lsusb and lsusb -t for info:

lsusb:

Code: Select all

Bus 003 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 002 Device 003: ID 0480:b202 Toshiba America Inc
Bus 002 Device 004: ID 0480:b202 Toshiba America Inc
Bus 002 Device 002: ID 05e3:0617 Genesys Logic, Inc.
Bus 002 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 001 Device 003: ID 05e3:0610 Genesys Logic, Inc. 4-port hub
Bus 001 Device 002: ID 2109:3431 VIA Labs, Inc. Hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
The two 0480:b202 Toshiba America Inc devices are the external USB 3 2.5" SATA HDD enclosures with old laptop drives in them. Branded "Anker".

The D-Link USB 3.0 Hub is 05e3:0617 Genesys Logic, Inc. and has 4 downstream USB 3 ports, and its own 4A PSU.

lsusb -t:

Code: Select all

/:  Bus 03.Port 1: Dev 1, Class=root_hub, Driver=dwc_otg/1p, 480M
/:  Bus 02.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/4p, 5000M
    |__ Port 2: Dev 2, If 0, Class=Hub, Driver=hub/4p, 5000M
        |__ Port 1: Dev 4, If 0, Class=Mass Storage, Driver=uas, 5000M
        |__ Port 2: Dev 3, If 0, Class=Mass Storage, Driver=uas, 5000M
/:  Bus 01.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/1p, 480M
    |__ Port 1: Dev 2, If 0, Class=Hub, Driver=hub/4p, 480M
        |__ Port 2: Dev 3, If 0, Class=Hub, Driver=hub/4p, 480M

jdb
Raspberry Pi Engineer & Forum Moderator
Raspberry Pi Engineer & Forum Moderator
Posts: 2076
Joined: Thu Jul 11, 2013 2:37 pm

Re: USB problem on Pi 4B

Mon Aug 12, 2019 3:34 pm

Hm. A trb type code of 37 implies Host Controller Event but not necessarily "event ring full". More debug required.

Can you use this script:

Code: Select all

#!/bin/bash
set -e
while : ; do
        cat /sys/kernel/debug/usb/xhci/0000\:01\:00.0/event-ring/trbs | grep "Controller"
done
and run it as root until you get some output (when doing IO that causes dmesg spam)?
Rockets are loud.
https://astro-pi.org

andrum99
Posts: 778
Joined: Fri Jul 20, 2012 2:41 pm

Re: USB problem on Pi 4B

Mon Aug 12, 2019 3:57 pm

jdb wrote:
Mon Aug 12, 2019 3:34 pm
Hm. A trb type code of 37 implies Host Controller Event but not necessarily "event ring full". More debug required.

Can you use this script:

Code: Select all

#!/bin/bash
set -e
while : ; do
        cat /sys/kernel/debug/usb/xhci/0000\:01\:00.0/event-ring/trbs | grep "Controller"
done
and run it as root until you get some output (when doing IO that causes dmesg spam)?
Looks like you were right the first time - it is an event ring full error. I had to take out the set -e otherwise it dropped out of the infinite loop straight away:

Code: Select all

0x000000001ed05490: TRB 0000000000000000 status 'Event Ring Full Error' len 0 slot 0 ep 0 type 'Host Controller Event' flags e:C
0x000000001ed05490: TRB 0000000000000000 status 'Event Ring Full Error' len 0 slot 0 ep 0 type 'Host Controller Event' flags e:C
0x000000001ed05490: TRB 0000000000000000 status 'Event Ring Full Error' len 0 slot 0 ep 0 type 'Host Controller Event' flags e:C
0x000000001ed05490: TRB 0000000000000000 status 'Event Ring Full Error' len 0 slot 0 ep 0 type 'Host Controller Event' flags e:C
0x000000001ed05490: TRB 0000000000000000 status 'Event Ring Full Error' len 0 slot 0 ep 0 type 'Host Controller Event' flags e:C
0x000000001ed05770: TRB 0000000000000000 status 'Event Ring Full Error' len 0 slot 0 ep 0 type 'Host Controller Event' flags e:c
0x000000001ed05770: TRB 0000000000000000 status 'Event Ring Full Error' len 0 slot 0 ep 0 type 'Host Controller Event' flags e:c

jdb
Raspberry Pi Engineer & Forum Moderator
Raspberry Pi Engineer & Forum Moderator
Posts: 2076
Joined: Thu Jul 11, 2013 2:37 pm

Re: USB problem on Pi 4B

Mon Aug 12, 2019 4:15 pm

Linux allocates a single Event Ring Segment of size 4k, which corresponds to space for 256 event TRBs - if there are more than 256 events generated before the CPU services the xhci interrupt, then the host controller will stall processing of its command/transfer rings until the kernel acknowledges the events. In practice this results in throughput degradation.

The hardware supports up to 8 event segment rings - it would be sensible to adapt the driver to do something less rigidly constraining.
Rockets are loud.
https://astro-pi.org

andrum99
Posts: 778
Joined: Fri Jul 20, 2012 2:41 pm

Re: USB problem on Pi 4B

Mon Aug 12, 2019 4:32 pm

jdb wrote:
Mon Aug 12, 2019 4:15 pm
Linux allocates a single Event Ring Segment of size 4k, which corresponds to space for 256 event TRBs - if there are more than 256 events generated before the CPU services the xhci interrupt, then the host controller will stall processing of its command/transfer rings until the kernel acknowledges the events. In practice this results in throughput degradation.

The hardware supports up to 8 event segment rings - it would be sensible to adapt the driver to do something less rigidly constraining.
Should I raise this as a bug on https://github.com/raspberrypi/linux?

andrum99
Posts: 778
Joined: Fri Jul 20, 2012 2:41 pm

Re: USB problem on Pi 4B

Mon Aug 12, 2019 4:57 pm

I tried blacklisting the UAS module for that particular USB/SATA bridge - that got rid of the event ring full errors. I also noticed that the errors correspond to when the speed of the network transfers drops off, which is the expected behaviour. I will run with UAS blacklisted for now. Maybe there is some kind of bug in this particular USB to SATA bridge? The downside of running with the old MSD driver is that it uses more CPU, but on the Pi 4 we've got a lot more CPU to play with, so I can live with that for now.

jdb
Raspberry Pi Engineer & Forum Moderator
Raspberry Pi Engineer & Forum Moderator
Posts: 2076
Joined: Thu Jul 11, 2013 2:37 pm

Re: USB problem on Pi 4B

Mon Aug 12, 2019 6:01 pm

UAS can have multiple outstanding transfers at any one time, plus there is a separate completions pipe. The completions pipe could return very bursty data if the adapter returns completions out-of-order. I'm not surprised that the ring isn't filled when usb-storage is in use, as that has a single command/data pipe.
Rockets are loud.
https://astro-pi.org

jerrm
Posts: 168
Joined: Wed May 02, 2018 7:35 pm

Re: USB problem on Pi 4B

Mon Aug 12, 2019 6:04 pm

andrum99 wrote:
Mon Aug 12, 2019 4:57 pm
I will run with UAS blacklisted for now. Maybe there is some kind of bug in this particular USB to SATA bridge?
Maybe, but I wouldn't jump to that conclusion.

After trying multiple adapters, I've come to the conclusion something is "off" for USB3/UAS on the Pi. Several adapters that work great with uas under PC Buster need uas disabled on the Pi. I also don't see the same relative improvements between the uas/usb-storage as seen under PC Buster.

jdb
Raspberry Pi Engineer & Forum Moderator
Raspberry Pi Engineer & Forum Moderator
Posts: 2076
Joined: Thu Jul 11, 2013 2:37 pm

Re: USB problem on Pi 4B

Mon Aug 12, 2019 7:17 pm

jerrm wrote:
After trying multiple adapters, I've come to the conclusion something is "off" for USB3/UAS on the Pi. Several adapters that work great with uas under PC Buster need uas disabled on the Pi. I also don't see the same relative improvements between the uas/usb-storage as seen under PC Buster.
If you have specific hardware that behaves differently between PC and Pi 4, then post bug reports in separate threads.
Rockets are loud.
https://astro-pi.org


jerrm
Posts: 168
Joined: Wed May 02, 2018 7:35 pm

Re: USB problem on Pi 4B

Tue Aug 13, 2019 5:02 pm

andrum99 wrote:
Tue Aug 13, 2019 3:28 pm
See https://github.com/raspberrypi/linux/pull/3147
I was preparing a bug report, but would happily test this first.

I see the commit in github. Do you know how soon should this be seen in an rpi-update? Are the builds nightly/weekly/etc?

andrum99
Posts: 778
Joined: Fri Jul 20, 2012 2:41 pm

Re: USB problem on Pi 4B

Tue Aug 13, 2019 5:20 pm

jerrm wrote:
Tue Aug 13, 2019 5:02 pm

I see the commit in github. Do you know how soon should this be seen in an rpi-update? Are the builds nightly/weekly/etc?
No idea - keep an eye on https://github.com/raspberrypi/firmware - when you see new firmware hit that repo with a new kernel build that should then get copied across to https://github.com/Hexxeh/rpi-firmware which is where rpi-update gets its files from.

Bear in mind that the usual health warning for rpi-update applies - it may break stuff on your system, and there is no automatic way of getting back to the kernel and firmware you had before rpi-update ran.

jerrm
Posts: 168
Joined: Wed May 02, 2018 7:35 pm

Re: USB problem on Pi 4B

Tue Aug 13, 2019 5:43 pm

andrum99 wrote:
Tue Aug 13, 2019 5:20 pm
Bear in mind that the usual health warning for rpi-update applies - it may break stuff on your system, and there is no automatic way of getting back to the kernel and firmware you had before rpi-update ran.
Understood and not a problem. Nothing I care about installed, and I have "buster lite + my basic setup" backup image.

andrum99
Posts: 778
Joined: Fri Jul 20, 2012 2:41 pm

Re: USB problem on Pi 4B

Thu Aug 15, 2019 5:07 am

It turns out my problem was caused by buggy firmware on the USB-SATA bridge chips my enclosures have in them.

It seems the particular USB to SATA bridge my drive enclosures use is a bit buggy, to say the least: the JMicron JMS578. I only found it was one of these by opening them up and checking the top of the chip, as the non-standard vid/pid pretty much turns up a blank in Google. Luckily there is a new firmware available that appears to fix the above problem with the kernel ring buffer getting full and spamming the logs on the Pi 4, and the transfer rate dropping, but it is only available from Odriod: https://wiki.odroid.com/odroid-xu4/soft ... _fw_update. I updated to the very latest version of their firmware and I'm no longer seeing any errors in the log, and the transfer rate over the network is a lot more stable.

I've also managed to fix another problem I was having with these enclosures where the drives would always spin down after 3 minutes, and I could not get Linux to change that. It seems this can only be changed via a firmware tweak - luckily the same Odroid firmware update tool allowed me to change the standby (spin down) timer to a much more sensible 20 minutes.

I may bin these two enclosures as they don't exactly fill me with confidence. I've got another enclosure with what will become the Pi 4's boot drive installed in it (was my Pi 3B+'s boot drive) from startech.com that uses an AS1153 chip. That supports changing the spin down timer in the normal way, and a quick google suggests it is reliable.

Obviously updating a USB-SATA bridge's firmware comes with a rather large health warning. You could end up making the device completely unusable, or the controller could end up causing silent data corruption. Or some other interesting failure mode.

jdb
Raspberry Pi Engineer & Forum Moderator
Raspberry Pi Engineer & Forum Moderator
Posts: 2076
Joined: Thu Jul 11, 2013 2:37 pm

Re: USB problem on Pi 4B

Thu Aug 15, 2019 9:54 am

I levered open one of the Sabrent USB3.0 adapters that we have (0x152d:0x1561) that exhibit UAS errors and lo, it's a JMS578 inside. After blasting the slightly sketchy Hardkernel firmware to the device, it reports a PID of 0x152d:0x0578 and no longer errors. YMMV.
Rockets are loud.
https://astro-pi.org

jerrm
Posts: 168
Joined: Wed May 02, 2018 7:35 pm

Re: USB problem on Pi 4B

Thu Aug 15, 2019 1:05 pm

jdb wrote:
Thu Aug 15, 2019 9:54 am
I levered open one of the Sabrent USB3.0 adapters that we have (0x152d:0x1561) that exhibit UAS errors and lo, it's a JMS578 inside. After blasting the slightly sketchy Hardkernel firmware to the device, it reports a PID of 0x152d:0x0578 and no longer errors. YMMV.
I still get resets with bonnie and iozone with the updated fw. Also some nonsensical values that make me wonder if it is really working.

But why has the adapter been solid on PC Linux and not on Pi (/ARM}?

andrum99
Posts: 778
Joined: Fri Jul 20, 2012 2:41 pm

Re: USB problem on Pi 4B

Thu Aug 15, 2019 4:59 pm

jdb wrote:
Thu Aug 15, 2019 9:54 am
I levered open one of the Sabrent USB3.0 adapters that we have (0x152d:0x1561) that exhibit UAS errors and lo, it's a JMS578 inside. After blasting the slightly sketchy Hardkernel firmware to the device, it reports a PID of 0x152d:0x0578 and no longer errors. YMMV.
Same here. I also get a rather nifty serial number of 0123456789ABCDEF on both bridges :lol:

Return to “General discussion”