Defold: Sounds with higher speeds don't stop playing

[JCash]

The higher the speeds, the more likely the sound won't actually stop.

https://forum.defold.com/t/sound-buffer-full-if-sound-speed-is-3/66503

Check the dmSound::IsPlaying() for clues.

[otsakir]

I reproduced the issue with the given project and did some further digging. I'm sharing my "findings", in case it helps:

Manual tests

I kept upper button at speed 1 and experimented with various speeds from 2 to 5 for the lower button. I built the project and hammered the lower button trying to find any clues.

2 works
2.5 works
2.8 fails, but not exactly after 32 clicks. Heard some crackling.
2.9 works, hear some crackling
3 it fails. Exactly 32 clicks
3.1 fails. Needed hamering. Heard some crackling.
3.5 fails. Exactly 32 clicks
4 it fails. Exactly 32 clicks
4.5 fails. Exactly 32 clicks
4.9 fails. Exactly 32 clicks
5 works

Digging with GDB

Starting from the assumption that dmSound::IsPlaying() doesn't work correctly i tried to get to the bottom of it. With only a minimal understanding of how the sound mixing works, it seemed to me that it came down to SoundInstance.m_Playing and from there to SoundInstance.m_FrameCount. I tried to monitor m_FrameCount property of a sound instance after a speedy sound was played. It reflected mixing of packets of ~3000 frames while the sound played but at the end it fell to '2' and stayed there.

My guess is that these '2' frames prevent the sound instance of actually terminating. Thus, 'IsPlaying' stays true. I'll try to dig further tomorrow now that it starts to make some sense.

[otsakir]

Moving forward in that direction, i'm pasting some debug data. In my test case, i set speed=4 in the sound component, i started the app and hit 'Speed 3' button. Below i'm monitoring a SoundInstance object and m_FrameCount property in particular.

1063            uint64_t delta = (uint32_t) ((((uint64_t) info->m_Rate) << RESAMPLE_FRACTION_BITS) / sound->m_MixRate);
4: *instance = {m_Decoder = 0x10c9f10, m_Frames = 0x10cff30, m_Group = 12057225920102567308, m_Gain = {m_Prev = 1, m_Current = 1, 
    m_Next = 1}, m_Pan = {m_Prev = 0.5, m_Current = 0.5, m_Next = 0.5}, m_Speed = 4, m_FrameCount = 3072, m_FrameFraction = 0, 
  m_Index = 0, m_SoundDataIndex = 0, m_Looping = 0 '\000', m_EndOfStream = 0 '\000', m_Playing = 1 '\001'}
(gdb) c
Continuing.

Thread 18 "sound" hit Breakpoint 5, dmSound::Mix (mix_context=0x7fffe409be18, instance=0x10cb720, info=0x7fffe409bd38)
    at ../src/sound.cpp:1063
1063            uint64_t delta = (uint32_t) ((((uint64_t) info->m_Rate) << RESAMPLE_FRACTION_BITS) / sound->m_MixRate);
4: *instance = {m_Decoder = 0x10c9f10, m_Frames = 0x10cff30, m_Group = 12057225920102567308, m_Gain = {m_Prev = 1, m_Current = 1, 
    m_Next = 1}, m_Pan = {m_Prev = 0.5, m_Current = 0.5, m_Next = 0.5}, m_Speed = 4, m_FrameCount = 3072, m_FrameFraction = 0, 
  m_Index = 0, m_SoundDataIndex = 0, m_Looping = 0 '\000', m_EndOfStream = 0 '\000', m_Playing = 1 '\001'}
(gdb) c
Continuing.

Thread 18 "sound" hit Breakpoint 5, dmSound::Mix (mix_context=0x7fffe409be18, instance=0x10cb720, info=0x7fffe409bd38)
    at ../src/sound.cpp:1063
1063            uint64_t delta = (uint32_t) ((((uint64_t) info->m_Rate) << RESAMPLE_FRACTION_BITS) / sound->m_MixRate);
4: *instance = {m_Decoder = 0x10c9f10, m_Frames = 0x10cff30, m_Group = 12057225920102567308, m_Gain = {m_Prev = 1, m_Current = 1, 
    m_Next = 1}, m_Pan = {m_Prev = 0.5, m_Current = 0.5, m_Next = 0.5}, m_Speed = 4, m_FrameCount = 3072, m_FrameFraction = 0, 
  m_Index = 0, m_SoundDataIndex = 0, m_Looping = 0 '\000', m_EndOfStream = 0 '\000', m_Playing = 1 '\001'}
(gdb) c
Continuing.

Thread 18 "sound" hit Breakpoint 5, dmSound::Mix (mix_context=0x7fffe409be18, instance=0x10cb720, info=0x7fffe409bd38)
    at ../src/sound.cpp:1063
