Comment 13 for bug 1777480

Revision history for this message
Dale (dj-kaza) wrote :

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.