Fedora Account System
Red Hat Associate
Red Hat Customer
Created attachment 2134949 [details] Annotated usbmon log 1. Please describe the problem: When interrupt latency causes xHC servicing to be delayed, sometimes the isoch schedule gets silently reset, causing a "bubble" that delays all future packets. This causes glitches with some USB audio devices, which are not reported back to snd-usb-audio/userspace as an xrun. The USB controller is: 05:00.3 USB controller [0c03]: Advanced Micro Devices, Inc. [AMD] Raphael/Granite Ridge USB 3.1 xHCI [1022:15b6] caps: CAPLENGTH = 0x01200020 HCSPARAMS1 = 0x04000840 HCSPARAMS2 = 0x140000f1 HCSPARAMS3 = 0x0007000a HCCPARAMS1 = 0x0120ffc5 DOORBELLOFF = 0x00002000 RUNTIMEOFF = 0x00001000 HCCPARAMS2 = 0x0000003f That's IST=1 microframe, CFC=supported. Annotated usbmon log of the issue is attached. This is a USB audio device (Digiface USB, 32/34 channel i/o 32bit frames). This device uses implicit feedback, so out TRBs track in TRBs. Interval is 1 microframe, URBs are isoch 8 packets (1 frame worth). The annotations on the left pair up isoch out submissions with completions. At the beginning of the log, the delay between submission and completion is 3 milliseconds. This makes sense, because: XHCI_CFC_DELAY + IST = 11, round up to frame = 16 uframes So the initial URB gets scheduled 2 frames (2ms) in the future, and since the URB is 1ms worth of microframes, it completes just under 3ms after submission. Normally, the isoc in/out endpoints track this schedule and the urb->start_frame continously increases, with isoc in/out matched at completion time (adjacent Zo/Zi lines). Note that the xep->next_frame_id logic in xhci-ring.c does not mask off the top bits while incrementing, so the frame ID as seen in usbmon counts up in those bits (even though they are unused). At time 16.288461, there is a delay in processing URBs. I believe this is due to IRQ contention from another device processing IRQs on the same CPU. The previous cycle was at 16.286385, so the IRQ arrived ~1ms late (would have been around 16.2874 otherwise). Two pairs of URBs are processed back to back to catch up. So far so good. I have enabled all the dynamic_debug messages in handle_tx_event(), but dmesg shows no errors when this happens (no underrun/overrun, no missed service interval). So as far as the xHC is concerned, nothing bad happened. However, a couple frames later at 16.2903, there is no out URB completion. Instead, it comes in at 16.291337, one frame later (3ms after the *late* submission). The urb->start_frame becomes 13616 (0x3530), vs. 95536 (0x17530) for the co-completing input URB. This indicates that the start_frame was recalculated, resetting the endpoint isoch schedule. Subsequent URBs keep this new schedule, which now has a latency of 4ms between submission and completion, one frame longer than before. As one out URB was skipped, in and out are no longer in sync. This situation causes problems for this audio device, which expects its output stream to remain synchronized with the input (implicit feedback), and corrupts the playback stream permanently (persistent glitches and corrupted audio data, I suspect because the device is probably now racing an internal buffer every frame or something to that effect). As the ALSA side has no idea anything bad happened, there is no xrun fired to userspace (an xrun would trigger a reset of the streams and fix the problem). Detecting this and recovering is possible for this particular device with a quirk (there's a flag bit in the isoch in data indicating a problem), but the kernel doesn't currently handle this. There are two reasons why the schedule can get reset. One of them is in xhci_queue_isoc_tx_prepare(): /* Calculate the start frame and put it in urb->start_frame. */ if ((xhci->hcc_params & HCC_CFC) && !list_empty(&ep_ring->td_list)) { if (GET_EP_CTX_STATE(ep_ctx) == EP_STATE_RUNNING) { urb->start_frame = xep->next_frame_id; goto skip_start_over; } } At the point of URB 63e54c00 submission (16.288479), the endpoint should be running and there should be other URBs (63e57e00, 63e56600) pending, so this condition is not met. Second, in xhci_get_isoc_frame_id(), we have: current_frame_id = readl(&xhci->run_regs->microframe_index); start_frame_id = roundup(current_frame_id + ist + 1, 8); start_frame &= 0x7ff; start_frame_id = (start_frame_id >> 3) & 0x7ff; end_frame_id = (end_frame_id >> 3) & 0x7ff; [...] if (index == 0) { if (ret == -EINVAL || start_frame == start_frame_id) { start_frame = start_frame_id + 1; if (urb->dev->speed == USB_SPEED_LOW || urb->dev->speed == USB_SPEED_FULL) urb->start_frame = start_frame; else urb->start_frame = start_frame << 3; ret = 0; } } At 16.288479 when the URB is submitted, we are slightly over 1ms late, say 9 microframes later than the usual frame boundary. Call t=0 when we would have normally submitted this (after the last microframe packet completes for the previous input URB, so essentially aligned with the frame boundary). We're at t=9, 9 + ist(1) + 1 = 11, round up to 16. Shifted to frames, start_frame_id = 2. The schedule is normally 16 microframes into the future = 2 frames, so start_frame == start_frame_id. That hits the non-EINVAL condition and urb->start_frame gets *silently* bumped up to the next frame (and top bits cleared). The xHC then silently skips a frame period. The xHCI spec says (4.11.2.5): > Software should not schedule an Isoch TD with a Frame ID value that is less than the Start Frame ID, where: > Start Frame ID = (Frame Index of the current MFINDEX register value + IST + 1) MOD 2048 > where IST shall be rounded up to the nearest frame boundary if it is defined in microframes This is a different calculation, but it's equivalent (Frame Index is 1 (9 >> 3), Start Frame ID = 3). I think this "silent" resynchronization is a bug. This code is only called for xHCs with CFC. Since the CFC capability requires the xHC to be able to resynchronize, I think the driver should just go ahead and schedule the TD in that case, and let the xHC report a missed service error if it can't make it in time. That would at least be reported up to the device driver instead of silently skipping a frame (allowing it to reset). 2. What is the Version-Release number of the kernel: Kernel: 6.19.8-200.fc43.x86_64 3. Did it work previously in Fedora? If so, what kernel version did the issue *first* appear? Old kernels are available for download at https://koji.fedoraproject.org/koji/packageinfo?packageID=8 : No. 4. Can you reproduce this issue? If so, please provide the steps to reproduce the issue below: Leaving the USB controller on the same IRQ as the GPU (amdgpu, which seems to be pretty badly behaved with IRQ latency) and other devices and loading the system seems to fairly reliably trigger this. You probably need this particular device to experience the "persistently" corrupted output stream though, I imagine many other USB audio devices would handle it better and just have a momentary glitch. Aside: It seems the reason I've been hitting this (despite having previously configured IRQ affinity to avoid high latencies for audio devices) is that apparently IRQ SMP affinity is reset on system suspend/resume. That might be another bug... 5. Does this problem occur with the latest Rawhide kernel? To install the Rawhide kernel, run ``sudo dnf install fedora-repos-rawhide`` followed by ``sudo dnf update --enablerepo=rawhide kernel``: Most likely, since this code has not changed. 6. Are you running any modules that not shipped with directly Fedora's kernel?: No. 7. Please attach the kernel logs. You can get the complete kernel log for a boot with ``journalctl --no-hostname -k > dmesg.txt``. If the issue occurred on a previous boot, use the journalctl ``-b`` flag. No logs during this event, not even with relevant xHCI debug messages enabled.