Buffer underflow in every second with JACK @96K

[atskler]

Bug Description

I just observed that the current Mixxx main (Mixxx 2.5.0-alpha) compared to the v2.3.4* produces constant buffer underflow in every one second, especially when none of the decks are loaded. It produces it with JACK running at 96kHz and deck 1 is configured to interface channels 1-2 and deck two to interface channels 3-4.

edit: *correctly: v2.3.3-121-gd1f63374fc

Version

2.5.0-alpha, 2.3.4

OS

OpenSUSE Tumbleweed

[atskler]

Config in QJackCtl:

Driver: alsa
Realtime: checked
Sample Rate: 96000
Frame/Period: 2048
Periods/Buffer: 3

Interface: Roland Rubix 24, USB

[atskler]

I put my notebook in a special performance mode and in that v2.5.0-alpha also works flawlessly.
Just in the default desktop performance mode produces the v2.5.0-alpha more buffer underflows than the v2.3.4*
So this bug report can be closed.

edit: *correctly: v2.3.3-121-gd1f63374fc

[ronso0]

via CPU governor?

[atskler]

turning off wifi with hardware switch

cpupower frequency-set -g performance
cpupower set -b 0
echo 1 > /sys/devices/system/cpu/intel_pstate/no_turbo

systemctl stop cron
systemctl stop NetworkManager
systemctl stop cups

AND: running Ardour in the background for additional processing with:
"Power Management, CPU DMA latency: Lowest (prevent CPU sleep states)"

This "CPU DMA latency" one additionally means a lot.

[daschuer]

With the same mixxx.cfg file there should be no performance regression with the 2.4 or main branch compared to our stable 2.3.4 release. If this is the case, we should reopen the bug and find out when the performance regression has happened.
I have recently fixed one of such a regression in #11336
Can you confirm if this issue is fixed with it?

[atskler]

@daschuer probably you are right. That fix not fixes the issue. Unfortunately even my performance mode not solves it. In my performance mode I'm using another QJackCtl profile. So this issue is bound to the mentioned QJackCtl settings.

The issue seem to be not present with the following settings:

Driver: alsa
Realtime: checked
Sample Rate: 96000
Frame/Period: 1024
Periods/Buffer: 3

[atskler]

Additionally I managed to reproduce the issue with v2.3.4.
But works correctly with my old v2.3.3-121-gd1f63374fc.
Date: 2023. January 26., Thursday 13:17:42 CET

[atskler]

The most relevant change since my working copy seems to be this:

JACK buffer size fix. #11121
#11121
0f53f91

I will check a build just before that, and with that.

[atskler]

Built them.

This is before the jack-api-check-rebase happened and works without problems:
https://github.com/mixxxdj/mixxx/tree/4834e90e13a62a1d865237e4c62756c965f04137

This is the one where the "jack-api-check-rebase" happened and with this the problem is present:
https://github.com/mixxxdj/mixxx/tree/0f53f915bd524e96d6298247dfc85d588521c0f4

So the problem arises from this:
JACK buffer size fix. #11121
#11121

[robbert-vdh]

So the problem arises from this: JACK buffer size fix. #11121 #11121

What is your JACK period size set to? Before that PR Mixxx would ignore the JACK server's settings and always used a 'virtual' period with a size corresponding to the grayed out latency setting in the audio settings tab. Now PortAudio should use the period size configured on the the JACK server (like you'd expect from a JACK application).

[atskler]

@robbert-vdh settings in QjackCtl:

produces buffer underflow:

jackd -dalsa -r96000 -p2048 -n3 -D -Chw:Rubix24 -Phw:Rubix24

Sample Rate: 96000
Frame/Period: 2048
Periods/Buffer: 3

works correctly:

jackd -dalsa -r96000 -p1024 -n3 -D -Chw:Rubix24 -Phw:Rubix24

Sample Rate: 96000
Frame/Period: 1024
Periods/Buffer: 3

[daschuer]

Please confirm:

Mixxx 2.3.4 works with 96 kHz/1024 frames/period and produces buffer underflow with 96 kHz/2048 frames/period.

