Comment 1 Hans Petter Selasky 2021-07-09 19:22:23 UTC

Hi,

Can you check what these two sysctls are set to:

dev.pcm.<N>.rec.vchanrate
dev.pcm.<N>.play.vchanrate

hw.usb.uaudio.buffer_ms: 8
hw.usb.uaudio.default_channels: 0
hw.usb.uaudio.default_bits: 32
hw.usb.uaudio.default_rate: 0

Also try to set:

hw.usb.uaudio.default_rate=48000

Maybe the high data-rate this interface supports overflows the USB budget.

--HPS

(In reply to Hans Petter Selasky from comment #1)

% sysctl dev.pcm.4
dev.pcm.4.feedback_rate: 0
dev.pcm.4.bitperfect: 0
dev.pcm.4.buffersize: 0
dev.pcm.4.rec.vchanformat: s16le:2.0
dev.pcm.4.rec.vchanrate: 48000
dev.pcm.4.rec.vchanmode: fixed
dev.pcm.4.rec.vchans: 1
dev.pcm.4.play.vchanformat: s16le:2.0
dev.pcm.4.play.vchanrate: 48000
dev.pcm.4.play.vchanmode: fixed
dev.pcm.4.play.vchans: 1
dev.pcm.4.hwvol_mixer: vol
dev.pcm.4.hwvol_step: 5
dev.pcm.4.%parent: uaudio0
dev.pcm.4.%pnpinfo: 
dev.pcm.4.%location: 
dev.pcm.4.%driver: pcm
dev.pcm.4.%desc: USB audio

% sysctl hw.usb.uaudio
hw.usb.uaudio.debug: 0
hw.usb.uaudio.buffer_ms: 8
hw.usb.uaudio.default_channels: 0
hw.usb.uaudio.default_bits: 32
hw.usb.uaudio.default_rate: 0
hw.usb.uaudio.handle_hid: 1

(In reply to Hans Petter Selasky from comment #1)

I just added hw.usb.uaudio.default_rate=48000 to /etc/sysctl.conf and rebooted.

% sysctl hw.usb.uaudio.default_rate
hw.usb.uaudio.default_rate: 48000

Even doing that doesn't solve the issue.

Comment 4 Hans Petter Selasky 2021-07-10 09:35:44 UTC

Can you collect some more info?

usbdump -i usbusX -f Y -s 65535 -v | gzip > log.txt.gz

X and Y are the numbers after ugen.

Start playback and recording and upload the log.txt.gz.

--HPS

Just an idea - I remember having problems with timing accuracy when using USB 2.0 devices on USB 3.0 ports (XHCI).

If feasible you could try to use a USB port that is limited to USB 2.0 (EHCI, maybe via BIOS setting if not in hardware).

(In reply to Hans Petter Selasky from comment #4)

usbdump -i usbus1 -f 2 -s 65535 -v > playback-log.txt

https://usaupload.com/D73/playback-log.txt.gz

(In reply to Florian Walpen from comment #5)

I've already tried with usb 2.0 port, but I'm having the same problem.

Thank you.

---

Mainboard: Asus PRIME A320I-K (BIOS Version 2203)

Comment 8 Hans Petter Selasky 2021-07-10 12:04:58 UTC

Hi,

I see in the log there is a problem with the XHCI controller, not the Focusrite.

19:56:09.868398 usbus1.2 DONE-ISOC-EP=00000001,SPD=HIGH,NFR=0,SLEN=0,IVAL=0,ERR=TIMEOUT

It looks like it didn't generate a completion event for an isochronous job, so the isochronous schedule stopped feeding audio.

Try to build a new kernel with:

options USB_DEBUG

added to the kernel config.

Then set for example:

sysctl hw.usb.xhci.debug=17
sleep 10
sysctl hw.usb.xhci.debug=0

Then repeat the test and collect logs from /var/log/messages

--HPS

Files are too large. It causes too much noise.

% ls -al messages playback-log-2.txt 
-rw-r--r--  1 hodong  hodong  268179252 Jul 10 22:06 messages
-rw-r--r--  1 hodong  hodong   28922350 Jul 10 22:05 playback-log-2.txt

% grep SHORT_XFER playback-log-2.txt | wc -l
     289

...
22:05:38.236716 usbus1.2 DONE-ISOC-EP=00000001,SPD=HIGH,NFR=64,SLEN=0,IVAL=0,ERR=SHORT_XFER
22:05:38.247331 usbus1.2 DONE-ISOC-EP=00000001,SPD=HIGH,NFR=64,SLEN=0,IVAL=0,ERR=SHORT_XFER
22:05:38.294055 usbus1.2 DONE-ISOC-EP=00000001,SPD=HIGH,NFR=64,SLEN=0,IVAL=0,ERR=SHORT_XFER
22:05:38.341536 usbus1.2 DONE-ISOC-EP=00000001,SPD=HIGH,NFR=64,SLEN=0,IVAL=0,ERR=SHORT_XFER
22:05:38.397577 usbus1.2 DONE-ISOC-EP=00000001,SPD=HIGH,NFR=64,SLEN=0,IVAL=0,ERR=SHORT_XFER
22:05:38.438745 usbus1.2 DONE-ISOC-EP=00000001,SPD=HIGH,NFR=64,SLEN=0,IVAL=0,ERR=SHORT_XFER


Should I capture ERR=TIMEOUT ?

Comment 10 Hans Petter Selasky 2021-07-10 13:28:49 UTC

Can you grep /var/log/messages for:

grep -i "start next=" /var/log/messages

--HPS

Created attachment 226349 [details]
start-next.log.gz

I already copied /var/logmessages to my home directory.

% grep -i "start next=" messages

Comment 12 Hans Petter Selasky 2021-07-10 16:49:53 UTC

Created attachment 226355 [details]
Patch to try

Can you try this patch? It is for 14-current, but should apply cleanly to 13-stable aswell.

Comment 13 commit-hook 2021-07-10 19:04:59 UTC

A commit in branch main references this bug:

URL: https://cgit.FreeBSD.org/src/commit/?id=8fc2a3c41791b205a107dc2bec16ac7514a57958

commit 8fc2a3c41791b205a107dc2bec16ac7514a57958
Author:     Hans Petter Selasky <hselasky@FreeBSD.org>
AuthorDate: 2021-07-10 16:17:51 +0000
Commit:     Hans Petter Selasky <hselasky@FreeBSD.org>
CommitDate: 2021-07-10 18:59:00 +0000

    Factor out repeated code in the USB controller drivers to avoid bugs
    computing the same isochronous start frame number over and over again.

    PR:             257082
    MFC after:      1 week
    Sponsored by:   NVIDIA Networking

 sys/dev/usb/controller/atmegadci.c   | 37 +-------------
 sys/dev/usb/controller/avr32dci.c    | 37 +-------------
 sys/dev/usb/controller/dwc_otg.c     | 45 +----------------
 sys/dev/usb/controller/ehci.c        | 96 ++++++------------------------------
 sys/dev/usb/controller/musb_otg.c    | 42 +---------------
 sys/dev/usb/controller/ohci.c        | 33 +++----------
 sys/dev/usb/controller/saf1761_otg.c | 70 ++------------------------
 sys/dev/usb/controller/uhci.c        | 41 +++------------
 sys/dev/usb/controller/uss820dci.c   | 35 +------------
 sys/dev/usb/controller/xhci.c        | 85 +++++++++++--------------------
 sys/dev/usb/usb_transfer.c           | 69 ++++++++++++++++++++++++++
 sys/dev/usb/usb_transfer.h           |  1 +
 12 files changed, 140 insertions(+), 451 deletions(-)

Comment 14 Hans Petter Selasky 2021-07-10 19:46:39 UTC

Created attachment 226357 [details]
Patch to try

Fixed kernel build w/debugging.

(In reply to Hans Petter Selasky from comment #14)

I am compiling the kernel after applying your patch to FreeBSD-13. If it fails, I'll test with 14-CURRENT. Thank you.

(In reply to Hans Petter Selasky from comment #14)

I applied your patch to FreeBSD-13 and I'm listening to music and still having the same problem.

An error occurred in xhci.c when applying your patch, so I applied it manually. Perhaps only the line number is different.

diff --git a/sys/dev/usb/controller/xhci.c b/sys/dev/usb/controller/xhci.c
index 10e37c97c..690091fce 100644
--- a/sys/dev/usb/controller/xhci.c
+++ b/sys/dev/usb/controller/xhci.c
@@ -133,8 +133,8 @@ struct xhci_std_temp {
        uint32_t                offset;
        uint32_t                max_packet_size;
        uint32_t                average;
+       uint32_t                isoc_frame;
        uint16_t                isoc_delta;
-       uint16_t                isoc_frame;
        uint8_t                 shortpkt;
        uint8_t                 multishort;
        uint8_t                 last_frame;
@@ -644,6 +644,9 @@ xhci_init(struct xhci_softc *sc, device_t self, uint8_t dma32)
 
        DPRINTF("HCS2=0x%08x\n", temp);
 
+       /* get isochronous scheduling threshold */
+       sc->sc_ist = XHCI_HCS2_IST(temp);
+
        /* get number of scratchpads */
        sc->sc_noscratch = XHCI_HCS2_SPB_MAX(temp);
 
@@ -2075,58 +2078,57 @@ xhci_setup_generic_chain(struct usb_xfer *xfer)
 
                x = XREAD4(temp.sc, runt, XHCI_MFINDEX);
 
-               DPRINTF("MFINDEX=0x%08x\n", x);
+               DPRINTF("MFINDEX=0x%08x IST=0x%x\n", x, temp.sc->sc_ist);
 
                switch (usbd_get_speed(xfer->xroot->udev)) {
                case USB_SPEED_FULL:
                        shift = 3;
                        temp.isoc_delta = 8;    /* 1ms */
-                       x += temp.isoc_delta - 1;
-                       x &= ~(temp.isoc_delta - 1);
                        break;
                default:
                        shift = usbd_xfer_get_fps_shift(xfer);
                        temp.isoc_delta = 1U << shift;
-                       x += temp.isoc_delta - 1;
-                       x &= ~(temp.isoc_delta - 1);
-                       /* simple frame load balancing */
-                       x += xfer->endpoint->usb_uframe;
                        break;
                }
 
-               y = XHCI_MFINDEX_GET(x - xfer->endpoint->isoc_next);
+               /* Compute isochronous scheduling threshold. */
+               if (temp.sc->sc_ist & 8)
+                       y = (temp.sc->sc_ist & 7) << 3;
+               else
+                       y = (temp.sc->sc_ist & 7);
 
-               if ((xfer->endpoint->is_synced == 0) ||
-                   (y < (xfer->nframes << shift)) ||
-                   (XHCI_MFINDEX_GET(-y) >= (128 * 8))) {
+               /* Range check the IST. */
+               if (y < 8) {
+                       y = 0;
+               } else if (y > 15) {
+                       DPRINTFN(3, "IST(%d) is too big!\n", temp.sc->sc_ist);
                        /*
-                        * If there is data underflow or the pipe
-                        * queue is empty we schedule the transfer a
-                        * few frames ahead of the current frame
-                        * position. Else two isochronous transfers
-                        * might overlap.
+                        * The USB stack minimum isochronous transfer
+                        * size is typically 2x2 ms of payload. If the
+                        * IST makes is above 15 microframes, we have
+                        * an effective scheduling delay of more than
+                        * or equal to 2 milliseconds, which is too
+                        * much.
                         */
-                       xfer->endpoint->isoc_next = XHCI_MFINDEX_GET(x + (3 * 8));
-                       xfer->endpoint->is_synced = 1;
-                       temp.do_isoc_sync = 1;
-
-                       DPRINTFN(3, "start next=%d\n", xfer->endpoint->isoc_next);
+               } else {
+                       /*
+                        * Subtract one millisecond, because the
+                        * generic code adds that to the latency.
+                        */
+                       y -= 8;
                }
 
-               /* compute isochronous completion time */
-
-               y = XHCI_MFINDEX_GET(xfer->endpoint->isoc_next - (x & ~7));
+               if (usbd_xfer_get_isochronous_start_frame(
+                   xfer, x, y, 8, XHCI_MFINDEX_GET(-1), &temp.isoc_frame)) {
+                       /* Start isochronous transfer at specified time. */
+                       temp.do_isoc_sync = 1;
 
-               xfer->isoc_time_complete =
-                   usb_isoc_time_expand(&temp.sc->sc_bus, x / 8) +
-                   (y / 8) + (((xfer->nframes << shift) + 7) / 8);
+                       DPRINTFN(3, "start next=%d\n", temp.isoc_frame);
+               }
 
                x = 0;
-               temp.isoc_frame = xfer->endpoint->isoc_next;
                temp.trb_type = XHCI_TRB_TYPE_ISOCH;
 
-               xfer->endpoint->isoc_next += xfer->nframes << shift;
-
        } else if (xfer->flags_int.control_xfr) {
                /* check if we should prepend a setup message */
 
@@ -3063,15 +3065,7 @@ xhci_device_done(struct usb_xfer *xfer, usb_error_t error)
 static void
 xhci_device_generic_open(struct usb_xfer *xfer)
 {
-       if (xfer->flags_int.isochronous_xfr) {
-               switch (xfer->xroot->udev->speed) {
-               case USB_SPEED_FULL:
-                       break;
-               default:
-                       usb_hs_bandwidth_alloc(xfer);
-                       break;
-               }
-       }
+       DPRINTF("\n");
 }
 
 static void
@@ -3080,16 +3074,6 @@ xhci_device_generic_close(struct usb_xfer *xfer)
        DPRINTF("\n");
 
        xhci_device_done(xfer, USB_ERR_CANCELLED);
-
-       if (xfer->flags_int.isochronous_xfr) {
-               switch (xfer->xroot->udev->speed) {
-               case USB_SPEED_FULL:
-                       break;
-               default:
-                       usb_hs_bandwidth_free(xfer);
-                       break;
-               }
-       }
 }
 
 static void

-------------------------

Before installing the kernel, I gave the following commands:

cd /boot
git init
git add .
git commit -m initial

So I can see that the kernel is properly installed.

-----------------------------------------------
/boot % git status
On branch master
Changes not staged for commit:
  (use "git add/rm <file>..." to update what will be committed)
  (use "git restore <file>..." to discard changes in working directory)
	modified:   entropy
	deleted:    kernel.old/.freebsd-update
	modified:   kernel/ehci.ko
	modified:   kernel/kernel
	modified:   kernel/ohci.ko
	modified:   kernel/uhci.ko
	modified:   kernel/usb.ko
	modified:   kernel/xhci.ko

Untracked files:
  (use "git add <file>..." to include in what will be committed)
	kernel.old/if_igb.ko
	kernel.old/if_ixlv.ko

no changes added to commit (use "git add" and/or "git commit -a")
-----------------------------------------------

The xhci.c of FreeBSD-13 and FreeBSD-14-CURRENT is different. So when I have time later, I'll install FreeBSD-14-CURRENT and listen to music with Scarlett Solo.
Thank you so much.

Comment 17 Hans Petter Selasky 2021-07-11 23:13:17 UTC

I have some more patches you can try.

But first, can you collect the xhci debug logs again, and grep for:

grep -E "MFINDEX|start next=" /var/log/messages

--HPS

Created attachment 226397 [details]
MFINDEX-or-start-next-log-before-applying-patch.log.gz

grep -E "MFINDEX|start next=" messages

That log is a copy before applying the patch.

Comment 19 Hans Petter Selasky 2021-07-12 16:32:44 UTC

Hi,

I see in the log that the time between interrupts is unstable.

The delta on MFINDEX should be close to 8*8 = 64 microframes.

Jul 10 22:02:46 nimfsoft kernel: xhci_setup_generic_chain: MFINDEX=0x00000bfa
Jul 10 22:02:46 nimfsoft kernel: xhci_setup_generic_chain: MFINDEX=0x00000c45
Jul 10 22:02:46 nimfsoft kernel: xhci_setup_generic_chain: MFINDEX=0x00000c8a
Jul 10 22:02:46 nimfsoft kernel: xhci_setup_generic_chain: MFINDEX=0x00000cd4
Jul 10 22:02:46 nimfsoft kernel: xhci_setup_generic_chain: MFINDEX=0x00000d03
Jul 10 22:02:46 nimfsoft kernel: xhci_setup_generic_chain: MFINDEX=0x00000d54
Jul 10 22:02:46 nimfsoft kernel: xhci_setup_generic_chain: MFINDEX=0x00000dab

1) Can you check the "top" command, that no CPU cores are 100% busy?

2) Have you tried to disable any CPU power saving features?

3) What does "pciconf -lv" say about the XHCI host controller?

4) Can you do "dmesg | grep xhci". Should output something like this:

xhci0: <Intel Sunrise Point-LP USB 3.0 controller> mem 0xdf210000-0xdf21ffff irq 16 at device 20.0 on pci0
xhci0: 32 bytes context size, 64-bit DMA

--HPS

(In reply to Hans Petter Selasky from comment #19)

Hello.

1) No CPU cores are 100% busy. It was confirmed with gnome-system-monitor and top.

2) In /etc/rc.conf, powerd_enable="YES" or #powerd_enable="YES" has the same problem.

3) pciconf -lv
hostb0@pci0:0:0:0:	class=0x060000 rev=0x00 hdr=0x00 vendor=0x1022 device=0x15d0 subvendor=0x1043 subdevice=0x876b
    vendor     = 'Advanced Micro Devices, Inc. [AMD]'
    device     = 'Raven/Raven2 Root Complex'
    class      = bridge
    subclass   = HOST-PCI
none0@pci0:0:0:2:	class=0x080600 rev=0x00 hdr=0x00 vendor=0x1022 device=0x15d1 subvendor=0x1043 subdevice=0x876b
    vendor     = 'Advanced Micro Devices, Inc. [AMD]'
    device     = 'Raven/Raven2 IOMMU'
    class      = base peripheral
    subclass   = IOMMU
hostb1@pci0:0:1:0:	class=0x060000 rev=0x00 hdr=0x00 vendor=0x1022 device=0x1452 subvendor=0x0000 subdevice=0x0000
    vendor     = 'Advanced Micro Devices, Inc. [AMD]'
    device     = 'Family 17h (Models 00h-1fh) PCIe Dummy Host Bridge'
    class      = bridge
    subclass   = HOST-PCI
pcib1@pci0:0:1:2:	class=0x060400 rev=0x00 hdr=0x01 vendor=0x1022 device=0x15d3 subvendor=0x1022 subdevice=0x1234
    vendor     = 'Advanced Micro Devices, Inc. [AMD]'
    device     = 'Raven/Raven2 PCIe GPP Bridge [6:0]'
    class      = bridge
    subclass   = PCI-PCI
hostb2@pci0:0:8:0:	class=0x060000 rev=0x00 hdr=0x00 vendor=0x1022 device=0x1452 subvendor=0x0000 subdevice=0x0000
    vendor     = 'Advanced Micro Devices, Inc. [AMD]'
    device     = 'Family 17h (Models 00h-1fh) PCIe Dummy Host Bridge'
    class      = bridge
    subclass   = HOST-PCI
pcib7@pci0:0:8:1:	class=0x060400 rev=0x00 hdr=0x01 vendor=0x1022 device=0x15db subvendor=0x1043 subdevice=0x876b
    vendor     = 'Advanced Micro Devices, Inc. [AMD]'
    device     = 'Raven/Raven2 Internal PCIe GPP Bridge 0 to Bus A'
    class      = bridge
    subclass   = PCI-PCI
pcib8@pci0:0:8:2:	class=0x060400 rev=0x00 hdr=0x01 vendor=0x1022 device=0x15dc subvendor=0x1043 subdevice=0x876b
    vendor     = 'Advanced Micro Devices, Inc. [AMD]'
    device     = 'Raven/Raven2 Internal PCIe GPP Bridge 0 to Bus B'
    class      = bridge
    subclass   = PCI-PCI
intsmb0@pci0:0:20:0:	class=0x0c0500 rev=0x61 hdr=0x00 vendor=0x1022 device=0x790b subvendor=0x1043 subdevice=0x876b
    vendor     = 'Advanced Micro Devices, Inc. [AMD]'
    device     = 'FCH SMBus Controller'
    class      = serial bus
    subclass   = SMBus
isab0@pci0:0:20:3:	class=0x060100 rev=0x51 hdr=0x00 vendor=0x1022 device=0x790e subvendor=0x1043 subdevice=0x876b
    vendor     = 'Advanced Micro Devices, Inc. [AMD]'
    device     = 'FCH LPC Bridge'
    class      = bridge
    subclass   = PCI-ISA
hostb3@pci0:0:24:0:	class=0x060000 rev=0x00 hdr=0x00 vendor=0x1022 device=0x15e8 subvendor=0x0000 subdevice=0x0000
    vendor     = 'Advanced Micro Devices, Inc. [AMD]'
    device     = 'Raven/Raven2 Device 24: Function 0'
    class      = bridge
    subclass   = HOST-PCI
hostb4@pci0:0:24:1:	class=0x060000 rev=0x00 hdr=0x00 vendor=0x1022 device=0x15e9 subvendor=0x0000 subdevice=0x0000
    vendor     = 'Advanced Micro Devices, Inc. [AMD]'
    device     = 'Raven/Raven2 Device 24: Function 1'
    class      = bridge
    subclass   = HOST-PCI
hostb5@pci0:0:24:2:	class=0x060000 rev=0x00 hdr=0x00 vendor=0x1022 device=0x15ea subvendor=0x0000 subdevice=0x0000
    vendor     = 'Advanced Micro Devices, Inc. [AMD]'
    device     = 'Raven/Raven2 Device 24: Function 2'
    class      = bridge
    subclass   = HOST-PCI
hostb6@pci0:0:24:3:	class=0x060000 rev=0x00 hdr=0x00 vendor=0x1022 device=0x15eb subvendor=0x0000 subdevice=0x0000
    vendor     = 'Advanced Micro Devices, Inc. [AMD]'
    device     = 'Raven/Raven2 Device 24: Function 3'
    class      = bridge
    subclass   = HOST-PCI
hostb7@pci0:0:24:4:	class=0x060000 rev=0x00 hdr=0x00 vendor=0x1022 device=0x15ec subvendor=0x0000 subdevice=0x0000
    vendor     = 'Advanced Micro Devices, Inc. [AMD]'
    device     = 'Raven/Raven2 Device 24: Function 4'
    class      = bridge
    subclass   = HOST-PCI
hostb8@pci0:0:24:5:	class=0x060000 rev=0x00 hdr=0x00 vendor=0x1022 device=0x15ed subvendor=0x0000 subdevice=0x0000
    vendor     = 'Advanced Micro Devices, Inc. [AMD]'
    device     = 'Raven/Raven2 Device 24: Function 5'
    class      = bridge
    subclass   = HOST-PCI
hostb9@pci0:0:24:6:	class=0x060000 rev=0x00 hdr=0x00 vendor=0x1022 device=0x15ee subvendor=0x0000 subdevice=0x0000
    vendor     = 'Advanced Micro Devices, Inc. [AMD]'
    device     = 'Raven/Raven2 Device 24: Function 6'
    class      = bridge
    subclass   = HOST-PCI
hostb10@pci0:0:24:7:	class=0x060000 rev=0x00 hdr=0x00 vendor=0x1022 device=0x15ef subvendor=0x0000 subdevice=0x0000
    vendor     = 'Advanced Micro Devices, Inc. [AMD]'
    device     = 'Raven/Raven2 Device 24: Function 7'
    class      = bridge
    subclass   = HOST-PCI
xhci0@pci0:1:0:0:	class=0x0c0330 rev=0x02 hdr=0x00 vendor=0x1022 device=0x43bc subvendor=0x1b21 subdevice=0x1142
    vendor     = 'Advanced Micro Devices, Inc. [AMD]'
    class      = serial bus
    subclass   = USB
ahci0@pci0:1:0:1:	class=0x010601 rev=0x02 hdr=0x00 vendor=0x1022 device=0x43b8 subvendor=0x1b21 subdevice=0x1062
    vendor     = 'Advanced Micro Devices, Inc. [AMD]'
    class      = mass storage
    subclass   = SATA
pcib2@pci0:1:0:2:	class=0x060400 rev=0x02 hdr=0x01 vendor=0x1022 device=0x43b3 subvendor=0x1b21 subdevice=0x0201
    vendor     = 'Advanced Micro Devices, Inc. [AMD]'
    class      = bridge
    subclass   = PCI-PCI
pcib3@pci0:2:4:0:	class=0x060400 rev=0x02 hdr=0x01 vendor=0x1022 device=0x43b4 subvendor=0x1b21 subdevice=0x3306
    vendor     = 'Advanced Micro Devices, Inc. [AMD]'
    device     = '300 Series Chipset PCIe Port'
    class      = bridge
    subclass   = PCI-PCI
pcib4@pci0:2:5:0:	class=0x060400 rev=0x02 hdr=0x01 vendor=0x1022 device=0x43b4 subvendor=0x1b21 subdevice=0x3306
    vendor     = 'Advanced Micro Devices, Inc. [AMD]'
    device     = '300 Series Chipset PCIe Port'
    class      = bridge
    subclass   = PCI-PCI
pcib5@pci0:2:6:0:	class=0x060400 rev=0x02 hdr=0x01 vendor=0x1022 device=0x43b4 subvendor=0x1b21 subdevice=0x3306
    vendor     = 'Advanced Micro Devices, Inc. [AMD]'
    device     = '300 Series Chipset PCIe Port'
    class      = bridge
    subclass   = PCI-PCI
pcib6@pci0:2:7:0:	class=0x060400 rev=0x02 hdr=0x01 vendor=0x1022 device=0x43b4 subvendor=0x1b21 subdevice=0x3306
    vendor     = 'Advanced Micro Devices, Inc. [AMD]'
    device     = '300 Series Chipset PCIe Port'
    class      = bridge
    subclass   = PCI-PCI
re0@pci0:5:0:0:	class=0x020000 rev=0x15 hdr=0x00 vendor=0x10ec device=0x8168 subvendor=0x1043 subdevice=0x8677
    vendor     = 'Realtek Semiconductor Co., Ltd.'
    device     = 'RTL8111/8168/8411 PCI Express Gigabit Ethernet Controller'
    class      = network
    subclass   = ethernet
vgapci0@pci0:7:0:0:	class=0x030000 rev=0xcc hdr=0x00 vendor=0x1002 device=0x15d8 subvendor=0x1043 subdevice=0x876b
    vendor     = 'Advanced Micro Devices, Inc. [AMD/ATI]'
    device     = 'Picasso'
    class      = display
    subclass   = VGA
hdac0@pci0:7:0:1:	class=0x040300 rev=0x00 hdr=0x00 vendor=0x1002 device=0x15de subvendor=0x1043 subdevice=0x876b
    vendor     = 'Advanced Micro Devices, Inc. [AMD/ATI]'
    device     = 'Raven/Raven2/Fenghuang HDMI/DP Audio Controller'
    class      = multimedia
    subclass   = HDA
none1@pci0:7:0:2:	class=0x108000 rev=0x00 hdr=0x00 vendor=0x1022 device=0x15df subvendor=0x1043 subdevice=0x876b
    vendor     = 'Advanced Micro Devices, Inc. [AMD]'
    device     = 'Family 17h (Models 10h-1fh) Platform Security Processor'
    class      = encrypt/decrypt
xhci1@pci0:7:0:3:	class=0x0c0330 rev=0x00 hdr=0x00 vendor=0x1022 device=0x15e5 subvendor=0x1043 subdevice=0x876b
    vendor     = 'Advanced Micro Devices, Inc. [AMD]'
    device     = 'Raven2 USB 3.1'
    class      = serial bus
    subclass   = USB
hdac1@pci0:7:0:6:	class=0x040300 rev=0x00 hdr=0x00 vendor=0x1022 device=0x15e3 subvendor=0x1043 subdevice=0x86c7
    vendor     = 'Advanced Micro Devices, Inc. [AMD]'
    device     = 'Family 17h (Models 10h-1fh) HD Audio Controller'
    class      = multimedia
    subclass   = HDA
ahci1@pci0:8:0:0:	class=0x010601 rev=0x61 hdr=0x00 vendor=0x1022 device=0x7901 subvendor=0x1043 subdevice=0x876b
    vendor     = 'Advanced Micro Devices, Inc. [AMD]'
    device     = 'FCH SATA Controller [AHCI mode]'
    class      = mass storage
    subclass   = SATA

4) dmesg | grep xhci
xhci0: <XHCI (generic) USB 3.0 controller> mem 0xfcea0000-0xfcea7fff irq 28 at device 0.0 on pci1
xhci0: 32 bytes context size, 64-bit DMA
usbus0 on xhci0
xhci1: <XHCI (generic) USB 3.0 controller> mem 0xfca00000-0xfcafffff irq 55 at device 0.3 on pci7
xhci1: 64 bytes context size, 64-bit DMA
usbus1 on xhci1

Thank you.

Comment 21 Hans Petter Selasky 2021-07-13 09:29:53 UTC

Created attachment 226420 [details]
Patch to try

Hi,

1) Can you try this patch? Not sure if it helps.

2) Also try putting:

hw.usb.xhci.msi=0
hw.usb.xhci.msix=0

Into /boot/loader.conf

Either one at a time, or both.

Any effect?

--HPS

(In reply to Hans Petter Selasky from comment #21)

After applying 226357 patch.

I applied 226420 patch after applying 226357 patch. But same problem.
I will try 226420 patch after deleting 226357 patch (using git reset ... --hard).

(In reply to Hodong from comment #22)

The first line is a typo. "After applying 226357 patch."

Comment 24 Hans Petter Selasky 2021-07-13 14:30:45 UTC

OK, no problem.

Beware that your keyboard may stop working when setting those XHCI quirks, so try first only setting them from inside the loader before booting, if you know what I mean.

--HPS

% sudo sysctl hw.usb.xhci.msi
sysctl: unknown oid 'hw.usb.xhci.msi'
% sudo sysctl hw.usb.xhci.msix
sysctl: unknown oid 'hw.usb.xhci.msix'

Next time I'll try with 14-CURRENT.

Comment 26 Hans Petter Selasky 2021-07-13 16:12:48 UTC

These are not sysctls, they are hidden tuneables.

When booting, enter the loader prompt and type:

set hw.usb.xhci.msi=1
set hw.usb.xhci.msix=1
boot

Try one at a time, then both.

--HPS

(In reply to Hans Petter Selasky from comment #26)

I have the same problem after applying the patch (226420) to 13.0-RELEASE-p3.

% cat /boot/loader.conf
kern.geom.label.disk_ident.enable="0"
kern.geom.label.gptid.enable="0"
cryptodev_load="YES"
zfs_load="YES"
hw.usb.xhci.msi=0
hw.usb.xhci.msix=0

Created attachment 226461 [details]
Screenshot-set-boot-options

Comment 29 Hans Petter Selasky 2021-07-14 14:40:36 UTC

Created attachment 226462 [details]
One more patch to try

Please also try this patch.

Can you also show the output from "vmstat -i"

--HPS

(In reply to Hans Petter Selasky from comment #29)

I applied the patch 226462. Same problem occurs.

% vmstat -i
interrupt                          total       rate
cpu0:timer                        734511       1040
cpu1:timer                        185113        262
cpu2:timer                        194354        275
cpu3:timer                        173520        246
irq60: ahci0                       45064         64
irq61: re0                        244322        346
irq62: hdac0                        2089          3
irq64: hdac1                        9427         13
irq66: vgapci0                    204569        290
Total                            1792969       2539

Thank you.

Comment 31 Hans Petter Selasky 2021-07-16 10:26:20 UTC

Hi,

Could you enable "options USB_DEBUG" in the kernel configuration file?

Then:

sysctl hw.usb.xhci.debug=16
# start playback for 2 seconds
# stop playback
sysctl hw.usb.xhci.debug=0

Then collect those message from /var/log/messages ?

--HPS

(In reply to Hans Petter Selasky from comment #31)

I already recovered with 13.0-RELEASE-p3.
Should I do it after applying the patch (226462)?

Comment 33 Hans Petter Selasky 2021-07-16 13:23:34 UTC

You can do it after applying my patch.

I think you didn't upload the full XHCI debug prints yet, only output from usbdump.

--HPS

Comment 34 Hans Petter Selasky 2021-07-16 13:28:37 UTC

Hi,

If you want maybe we could have a debug session on IRC, probably sometime next week. It would speed up the testing.

Just send me an e-mail privately: hselasky@freebsd.org

My theory is that the AMD based XHCI hardware you've got doesn't function properly with the USB stack in FreeBSD :-( I'm trying to narrow down what is causing the missing isochronous completion events from happening.

--HPS

Comment 35 Hans Petter Selasky 2021-08-05 13:36:15 UTC

Hi,

I got my hands on an:

AMD Ryzen 5 3400G with Radeon Vega Graphics     (3693.15-MHz K8-class CPU)

And I think I figure out the problem:

Can you run:

sysctl machdep.idle

Then:

sysctl machdep.idle=spin

Does the problem go away?

--HPS

(In reply to Hans Petter Selasky from comment #35)

sysctl machdep.idle=spin

When I apply that option, it works fine. Thank you very much.

Comment 37 Hans Petter Selasky 2021-08-11 18:38:17 UTC

jkim @

Do we have a bug in:

sysctl machdep.idle=acpi

which is the default?

See this report.

I can reproduce the same with my Ryzen!

--HPS

Comment 38 Konstantin Belousov 2021-08-12 00:14:39 UTC

(In reply to Hans Petter Selasky from comment #37)
With idle acpi, idle handling is completely driven by firmware. And I think that
both Linux and Windows prefer mwait-like idle loops, instead of what we call
ACPI.  I am not sure why your machine selected ACPI.

Do you have mwait reported as available? Did you turned it off in BIOS?
Show the output of sysctl dev.cpu

I just checked few machines of mine and they all use acpi for idle loops. Those are i5 based desktop, i7 based laptop, APU (first series) and AMD Ryzen 5 2400G. On all of them I have 

machdep.idle_available: spin, mwait, hlt, acpi

Even VM on Vultr (KVM based) has similar output (mwait is missing). Does it mean that acpi shouldn't be the idle choice on all of them?

(In reply to Goran Mekić from comment #39)
I'm curious.  Do you use SCHED_ULE?  If your kernel is based on GENERIC then that is the default.
I use SCHED_4BSD and idle is set automatically to hlt.

GENERIC on all of them.

Comment 42 commit-hook 2022-03-10 08:35:51 UTC

A commit in branch stable/13 references this bug:

URL: https://cgit.FreeBSD.org/src/commit/?id=99977369433de3eaec6907e51bcabc1dbb088628

commit 99977369433de3eaec6907e51bcabc1dbb088628
Author:     Hans Petter Selasky <hselasky@FreeBSD.org>
AuthorDate: 2021-07-10 16:17:51 +0000
Commit:     Hans Petter Selasky <hselasky@FreeBSD.org>
CommitDate: 2022-03-10 08:29:19 +0000

    Factor out repeated code in the USB controller drivers to avoid bugs
    computing the same isochronous start frame number over and over again.

    PR:             257082
    Sponsored by:   NVIDIA Networking

    (cherry picked from commit 8fc2a3c41791b205a107dc2bec16ac7514a57958)
    (cherry picked from commit f52783fcf5cc60734121d061beef0d4ea47b224a)
    (cherry picked from commit cf48d1f77126d8de4c03c4dd7c8502be2b5f1954)

 sys/dev/usb/controller/atmegadci.c   | 37 +-------------
 sys/dev/usb/controller/avr32dci.c    | 37 +-------------
 sys/dev/usb/controller/dwc_otg.c     | 45 +----------------
 sys/dev/usb/controller/ehci.c        | 96 ++++++------------------------------
 sys/dev/usb/controller/musb_otg.c    | 42 +---------------
 sys/dev/usb/controller/ohci.c        | 33 +++----------
 sys/dev/usb/controller/saf1761_otg.c | 70 ++------------------------
 sys/dev/usb/controller/uhci.c        | 41 +++------------
 sys/dev/usb/controller/uss820dci.c   | 35 +------------
 sys/dev/usb/controller/xhci.c        | 88 ++++++++++++---------------------
 sys/dev/usb/usb_transfer.c           | 69 ++++++++++++++++++++++++++
 sys/dev/usb/usb_transfer.h           |  1 +
 12 files changed, 142 insertions(+), 452 deletions(-)

Comment 43 commit-hook 2022-03-17 12:29:18 UTC

A commit in branch releng/13.1 references this bug:

URL: https://cgit.FreeBSD.org/src/commit/?id=cd60f3f39a76d1d5c1a9859ce78c7b7052e1173b

commit cd60f3f39a76d1d5c1a9859ce78c7b7052e1173b
Author:     Hans Petter Selasky <hselasky@FreeBSD.org>
AuthorDate: 2021-07-10 16:17:51 +0000
Commit:     Hans Petter Selasky <hselasky@FreeBSD.org>
CommitDate: 2022-03-17 12:25:56 +0000

    Factor out repeated code in the USB controller drivers to avoid bugs
    computing the same isochronous start frame number over and over again.

    PR:             257082
    Sponsored by:   NVIDIA Networking
    Approved by:    re (gjb)

    (cherry picked from commit 8fc2a3c41791b205a107dc2bec16ac7514a57958)
    (cherry picked from commit f52783fcf5cc60734121d061beef0d4ea47b224a)
    (cherry picked from commit cf48d1f77126d8de4c03c4dd7c8502be2b5f1954)
    (cherry picked from commit 99977369433de3eaec6907e51bcabc1dbb088628)

 sys/dev/usb/controller/atmegadci.c   | 37 +-------------
 sys/dev/usb/controller/avr32dci.c    | 37 +-------------
 sys/dev/usb/controller/dwc_otg.c     | 45 +----------------
 sys/dev/usb/controller/ehci.c        | 96 ++++++------------------------------
 sys/dev/usb/controller/musb_otg.c    | 42 +---------------
 sys/dev/usb/controller/ohci.c        | 33 +++----------
 sys/dev/usb/controller/saf1761_otg.c | 70 ++------------------------
 sys/dev/usb/controller/uhci.c        | 41 +++------------
 sys/dev/usb/controller/uss820dci.c   | 35 +------------
 sys/dev/usb/controller/xhci.c        | 88 ++++++++++++---------------------
 sys/dev/usb/usb_transfer.c           | 69 ++++++++++++++++++++++++++
 sys/dev/usb/usb_transfer.h           |  1 +
 12 files changed, 142 insertions(+), 452 deletions(-)

Comment 44 Mark Linimon 2024-01-10 03:02:41 UTC

^Triage: committed to stable/13 back in 2022.