OS X Only: Looping Sounds Break Audio #484
Comments
|
Hi @ggadwa, thanks for taking the time to write this up. Definitely not useless. It will indeed be tricky to break down, but let's try! First, the fact that Windows seems unaffected means that either
If you remember, can you add more details:
If you are willing, could you share some info about the looped file:
Right now I can think of two paths to further look into:
After evaluating your answers I could maybe put forward a custom build with more logging and a simplified loop algorithm and we can check if that helps? |
|
Details! Looping sound is an ogg; decodes to stereo, 44100Hz, 32 bit float (in Audacity.). 1,559,748 samples, 35.368 seconds. Start of loop is at 2.526 seconds, end of loop at 35.368 seconds (play starts at 0 seconds and loops between those two points.) I only saw the crash once; the main thread panicked and exited the application but that might be a coincidence, since the silence or cracking happens almost every time. I'd tend to, at least at this point, consider the crash secondary. It could have also happened from attempts to debug. 90% of the time it's just silence; but when it's silence the cpu activity almost doubles. No other part of the audio graph admits sound. The crackling is maybe 10% of the time, and it doesn't seem related to any sound playing, just a general crackle. Another wrinkle; when I recreate the game normally keeps running but if I exit a level and then the music restarts, there's a pause where I'm no longer getting events in my game; it goes into what I assume is an audio routine and doesn't return for a couple seconds. Then sounds kind of half work, but the looping ones are failing. It also seems to happen more if new sounds come in before the first loop point is reached, but that might also be coincidence. I'd be more than happy to check out a specialized version! |
|
Should add:
|
|
Thanks @ggadwa I have prepared the branch You could try to run you app with this branch checkout (do you need help with that? use a cargo Let me know if that works! And if you hit the bug, please share the logging output |
|
Alright, I had to do a couple different things to get logging to work (it was a learning experience) and I had to do "git" and "branch" in the cargo to get your branch (instead of path) but I figured all that out. Took a while to recreate, but at the end of this log is sound dropping out and then a huge multi second pause before sound started again (after the looping sound was cancelled.). Hope this helps! This is the entire dump; the error happened near the end but here's everything. [2024-04-10T22:55:58Z DEBUG web_audio_api::node::audio_buffer_source] AudioBufferSourceRenderer is dropped: AudioBufferSourceRenderer { start_time: 60.162902494331064, stop_time: 1.7976931348623157e308, offset: 0.0, duration: 1.7976931348623157e308, buffer: Some(AudioBuffer { channels: [ChannelData { len: 8968, .. }], sample_rate: 44100.0 }), detune: AudioParamId(16), playback_rate: AudioParamId(45), loop_state: LoopState { is_looping: false, start: 0.0, end: 0.0 }, render_state: AudioBufferRendererState { buffer_time: 0.2060770975056691, started: true, entered_loop: false, buffer_time_elapsed: 0.2060770975056691, is_aligned: true }, ended_triggered: true } |
|
BTW: Another wrinkle -- my audio device is my Scarlett 2i2 usb which runs my studio speaker when I mix music.). It's hard to recreate but as far as I know I've only recreated it there. Might be a dead end! FYI. IGNORE ABOVE. I was able to recreate through monitor speakers, with the usb interface off, so that is unrelated. This gives me another giant debug dump, too, which I'll keep in case it is helpful. |
|
@ggadwa Thanks for the information. I can't find anything suspicious in the log though, all seems to look normal. |
|
Yes, I enabled the logging as the first line in the main. It's possible I missed copying that out for some reason. I am very frustrated by this bug (as you probably are) it's so hard for me to catch. For instance, it only seems to happen when I am running clean code, usually code that is wrapped in a OS X app. The minute I try anything like println statements (for instance, to catch what api it goes into when the pause happens) I can never recreate it. It's super specific and potentially a race condition. I can say that when the sound stops the fps of the game don't drop at all but the game does start taking up a bit more cpu, but the main game loop is never starved, so I suspect the audio loop is getting caught somewhere. I just can't gather enough information. It's really infuriating! And I apologize for it being so hard to nail down. |
|
Right, yeah these issues are very tricky. But I hope you are also sort of enjoying this adventure? If you have time, could you try again? I have updated the branch to abort and run logging on frame drops. Maybe that will help investigate. Could you also add to your program: It will print load information every second. |
|
OK so this might be something! The level (which has the song I think is related) panics IMMEDIATELY and every time. ran with: RUST_LOG=web_audio_api=debug RUST_BACKTRACE=1 cargo run --release ---- the log ---- [2024-04-16T00:58:57Z INFO web_audio_api::io::cpal] Audio Output Host: cpal CoreAudio |
|
BTW I didn't even get to the load information yet -- I was just putting back in the logging with the new branch and checking that first. It aborts immediately so I wanted to get that to you. I can put that in but I don't know if you'll even see a single data point! |
|
Thanks for the extra info. I need a bit more time to digest this though.
With a buffer size of 1024 and 44k sample rate we're looking at a render quantum that took 3.3 * 1024 / 44000 = 75 milliseconds. That is an eternity... However, I'm not sure if that frame drop is then related to your actual issue. Maybe the audio thread is a bit spurious anyway.. |
|
If you want, I can give you the ogg that causes all this. While some of the stuff I have told you is guess work and could easily be dead ends I'm pretty sure this ogg is what triggers it as I can jump into any other level with other music and never recreate (can't prove that it's not possible, I just haven't seen it) but this piece of music (and it's level) always causes this. That said, it also seems OS X related. |
|
@orottier Feel free to delete after reading as OT but you wanted to see the game I was using this library for; the store page on steam is live, game out in a couple of weeks -- you can hear the audio in the trailer! Search for "Atomite" on steam! Steam's UI is ... complex .. so if I can figure out how to get beta keys I can get you one! |
|
Look (and sounds) pretty cool, congrats on your release :) |
|
@orottier I have some probable info; the big problem with this bug is any change I make -- especially trying to log anything -- stops the problem from happening. So when I try different thing I can never tell if I've just avoiding a some subtle threading bug or have found something. But after a lot of A/B tests, I think I discovered something else required to cause it. Again, I am sorry for the mystery, but as above, this is just something I think is happening. Like a lot of bug reports I give you at times it's something different. But wrapping the app into a bundle and running it directly makes it happen continuously so at least this is a decent test. This is the code, which gets run multiple times a second (as the physics update): Note the music has no panner nodes but there is looping sounds (monster ambients) that do have a panner node. Seems to eliminate the pause (which I think is in this code) and the sound dropping out at all. This is obviously positioning code. So, questions:
Again, I apologize for this confounding bug. |
|
So I'm not the smartest cookie in the basket of dumb cookies (why do I set up value to the save value every time) but it did dawn on me that if I couldn't catch this by logging because of timing, I should only log if I see the timing going wild. So that is what I did, and now I can capture it every time. So, verified:
To demonstrate the race nature of this I ran my new code multiple times and I got a single 2-3 second pause on a RANDOM line. It could be setting position_y. It could be setting up_x. It would only happen on one of them, never any of the others. Note I think this is a symptom of whatever broke the audio, but might get you closer. |
|
@orottier Just pinging you on this if you didn't see the latest. My game is launching in a day or so, this isn't an emergency because now that I know where the problem is coming from I can avoid it relatively easily (I set the up vector once, and only change the others if my position has changed, which at the 60 times a second physics happened A lot.). I haven't recreated it after this move. It's still there, just easy to avoid now. |
I sadly do not have an easy way to recreate this but it has happened enough to draw some conclusions (this is with the latest rc.3):
I understand this bug report is nearly useless, as I suspect there might be some timing involved or it might involve the specific start/stop points (the music successfully loops.). I can say it seems to start with another non-looping sound is played during the sound loop, but that's a wild guess.
The music channel only contains a source node (which is kept to stop the music) and a gain node. There is only ever 1 of these.
The sound channel contains a source node, a panner node, and a gain node. There could be any number of these.
The text was updated successfully, but these errors were encountered: