DreamWorks Over the Hedge: Doesn't make it past the intro FMV's

[TGP482]

Title

https://xemu.app/titles/41560058/#DreamWorks-Over-the-Hedge

Bug Description

The game doesn't make it past the intro FMV's and crashes before the menu

Expected Behavior

The game should make it to menu and be playable

xemu Version

0.8.25

System Information

Windows 10
R7 7800x3D
RTX 5080
Nvidia 572.47 Driver

Additional Context

No response

[abaire]

Can you test with the latest version of xemu and attach the xemu.log file to this issue? Thanks!

[Triticum0]

Here you go. The way I was getting the trace log I can't reproduce the issue only occurs on first boot or I getting unlucky. It is very reproduce-able but after first boot not so much seem this issue always been the case even when I tested back in 2021. Did make it ingame performance has regressed since then so did play any further too the second softlock cutscence. was trace causing slowdowns

output (2).zip

Edit: manged to get a log with the freeze above

[abaire]

Thanks! Unfortunately I don't see anything obvious in the log, it looks like it did one last frame flip and then there was no other output.

[Triticum0]

Wouldn't expect there to be as using pvideo to render fmv so after intro logo don't thing any else on log unless used other trace type

[abaire]

Oh, interesting. Could you enable the nv2a_reg_write traces in the debug monitor so we can see how it's interacting with PVIDEO?

https://github.com/abaire/nxdk_pgraph_tests/wiki/PVIDEO#debugging-with-xemu has some notes on enabling register write tracing for anybody else following along.

Note: If you use the artifact from my work branch you can toggle the register tracing using shift + F9 (it'll turn on the pgraph traces at the same time, which will probably do nothing in this case if it's only rendering PVIDEO)

[Triticum0]

Here you go, let me know if actually uses pvideo of not.

output (4).zip

[abaire]

There's some PVIDEO interaction in there, but it looks like it might just be initialization. There is no more than a single static overlay frame.

The log continues to write to PRMCIO after the PVIDEO frame so I'm assuming the game hasn't hung, but it might be worth running info registers a few times to see if EIP changes.

[abaire]

EIP=00210887. According to the XBE Ghidra plugin it's stuck in a tight loop in D3D_BlockOnTime, which was called from D3DDevice_Swap(0) (@0x21167B) which was called from game code at 0x13F650. This execution can be traced back to XapiThreadStartup. Two threads are kicked off just prior to the livelock, threadproc is 0x001fcbd0 for both. This threadproc is also kicked off twice at the start of the working FMV.

	mov    ecx,DWORD PTR [edx]      
	mov    edi,esi                  
	sub    edi,ecx                  
	cmp    eax,edi                  
	jb     0x210887       

• eax is 0x8
• edx is 0x817df000
• The value in 0x817df000 is 0x05C7 and does not seem to change.
• edi is 0x0A for every call to cmp, so it never breaks out of the loop.

Presumably there is some external behavior that should be updating 0x817df000 but is not.

EDIT: Looks like it's written to by NV097_BACK_END_WRITE_SEMAPHORE_RELEASE. I see that the calls to this end when the guest CPU gets stuck in the loop, presumably because the pushbuffer empties out while the CPU is spinning.

EDIT 2:
On another run w/ tracing enabled"

• *edx = 0xA7B. The last NV097_BACK_END_WRITE_SEMAPHORE_RELEASE before the freeze was also 0xA7B.
• esi is 0xA85
• This results in edi being 0x10, but eax is 0x08 so it can never break out.
• The pfifo thread is waiting on the fifo_cond kick event and (as expected) CPU0 is not blocked

Annoyingly, if I run with GDB attached to xemu, and especially with a breakpoint at 0x001fcbd0 (the threadproc for the FMV video player?), I can get past the second FMV and into the menu, leading me to believe that this is a race condition.
I can see that there is CD read activity around the time that the livelock occurs and in Ghidra can see that there's a loop reading chunks, presumably from the FMV file.

...
ide_atapi_cmd_read_dma_cb_aio IDEState: 0x13d0c0f80; aio read: lba=418508 n=30
ide_atapi_cmd_read_dma_cb_aio IDEState: 0x13d0c0f80; aio read: lba=418538 n=2
ide_atapi_cmd_read_dma_cb_aio IDEState: 0x13d0c0f80; aio read: lba=418540 n=30
ide_atapi_cmd_read_dma_cb_aio IDEState: 0x13d0c0f80; aio read: lba=418570 n=2
  <livelock in one run>

