Bishoujo Senshi Sailor Moon: game freezes after character select

[Thelypody]

Bishoujo Senshi Sailor Moon (Japan). A .chd image created from Redump .bin/.cue image, playing of an micro SD card.

I'm often running into an issue with this game where it tends to freeze after selecting a character and continues doing nothing instead of starting a game. It is not 100% consistent, as I had some luck with it after a while, but I could repeatedly replicate it after reloading. The bug can be easily replicated by booting the game and mashing Start button to skip everything until the following screen appears. Here you can choose whose story you wish to follow. After selecting one of the girls, it will shout chosen character's name and the game is supposed to start. Instead nothing happens after the shout and a short music loop continues to play. The issue can be effectively nullified by setting CD Seek option to Fast. The game will successfully load with that option.

[dshadoff]

I was unable to replicate this issue on my setup with about 12 attempts. I am not using the same rip however - I used TurboRip to get a cue/iso/wav rip from an original disc that I own.

However, this issue does sound a little bit like an issue I saw on another game - Tanjou Debut (for which there is separate issue). I seem to recall that issue was improved to some degree by a fix that went in some time ago, but may still be sensitive to minor delays in CD data return.

But perhaps you could supply a bit more information: a) which version (date) of the TurboGrafx16 core you are using to get this result ? b) Does this issue happen more often with one (or some) of the characters than it does with other(s) ? If so, which character(s) ?

[Thelypody]

I'm using the latest version of the core (20230102) alongside the latest Main (20221224).

For the sake of experiment I decided to launch the .chd image 150 times, 30 times per each character, using Run+Select to reset the game after choosing a character. What I discovered is that Sailor Mars, Jupiter, Mercury and Venus have successfully launched every single time without an issue, while Sailor Moon tanks the entire group by launching only 7 times out of 30. Trying to launch Sailor Moon's story from a .bin/.cue image did not provide any substantial differences as it also freezes more often than it loads.

[dshadoff]

OK, I was able to confirm the issue on my system (and my rip).

Attached are some debug logs I captured:

This log is where the game freezes:

From sector 125965 to sector 125965:
Time = 33.00 milliseconds
seek time ticks: 2
PCECD: Command READ6, lba = 125965, cnt = 15
From sector 125980 to sector 125980:
Time = 33.00 milliseconds
seek time ticks: 2
PCECD: Command READ6, lba = 125980, cnt = 15
From sector 125995 to sector 125995:
Time = 33.00 milliseconds
seek time ticks: 2
PCECD: Command READ6, lba = 125995, cnt = 15
From sector 126010 to sector 8566:
Time = 1380.24 milliseconds
seek time ticks: 87
PCECD: Command SAPSP, start = 8566, end = 233315, [1] = 00, [2] = 01, [9] = 40
PCECD: Command SAPEP, end = 8872, [1] = 02, [2] = 02, [9] = 40
PCECD: playback reached the end 8873
PCECD: Command undefined, [0] = FF, [1] = FF, [2] = FF, [3] = FF, [4] = FF, [5] = FF

This log is the same section, on a game play which didn't freeze:

PCECD: Command READ6, lba = 125965, cnt = 15
From sector 125980 to sector 125980:
Time = 33.00 milliseconds
seek time ticks: 2
PCECD: Command READ6, lba = 125980, cnt = 15
From sector 125995 to sector 125995:
Time = 33.00 milliseconds
seek time ticks: 2
PCECD: Command READ6, lba = 125995, cnt = 15
From sector 126010 to sector 8566:
Time = 1380.24 milliseconds
seek time ticks: 87
PCECD: Command SAPSP, start = 8566, end = 233315, [1] = 00, [2] = 01, [9] = 40
PCECD: Command SAPEP, end = 8872, [1] = 02, [2] = 02, [9] = 40
PCECD: playback reached the end 8873
PCECD: Command undefined, [0] = FF, [1] = FF, [2] = FF, [3] = FF, [4] = FF, [5] = FF
From sector 8873 to sector 128555:
Time = 1431.23 milliseconds
seek time ticks: 107
PCECD: Command READ6, lba = 128555, cnt = 3
From sector 128558 to sector 128955:
Time = 443.17 milliseconds
seek time ticks: 33
PCECD: Command READ6, lba = 128955, cnt = 7
From sector 128962 to sector 127355:
Time = 526.17 milliseconds
seek time ticks: 39
PCECD: Command READ6, lba = 127355, cnt = 6
From sector 127361 to sector 125666:
Time = 526.17 milliseconds
seek time ticks: 39
PCECD: Command READ6, lba = 125666, cnt = 15
From sector 125681 to sector 126891:
Time = 443.17 milliseconds
seek time ticks: 33
PCECD: Command READ6, lba = 126891, cnt = 3
From sector 126894 to sector 129553:
Time = 527.21 milliseconds
seek time ticks: 39
PCECD: Command READ6, lba = 129553, cnt = 7

And this is a capture of the same section, with CD Seek set to FAST (no freeze):

PCECD: Command READ6, lba = 125980, cnt = 15
seek time ticks: 0
PCECD: Command READ6, lba = 125995, cnt = 15
seek time ticks: 0
PCECD: Command SAPSP, start = 8566, end = 233315, [1] = 00, [2] = 01, [9] = 40
PCECD: Command SAPEP, end = 8872, [1] = 02, [2] = 02, [9] = 40
PCECD: playback reached the end 8873
seek time ticks: 0
PCECD: Command READ6, lba = 128555, cnt = 3
seek time ticks: 0
PCECD: Command READ6, lba = 128955, cnt = 7
seek time ticks: 0
PCECD: Command READ6, lba = 127355, cnt = 6
seek time ticks: 0
PCECD: Command READ6, lba = 125666, cnt = 15
seek time ticks: 0
PCECD: Command READ6, lba = 126891, cnt = 3
seek time ticks: 0
PCECD: Command READ6, lba = 129553, cnt = 7

[dshadoff]

Running the same sequence in Mednafen, I get a similar trace, but with a few extra details of the what the game intends to do (Mednafen did not freeze on this trace).

The same audio playback is set up in lines 99-101. Then we see that the drive status is queried (CD_STAT). (Logging of this is usually suppressed in MiSTer because many games call it hundreds of times per second.) Then a CD IRQ is raised (presumably indicating the completion of audio playback), followed by a subchannel read.

Possibilities: 1) MiSTer probably handled the CD_STAT calls fine, unless the program (running on the TG16 core) had too fast of a timeout. Not likely, but possible. 2) There is a possibility that the IRQ is not always raised. Not sure what the mechanism of this type of failure would be. 3) The read subchannel Q may also play a role in this. It is possible that the malformed SCSI request ("Command undefined, [0] = FF, [1] = FF, [2] = FF, [3] = FF, [4] = FF, [5] = FF") is actually intended to be a subchannel Q request, but is perhaps improperly-formed because some prior step was unsuccessful.

[dshadoff]

Adding a bit more logging in Main_MiSTer, we have:

Lockup:

PCECD: Command READ6, lba = 125995, cnt = 15
From sector 126010 to sector 8566:
Time = 1380.24 milliseconds
seek time ticks: 87
PCECD: Command SAPSP, start = 8566, end = 233315, [1] = 00, [2] = 01, [9] = 40
PCECD: Command SAPEP, end = 8872, [1] = 02, [2] = 02, [9] = 40
PCECD: playback reached the end 8873
PCECD: Command undefined, [0] = FF, [1] = FF, [2] = FF, [3] = FF, [4] = FF, [5] = FF
PCECD: Command READSUBQ, [1] = 0A, track = 4, index = 3, lba_rel = 1, lba_abs = 8873

Successful run:

PCECD: Command READ6, lba = 125995, cnt = 15
From sector 126010 to sector 8566:
Time = 1380.24 milliseconds
seek time ticks: 87
PCECD: Command SAPSP, start = 8566, end = 233315, [1] = 00, [2] = 01, [9] = 40
PCECD: Command SAPEP, end = 8872, [1] = 02, [2] = 02, [9] = 40
PCECD: playback reached the end 8873
PCECD: Command undefined, [0] = FF, [1] = FF, [2] = FF, [3] = FF, [4] = FF, [5] = FF
PCECD: Command READSUBQ, [1] = 0A, track = 4, index = 3, lba_rel = 1, lba_abs = 8873
PCECD: Command READSUBQ, [1] = 0A, track = 4, index = 3, lba_rel = 1, lba_abs = 8873
From sector 8873 to sector 128555:
Time = 1431.23 milliseconds
seek time ticks: 107
PCECD: Command READ6, lba = 128555, cnt = 3
From sector 128558 to sector 128955:
Time = 443.17 milliseconds

