Buffer underflow when adding a track

[ronso0]

Imagine one deck is playing, then you load a track to another deck.
That's where an audible buffer underflow happens.

Must admit, I set a pretty aggressive latency of 5.33ms but don't run into any underflows when playing two decks. Keylock/speed offset and massive effects don't have any impact on playback quality.

Loading a track shouldn't have such an apparently high priority because I suspect noone minds that 100ms more it takes to load and even to re-analyze a track.

mixxx rev5973
Linux 3.14.23-rt20 #1 SMP PREEMPT RT x86_64

[RJ Skerry-Ryan (rryan)]

Mixxx doesn't get nearly as much testing as it ought to on rt kernels -- it's possible we have some kind of priority inversion problem that only shows up on rt. But this shouldn't happen in general (our audio processing thread runs at a higher priority than the rest of Mixxx's threads).

Do you see the same problem on a non-rt kernel?

Out of curiosity, what are your CPU specs?

[ronso0 (ronso0)]

I only run this sys (Ubuntu studio) with rt kernel. On vanilla Ubuntu on the same machine I experienced very lame (aka unsatisfiying) performance so I don't see a reason to install standard kernel. Should I, would the results help?

I'm running mixxx on a AMD A4-3300M @ 1900MHz, full lshw attached.

[Daniel Schürmann (daschuer)]

What kind of hard disk do you have?
Does the underflow counter in hardware preferences count when the audio dropout happens?
Does you see the "real time scheduling disabled" hint in hardware preferences?
Is there something suspicious in the log file when the underflow happens?

[ronso0 (ronso0)]

* Hardware prefs show "Real time scheduling enabled"
* yes, counter is increased by 1 at a dropout, otherwise I'd suspected a flawed file
* db is on SSD, media files on HDD
* didn't watch the log and (demo paradoxon I suppose): right now I can't reproduce it even though everything is set up the same, same progs running etc.
Will be back if log shows something.

[Owen Williams (ywwg)]

Almost certainly the issue is the low latency setting. A lot happens during track loading and that's a common place to experience dropouts even if you don't get dropouts during playback. Try doubling it to 10ms and see if the problem goes away.

[Daniel Schürmann (daschuer)]

From the scheduler theory, a real-time thread should not be suspended by any other thread.
It should run very deterministic and independent from what else is going on in the machine.

Since this seams to be not the case, we may have still locking calls, or it is an CPU frequency scaling issue, or it is just some extra engine work wen loading a track.

Your AMD A4-3300M has a frequency scaling 1900 - 2500 MHz.
If I read it right, it lowers the frequency to 1900 MHz if both cores are used. This is most likely the case if both cores are used.

This issue become worth when we consider hyper-threading (not the case here)

It could be interesting to lock the cpu clock on 1900 MHz and check how the issue behaves than.

[RJ Skerry-Ryan (rryan)]

Daniel's right -- the Mixxx RT thread (assuming it's actually getting
marked RT, which it should by default on Ubuntu Studio) should never get
pre-empted by another Mixxx thread, so this is likely priority inversion.

Our use of signals/slots in the engine means we're constantly locking
global Qt mutexes (for example
http://code.qt.io/cgit/qt/qt.git/tree/src/corelib/kernel/qcoreapplication.cpp#n1360
is
locked on every emit() that is queued) and allocating memory (emitting a
queued signal calls malloc). If any other thread is pre-empted while
holding that mutex or allocating memory then the engine thread will block.

On Wed, Nov 16, 2016 at 1:41 PM Daniel Schürmann <email address hidden>
wrote:

> >From the scheduler theory, a real-time thread should not be suspended by
> any other thread.
> It should run very deterministic and independent from what else is going
> on in the machine.
>
> Since this seams to be not the case, we may have still locking calls, or
> it is an CPU frequency scaling issue, or it is just some extra engine
> work wen loading a track.
>
> Your AMD A4-3300M has a frequency scaling 1900 - 2500 MHz.
> If I read it right, it lowers the frequency to 1900 MHz if both cores are
> used. This is most likely the case if both cores are used.
>
> This issue become worth when we consider hyper-threading (not the case
> here)
>
> It could be interesting to lock the cpu clock on 1900 MHz and check how
> the issue behaves than.
>
> --
> You received this bug notification because you are a member of Mixxx
> Development Team, which is subscribed to Mixxx.
> https://bugs.launchpad.net/bugs/1642105
>
> Title:
> Buffer underflow when adding a track
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/mixxx/+bug/1642105/+subscriptions
>

