Quantised HotCues sometimes miss the beat

[Dale]

I'd experienced it a few times for ages but as I generally have Quantise off and am most preparing tracks for the future (not real DJing and using Mixxx to its fullest) I'd never got around to confirming this bug until it was reported in the forum at:
https://mixxx.org/forums/viewtopic.php?f=3&t=11899

In short Mixxx occasionally delays the triggering of a HotCue when Quantise is enabled (separate to the bug with 2.1.1 when HotCues are always Quantised.)

When I was testing the HotCue Always Quantised bug I was getting the offset HotCue about once every 10-15 presses. Just now I was testing to confirm whether the offset is visual only or really affecting the audio I only had it do it once in about 10 minutes of repeatedly bashing the HotCue buttons. Therefore it can be quite hard to test for.

But I did confirm it definitely affects the audio, not only the waveforms!

I believe (but not conclusive) that the HotCue is always triggered a little late, so possibly something is causing a delay and the command is not running exactly on time as it should.

Tested and seen on Ubuntu Studio 18.04 with Mixxx 2.1.1 and 2.1.0.

[Daniel Schürmann (daschuer)]

I cannot confirm the bug. Is quantized CUE and Play also effected?
What is your audio buffer size?
Did you enable constant beat grids?

[Daniel Schürmann (daschuer)]

The only thing that I can confirm it that the CUE respects quantize when the track is paused but not hot cues.

[Dale (dj-kaza)]

"The only thing that I can confirm it that the CUE respects quantize when the track is paused but not hot cues."

Not sure what you mean about this, both Cue and HotCues respect Quantise when on and are only triggered or set on the beatmarker when activated from Pause here....

"I cannot confirm the bug."

