Race condition in "stop track" and then "play track" requests causes SD2SNES bugginess. Was: Music On SD2SNES fails to load at seeming random

[Dan Yetman]

The current commit, 5cf5f1e, is in use on my SD2SNES, running on an NTSC Snes Mini. Currently, the .pcm audio seems to have trouble loading at seemingly random intervals. Whenever this happens, usually there is silence, but at least once, a loud 'buzzing' was the result. The issue resolves itself whenever a new audio track is loaded, but it is problematic.

If I had a guess, the current code that selects and plays the desired audio track doesn't seem 'fast' enough to always successfully play. If nothing else, may I suggest a fallback where after each load, the MSU-1 can check to see if audio is playing properly, and if not, it will play the .spc audio instead?

[Dylan Morrison]

Hmm. That sounds rather like an earlier problem we solved a while back. If the track isn't loaded it should be defaulting to the SPC always, the only way something like that could happen is if the track is showing as loaded but somehow not being played. I'll investigate my track loading code to be sure but this sounds like a hardware issue almost.

To be clear, if the flags are indicating to me that the track is loading and the MSU is playing the audio, then there's nothing I can do to know that they aren't. I currently do a proper check for loading but I don't currently check for the "playing" bit after I set the song to play. I don't know how I would handle that if it wasn't being set other than to display an error though.

[Dylan Morrison]

Okay, so here's the first step towards a solution. Either tomorrow or the next day, whenever I get around to it, I'm going to upload a new .ips file just for you for testing this issue, this ips file, which you'll have to apply to the unmodified ROM and replace the current .sfc file, will check for MSUStatus_AudioPlaying after setting the track to play. It will infinitely loop until it gets that status. This is after the track loading routine itself, which I can't find any issues with yet. If the track loads and it never gets MSUStatus_AudioPlaying after I ask it to play, then the game should lock up completely because it'll be stuck on that routine forever. So at the very least it'll be a useful diagnostic tool.

If things work exactly the way they worked before then I would go looking for issues in the firmware of the SD2SNES, because that would mean that the MSU is telling me it's playing when it's not.

[Dylan Morrison]

Alright, couldn't sleep so I had an industrious morning.

RetroDan, please grab the ips from the patch dir on commit 88c7d5a and apply that to your unmodified FF3 US v1.0 ROM using your IPS patcher of choice, then try that. This is not a fix per se, more a diagnostic tool since I don't exactly have a way to debug for the SD2SNES myself. What we want to see is if it freezes, and if so, where. I'll likely be putting out more "diagnostic patches" as we go along testing this. Probably get some use out of the error reporting code I put in and haven't used yet. (It changes Terra's name to signify major errors)

I would ask nobody else to grab the ips from that commit yet (in fact, please ignore the experimental branch in general. It will disappear and reappear as necessary when things like this happen :P). It's likely of no use to you. Unless you are an SD2SNES user and have the exact same issue and want to aid in tracking this bug down.

[Dan Yetman]

Yeah, I remember that being an issue for a while. Maybe that fix got rolled back by accident, but I hope that it can be tracked down again.

[Dan Yetman]

Okay, here's what I can report with the diagnostic patch.

It appears that the game will soft lock when a track fails to load successfully. However, I'm a little concerned that there does not seem to be a 100% reliable method of determining the pattern, if it in fact exists. My methodology for testing was simple: Start a brand new game, see where it stops.

Each number denotes a new game and where it soft locked.

1) Softlock on Overlooking Narshe to Credits Roll transition. Screen fades out, does not fade in, no music or sfx. 2) Softlock on 1st battle in Narshe transition. Screen fades out, does not fade in, no music, wind sfx continues to play. 3) Identical to #1. 4) Identical to #1. 5) Identical to #1 6) Identical to #1 7) Softlock on screen transition between Narshe and Narshe Mines. Screen fades out, does not fade in, no music, wind sfx continues to play. 8) Identical to #2 9) Identical to #1 10) Identical to #1