unlike the issues fixed by #2514, I do not see any obvious overlapped SurfaceBindings around the time of this read.

EDIT 3:
Looking at the pfifo put/get registers it looks like there should still be data in the PFIFO but it's not being processed by xemu

# pControlDma->Put @0xfd800040 => 0x017CFD74
# pControlDma->Get @0xfd800044 => 0x017CEAEC

Looking at pfifo_run_pusher, the dma pointers indicate that there is data in the pushbuffer, but pfifo_run_puller returns -1 the first time through the loop. This is because pfifo_puller_should_stall returns true as pfifo_stall_for_flip returns true, leading to an early bailout

d->pgraph.waiting_for_flip is true

Snippit just before the livelock:

PGRAPH: NV_PGRAPH_INCREMENT 1 => 2 (mod)

SET_FLIP_READ 0x0
SET_FLIP_WRITE 0x1
SET_FLIP_MODULO 0x3
FLIP_INCREMENT_WRITE 0x1 => 0x2
FLIP_STALL

flip stall read: 0, write: 2, modulo: 3

NO_OPERATION: Waiting for nop, param is 0x29080041
NV_PGRAPH_INTR: Clear waiting_for_nop

PVIDEO STOP 0x0
PVIDEO enable 0x1

NO_OPERATION: Waiting for nop, param is 0x7
NV_PGRAPH_INTR: Clear waiting_for_nop

FLIP_INCREMENT_WRITE 0x2 => 0x0
FLIP_STALL

flip stall read: 0, write: 0, modulo: 3
flip stall read: 0, write: 0, modulo: 3
flip stall read: 0, write: 0, modulo: 3
flip stall read: 0, write: 0, modulo: 3
flip stall read: 0, write: 0, modulo: 3
flip stall read: 0, write: 0, modulo: 3

So a NV_PGRAPH_INCREMENT call never happens before the second incwrite + stall.

EDIT 4:

I see that D3DDevice_Reset is called just before each video starts and this reinitializes the read/write/modulo values to 0, 1, 3 respectively:

SET_FLIP_READ 0x0
SET_FLIP_WRITE 0x1
SET_FLIP_MODULO 0x3

I'm wondering if the remainder of the reset code is supposed to wait on some steady state or more thoroughly clear things and xemu is leaving them in a partially updated state, allowing the livelock to develop.

Looking at the method in Ghidra 0020b780 I see it calls KickOffAndWaitForIdle and IsFlipPending, which seem like interesting candidates for further inspection.

Setting a breakpoint on D3DDevice_Reset, even one that just echo's and continue's seems to consistently prevent the livelock.

Diffing the working versus livelocked traces, I see that the NV_PGRAPH_INCREMENT register is updated prior to the FLIP_STALL that locks. I suspect the increment register is pinged from an interrupt handler that may be triggered by the NO_OPERATION sent just before the reset (see handler here)

Looking at the title's code,NV_PGRAPH_INCREMENT is triggered from the PCRTC vblank interrupt, but it checks to see if some value (presumably a frame counter as it increments by one each time the code is run) is equal to some other value (presumably the expected frame at which the associated frame buffer has been used). This check is done at 0x00214a64, EDI is (presumably) the frame count and EDX is the target value that it must match to go down the code path that increments the PGRAPH read buffer index.

• EDI comes from GVA 0x21e0b8 + 0x1C0
• EDX comes from one of two buffers at GVAs 0x21e0b8 + 0x178 and 0x21e0c4 + 0x178
• I see that sometimes the handler is called more than once with the same frame count, e.g., 0x3e1, 0x3e2, 0x3e2 with the target 0x3e2. I do not think this causes any issues but indicates that there may be a second code path or some mechanism that bails before the frame counter is incremented.
• I see that when the problem manifests, the frame count skips a value, leading to the ~infinite loop. This happens before the FLIP_STALL is processed but after the reset.

      nv2a_update_irq: CLEAR VBLANK. Flip info 0x17B tgt 0x179 or 0x17B
      // ^^^ must have been handled w/ the active check being the second buf, as the value of the first target is updated
  
      SET_FLIP_READ 0x0
      SET_FLIP_WRITE 0x1
      SET_FLIP_MODULO 0x3
      FLIP_INCREMENT_WRITE 0x1 => 0x2
      FLIP_STALL
      flip stall read: 0, write: 2, modulo: 3
      NO_OPERATION: Waiting for nop, param is 0x29080041  clear_z: 0xFFFFFF00 clear_c: 0x401
      pgraph_write: NV_PGRAPH_FIFO: End of graphics interrupt? 0x1
      nv2a_update_irq: Clearing pmc NV_PMC_INTR_0_PGRAPH
  
      // At this point buf 0 is the target, so the frame counter must match 0x17D 
      nv2a_update_irq: VBLANK
      nv2a_update_irq: CLEAR VBLANK. Flip info 0x17C tgt 0x17D or 0x17B
  
      // Frame counter has skipped the target, now it'll stall forever (until the 32-bit counter rolls around)
      nv2a_update_irq: VBLANK
      nv2a_update_irq: CLEAR VBLANK. Flip info 0x17E tgt 0x17D or 0x17B
      nv2a_update_irq: VBLANK
      nv2a_update_irq: CLEAR VBLANK. Flip info 0x17F tgt 0x17D or 0x17B
  

