fix: stop() takes too much time

[filiph]

Description

I keep seeing a log with “stop() takes too much time for handle" when running my flutter_soloud-using game.

I wanted to provide a failing test but I've been busy so I'll at least file this bug.

I've tracked the problem to something like this. I get the problem when:

• playing a lot of “single channel” sounds - new sounds replace preceding sounds
  • I'm doing this programatically (NOT using Soloud's voice feature). This is because I want to fade out the preceding sound while the new sound is playing.
• I don’t ignore the future returned by `SoLoud.stop(handle)`
• I spam starting the new sounds

I’m pretty sure there’s a bug. Some sound handles get through the cracks and their voiceEndedCompleters[handle]?.complete() never gets called.

Steps To Reproduce

I wish I had a better repro, but here's how I can do it in the giant_robot project (which @alnitak has access to):

• open the game
• wait until SFX are loaded (this takes a while in debug mode)
• start moving the mouse pointer up and down the menu, so that it produces a bunch of "bleep" sounds in quick succession

Expected Behavior

All voiceEndedCompleters are completed.

[alnitak]

Hi Filip,

the problem occurs in some rare conditions when a stop is called while another stop hasn't triggered yet the voice ended callback from C to Dart. It's a race condition.

Looking at giant_robot code, I see in soloud_audio_controller.dart line 817 that the stop is awaited, but in audio_controller.dart line 434, it doesn't await. Here comes the rare race condition. But even if you await the stop, the problem persists. By commenting out one of those, the problem disappears.

This probably could be fixed on the C side, because by calling the voiceEndedCallback in the stop function, instead of waiting for the engine to do that, the problem goes out.

I tried hard to reproduce this without success!!

FYI, the button sound never fades out. When debugging, I never entered line 819 of soloud_audio_controller.dart.

[filiph]

Thanks Marco for looking at this!

I wonder, is it possible that _isHandlePresent() on soloud.dart:371 returns null despite voiceEndedCompleters having that handle? In other ways, is it maybe possible for _activeSounds and voiceEndedCompleters to get out of sync?

Because if so, then voiceEndedCompleters[SoundHandle(handle)]?.complete(); on soloud.dart:390 never gets called for that handle. I'd start with asserting that:

assert((soundHandleFound == null && voiceEndedCompleters[SoundHandle(handle)] == null) || (soundHandleFound != null && voiceEndedCompleters[SoundHandle(handle)] != null), '$soundHandleFound vs ${voiceEndedCompleters[SoundHandle(handle)] }');

[filiph]

I couldn't resist and at least created a failing "test":

https://github.com/filiph/flutter_soloud/tree/fix/stop-takes-too-much-time

[filiph]

I couldn't resist and at least created a failing "test":

https://github.com/filiph/flutter_soloud/tree/fix/stop-takes-too-much-time

To run it, do

cd example/
flutter run tests/tests.dart

And click on the new testStopFutures button.

I just modified the test to actually fail (as opposed to just print the severe logs and pass anyway.

[filiph]

I created a PR so the failing test doesn't live only on my fork: #316

[filiph]

Was #316 merged in error? That was just a work in progress.

[filiph]

Anyway, I've played some more with https://github.com/filiph/flutter_soloud/tree/fix/stop-takes-too-much-time and realized that _controller.soLoudFFI.voiceEndedEvents.listen isn't being called when I'd expect it to be.

Even if I play only a single sound. At this point I'm pretty sure I'm holding it wrong but I thought I'd report on my findings anyway.

[alnitak]

Hey Filip,

I have merged just now to have the test still present in the code. I think it could be useful.

While committing a new branch to fix this, in the message I wrote "fix #312" and GitHub auto closed this :). I did well to reopen.

[filiph]

Ah, got it. Makes sense! I improved somewhat on the test over at https://github.com/filiph/flutter_soloud/tree/fix/stop-takes-too-much-time. Should I create another PR?

[alnitak]

So, it seems that the fix in the stopFutures branch works. It's still a draft, and I need to verify other things.

I could describe the problem better with an image:

If a stop() is called while in the red ellipses, then the issue is fired.

In the stopFuture branch, I tried to call the voiceEndedCallback directly from the stop() C function. I still need to look at other cases when a stop occurs, but I think this is the way.

update: ah sorry, I've merged because I was too lazy to copy/paste to try the fix :)

[alnitak]

Ah, got it. Makes sense! I improved somewhat on the test over at https://github.com/filiph/flutter_soloud/tree/fix/stop-takes-too-much-time. Should I create another PR?

ok, no problem