Mixxx 2.3.3 up to https://github.com/mixxxdj/mixxx/tree/4834e90e13a62a1d865237e4c62756c965f04137
works correctly with 96 kHz/1024 frames/period and 96 kHz/2048 frames/period.

In the later case, Portaudio uses an extra buffer and Mixxx is running with it's default 1024 frames/period.

Do you use native Jack or Pipewire?

[atskler]

yes
yes
native jack

[daschuer]

Is there something logged in the mixxx.log when the underflow happens?

[atskler]

nothing strange
underflow happens without logging anything while it happens

[atskler]

if it matters: with both jack settings Mixxx's system reported latency is:
4.47392e+07 ms

[daschuer]

How do you identify the underflow? Does the underflow counter count in Mixxx? Is it a playback or input underflow? Do you use input channels in Mixxx like mic and aux?

[atskler]

• the counter counts as soon as I start Mixxx, I don't have to load decks and play
• I don't know if playback or input underflow is reported in Mixxx's "Sound Hardware" preferences
• no input channels are in use

[atskler]

please ignore the post where I mentioned the 4.47392e+07 ms, because it is when the utility named jack-passthru is used

without that, directly, the latency is:
21.3333 ms and 42.6667 ms

the underflow happens independent of jack-passthru

[atskler]

Interestingly this problem seems be there without audible effects.
Could be that only the counter in preferences and the indicator on the main ui is broken?

[daschuer]

When you start Mixxx with "./mixxx --developer" it will print an underflow code to the terminal output.
Which one do you see?
"underflowHappened code:"

[atskler]

warning [Engine] underflowHappened code: 24

[daschuer]

So it originates from here:
https://github.com/mixxxdj/mixxx/blob/2.3/src/soundio/sounddevicenetwork.cpp#L301

[daschuer]

I have prepared a fix here:
#11366

[atskler]

I have prepared a fix here:
#11366

@daschuer unfortunately the issue is still there with the fix gh11341.

[daschuer]

Strange, at least I can reproduce a similar issue printing warning [Engine] underflowHappened code: 24 and warning [Engine] underflowHappened code: 22 when I configure Mixxx with ALSA and 5 ms buffer size and than enable Jack via pipewire with the default 23 ms buffer. This issue is fixed after #11366.

@atskler Can you please provide a full mixxx.log of a faulty run using #11366? you can find it at ~/.mixxx/mixxx.log

[atskler]

@daschuer here it is:
mixxx.log

[daschuer]

Oh I forget, I need a mixxx.log from "./mixxx --developer" to see the "underflowHappened" numbers.

[atskler]

@daschuer here it is:
mixxx.log

[daschuer]

Jack is running still with Frame/Period: 2048?

This is interesting, because the "Network stream" runs initial with the same value:

Debug [Main]: SoundDeviceNetwork - open: "Network stream"
Debug [Main]: framesPerBuffer: 2048

This means my PR has no effect here.

[atskler]

I will rebuild you PR - maybe I misdone something before.

jackd -dalsa -r96000 -p2048 -n3 -D -Chw:Rubix24 -Phw:Rubix24
...

16:38:33.449 JACK was started with PID=21138.
audio_reservation_init
Acquire audio card Audio1
creating alsa driver ... hw:Rubix24|hw:Rubix24|2048|3|96000|0|0|nomon|swmeter|-|32bit
configuring for 96000Hz, period = 2048 frames (21.3 ms), buffer = 3 periods
ALSA: final selected sample format for capture: 32bit integer little-endian
ALSA: use 3 periods for capture
ALSA: final selected sample format for playback: 32bit integer little-endian
ALSA: use 3 periods for playback

...

[daschuer]

I have just prepared a new commit with more debug output. Please use that.
The interesting part is that the Jack period matches the internal buffer size already.
Can you reproduce the issue with 48 kHz?

[atskler]

Yes, 48kHz does the same.

jackd -dalsa -r48000 -p2048 -n3 -D -Chw:Rubix24 -Phw:Rubix24

Acquire audio card Audio1
creating alsa driver ... hw:Rubix24|hw:Rubix24|2048|3|48000|0|0|nomon|swmeter|-|32bit
configuring for 48000Hz, period = 2048 frames (42.7 ms), buffer = 3 periods
ALSA: final selected sample format for capture: 32bit integer little-endian
ALSA: use 3 periods for capture
ALSA: final selected sample format for playback: 32bit integer little-endian
ALSA: use 3 periods for playback

