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

mixxxbot commented 2 years ago

Reported by: sblaisot Date: 2015-09-12T10:16:21Z Status: Fix Released Importance: Critical Launchpad Issue: lp1495047 Attachments: [equalizer preferences](https://bugs.launchpad.net/bugs/1495047/+attachment/4509841/+files/equalizer preferences), mixxx.log

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 ?

mixxxbot commented 2 years ago

Commented by: daschuer Date: 2015-09-12T19:00:21Z

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?

mixxxbot commented 2 years ago

Commented by: sblaisot Date: 2015-09-12T19:50:01Z

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".

mixxxbot commented 2 years ago

Commented by: daschuer Date: 2015-09-12T20:30:04Z

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
     }

mixxxbot commented 2 years ago

Commented by: sblaisot Date: 2015-10-31T10:05:54Z

I hav a party yesterd

mixxxbot commented 2 years ago

Commented by: sblaisot Date: 2015-10-31T10:10:38Z

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 ?

mixxxbot commented 2 years ago

Commented by: daschuer Date: 2015-10-31T12:18:22Z

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.

mixxxbot commented 2 years ago

Commented by: sblaisot Date: 2015-10-31T13:08:07Z

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...)

mixxxbot commented 2 years ago

Commented by: sblaisot Date: 2015-10-31T13:42:23Z

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 ;)

mixxxbot commented 2 years ago

Commented by: sblaisot Date: 2015-10-31T13:47:35Z

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.

mixxxbot commented 2 years ago

Commented by: sblaisot Date: 2015-10-31T13:49:09Z

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

mixxxbot commented 2 years ago

Commented by: ywwg Date: 2015-10-31T14:37:42Z

which equalizer plugin are you using? (See preferences)

mixxxbot commented 2 years ago

Commented by: ywwg Date: 2015-10-31T14:39:11Z

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

mixxxbot commented 2 years ago

Commented by: daschuer Date: 2015-10-31T15:22:46Z

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.

mixxxbot commented 2 years ago

Commented by: sblaisot Date: 2015-10-31T15:29:45Z Attachments: [equalizer preferences](https://bugs.launchpad.net/mixxx/+bug/1495047/+attachment/4509841/+files/equalizer preferences)

Sure, here are my preferences.

mixxxbot commented 2 years ago

Commented by: sblaisot Date: 2015-10-31T15:31:51Z

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

mixxxbot commented 2 years ago

Commented by: sblaisot Date: 2015-10-31T15:34:03Z

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.

mixxxbot commented 2 years ago

Commented by: sblaisot Date: 2015-10-31T15:50:58Z

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 ?

mixxxbot commented 2 years ago

Commented by: ywwg Date: 2015-10-31T16:01:52Z

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

mixxxbot commented 2 years ago

Commented by: ywwg Date: 2015-10-31T16:02:08Z

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

mixxxbot commented 2 years ago

Commented by: daschuer Date: 2015-10-31T16:32:21Z

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.

mixxxbot commented 2 years ago

Commented by: daschuer Date: 2015-10-31T16:36:39Z

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 ;-).

mixxxbot commented 2 years ago

Commented by: daschuer Date: 2015-10-31T16:38:14Z

"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?

mixxxbot commented 2 years ago

Commented by: sblaisot Date: 2015-10-31T16:47:53Z

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.

mixxxbot commented 2 years ago

Commented by: sblaisot Date: 2015-10-31T16:49:48Z

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.

mixxxbot commented 2 years ago

Commented by: daschuer Date: 2015-10-31T21:10:47Z

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"

mixxxbot commented 2 years ago

Commented by: daschuer Date: 2015-10-31T21:17:50Z

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.

mixxxbot commented 2 years ago

Commented by: daschuer Date: 2015-10-31T21:24:23Z

Got it!

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

mixxxbot commented 2 years ago

Commented by: daschuer Date: 2015-10-31T21:34:00Z

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.

mixxxbot commented 2 years ago

Commented by: daschuer Date: 2015-10-31T21:34:39Z

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

mixxxbot commented 2 years ago

Commented by: daschuer Date: 2015-10-31T21:52:29Z

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

mixxxbot commented 2 years ago

Commented by: sblaisot Date: 2015-10-31T21:53:27Z

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.

mixxxbot commented 2 years ago

Commented by: sblaisot Date: 2015-10-31T22:05:15Z

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 ?

mixxxbot commented 2 years ago

Commented by: daschuer Date: 2015-10-31T22:37:52Z

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.

mixxxbot commented 2 years ago

Commented by: sblaisot Date: 2015-10-31T23:35:22Z

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 ?

mixxxbot commented 2 years ago

Commented by: sblaisot Date: 2015-10-31T23:59:42Z Attachments: mixxx.log

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

mixxxbot commented 2 years ago

Commented by: sblaisot Date: 2015-11-01T00:36:04Z

With 
if (!m_bSetThreadPriority) { 
block removed, I added the code snippet of your comment mixxxdj/mixxx#4912 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 ?

mixxxbot commented 2 years ago

Commented by: daschuer Date: 2015-11-01T08:09:33Z

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)) {

mixxxbot commented 2 years ago

Commented by: daschuer Date: 2015-11-01T08:12:01Z

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

mixxxbot commented 2 years ago

Commented by: sblaisot Date: 2015-11-01T08:31:10Z

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

mixxxbot commented 2 years ago

Commented by: sblaisot Date: 2015-11-01T08:52:35Z

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.

mixxxbot commented 2 years ago

Commented by: sblaisot Date: 2015-11-01T09:19:19Z

    // 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.

mixxxbot commented 2 years ago

Commented by: daschuer Date: 2015-11-01T09:21:13Z

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>

mixxxbot commented 2 years ago

Commented by: daschuer Date: 2015-11-01T09:31:52Z

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 ==.

mixxxbot commented 2 years ago

Commented by: sblaisot Date: 2015-11-01T09:41:29Z

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

My mistake.

thanks.

I'm compiling code of comment #⁠42

mixxxbot commented 2 years ago

Commented by: sblaisot Date: 2015-11-01T09:47:12Z

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

mixxxbot commented 2 years ago

Commented by: sblaisot Date: 2015-11-01T10:09:12Z

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.

mixxxbot commented 2 years ago

Commented by: daschuer Date: 2015-11-01T10:37:43Z

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.

mixxxbot commented 2 years ago

Commented by: sblaisot Date: 2015-11-01T11:34:10Z

mixxxbot commented 2 years ago

Commented by: sblaisot Date: 2015-11-01T13:40:59Z

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.

mixxxbot commented 2 years ago

Commented by: sblaisot Date: 2015-11-01T17:57:10Z

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

mixxxdj / mixxx

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