[Left-Empty]

I was catching up on the issues (such cool reads btw David, love that you keep notes here!) and as a total newbie, I was wondering, could this issue be related to #154 , your Princess Maker 2 freeze? They seem somewhat similar, excepting for the command called after the freeze (READSUBQ instead of READ6 here), and it seemed srg320 proposed a workaround, but not a fix of the underlying issue if I understood what went on right? Or you most likely probably are aware of this if it is indeed the case. Sorry if this isn't the appropriate place to throw a random suggestion.

[dshadoff]

I was catching up on the issues (such cool reads btw David, love that you keep notes here!) and as a total newbie, I was wondering, could this issue be related to https://github.com/MiSTer-devel/TurboGrafx16_MiSTer/issues/154 , your Princess Maker 2 freeze?

It's plausible - they both appear to be waiting for an interrupt which doesn't occur - but there could be very different mechanisms of why.

I am writing these notes for two reasons - first, so that somebody else can get the context of what investigation has already been done, in case they are able to help. But also, because I won't have much time to work on it for the next few months, so if the issues aren't solved by then, they would be notes to my future self.

it seemed srg320 proposed a workaround, but not a fix of the underlying issue if I understood what went on right? Or you most likely probably are aware of this if it is indeed the case.

Sorry, I just checked the notes and didn't see a comment from srg320. However, I suggested a possible workaround - to reduce the frequency of the check status command by answering it from within the core itself. But that's not easy to do, and not a guaranteed fix. And it wouldn't address Sailor Moon, as it doesn't seem to be checking status like that.

[dshadoff]

Interestingly, moving the printf() within pcecd.cpp's PCECD_COMM_READSUBQ section, to BEFORE the "if (SendData)" statement seems to have helped.

Perhaps there is a need for a ~1ms delay between the request and response for READSUBQ....

I am dropping a test build of MiSTer here, for validation.

MainMiSTer_TEST_PCESailorMoon.zip

[Thelypody]

The attached MiSTer build seems to work, Sailor Moon's path did not freeze once after several retries.

[dshadoff]

Nice ! I'll simplify and post a PR.

This fix might also work for Tanjou Debut (although the binary above will definitely cause stuttering in the audio, so don't bother trying until I can simplify).

[dshadoff]

Hmm... not so fast....

That printf statement's existence causes choppy audio for some other games. It seems that sending a few thousand requests per second, times ~40 microseconds per print statement causes some slowdown for MiSTer Main (on some other games), so the printf statement will need to be suppressed...

On the other hand, responding too quickly seems to be a problem for a very small number of games, under certain circumstances. It may be best to add a small delay (several microseconds) within the core, to prevent visibility of the data too early, but allow MiSTer Main to still run freely. This delay should actually be some sort of "data ready" signal, but maybe a delay is the best temporary solution until we understand more specifics. In any case, it is easier to control microsecond-level delays in the core.

[dshadoff]

I made an update to the SCSI module, for it to wait for several microseconds in STAT_PEND state, when the status information is passed back from HPS.

40 microseconds was not sufficient to prevent the freeze when selecting Sailor Moon, but the next increment I tried (~105 microseconds) seems to work fine.

This value is empirical in order to fix an issue - it has not been tested on a real system (not sure how to test it). In any case, this means that it may need some further fine-tuning or even a different approach eventually.

I tested with some timing-sensitive games (Sherlock Holmes, Yuna HuVideo, Steam Hearts), and all were OK.

However, this status delay does not prevent the message: PCECD: Command undefined, [0] = FF, [1] = FF, [2] = FF, [3] = FF, [4] = FF, [5] = FF

I will submit a PR with this update.