The fact it is intermittent and I'd never got a grasp on exact characteristics, yet alone a way to easily recreate the issue, is part of why I hadn't reported the bug before another user posted the same issue on the forum (along with the fact I stopped pretty much ever using Quantise anyway so it doesn't overly affect me most of the time.)

"Is quantized CUE and Play also effected?"

Yes Play is also affected sometimes, I never use the standard Cue button.

"What is your audio buffer size?"

Mixxx reports the 23.2ms buffer and this is not possible to be changed from Preferences. Jack is set to 44.1kHz, 128 frames, 3 buffers to give a latency of 8.71ms.

"Did you enable constant beat grids?"

Some people think I'm weird but I always analyse with Assume Constant Tempo enabled. I like to have a consistent beatgrid and know if a track varies from a solid tempo and manually adjest, rather than getting to try and keep tracks with a drifting tempo in time using Master Sync.

[Dale (dj-kaza)]

Yesterday when I was trying to confirm the audio really lags as well and waveforms I got one instance in ten minutes of near constant triggering. This morning double-checking I had really seen it with Play and again playing with HotCues a little and I got an occurrence rate of probably 30-40% of the time. So sometimes it really can be very prevalent! Probably not in the slightest related but both times it's occurred with high regularity in last couple of days the laptop has only been fairly recently switched on......

[Dale (dj-kaza)]

OK this does seem to affect every way of changing (or starting) PlayPos but by far the one that shows the behaviour the most often on my system is dropping the cursor on the overview waveform view to seek to a random new location.

Could it be related to flushing and refilling the audio buffer? Or some other kind of track buffer?

[Dale (dj-kaza)]

I know you've not managed to recreate this but I still see it on PR1716, which fixes this other issue with Quantise and I hoped may have been in some way related.

https://bugs.launchpad.net/mixxx/+bug/1777667

[Daniel Schürmann (daschuer)]

Yes, if you click on the overview waveform, cache misses are likely because Mixxx cannot predict where you click.

I am not sure if I get the issue correct here.
You play one track in deck A and you have a track in deck B cued at a hot cue. Quantize is on. Now you press and hold the hot cue, or play and the track does not perfectly allign with the track in deck A, right?

How big is the offset in percent of a beat?
Does the offset change if you try the same thing again? Is the visalisation offset of the alougned brats constant, when moving out of the waveform view?
Does sync enabled make any difference? Does the track shift to be synced when sync is enabled?
Does the issue accour if you load the same track to both decks? Does it accour if the rate slider is at unity?

[Daniel Schürmann (daschuer)]

Can you add a step by step guide how to reproduce the issue?

[Dale (dj-kaza)]

"Yes, if you click on the overview waveform, cache misses are likely because Mixxx cannot predict where you click."

I think the issue is the same as this but I don't only get in on clicking the waveform.

I generally have experienced it (and test) by playing two tracks and jumping hotcues while playing. As said I did see the behaviour on a Play though, and that would have been from a paused state so not only while jumping audio that would be buffered. Often get it from repeated trigger of same hotcue.

Percentage is small, best to have maximum zoom to see it, and is audible in a slightly clipity-clop beat. Yes it happens at unity pitch. The rest of the questions I can try and test in a few days time and get back....

"Can you add a step by step guide how to reproduce the issue?"

Unfortunately it has always been intermittent so this is hard. Part of the reason I let myself forget about it until another user posted it in the forum and has downgraded to 2.0 because of it.

[Dale (dj-kaza)]

"Yes, if you click on the overview waveform, cache misses are likely because Mixxx cannot predict where you click."

Would it be possible to add a check if the buffered audio has come from the sections by the triggered position and if not delay trigger for a buffer while you flush and refil it? A slight delay in trigger would be better than the sync going out of time.

[Dale (dj-kaza)]

I find it hard to believe nobody else can recreate this. I have a fairly fast laptop with an i7 5500U and 16BG of RAM so shouldn't be an issue with resources.

We did a chill event a couple of days ago and I accidentally opened 2.1.1 rather than the GIT version I have built so had the forced quantise on hotcue bug mentioned above and I would say this offset trigger occurred 30% plus of the time when triggering hotcues and occasionally on Play from pause in a normal DJ set. Mostly I would fix it by hitting Sync after triggering if I see it....

[Dale (dj-kaza)]

Have you tested with Xubuntu or Ubuntu Studio (which is Xubuntu based)? That OS seems to be a common denominator between me and the OP in the forum thread....

[Dale (dj-kaza)]

OK happening a lot but as just been working on my mapping had all the terminal debug information being written. Hopefully the messages here can help you find the source of the issue.

Three presses of a HotCue with no issue below. Note there is a "BpmControl::getNearestPositionInPhase out of date" for each which is not related (at first thought it might be.)
Debug [Controller]: "Twitch MIDI 1: t:1442560 ms status 0x97 (ch 8, opcode 0x9), ctrl 0x60, val 0x7F"
Debug [Engine]: BpmControl::getNearestPositionInPhase out of date 2.40989e+06 6.57266e+06 6.50659e+06
Debug [Engine]: 2.41033e+06 2.4764e+06 66068 2.40989e+06
Debug [Engine]: 3.59043e+06 3.65658e+06 66150 0.0896145
Debug [Engine]: -0.134422 0.0099896 0.0896145 2.41625e+06
Debug [CachingReaderWorker 1]: SoundSourceMP3 - restartDecoding @ 1178496
Debug [CachingReaderWorker 1]: SoundSourceMP3 - Retry decoding MP3 frame @ 1178496
Debug [Controller]: "Twitch MIDI 1: t:1442596 ms status 0x97 (ch 8, opcode 0x9), ctrl 0x60, val 0x00"
Debug [Controller]: "Twitch MIDI 1: t:1443440 ms status 0x97 (ch 8, opcode 0x9), ctrl 0x64, val 0x7F"
Debug [Engine]: BpmControl::getNearestPositionInPhase out of date -34648 2.87281e+06 2.80675e+06
Debug [Engine]: -34208 31862 66070 -34648
Debug [Engine]: 3.98733e+06 4.05348e+06 66150 0.188723
Debug [Engine]: -0.283084 0.0099896 0.188723 -21739.3
Debug [CachingReaderWorker 1]: SoundSourceMP3 - restartDecoding @ 0
Debug [CachingReaderWorker 1]: SoundSourceMP3 - Retry decoding MP3 frame @ 0
Debug [Controller]: "Twitch MIDI 1: t:1443480 ms status 0x97 (ch 8, opcode 0x9), ctrl 0x64, val 0x00"
Debug [Engine]: CachingReader - Prepending 642 frames of silence

Then the fourth press I had the issue apparent. Very clearly a cache error, as shown in the two Debug lines.
Debug [Controller]: "Twitch MIDI 1: t:1443648 ms status 0x97 (ch 8, opcode 0x9), ctrl 0x60, val 0x7F"
Debug [Engine]: BpmControl::getNearestPositionInPhase out of date 2.40989e+06 97930 31862
Debug [Engine]: 2.41033e+06 2.4764e+06 66068 2.40989e+06
Debug [Engine]: 4.05348e+06 4.11963e+06 66150 0.64384
Debug [Engine]: 0.53424 0.0099896 0.64384 2.3868e+06
Debug [Engine]: CachingReader - Cache miss for chunk with index 145
Debug [Engine]: didn't get what we wanted 0 2044
Debug [Engine]: CachingReader - Cache miss for chunk with index 145
Debug [Engine]: didn't get what we wanted 0 2044
Debug [CachingReaderWorker 1]: SoundSourceMP3 - restartDecoding @ 1154304
Debug [CachingReaderWorker 1]: SoundSourceMP3 - Retry decoding MP3 frame @ 1154304

I was only alternating between HC1 and HC5, so this area had been recently (but not last) played.

I think all audio should be decoded and buffered in RAM on track load, in a background process so this does not need to complete before you can start to play a track. I think the realtime decoding is likely at least exasperating this issue.

[Daniel Schürmann (daschuer)]

Is
BpmControl::getNearestPositionInPhase
or the
CachingReader - Cache miss for chunk with index the issue?

Is sync enabled? Maybe you see
https://bugs.launchpad.net/mixxx/+bug/1777667
fixed here:
https://github.com/mixxxdj/mixxx/pull/1716

[Dale (dj-kaza)]

I'm using #1716 which fixes the sync issue (and Master Sync wasn't enabled at the time anyway.)

The issue only occurred when the CachingReader lines were printed so I highly suspect those are the related ones. (I realise how unclear the above can be with no formatting on here now.)

[Daniel Schürmann (daschuer)]

So this bug happens with #1716, everytime we have a cache miss?

[Dale (dj-kaza)]

A cache miss happens every time this fault occurs, I couldn't say for certain the other way around (but it seems likely from what I've seen.)

I have only tested with mp3 files. I will try with some wav files later today to rule out it being when decoding kicks back in etc.

Still I was surprised to see the decoding done live! Thought the entire track would be cached in RAM as PCM data upon loading. Surely it would make this kind of thing a lot quicker and less likely....

[Uwe Klotz (uklotzde-deactivatedaccount)]

If the caching reader is not able to provide the requested samples in time the only consequence should be a short moment of silence produced by 0 samples. Subsequent samples should arrive in time as the reader catches up. This caching issue shouldn't affect the timing in any way, i.e. play time in the engine should pass regardless of which samples are actually provided by the reader at a certain position. The reason why the engine only polls twice for the sample range (non-blocking) and then continues processing to stay in time.

Of course, by jumping around within the track you will very likely see those cache misses. But I suppose it is unlikely that there is any direct causal relationship between those cache misses and the timing issues. There actually would be timing issues only if the engine decided to block and wait for those samples indefinitely.

I've never noticed any audible artifacts caused by cache misses.

[Dale (dj-kaza)]

Managed to get it to occur with two wav files.

Debug [Main]: keyboard press: "C"
Debug [Engine]: BpmControl::getNearestPositionInPhase out of date 1.45671e+07 5.57023e+06 5.53243e+06
Debug [Engine]: 1.45666e+07 1.46044e+07 37800 1.45671e+07
Debug [Engine]: 413176 454318 41142 0.939304
Debug [Engine]: 0.0520244 -0.0101587 0.939304 1.45643e+07
Debug [Engine]: CachingReader - Cache miss for chunk with index 888
Debug [Engine]: didn't get what we wanted 0 2048
Debug [Engine]: CachingReader - Cache miss for chunk with index 888
Debug [Engine]: didn't get what we wanted 0 2048

[Dale (dj-kaza)]

"I've never noticed any audible artifacts caused by cache misses."

I can definitely hear it. It's not so far out to sound like a train wreck clashing mix but you do get a clip-clop kinda beat where you can hear they're not quite aligned.

"If the caching reader is not able to provide the requested samples in time the only consequence should be a short moment of silence produced by 0 samples. Subsequent samples should arrive in time as the reader catches up. This caching issue shouldn't affect the timing in any way,"

I think playing the contents of the old buffer (so it would be like hitting the hotcue a fraction of a second later audibly) would be better but either would be better than the current method.

[Daniel Schürmann (daschuer)]

I cannot reprepeoduce the issue, nor the cache misses. But cues are held in cache.

The original reporter has four decks playing, all decks sync enabled and jumps around using hot cues. It sound like a race condition.

How much is the deck off after jumping to a hot cue?

Dale, can you reproduce this original issue with #1716?

[Dale (dj-kaza)]

Just been recording some videos with it happening with wav files and then went to edit them and KDenLive has broken itself....

But as I said it happens to me regularly on #1716 using only two decks whether Master Sync is enabled or not. But yes, jumping around hotcues is what most often triggers it (but I have also experienced it on pressing Play from pause.)

I'll upload the videos anyway unedited. The issue wasn't happening as often as it sometimes does (especially the second video where I have same track in both decks to try and emphasise the audible effect which I wanted to trim the beginning off it) so at least you can see and hear for yourself what happens here.

[Dale (dj-kaza)]

http://www.deaddogdisko.co.uk/Stuff/mixxxHCQ.mkv
About three times over the two minutes, end of the file I leave it playing for a little the hit 1 to bring the beats together so you can (hopefully) hear the difference but not the best tracks to demonstrate it.

http://www.deaddogdisko.co.uk/Stuff/mixxxHCQ2.mkv
Same track in both decks, doesn't happen for quite some time at the start but when it does hopefully it's easier to hear.

[Dale (dj-kaza)]

Second file jump to about 1m20s to hear it.

[Uwe Klotz (uklotzde-deactivatedaccount)]

We should check what actually happens on a cache miss. Your screen recording shows that this might in fact be an issue.

[Uwe Klotz (uklotzde-deactivatedaccount)]

@Dale: Could you please try if the following changes fix the timing issues on a cache miss?
https://github.com/mixxxdj/mixxx/pull/1745

[Daniel Schürmann (daschuer)]

Thank you for the videos. Interesting, unfortunately I still cannot reproduce the cache misses using hot cues. @Uwe: do you have an idea why this happens on dale device.

I have an SSD :-/ mmm maybe I should try with my USB HDD.

[Daniel Schürmann (daschuer)]

With the USB drive I have Cache misses during analyse, but not with hot cues.
I am using the 2.1 branch.

So it looks like we have two issues:
* Cache misses when jumping to hot cues.
* Phase shift due to cache misses

[Dale (dj-kaza)]

"I have an SSD :-/ mmm maybe I should try with my USB HDD."

I use an SSD, plus another sat around with 16.04 installed on it I could just plug in for direct testing which I recently replaced (when I installed 18.04.) Pretty sure that isn't the issue.

[Dale (dj-kaza)]

This is a HP Elitebook 840 G2 with i7 and 16GB of RAM. I'm not running a low spec machine here, which is what has made it all the more surprising to me I see it and you don't.

[Uwe Klotz (uklotzde-deactivatedaccount)]

The occurrence of cache misses depends on both the distance between the hot cues and the speed of the storage media. I can easily reproduce those cache misses by jumping randomly within any track stored on a HDD!

[Daniel Schürmann (daschuer)]

I can confirm the cache misses with random jumps.
Hot-Cues are normally held in the cache, so there must be an issue with this feature in the video.

[Dale (dj-kaza)]

Again thanks for fixing this. Just a note as to why I still don't believe read/write/access speeds is my issue here. It would be nice to know why I get this issue and you could only recreate it when using a slow HDD with your library on it.

$ sudo hdparm -Tt /dev/sda
[sudo] password for dale:

/dev/sda:
 Timing cached reads: 10756 MB in 2.00 seconds = 5388.74 MB/sec
 Timing buffered disk reads: 1592 MB in 3.00 seconds = 530.21 MB/sec

That's my Samsung Evo 850 SSD I currently use. I used to get the same issue on my Crucial MX200 SSD before I upgraded it for more space. I tried every available i/o scheduler and they made no different to cache misses.

[Swiftb0y (swiftb0y)]

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