Ski Champ hanging on FBI screen - a possible fix

[gm_matthew]

When running Ski Champ with the region set to USA, the game hangs on the "winners don't use drugs" splash screen. This has been a known bug since 2014:

When I change the region to USA in Ski Champ on Supermodel, it freezes at the "WINNERS DON'T USE DRUGS" screen. Wtf?

Meanwhile, I have it set to 'EXPORT'.

The game gets stuck in this loop:

Code: Select all

>>*Jmp000A63B0  addi    r4,r13,-$7F9C       ; set r4 to $1E0064
   $000A63B4    lwarx   r5,0,r4
   $000A63B8    and     r6,r5,$000000FF
   $000A63BC    rlwinm  r7,r5,16,$000000FF
   $000A63C0    addi    r6,r6,$01
   $000A63C4    cmpi    cr0,0,r6,$20
   $000A63C8    bt      cr0[gt],Jmp000A63B0

Basically if the low byte of the word stored in $1E0064 is 0x20 or higher, the code spins in a loop. I think what is happening is that this function builds a queue of soundboard commands, and if the queue gets full it is supposed to wait until the IRQ 0x40 (SCSP) handler removes a command from the queue and decrements the low byte of $1E0064, breaking the loop. But there's a problem: this loop runs during the IRQ2 handler, when external interrupts are disabled! This means the IRQ 0x40 interrupt cannot fire and the game hangs.

A later part of this function sets the midiCtrlPort value to 0x27 if the low byte of $1E0064 equals 1, triggering an IRQ 0x40 sequence. However, I found out that just before the game hangs the midiCtrlPort value is already 0x27 before IRQ2 fires - interesting. On real hardware I believe the soundboard would fire an IRQ 0x40 immediately, but Supermodel currently waits until after IRQ2. I decided to try making it so that Supermodel also fires any pending IRQ 0x40s at the start of the frame after ping-pong flip and before IRQ2, and the game no longer hangs!

I'll upload a pull request to GitHub when I have a more elegant fix

[Ian]

That's a really nice fix Mathew. I think the exact order of the irq has long been a mystery. Bart did some tests on the original hardware a while ago to figure out when various irqs were being fired. We used those findings to fix the video related timing issues:)

Maybe can find the screen grabs of these findings

[Ian]

Bart's findings. Maybe this helps.
Screenshots here

https://imgur.com/a/NPzDyYi

The upper set of numbers in 3 columns are all values that VF3 computes, which I read and print each frame.

The bottom two columns of numbers are values that I compute myself by hooking the IRQ handler.

First group (values I read from VF3’s memory):

- The top left number, 2e0cc is the DEC reload value (the time from IRQ02 until the ping pong bit flips).

- On the upper right, 45602, we have the time from when the last IRQ08 fired to when the DEC exception fired (which in turn should correspond to when the ping pong bit flips).

- The number below that, 45024, is the time from the last IRQ04 to the last IRQ02.

- The middle column, 9e and 9f, are the number of times IRQ04 and IRQ08 have fired, respectively. They occur each frame. Interestingly the count is off by 1, which probably reflects that my routine runs somewhere between them (I don’t have a good idea of where in the frame my routine runs, except that it happens after flush and after VF3 writes polygon RAM and to the tilegen).


Second group:

- The left column of 8 values are timestamps for the last time IRQ01,02,...,80 fired. Some of these obviously change every frame, some don’t fire at all. IRQs 01,02,04,08 (note I number these by bit position, not an ordinal numbering) are all frame related. From top to bottom, the 8 values are:

IRQ01
IRQ02
IRQ04
IRQ10
IRQ20
IRQ40
IRQ80

- The right column is the IRQ timestamp (left column) minus the IRQ02 timestamp.

Weirdly, these delta values are not consistent and at times they stop updating. I think some of the IRQs may not fire each frame. It’s a little bit hard to interpret what is going on.

I have videos that will make this more clear. You can see how the numbers change.

Generally, some of the deltas are very consistent

