audio latecy usage meter at 100% when track loaded + paused

[Sébastien BLAISOT]

today I faced something really strange.

64bits 1.12 git5545 on win10 64bits

track was playing in deck 1. deck 2-4 were empty.
buffer fill indicator was low.

loaded a track in deck 2, on played it. buffer indicator still low.

as soon as I paused deck 1, the buffer indicator jumped very high in the red, stayed there and sound (from track in deck 2) began to be crackling.

so I played a bit with this situation (glad it was not during a gig), and found that the high buffer only happens when there is a paused track loaded in deck 1.
if you eject track, the buffer indicator becomes low.
if you play the track, no problem.
if you load a new track (paused at load), it begins to fill buffer and produce bad sound.
so if a track is loaded and paused in deck 1, buffer fill indicator jumps into red and sound begin to be so bad that it is unusable.

I did not see the same for other decks.

If I restart mixxx, everything works fine for some time.

I thing we face a race condition when, sometimes, maybe in particular conditions, you pause a track.

I'm not sure I will be able to reproduce it easily.

What can I check/do to gather more information ?

[Daniel Schürmann (daschuer)]

I assume you "buffer indicator" the the "Audio Latency Usage Meter".
By the selected Audio Buffer in hardware preferences, you define the 100 % lets say 23 ms.
For a non crackling sound, Mixxx has to process chunks of 23 ms samples in time < 23 ms.
If it takes 11 ms the "Audio Latency Usage Meter" is at 50 %. If it takes 24 ms, one chunk is skipped.

I guess you use a non SSE build. I had exactly the same issues on Linux.

You should use at least
scons optimize=portable
or just
scons

Even if a Deck is paused the silence stream is processed. If the samples are not exactly 0 but near, the CPU uses a lot of extra cycles to still produce scientific exact results.
https://en.wikipedia.org/wiki/Denormal_number

We have to bes sure that the de-normals are treated as 0, to prevent this issue on Windows as well.
This should happen here
https://github.com/mixxxdj/mixxx/blob/3f854c1674084609497036ba92e1605a43fb492f/src/sounddeviceportaudio.cpp#L772

do you see the
"SSE: Enabling denormals to zero mode"
log message?

[Sébastien BLAISOT (sblaisot)]

Yes, I'm talking about the "audio latency usage meter".

Thanks for all your explanations that make me understand a little better how mixxx works.

I'm using the build found on http://downloads.mixxx.org/builds/1.12/release/mixxx-1.12.0-beta1-1.12-git5545-release-x64.exe
I guess it's a build with SSE enabled, but I may be wrong.
I didn't built it myself.

yes, I have the following two lines in the log file :
SSE: Enabling denormals to zero mode
SSE: Enabling flush to zero mode

I think that under some circumstances, the silence stream processing abnormally consumes extra CPU, but I didn't find a way to reproduce it, it only happens "sometimes".

[Daniel Schürmann (daschuer)]

My guess is Mixxx is lying. ;-)
It should say:

"SSE: Trying to enable denormals to zero mode"

After that we should check it by a dummy calculation as below. I think we should keep it in the release as well.
Are you able to check it in a custom build?

diff --git a/src/sounddeviceportaudio.cpp b/src/sounddeviceportaudio.cpp
index 7e6c3e0..1478ff1 100644
--- a/src/sounddeviceportaudio.cpp
+++ b/src/sounddeviceportaudio.cpp
@@ -16,6 +16,7 @@
 ***************************************************************************/

 #include <portaudio.h>
+#include <float.h>

 #include <QtDebug>
 #include <QThread>
@@ -781,6 +782,10 @@ int SoundDevicePortAudio::callbackProcessClkRef(const unsig
         } else {
              qDebug() << "SSE: Flush to zero mode already enabled";
         }
+ volatile double doubleMin = DBL_MIN; // the smallest normalized double
+ DEBUG_ASSERT_AND_HANDLE(doubleMin / 2 == 0.0) {
+ qWarning() << "SSE: Denormals to zero mode not working";
+ }
 #endif
     }

[Sébastien BLAISOT (sblaisot)]

I hav a party yesterd

[Sébastien BLAISOT (sblaisot)]

I had a party yesterday and used Mixxx 1.12 r5595 64bits on wind 10 64 bits and encountered this bug again.

