Behringer WING usb audio - cyclic xruns dependent on periods/buffers

[Ben Bell]

On Fri, Nov 27, 2020 at 10:20:59AM +0100, Takashi Iwai wrote:
> On Thu, 26 Nov 2020 19:06:04 +0100, Ben Bell wrote:
> > I've got a Behringer WING digital mixer which is equipped with a USB
> > interface supporting 48 in, 48 out at 44.1 or 48kHz. It's plugged into a
> > USB3 interface and for the most part it seems to work well as a class-compliant
> > audio interface, but I'm struggling to eliminate xruns and it's starting to
> > feel either driver or hardware quirk related issue.
...

> In general you should avoid 44.1kHz if you want a small period size
> for a realtime process on USB-audio.  With 44.1kHz, the packet size
> can't be fixed in integer, and the ISO transfer requires variable
> packet sizes.  OTOH, ALSA API requires the fixed period size, hence
> it'll lead to inconsistencies occasionally.

Thanks Takashi, that's useful to know. Most of my historical projects are
at 44.1kHz which is why I'm using that here, but I'll try to switch to 48kHz
in future work to avoid this. That said, I've tested a little with 48kHz and
had similar problems. I'm currently encountering a period of relative
stability (an xrun every 20 minutes or so) so I don't want to touch anything
until I've got some recording out of the way, but I'll switch to 48kHz for
future testing too.

I've read people saying there are problems with USB3 and audio which go
away when they switch to USB 2, so I've got a card in the post so we'll see
whether that helps.

In the meantime, I've enabled xhci_hcd dynamic debugging and the xruns
all coincide with events like this. I'm wondering whether this is actually
more of a USB host issue rather than an ALSA one?

      1 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: Cancel URB 00000000d9d39c02, dev 4, ep 0x81, starting at offset 0xcfbNNNNN
      1 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: // Ding dong!
      1 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: Cancel URB 000000001152b022, dev 4, ep 0x81, starting at offset 0xcfbNNNNN
      1 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: Cancel URB 00000000aad0b004, dev 4, ep 0x81, starting at offset 0xcfbNNNNN
      1 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: Cancel URB 00000000014bb8b3, dev 4, ep 0x81, starting at offset 0xcfbNNNNN
      1 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: Cancel URB 0000000058d3a525, dev 4, ep 0x81, starting at offset 0xcfbNNNNN
      1 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: Cancel URB 00000000095e4d66, dev 4, ep 0x81, starting at offset 0xcfbNNNNN
      1 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: Cancel URB 00000000c5233f07, dev 4, ep 0x81, starting at offset 0xcfbNNNNN
      1 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: Cancel URB 0000000058cfb2b9, dev 4, ep 0x81, starting at offset 0xcfbNNNNN
      1 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: Cancel URB 00000000ecf776e8, dev 4, ep 0x81, starting at offset 0xcfbNNNNN
      1 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: Cancel URB 0000000090c79b8f, dev 4, ep 0x81, starting at offset 0xcfbNNNNN
      1 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: Cancel URB 00000000ad358790, dev 4, ep 0x81, starting at offset 0xcfbNNNNN
      1 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: Cancel URB 000000008f26c7ed, dev 4, ep 0x1, starting at offset 0xcfbNNNNN
      1 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: // Ding dong!
      1 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: Cancel URB 0000000020b0a760, dev 4, ep 0x1, starting at offset 0xcfbNNNNN
      1 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: Stopped on Transfer TRB for slot 1 ep 2
      1 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: Removing canceled TD starting at 0xcfbNNNNN (dma).
      1 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: Finding endpoint context
      1 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: Cycle state = 0x1
      1 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: New dequeue segment = 000000009fc8e305 (virtual)
      1 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: New dequeue pointer = 0xcfbNNNNN (DMA)
     84 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: Removing canceled TD starting at 0xcfbNNNNN (dma).
      1 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: Set TR Deq Ptr cmd, new deq seg = 000000009fc8e305 (0xcfbNNNNN dma), new deq ptr = 00000000cfc75f63 (0xcfb42440 dma), new cycle = 1
      1 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: // Ding dong!
      1 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: Stopped on Transfer TRB for slot 1 ep 1
     38 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: Removing canceled TD starting at 0xcfbNNNNN (dma).
      1 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: Finding endpoint context
      1 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: Cycle state = 0x0
      1 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: New dequeue segment = 0000000070effd6e (virtual)
      1 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: New dequeue pointer = 0xcfbNNNNN (DMA)
     29 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: Removing canceled TD starting at 0xcfbNNNNN (dma).
      1 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: Set TR Deq Ptr cmd, new deq seg = 0000000070effd6e (0xcfbNNNNN dma), new deq ptr = 0000000034521cdf (0xcfb77180 dma), new cycle = 0
      1 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: // Ding dong!
      1 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: Successful Set TR Deq Ptr cmd, deq = @cfb42440
      1 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: Successful Set TR Deq Ptr cmd, deq = @cfb77180
     32 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: Miss service interval error for slot 1 ep 2, set skip flag
      1 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: Found td. Clear skip flag for slot 1 ep 2.
      1 Nov 28 09:12:32 rowlf kernel: [nnn] retire_capture_urb: frames 0 - 7 of [138046467] still active: -18
      1 Nov 28 09:12:32 rowlf kernel: [nnn] retire_capture_urb: ...a total of 4 bad urbs; between [138046467] and [138046470]; kxrun = 238; 1120718 since last
     41 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: Miss service interval error for slot 1 ep 1, set skip flag
      1 Nov 28 09:12:32 rowlf kernel: [nnn] xhci_hcd 0000:29:00.3: Found td. Clear skip flag for slot 1 ep 1.

(First column is a dedup count, and the retire_capture_urb messages are my
own debug patch)

bjb