Timing values are in bus cycles

They are in, I think, bus cycles. IIRC, they increment at core clock frequency (66MHz) divided by 4.

So: hex*(1/(66e6/4)) / 1e-3 = milliseconds

[gm_matthew]

I’ve discovered that the frame before the game hangs, Supermodel tries to start the IRQ40 sequence while IRQ2 is still active, and before midiCtrlPort is set to 0x27. The game is expecting the IRQ40 sequence to happen before the next IRQ2, but it never does because Supermodel has already concluded that there are no outstanding IRQ40s to assert; this is what is causing the game to hang.

Right now Supermodel waits for 2.5% of the frame time (gapCycles) after IRQ2 before checking midiCtrlPort, assuming that this is plenty enough cycles for the IRQ2 routine to finish - but in this case it is not. My solution is to keep checking to see if the IRQ2 has been acknowledged before trying to start the IRQ40 sequence; Ski Champ no longer hangs with this change applied. I've just created a pull request on GitHub.

[Bart]

I’ve discovered that the frame before the game hangs, Supermodel tries to start the IRQ40 sequence while IRQ2 is still active, and before midiCtrlPort is set to 0x27. The game is expecting the IRQ40 sequence to happen before the next IRQ2, but it never does because Supermodel has already concluded that there are no outstanding IRQ40s to assert; this is what is causing the game to hang.

Right now Supermodel waits for 2.5% of the frame time (gapCycles) after IRQ2 before checking midiCtrlPort, assuming that this is plenty enough cycles for the IRQ2 routine to finish - but in this case it is not. My solution is to keep checking to see if the IRQ2 has been acknowledged before trying to start the IRQ40 sequence; Ski Champ no longer hangs with this change applied. I've just created a pull request on GitHub.

The sound board IRQs have always been a mystery. The current code checks midiCtrlPort & 0x20 to begin firing them. I don't understand what you mean when you say Supermodel starts firing them before the port is set to 0x27? Supermodel only seems to fire them when that port has bit 0x20 set.

If I understand correctly, you are saying that the IRQ02 handler in this game takes an unusually long time and while the IRQ02 line has not been deasserted and its handler is still running, Supermodel pushes through a bunch of IRQ40s and when the IRQ02 handler finally finishes and presumably sets some flag, the game then waits for those IRQs (and already missed them)?

[gm_matthew]

The sound board IRQs have always been a mystery. The current code checks midiCtrlPort & 0x20 to begin firing them. I don't understand what you mean when you say Supermodel starts firing them before the port is set to 0x27? Supermodel only seems to fire them when that port has bit 0x20 set.

If I understand correctly, you are saying that the IRQ02 handler in this game takes an unusually long time and while the IRQ02 line has not been deasserted and its handler is still running, Supermodel pushes through a bunch of IRQ40s and when the IRQ02 handler finally finishes and presumably sets some flag, the game then waits for those IRQs (and already missed them)?

I'm not saying Supermodel starts firing IRQ40 before the port is set to 0x27, rather that it checks the control port to determine whether or not to start firing IRQ40 before 0x27 is written.

During the frame just before the game hangs, it takes nearly 194,000 cycles for the IRQ2 handler to clear; that's a good 11% of the frame time even with the PowerPC frequency set to 100MHz. What is happening is that at 2.5% of the frame time after IRQ2 Supermodel checks the control port (while the IRQ2 handler is still running), sees 0x6, and concludes that IRQ40 doesn't need to be fired. Later on in the same frame, the IRQ2 handler writes 0x27 to the control port. The game is expecting IRQ40 to be fired before the next IRQ2, but it never does because Supermodel has already checked the control port and decided not to fire IRQ40. I don't know how other games would react to this, but it is fatal to Ski Champ due to the issue I mentioned in the original post.

My patch fixes the problem by ensuring that the control port is always checked after IRQ2 has been fully cleared. If we want a more hardware-accurate solution we would need to reimplement the RunMainBoardFrame() function.