1063            uint64_t delta = (uint32_t) ((((uint64_t) info->m_Rate) << RESAMPLE_FRACTION_BITS) / sound->m_MixRate);
4: *instance = {m_Decoder = 0x10c9f10, m_Frames = 0x10cff30, m_Group = 12057225920102567308, m_Gain = {m_Prev = 1, m_Current = 1, 
    m_Next = 1}, m_Pan = {m_Prev = 0.5, m_Current = 0.5, m_Next = 0.5}, m_Speed = 4, m_FrameCount = 2543, m_FrameFraction = 0, 
  m_Index = 0, m_SoundDataIndex = 0, m_Looping = 0 '\000', m_EndOfStream = 0 '\000', m_Playing = 1 '\001'}
(gdb) c
Continuing.

Thread 18 "sound" hit Breakpoint 5, dmSound::Mix (mix_context=0x7fffe409be18, instance=0x10cb720, info=0x7fffe409bd38)
    at ../src/sound.cpp:1063
1063            uint64_t delta = (uint32_t) ((((uint64_t) info->m_Rate) << RESAMPLE_FRACTION_BITS) / sound->m_MixRate);
4: *instance = {m_Decoder = 0x10c9f10, m_Frames = 0x10cff30, m_Group = 12057225920102567308, m_Gain = {m_Prev = 1, m_Current = 1, 
    m_Next = 1}, m_Pan = {m_Prev = 0.5, m_Current = 0.5, m_Next = 0.5}, m_Speed = 4, m_FrameCount = 3, m_FrameFraction = 0, 
  m_Index = 0, m_SoundDataIndex = 0, m_Looping = 0 '\000', m_EndOfStream = 1 '\001', m_Playing = 1 '\001'}
(gdb) c
Continuing.

Thread 18 "sound" hit Breakpoint 5, dmSound::Mix (mix_context=0x7fffe409be18, instance=0x10cb720, info=0x7fffe409bd38)
    at ../src/sound.cpp:1063
1063            uint64_t delta = (uint32_t) ((((uint64_t) info->m_Rate) << RESAMPLE_FRACTION_BITS) / sound->m_MixRate);
4: *instance = {m_Decoder = 0x10c9f10, m_Frames = 0x10cff30, m_Group = 12057225920102567308, m_Gain = {m_Prev = 1, m_Current = 1, 
    m_Next = 1}, m_Pan = {m_Prev = 0.5, m_Current = 0.5, m_Next = 0.5}, m_Speed = 4, m_FrameCount = 3, m_FrameFraction = 0, 
  m_Index = 0, m_SoundDataIndex = 0, m_Looping = 0 '\000', m_EndOfStream = 1 '\001', m_Playing = 1 '\001'}

Note how the samples go in chunks of 3072 frames (768*4. 4 is the speed from what i understand) as the sound plays. Right before the end i got 2543 frames and then it sticked to 3. Forever.

The details of mix process are not clear to me but i think this bug is about the 'granularity' of the number of frames in relation to the speed. So, if speed is 4, it makes sense to take a frame every 4. However 2543 % 4 == 3. So, _that's where the last 3 frames come from_.

To confirm the assumption, i also checked what happens for speed == 5. In this case m_FrameCount went like this:

3840 - 3840 - 3840 ... - 3840 - 1775

The division remainder here is zero, and thus, it works.

@britzl , @JCash , i could try to implement a fix for this. I was thinking about reseting m_FrameCount to 0, when the last batch of frames is processed and it is less than speed. That's the simplest i could think of and seems safe.

wdyt ?

[JCash]

Aha, nice catch!
Yes I believe you are right!
We'd be happy to get a fix for this, and your solution seems valid to me.

[otsakir]

Great! Thanks, @JCash .

Meanwhile, I implemented the fix and it seems to work ok ;-).

Btw, how do you guys handle such bug cases in terms of test automation? Do you test them ? I went quickly through engine/sound/src/test but i'm not sure it's the right place.

Can you suggest any existing test code that would be relevant ? I was thinking of programmatically opening the .ogg, and try to play it several times, get the exception. But it would help get an example how all this is set up.

Thanks

[JCash]

Btw, how do you guys handle such bug cases in terms of test automation? Do you test them ? I went quickly through engine/sound/src/test but i'm not sure it's the right place.

Yes, please add a test in the test_sound.cpp, TEST_P(dmSoundTestPlaySpeedTest, Play), by adding one or more entries in the params_test_play_speed_testlist at ~line 1091;

Also make sure the tests fail without your fix (i.e. give it a wonky speed parameter).

[otsakir]

@JCash , submitted a PR finally. I had some rough time on building the test.

Btw, i could use some help regarding the jc_test testsuite --test-filter parameter. Does it work ?

How can you select to run a specific test only, say dmSoundTestSpeedTest ?

I went through jc_test the docs and tried all sorts of values for --test-filter. When it was taken into account that were no tests run.

Btw, the --test-filter= mentioned in the docs (using the equal sign) doesn't seem to be taken into account. Just a heads-up because that's how it is mentioned in the docs:

https://github.com/defold/defold/blob/dev/README_BUILD.md#unit-tests

Regards

Orestis

[JCash]

Regarding --test-filter, I have a bug for one of the test classes, which makes it ignore the test filter :/
Thanks for reminding me that I need to fix it asap.