[Dylan Morrison]

The softlocking actually confirms the fix from last time is working, because it can't get to that part of the code (the bit where it hits the infinite loop) without the MSU basically signalling a correct track load (MSUStatus_AudioBusy stops and MSUStatus_BadTrack is not signalled). This is a new and very strange kettle of fish. I might try to poke ikari again, hopefully he's not tired of hearing from me :P.

Thanks for all the diagnostic data, I'm going to have a think on it and I'll get back to you.

I see a number of potential fixes, most of them temporary and not addressing the issue, primarily because I'm not certain what the issue is (I asked the MSU to play the track and it's apparently refusing? :P). This would be a lot easier if I could somehow attach a debugger to an SD2SNES but I don't own one nor do I know if that's even possible.

Fix number one:

If it gets to the condition that causes the diagnostic patch to softlock (I've asked the MSU-1 to play and it's not reporting it's playing), we wait for a certain number of iterations of the loop and if it's still not playing after that, we switch to the SPC music. This will have the side effect that you'll only sometimes hear MSU-1 music, sometimes SPC music, and it's probably going to be random, and potentially trigger some false positives (as sometimes it might eventually get to "playing"). This is hardly an optimal solution.

Fix number two:

If it gets to that condition, signal the MSU to play the track again. This is probably not the best idea, as if the problem is some sort of load time issue (though, as I said, since it's not showing MSUStatus_AudioBusy, it shouldn't be loading anything...), then, assuming the MSU doesn't simply take ignore redundant "play" requests, it would cause the track to start trying to be played over and over until it succeeds. Even if this fix works, it could cause stuttering.

Fix number three:

The only thing I really changed in this section of code between the last version you tested thoroughly and now is I added a bit to cleanly signal the MSU-1 to stop playing before I signalled it to change tracks and start playing again. Before, I relied on the fact the MSU-1 automatically stops playing when you signal it to switch a track. I added the clean stop signalling because this was given as a recommendation from Byuu himself re: implementing the resume functionality. Thus, my fix would be to remove the "stop" part and hope it doesn't break resume. This is a bad fix simply because it means we still have no reason why it's happening, and my code would now be off-standard.

Simply because of how easy it is to implement, I might give you "fix 3" as another diagnostic tool.

[Maximilian Rehkopf]

Hi, Dylan pointed me to this issue. I'll ask some basics first before debugging ;) What firmware version does the issue occur on? If any v0.1.7 flavor: a) does it work better with v0.1.6, and b) does it make a difference when in-game hooks are disabled?

[Maximilian Rehkopf]

It is some sort of race condition, turning on MSU1 debug logging makes it worse :) I am getting lots of these:

Intro scene:

Audio requested! Track=0
filename: /msu1/DancingMad/ff3-0.pcm
Audio requested! Track=0
filename: /msu1/DancingMad/ff3-0.pcm
Audio requested! Track=3
filename: /msu1/DancingMad/ff3-3.pcm
loop point: 0 samples
Repeat clear!
PAUSE!
Audio requested! Track=3
filename: /msu1/DancingMad/ff3-3.pcm
loop point: 0 samples
Repeat clear!
PAUSE!