It's really anoying because you can not use it anymore, it's a showstopper :(

I tried your piece of code without success (no warning in the logs).

I obsrved yesterday that sometimes it diseapears adn somtimes it apears again. I couldn't find any rationale.

any hint ?

[Daniel Schürmann (daschuer)]

Oh sh... this is seams to be relay a new blocker bug for 1.12 ... and no Idea how to fix it yet. 😠
I'll keep thinking.

[Sébastien BLAISOT (sblaisot)]

some additionnal notes :

* I've seen this happen in deck 1 and deck 2. I was using a 2-decks configuration (using only 2 of the four decks). toggling to four decks leads to deck 3/4 not subject to this problem and deck 1/2 affected. (it's possible that deck 3/4 didn't have quantize and/or keylock enabled when deck 1/2 had them)

* all my tracks had been analyzed before, so this doesn't seems to be related to previously unanalysed tracks.

* I had this bug with a soundcard configuration different from the last time, so this seems unrelated to a specific soundcard model.

* unfortunately, in the middle of a mix, I didn't have time to make much tests, but I will try to reproduce it and disable each configurable option to see if it helps (replaygain, effects, etc...)

[Sébastien BLAISOT (sblaisot)]

OK, I got it and can reproduce 100%

note : I use the LateNight skin, I don't know if this can be of some interrest

Steps to reproduce :
1) launch mixxx, make sure that all equalizer knobs are set to middle (no effect)
2) load a track in deck A (it seems to be the same with other decks although I have not tested yet)
3) Turn the "Low" knob a little bit to the right (more low)
4) start playing the track and then pause it

==> latency usage meter jumps to the red

5) right click the low knob to reset it to middle => latency usage meter falls down to zero

6) change any equalizer knob (low, middle or high) to differ from middle point => latency usage meter jumps in the red

so this seems to be related with equalizer ;)

[Sébastien BLAISOT (sblaisot)]

When a deck hasn't played anything yet, it is not affected. You should at least play one time with one of the equalizer knob not in the middle position to fire up the bug.

When a deck has all the three equalizer knobs in the middle position, it is not affected.

[Sébastien BLAISOT (sblaisot)]

also note that this is not specific to the "low" knob, I have the same with the high or middle knob.

[Owen Williams (ywwg)]

which equalizer plugin are you using? (See preferences)

[Owen Williams (ywwg)]

Can't reproduce. Can you post a screenshot of all your equalizer preferences?

[Daniel Schürmann (daschuer)]

That is the exactly the behaviour as if the CPU keeps processing de-normals.
I will add a patch thats has a enhanced test. It would be really strange if the test succeeds, but the bug persists.

[Sébastien BLAISOT (sblaisot)]

Sure, here are my preferences.

[Sébastien BLAISOT (sblaisot)]

When the bug comes, if I go to the equalizer preferences and select "Disable EQ treatment", the latency meter comes down to zero.
So this is definitively linked with equalizer

[Sébastien BLAISOT (sblaisot)]

Bessel8 -> latency meter goes to red
Bessel4 -> latency meter jumps to the middle of the bar
LinkwitzRiley -> latency meter goes to red

so this in not related to a particular algorithm.

[Sébastien BLAISOT (sblaisot)]

maybe helpful:

from https://en.wikipedia.org/wiki/Denormal_number
[...]
"Note that both of these methods must be performed on a *per-thread* basis."

Are we sure that DAZ is activated on *each* thread ?
especially the thread responsible of eq effect ?

[Owen Williams (ywwg)]

I don't understand how this could be denormals -- the track is paused, so none of the eq code should be processing

[Owen Williams (ywwg)]

(or I mean it should just be processing true zeros)

[Daniel Schürmann (daschuer)]

The incoming samples are true zeros, but the buffers are de-normals.

All the reported behaviour is exactly what I can see on Linux without the de-normal processing switched of.
So my bet is that it is not switched of on Windows.

Since we a re talking about a CPU feature, it must be a compiler setting issue.

[Daniel Schürmann (daschuer)]

> The incoming samples are true zeros, but the buffers are de-normals.

This explains also why we need to play a track first. Without doing that that, the internal buffers are also true zero.

The EQs are Infinity filters. So without a denormal to zero feature, we will only reach true zero at infinity after the buffers where filled before. No one wants to wait that long ;-).

[Daniel Schürmann (daschuer)]

> "Note that both of these methods must be performed on a *per-thread* basis."

We have one thread per sound card. But only one of them should processes the EQs.

How many hardware sound cards do you have?

[Sébastien BLAISOT (sblaisot)]

sure, Infinity is a really long time. especially at the end... ;)

yesterday, I used 2 soundcards: one for master (integrated USB DAC in the analog mixer used as preamp) and my laptop's built-in soundcard for cue output.