[atskler]

I downloaded and built it again, and the problem is still there.

Here is the log:
mixxx.log

[daschuer]

I do not see the additional debug messages.
You can find the the source here:
https://github.com/daschuer/mixxx/archive/refs/heads/gh11341.zip

[atskler]

That is "checksum match" with what I downloaded and built.

And it has additional info in the log:

Warning [Engine]: underflowHappened code: 24
Debug [Engine]: SoundDeviceNetwork - workerWriteProcess: buffer empty outChunkSize 2048 readAvailable 2048 writeAvailable 4136 5616605

[daschuer]

Oh yes, now I see it.

[daschuer]

We see a buffer and empty buffer after these times in unregulated intervals:
2,1 s
3,9 s
5,86 s

outChunkSize is 2048 which is strange, because if the period = 2048 and we have two channels, it is expected to be 4096. The available space until sync is 4114.

[daschuer]

I have updated #11366 with another overflow check (25) and even more debug messages.
Please create a mixxx.log again.

[atskler]

With that build I created two logs.

The simple one is just starting Mixxx and exiting.

The other one is starting Mixxx, then loading decks, then clicking qiuckly and repeatedly on the taskbar entry of Mixxx to show (maximize) and hide (minimize) its window.

Because I observed that sometimes loading the decks stops the buffer underflows for a while, and then it seems it can be triggered again by repeatedly clicking on Mixxx's entry on the taskbar to show and hide its window. But there seems to be loose causality here, it could be just coincidence, so it could be totally irrelevant.

mixxx_log.log
mixxx_log__loading_decks_and_taskbar_click_to_show_hide.log

[daschuer]

I have found the issue : -)

When using the Jack buffer, Portaudio uses an internal buffer of 1024 frames:
https://github.com/PortAudio/portaudio/blob/68e963a990da19bb013133dcbad59c2ed8ea0cf9/src/common/pa_process.c#L54
If you configure Jack with 'period = 2048', Portaudio delivers two buffers after each other. This means the pause is twice as long as Mixxx expects and it detects and underrun (24) but than receives the other part and detects an overflow (25)

Mixxx is not yet designed for this. Maybe we can detect this situation somehow. What is the Maximum period size Jackd allows?

[atskler]

Thank You!

What is the Maximum period size Jackd allows?

I don't know. It will start even with 16384 but it will not work eventually. For example Audacity crashes, Reaper produces a Jack crash. The max working value seems to be 8192 with my setup.

[daschuer]

Mixxx can't support more than 4096 frames.
Your issue should be fixed now with:
#11366
In your case you need to configure 2048 frames explicitly because the auto feature works only up to 1024 (the PortAudio limitation)

Please test.

[atskler]

Mixxx can't support more than 4096 frames. Your issue should be fixed now with: #11366 In your case you need to configure 2048 frames explicitly because the auto feature works only up to 1024 (the PortAudio limitation)

Please test.

@daschuer thank you. With the 4096 option the problem goes away but with 2048 it is still there. From the logs it seems that option 2048 sets: Debug [Main]: framesPerBuffer: 1024. In comparison the 4096 sets: Debug [Main]: framesPerBuffer: 4096

[daschuer]

Good catch, there was a copy and paste issue. This is now fixed. Please retry: #11366

[atskler]

Thank you. The gh11341 6a4c5df seems to fix the issue correctly.

I have just one observation:
If I set Jack to period = 512 frames and in Mixxx I choose the auto option then I still get Debug [Main]: framesPerBuffer: 1024. In this case is the reported 1024 correct?

[daschuer]

The behavior is correct, but I will have a look to avoid the misleading debug message.

[daschuer]

Now it prints the following:
Debug [Main]: SoundDeviceNetwork - Maximum: 1024 frames/buffer @ 48000 Hz = "21 ms"

[atskler]

Thank you. As far as I can tell everything seems to be good now - from my side as a user.

[daschuer]

Thank you very much for your patience and help with fixing this bug.