I'm extremely suspicious of the conditional increment done at 0x00210d60. This appears to be called once or twice early on during the title initialization and then only seems to be called again when an FMV is starting, just before the livelock condition. This is not invoked in cases where the FMV goes on to play successfully.
This increment is gated by a check of the 1st bit of the current frame count versus a value returned by AvSendTVEncoderOption.

The AvSendTVEncoderOption call sends a request for register 0x06 of the TV encoder. Looking at the xemu code for the TV encoders, it seems that nothing ever updates the register other than smbus writes (of which none seem to occur). So the value is always 0, meaning the extra inc will happen if the vblank count has the low bit cleared.

I suspect the encoder on HW actually increments this value, will need to write a test to verify.

• I wasn't able to observe it incrementing in a trivial test, but when I run the game on HW and use XBDM to break at this check, I see that the value is sometimes 1 and sometimes 0

[Triticum0]

Interesting note: Same behavior occurs on Microsoft official Xenon Fusion emulator like DJ Fight for NY so your probably correct about being the same issue. Even though it was official supported.

[abaire]

After investigation I'm suspicious that the issue is related to xemu's emulation of the TV encoder.

The livelock appears to happen when (what I think is) a frame counter skips a frame. This leads to a condition where the title waits ~forever for the current frame count to match the skipped value.

This extra increment appears to be triggered by a check during a chain of calls kicked off by D3DDevice_Reset (which is called at least once before each FMV) against a value returned by the TV encoder SMBus 0x06 register. On hardware, this value is sometimes 0 and sometimes 1 (I guess it's possible that it may be set to other values, but the code only checks bit 0 and I've only seen those two values). If this value matches the low bit of the current frame count, it increments it by one, creating the livelock condition.

I wrote a trivial test to try to see the TV encoder's 0x06 SMBus value change but it was always 0, matching xemu's behavior, so there is some additional complexity that I haven't figured out yet. (Edit, every value read back seems to be 0, so something is almost certainly wrong with my read mechanism)

Edit: Looking at the datasheet for the Conexant encoder, it looks like the low nibble would be the FIELD_CNT

EDIT 2: It looks like doing a D3D Present or nxdk frame flip disables the ability to read from the encoder registers. I see in the Conexant docs that 0x6C needs to have bit 6 set to enable readback, but doing this does not seem to change anything. If I build a test app with the XDK that just does a tight loop reading registers with no Present I do see values for the FIELD_CNT; in a quick test I've seen 0, 1, 2, 3

During the present, the following SMBus TV encoder activity occurs:

smbus_cx25871_receive_byte: addr=0x45 cmd=0xc8  value is 0x80
smbus_cx25871_write_data: addr=0x45 cmd=0xc8 val=0x80
smbus_cx25871_write_data: addr=0x45 cmd=0x34 val=0x80
smbus_cx25871_receive_byte: addr=0x45 cmd=0x96  value is 0x6
smbus_cx25871_write_data: addr=0x45 cmd=0x96 val=0x06

// This might be from the vsync interrupt
smbus_cx25871_receive_byte: addr=0x45 cmd=0x06  value is 0x0

Reproducing this outside the present does not prevent reads, however.

[abaire]

As an aside, in tracing this down, I'm suspicious that this bug may be specific to using the Conexant TV encoder. It looks like Focus/Xcalibur would bypass the SMBus read and always return 0, which makes me suspect that there would be some associated app/DX/HAL code that would do something else for that HW.