today, I reproduced it with only one soundcard: the laptop's built-in soundcard for master, no cue out as this soundcard is only 2-channels.

[Sébastien BLAISOT (sblaisot)]

I was able to reproduce the bug on another computer.

windows seven (insted of win10 on my laptop), different processor and different soundcard model.

so this doesn't seems to be related to windows version nor processor.

maybe it's a compiler setting issue.

[Daniel Schürmann (daschuer)]

I can confirm the issue on WinXP 32 and Win10 64
using mixxx-1.12.0-beta1-1.12-git5595-debug-x86.exe

But I do not have these lines in the log file:
"SSE: Enabling denormals to zero mode"
"SSE: Enabling flush to zero mode"

[Daniel Schürmann (daschuer)]

I have found checked:
http://builds.mixxx.org:8081/jenkins/job/1.12-debug/architecture=amd64,platform=windows/lastBuild/consoleFull

Optimization and Tuning... Disabled

So the result is quite clear.

What is the user for a non optimized debug build? I see non.

[Daniel Schürmann (daschuer)]

Got it!

cl : Command line warning D9002 : ignoring unknown option '/arch:SSE2'

[Daniel Schürmann (daschuer)]

Strange ... I cannot confirm the issue with:
mixxx-1.12.0-beta1-1.12-git5596-release-x86.exe on windowsXP
mixxx-1.12.0-beta1-1.12-git5596-release-x64.exe on windows10

I can see the SSE log entry and there is CPU load change issue if the track is paused.

[Daniel Schürmann (daschuer)]

Can you see the issues with on of the release builds above?

[Daniel Schürmann (daschuer)]

I have just pushed a fix for "ignoring unknown option" warning

[Sébastien BLAISOT (sblaisot)]

cl : Command line warning D9002 : ignoring unknown option '/arch:SSE2'

SSE2 flag is erroneous on x64 platform because SSE2 is always included in all 64 bits x64 processors, so this flag is not recognized by the compiler. I have corrected it in master only (didn't want to change compile options during the beta phase) with commit 1da4025
https://github.com/mixxxdj/mixxx/commit/1da40252f2a9ecf8ac06039e881caaf70405d846
This is only a warning telling that the compiler doesn't do anything with this flag, because SSE2 is always enabled on x64. This should be considered harmless.

I have the two lines
"SSE: Enabling denormals to zero mode"
"SSE: Enabling flush to zero mode"
in my logs each time I've seen the problem

I tried today with build r5595 from http://downloads.mixxx.org/builds/1.12/release/
I have the same as you : the two lines are present in the log and despite that the CPU load increase when equalizer was not at zero when playing track and you pause it.

[Sébastien BLAISOT (sblaisot)]

I just tried with
mixxx-1.12.0-beta1-1.12-git5596-release-x64.exe
on windows seven 64 bits

I also see the problem (High CPU load on pause)

I have the following two lines in the log :
Debug []: SSE: Enabling denormals to zero mode
Debug []: SSE: Enabling flush to zero mode

What seems strange to me is "[]" : there is no thread indication.
Are we trying to set DAZ outside of any thread despite the fact that this has to be done for each thread ?

[Daniel Schürmann (daschuer)]

Debug []: is normal, since the thread is created outside Mixxx and has not a Qt name.

In my comment #28, I missed an important word "not".

I have no CPU load issues with the latest release builds, only the debug builds are suffering the issues.

Maybe it is a Multicore issue on your hardware.

Please remove the condition:

    if (!m_bSetThreadPriority) {

and report the log output.
You are probably not able to play a track without stutter, but this will check the denomals flags every callback,
so we can check, if the flags remains set.

[Sébastien BLAISOT (sblaisot)]

daniel, when you say you don't see CPU load with latest build when track is paused, did you first turn one eq knob for that channel before starting playing track ?

because I am able to reproduce it with latest build.

I'm actually compiling after replacing
    if (!m_bSetThreadPriority) {
by
    if (false) {

to exclude the whole block.
This is what you meant, right ?

[Sébastien BLAISOT (sblaisot)]

ok, compilation done.

When replacing
    if (!m_bSetThreadPriority) {
by
    if (false) {

I don't see the two DAZ/FTZ log lines.
Mixxx reacts exactly the same (no problem to read a track, but high CPU when track is paused after eq has been used.

attached is my log file

[Sébastien BLAISOT (sblaisot)]

With
if (!m_bSetThreadPriority) {
block removed, I added the code snippet of your comment #3 and the log filled with warning messages Warning [Engine]: SSE: Denormals to zero mode not working

so now I know denormals are not treated as zero

I then make one more step in reenabling the if (!m_bSetThreadPriority) block
and I found in the log :

Debug []: SSE: Enabling denormals are zero (DAZ) mode
Debug []: SSE: Enabling flush to zero (FTZ) mode
Warning [Engine]: SSE: Denormals to zero mode not working
Warning [Engine]: SSE: Denormals to zero mode not working
Warning [Engine]: SSE: Denormals to zero mode not working

So we now have the evidence that DAZ/FTZ are not working on my two computers.

why the hell this doesn't work ?

[Daniel Schürmann (daschuer)]

with the current un-patched 1.12 branch, do you see:
SSE: Flush to zero mode not working; ?

If not, do you see the warning if you process the check in every cycle (below the if (!m_bSetThreadPriority) { block?

What is the result of this code:
         // test passes if one of the two flag is set.
         volatile double doubleMin = DBL_MIN; // the smallest normalized double
         DEBUG_ASSERT_AND_HANDLE(doubleMin / 2 == 0.0) {
- qWarning() << "SSE: Flush to zero mode not working";
+ qWarning() << "SSE: Flush to zero mode inital not working";
+ } else {
+ qDebug() << "SSE: Flush to zero mode inital working";
         }
 #endif
     }

+#ifdef __SSE__
+ volatile double doubleMin = DBL_MIN; // the smallest normalized double
+ DEBUG_ASSERT_AND_HANDLE(doubleMin / 2 == 0.0) {
+ qWarning() << "SSE: Flush to zero mode not working";
+ _MM_SET_DENORMALS_ZERO_MODE(_MM_DENORMALS_ZERO_ON);
+ _MM_SET_FLUSH_ZERO_MODE(_MM_FLUSH_ZERO_ON);
+ DEBUG_ASSERT_AND_HANDLE(doubleMin / 2 == 0.0) {
+ qWarning() << "SSE: Flush to zero mode still not working";
+ }
+ }
+#endif
+
     VisualPlayPosition::setTimeInfo(timeInfo);

     if (statusFlags & (paOutputUnderflow | paInputOverflow)) {

[Daniel Schürmann (daschuer)]

Which CPU do you use? Mine is i5-4570S

[Sébastien BLAISOT (sblaisot)]

My desktop computer is a core i5-3550
My Laptop is an i5-M520

[Sébastien BLAISOT (sblaisot)]

we are getting closer.

with your proposed code in comment #37, I don't see the high cpu usage on track pause.
but when I'm playing a track, I hear cracklings :(

here are the logs :

Debug []: SSE: Enabling denormals to zero mode
Debug []: SSE: Enabling flush to zero mode
Debug []: SSE: Flush to zero mode inital working
Warning [Engine]: SSE: Flush to zero mode not working
Warning [Engine]: SSE: Flush to zero mode not working

so activating FTZ works, but has to be reset each time.

[Sébastien BLAISOT (sblaisot)]

        // verify if flush to zero or denormals to zero works
        // test passes if one of the two flag is set.

I think this comment is wrong.
You only test FTZ (flush result to zero) and not DAZ because you don't have any operand that is a denormal.
DAZ treat denormal operands as zero, FTZ flush denormal results to zero.
So if DAZ is on and FTZ is off, the test will fail.

[Daniel Schürmann (daschuer)]

I assume if you remove the

 qWarning() << "SSE: Flush to zero mode not working";

The crackling will be gone.

This means someone in the library resets the flag or it is spawned a new thread on every process call.
The later means that the high priority will be gone as well.

Please extend the call to:
 qWarning() << "SSE: Flush to zero mode not working. Thread ID:" << QThread::currentThreadId() << GetCurrentThreadId();
and #include <Windows.h>

[Daniel Schürmann (daschuer)]

> I think this comment is wrong.
> You only test FTZ (flush result to zero) and not DAZ because you don't have any operand that is a denormal.
> DAZ treat denormal operands as zero, FTZ flush denormal results to zero.
> So if DAZ is on and FTZ is off, the test will fail.

I have tested it on my Linux machine. The test passes if one of the flags is set.
FTZ will flush the result of doubleMin / 2 to 0.0 while DAZ will use 0.0 as the left input for ==.

[Sébastien BLAISOT (sblaisot)]

Oh, yes, you're right, there are 2 operations : the division and the comparison.

My mistake.

thanks.

I'm compiling code of comment #42

[Sébastien BLAISOT (sblaisot)]

Debug []: SSE: Enabling denormals to zero mode
Debug []: SSE: Enabling flush to zero mode
Debug []: SSE: Flush to zero mode inital working
Warning [Engine]: SSE: Flush to zero mode not working. Thread ID: 0x2464 9316
Warning [Engine]: SSE: Flush to zero mode not working. Thread ID: 0x2464 9316
Warning [Engine]: SSE: Flush to zero mode not working. Thread ID: 0x2464 9316

each subsequent warning SSE: Flush to zero mode not working has the same thread ID

[Sébastien BLAISOT (sblaisot)]

I added thread ID to initial check also :

Debug []: SSE: Enabling denormals to zero mode
Debug []: SSE: Enabling flush to zero mode
Debug []: SSE: Flush to zero mode inital working. Thread ID: 0x2e04 11780
Warning [Engine]: SSE: Flush to zero mode not working. Thread ID: 0x2e04 11780
Warning [Engine]: SSE: Flush to zero mode not working. Thread ID: 0x2e04 11780
Warning [Engine]: SSE: Flush to zero mode not working. Thread ID: 0x2e04 11780
Warning [Engine]: SSE: Flush to zero mode not working. Thread ID: 0x2e04 11780

What is strange is that FTZ is working initially, and then is not working inside the same thread ID.

so what the hell is disabling FTZ/DAZ.

There is something strange I don't understand.

[Daniel Schürmann (daschuer)]

Ok so there is "evil" code which resets the flags.

As long as we can't find out who does it. We have to set the flags on every call.

By the way: Is the flag reset all the time or only for times, by the count of cores?

Please verify if the flags are still set at the end of the callbackProcessClkRef(), this might help to find the evil code.

[Sébastien BLAISOT (sblaisot)]

Now that I'm able to reproduce the bug, I'll try to find which version/commit introduced it.
I'll do that this evening.

[Sébastien BLAISOT (sblaisot)]

r5374 is already affected, so this doesn't come from code added during the 1.12 beta phase.

[Sébastien BLAISOT (sblaisot)]

made some more tests :

1) I have hundreds lines of "flush to zero mode not working" so it seams that the flag is reset all the time. it doesn't seems to be correlated with number of core although I can't garantee that windows save/restore fp flags on thread switch

2) I verified the flags at the end of the callbackProcessClkRef() function, they are still set, so there is no code inside that function that disables the flags.

[Owen Williams (ywwg)]

Can you build from source? The git bisect command can help narrow down the issue, as long as you can find a revision without the bug.

[Daniel Schürmann (daschuer)]

> I can't garantee that windows save/restore fp flags on thread switch

Since I do not see the issue, it can't be a windows issue nor a Mixxx issue.

Maybe it's a diver issue. It mightbe possible, that the your diever whants to set the flag as well, but fails to restor the original state and instead it goes back to default, which is unset.

Which Sound API do you use?

[Daniel Schürmann (daschuer)]

IMHO seaching the faulty commit does not lead to a solution of the issue.
You will probably find the commits where we hav introduced fidlib as IIF Filter generator.
But that does not matter, since we need FTZ for all effect code.

I am considering to set FAZ on every callback as a band aid.
I will have a look how expensive surch a set is.

[Daniel Schürmann (daschuer)]

Got it! I can reproduce you issue using Direct Sound API.

[Owen Williams (ywwg)]

If we have to add a per-callback workaround, we should make sure it's as narrowly targeted as possible.

[Sébastien BLAISOT (sblaisot)]

You're right, I'm using directsound API.

I have choosen this one because I don't have any device in ASIO API (I didn't install IASO drivers nor ASIO4ALL :( )

I will see if I can find ASIO driver for my intagrated soundcard I'm using to test in my desktop PC.

I have ASIO4ALL installed on my laptop, but I forgot I had once to change sound API in Mixxx to fallback to directsound and forgot to switch back to ASIO :(

[Sébastien BLAISOT (sblaisot)]

Tried with ASIO4ALL => no problem.

so the problem is definitively around DirectSound API

[Daniel Schürmann (daschuer)]

The time for setting and querying the flags is not measurable compared to the jitter of the timer call.
I assume that it is just as fast as setting any other CPU registers.
The manual denormals assertion takes much longer.

So it should be no harm to regularly set the bits.

We may guard it by __WINDOWS__ but we have no overview which API driver combination is effected on which target.
So I prefer to just set the bits always.

[Daniel Schürmann (daschuer)]

Implemented here, please check:
https://github.com/mixxxdj/mixxx/commit/c53fc66f679a9b3a0a784650edd5e3d0f03fd62e

[Daniel Schürmann (daschuer)]

Cool!

[Swiftb0y (swiftb0y)]

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