Overlooking Narshe (unused wind tune #57?) + Credit Roll:

Audio requested! Track=57
filename: /msu1/DancingMad/ff3-57.pcm
Audio requested! Track=0
filename: /msu1/DancingMad/ff3-0.pcm
Audio requested! Track=4
filename: /msu1/DancingMad/ff3-4.pcm
loop point: 0 samples
Repeat clear!
PAUSE!

Battle+Victory:

filename: /msu1/DancingMad/ff3-36.pcm
loop point: 888683 samples
Repeat clear!
PAUSE!
Audio requested! Track=47
filename: /msu1/DancingMad/ff3-47.pcm
loop point: 342368 samples
Repeat clear!
PAUSE!
Repeat set!
PLAY!
loop

The only audible music was the victory tune (#47) right at the end. What seems to happen here is that after requesting an audio track, you first zero out the playback control register, THEN write the corresponding flags. The sd2snes MSU1 loop picks up the first write (repeat clear, PAUSE) but misses the second one occasionally.

Also there's a lot of intermittent track 0 requests (that aren't harmful per se but seem redundant).

[Maximilian Rehkopf]

The workaround from the application's perspective would be not to quickly write the control register repeatedly. I'll change something to make the firmware ACK the control request flag as soon as possible so the 2nd write doesn't get masked (easily).

[Dylan Morrison]

Ahh, you see, as I mentioned a bit above I was zeroing out the playback control register then writing the flags because per what I read about resume support it seemed that byuu was saying (or implying) that you should always be doing that. It seemed odd (even unnecessary) considering the MSU worked fine the way I was doing it before, but I try to follow standards when it comes to things I know little about.

The track 0 requests are hard to avoid without specifically masking out track 0 from the code, which I just kind of was relying on the "bad track" detection to essentially do for me. (Again, because this seems to be a recommendation). FF6 makes a lot of spurious music requests.

[Dylan Morrison]

Thank you again for your help. This should be a really easy fix with that in mind, I merely have to take out the bit that zeroes the registers.

[Dylan Morrison]

Alright, Retro Dan, please try the ips from commit b735e40 (again, patched on an unmodified ROM). This still has the diagnostic code in, so if the MSU-1 doesn't reach "playing" state it should softlock.

If everything else seems to be working, please take special care to make sure resume support is still working as well (it should be in firmware 0.1.7). If so, I have one more patch (on the track 0 issue, which I've spun out into another bug) for you to test, and then we can remove the diagnostic code and pull this all back into the Master branch.

[Maximilian Rehkopf]

Byuu might have a point, I'd need to check with the resume spec again. It's not very straightforward for the sake of compatibility. ^^; Anyway, I rearranged the MSU1 loop and it seems to work now even with the present state (before b735e40).

[Dan Yetman]

Mostly okay. In fact, almost perfect. I'm fifteen minutes into my first play through, and the only issue I've seen was where the SFX cut out with the 'buzz' issue on the transition from Narshe town to the Mine Entrance. Zero soft locks so far, but will start a new game a few times just to be sure.

But this looks promising!

[Dan Yetman]

Okay, just did five playthroughs. The issue is largely resolved - zero soft locks.

Two things I noticed, though. First, the transition between Narshe Town and the Mine Entrance will ALWAYS cause the wind SFX to play for a brief instant and then buzz until a new audio track is loaded (like from a battle).

Secondly, if the opening intro is allowed to play all the way through and then a 'new game' is started (which will put the player just entering Narshe, as the cutscene has already played), then the wind SFX will not load properly and buzz (though much quieter).

Both of these are 100% reproducible. I played up to the second save point, so there may be other issues, but these are the ones I notice right away.

[Dylan Morrison]

Those seems to be unrelated issues so I'm going to mark this resolved and start a new bug for "Transition between SPC and MSU audio glitchy/causes buzzing"

[Dylan Morrison]

Seemingly resolved by b735e40, thanks everyone for your help. Started new bugs #14 (for Track 0 spamming) and #15 (for glitchy SPC->MSU transitions)

[Maximilian Rehkopf]

Yeah, the buzz is another bug I encountered yesterday. When requesting a non-existing track while another is being played back, output to the DAC isn't stopped; after a bit the FPGA audio output buffer gets filled with new data for some reason (probably opening+preparing track 0), but is never updated subsequently - thus creating a static buzz noise. This is now fixed as well.

[Maximilian Rehkopf]

Thanks for the nice edge cases. :D

[Dan Yetman]

Well, OCD has its upsides....

[Dylan Morrison]

Removed now-unnecessary diagnostic code from resolved issue #13.

→ <<cset 965ce09a6f22>>