[ronso0 (ronso0)]

@Daniel: I already locked cpu when setting up for audio.
http://wiki.linuxaudio.org/wiki/system_configuration
cat /sys/devices/system/cpu/cpu*/cpufreq/scaling_governor
performance
performance

@Owen: I set it to 20ms. So far it didn't happen, even when playing 3 decks (keylock/speed set off) and adding a track to the 4th.

Until now mixxx felt very responsive without dropouts, I'll see how it will do from now.
Appreciate your attension.

[ronso0 (ronso0)]

I set latency back to 10ms to maybe catch some log output.
Loaded a .m4a, et voilà, these were last lines after the dropout happened:

Warning [CachingReaderWorker 1]: Unable to determine the fixed sample duration of track 1 in file "file:///mnt/M_OOLI/audio/00__mu__iN/00__neo/DJ Shadow - Midnight In A Perfect World (Ben Gomori's Utopian Edit) xXx.m4a"
Warning [CachingReaderWorker 1]: Fallback: Using a default sample duration of 1024 sample frames per block
Warning [AnalyzerQueue 1]: Unable to determine the fixed sample duration of track 1 in file "file:///mnt/M_OOLI/audio/00__mu__iN/00__neo/DJ Shadow - Midnight In A Perfect World (Ben Gomori's Utopian Edit) xXx.m4a"
Warning [AnalyzerQueue 1]: Fallback: Using a default sample duration of 1024 sample frames per block
Warning [CachingReaderWorker 2]: Unable to determine the fixed sample duration of track 1 in file "file:///mnt/M_OOLI/audio/00__mu__iN/00__neo/Weaver Beats - Fall in love (ft. Multirex) xXx.m4a"
Warning [CachingReaderWorker 2]: Fallback: Using a default sample duration of 1024 sample frames per block
Warning [AnalyzerQueue 1]: Unable to determine the fixed sample duration of track 1 in file "file:///mnt/M_OOLI/audio/00__mu__iN/00__neo/Weaver Beats - Fall in love (ft. Multirex) xXx.m4a"
Warning [AnalyzerQueue 1]: Fallback: Using a default sample duration of 1024 sample frames per block
Warning [Engine]: SoundDevicePortAudio: Audio API provides invalid time stamps, syncing waveforms with a CPU Timer DacTime: 370.078 EntrytoDac: 0.0163333 TimeSinceLastCb: 0.0110719 diff: 0.00207285

File is an .m4a recoded from .wav with this command:
avconv -i "$file" -vn -acodec libfdk_aac -b 320k "${file%%.$ext}.m4a"

Still can't reproduce it, though. Neither when loading the same file, nor when also playing a .m4a (even a shitty one) on the other deck.

As next step I will build a more recent kernel with preempt patch, see if that makes a difference.

[Daniel Schürmann (daschuer)]

The file encoding issues are probably unrelated, but

Warning [Engine]: SoundDevicePortAudio: Audio API provides invalid time stamps, syncing waveforms with a CPU Timer DacTime: 370.078 EntrytoDac: 0.0163333 TimeSinceLastCb: 0.0110719 diff: 0.00207285

is suspicious.

This message is issued form the DAC timing validation code. If the DAC timing provided by your audio API is valid normally, this massage can happen if the Engine thread is suspended, before it enters the Mixxx audio callback.

The "Warning [Engine]" itself makes the issue worse since this concurrents with all the other messages, this can take loooong since ther might be an other lock at writing the mixxx.log to hdd.

This message will be displayed only once per Mixxx run so not that big issue here.

Do you have more [Engine] entries?

I think I will enable this message only in developer mode ...

[Daniel Schürmann (daschuer)]

I think we should move the logging output to a thread.

[Daniel Schürmann (daschuer)]

https://github.com/mixxxdj/mixxx/commit/ef6b8426c34e1e1cc3fc084e3025eeb205680a57

[ronso0 (ronso0)]

@Daniel: you're right, I found this Warning [Engine] once in each of the recent logs.
No other occurence of [Engine]

[Be (be.ing)]

I have noticed this occurring regularly when I first load a track to a deck. Have you? See https://bugs.launchpad.net/mixxx/+bug/1641360

[ronso0 (ronso0)]

Me? Anyway, my update:
I've set latency to 10ms and notice the underflow only & mostly when adding the second track of a set while 1st track is playing. Like you describe in lp:1641360

[ronso0 (ronso0)]

I recently set pitch-bending to Rubberband and audible underflow is happening on almost any track load. Since playing track is not pitched, I'm wondering why pitch-bending engine has such an effect.

[Daniel Schürmann (daschuer)]

Rubberband requires ages more CPU than Sounddouch.

If keylock is enabled the pitch-bending-engine is enabled as well even if it is not pitched. This is required for a click free transition.
Otherwise it is bypassed and a very fast linear pitch engine is used for anything you could do with a real vinyl as well

[Uwe Klotz (uklotzde-deactivatedaccount)]

The reason might not only be CPU utilization but also disk I/O. I experience buffer underflows while performing rsync operations on unrelated disks, CPU is not an issue here.

[Uwe Klotz (uklotzde-deactivatedaccount)]

This bug is related or even a duplicate:
https://bugs.launchpad.net/mixxx/+bug/1738253

We should decide which one is the master for tracking these issues.

[ronso0 (ronso0)]

I moved to Bionic and use 4.16.18-rt12 now.
2.3.0-alpha-pre (build master r6553)
Issue didn't pop since then.

I could test with 3.18.7-rt1 if that's of any help.

[RJ Skerry-Ryan (rryan)]

> The reason might not only be CPU utilization but also disk I/O. I experience buffer underflows while performing rsync operations on unrelated disks, CPU is not an issue here.

Uwe, did you check that it was a buffer underflow (Mixxx callback exceeds its deadline) or is it just a CachingReader cache miss? CachingReader is supposed to be able to cache miss and emit silence so that it doesn't block the rest of the callback. No file I/O should be happening in the callback so I don't see how disk I/O could cause xruns?

[Uwe Klotz (uklotzde-deactivatedaccount)]

Buffer underflows in the engine with audible artefacts while the audio was playing continuously.

CachingReader is not affected. The audio file is located on an (internal) disk that contains only audio files and is neither affected by the rsync activities and nor used by any other application than Mixxx.

[Owen Williams (ywwg)]

I've noticed an uptick in underflows with keylock on, even on my new laptop (i7-8550U) at ~10ms. Not a ton, mind you, just one or two per set, but that's up from never. Rubberband has always used a lot of CPU but it surprises me that every time I upgrade my laptop it's the same deep red in the cpu meter. (Can't we lazily precache rubber-banded track data at the current BPM instead of trying to do it on the fly?)

In the past I've been able to get by with 10ms and two tracks on keylock... I'm not sure if the move to qt5 has caused a perf regression in general that has pushed me over the edge.

[Daniel Schürmann (daschuer)]

Since we recently fighting some possible qt5 performance regression, it would be nice if you could verify it. Is there a difference between qt5 and qt4? Is this issue qt related?

You can either use the plain 2.1 branch or the 2.2 branch build with qt4 and this https://github.com/mixxxdj/mixxx/pull/1860
patch.

[Uwe Klotz (uklotzde-deactivatedaccount)]

Caching of pre-computed audio data? Just NO! The caching is already complicated and error prone. This would introduce a whole new level of complexity.

[Swiftb0y (swiftb0y)]

Mixxx now uses GitHub for bug tracking. This bug has been migrated to:
https://github.com/mixxxdj/mixxx/issues/8693