Regression: ppsspp >= 1.14 hard-freezes reliably at a particular scene in Final Fantasy IV; reliably works fine in <= 1.13 - system FFMPEG only

[shalottnet]

Game or games this happens in

ULUS-10560 - Final Fantasy 4

What area of the game / PPSSPP

Immediately after a particular 3d cinematic scene in FF IV, the emulator completely freezes -- the screen does not update anymore and the emulator does not respond to any input. The scene is when Leviathan swallows the ship while the party is on the way from Fabul to Baron:

https://github.com/hrydgard/ppsspp/assets/74591183/5cc138b2-1c0e-432c-b0b5-a1eb07da6aa4

The game plays just fine up until this point, and then reliably hangs at this exact point. Seeing as there is no user input during this part of the game, and this route/scene is not skippable, it is impossible to progress the game beyond this point.

While the game is hung, the process is still running. Tracing with ktrace shows writes to the sound device (even when sound is muted prior to this point) and UPnP calls (even though UPnP is disabled). Attempts to interact with the emulator in any way produce no response; even attempts to gracefully kill the process do not succeed -- kill -9 is the only way to end it.

This behaviour is seen under both ppsspp 1.14 and 1.15. Earlier versions do not exhibit the problem and it is possible to play the game through in its entirety.

What should happen

The emulator should not hang.

Logs

Output of ktrace while the emulator process is hung:

Continuous writes to the /dev/dsp sound device from SDLAudioP2 (even when audio is disabled in the ppsspp config):

 22433 SDLAudioP2 GIO   fd 14 wrote 1024 bytes
       0x0000 c1ff 5600 c1ff 5600 c1ff 5600 c1ff 5600  |..V...V...V...V.|
       0x0010 c1ff 5600 c1ff 5600 c1ff 5600 c1ff 5600  |..V...V...V...V.|
       [...]
 22433 SDLAudioP2 RET   write 1024/0x400
 22433 SDLAudioP2 CALL  write(0xe,0x859218000,0x400)

And continuous sleep calls from UPnPService (even when UPnP is disabled in the ppsspp config):

 22433 UPnPService RET   nanosleep 0
 22433 UPnPService CALL  nanosleep(0x8ac458ef0,0)

Platform

Linux / BSD

Mobile phone model or graphics card

Intel(R) HD Graphics 2500

PPSSPP version affected

1.15.4

Last working version

1.13.2

Graphics backend (3D API)

OpenGL / GLES

Checklist

• [X] Test in the latest git build in case it's already fixed.
• [X] Search for other reports of the same issue.
• [X] Try resetting settings or older versions and include if the issue is related.
• [X] Try without any cheats and without loading any save states.
• [X] Include logs or screenshots of issue.

[shalottnet]

Confirmed that the problem is still present in master as of the latest commit, 05ddd77 2023-05-23.

[hrydgard]

Any change you could try a bunch of builds between 13.x and 14.x, to narrow a range down?

[anr2me]

Regarding UPnP, it was planned to be for PPSSPP general use (ie. if later someone want to open ports for remote disc / debugger) and not just for games, so the thread is always running waiting for commands to be queued. When UPnP is disabled it won't push any command to the queue (i think, i kinda forgot how it works exactly).

The UPnPService thread (when started) also used to retrieve & clean up left over opened ports from previous session (in case PPSSPP was crashing and unable to close opened ports during shutdown), so if someone got crashing issue while playing with UPnP they should run PPSSPP again and close it down properly to close down all ports that were opened by PPSSPP on previous crashing session.

[hrydgard]

@shalottnet Sorry for picking this up again so late, but do you still have a savegame at this location in the game? Would greatly help with reproducing and bisecting. And again, if you could try a bunch of old builds, that would really help.

[anr2me]

I also wondered whether this issue is similar to https://github.com/hrydgard/ppsspp/issues/16403 (Intel driver related?)

PS: The Leviathan encounter scene seems to be from Part 8 of the game https://www.youtube.com/watch?v=xQ6Wc8yN7z0

[shalottnet]

Sorry, I also haven't looked at this in a while. I don't believe that I still have a save from that point, as I just reverted to the last working version of ppsspp and continued playing; but I can probably re-create it and re-confirm if the issue is there in the latest ppsspp binary that my OS offers.

As far as bisecting, I can try to spend some time on this over the next couple weeks. Can you recommend any likely tags/commits to start with that could plausibly be related?

PS: The Leviathan encounter scene seems to be from Part 8 of the game https://www.youtube.com/watch?v=xQ6Wc8yN7z0

Yes, it's there. The video that I posted in the description starts at about 16:20 in the above youtube video. The game freezes at 16:37, where it's supposed to switch from the 3d cutscene back to the regular 2d overhead view.

Thanks.

[hrydgard]

I'd just do a full bisect between 1.13 and 1.14, which seems like the confirmed range. It should be 10-11 steps..

[shalottnet]

Looks like I actually did keep a snapshot from the point where this problem manifests. Re-confirmed the original problem description is still accurate.

I started working on bisecting; but unfortunately, building older version on FreeBSD is currently hampered by now having upgraded to ffmpeg-6 on the base system (See https://github.com/hrydgard/ppsspp/issues/15308).

Looks like it's just a couple-line patch that could be manually applied to each version; or I could install a snapshot of the OS with older ffmpeg into a jail and do the builds in there. But bleah.

Anyway, thanks for the continued engagement on this issue; I'll try to figure out some way to make progress on this... Thanks.

[anr2me]

It would be nice if you can provide a save state right before the issue occurred, so other people can try to reproduce it too.

[shalottnet]

Snapshot of the ppsspp directory with the save state: https://shalott.net/ppsspp.tgz

Untar into ${HOME}/.config/ and start up ppsspp with the FFIV ISO.

The main Final Fantasy IV game has a save at the last point where the user has control of the game. After loading the save, walk onto the boat at the top right of the screen, and click through all the dialogue until either you regain control of the game on the beach of Mysidia or the emulator hangs. It takes a little over three minutes from the save point.

[hrydgard]

I got word that this doesn't happen in the latest builds, or maybe a different version of the game? Might be worth trying again.

[shalottnet]

I checked this again just now against the latest release (v1.17.1), and the hang is still present.

Will try next against HEAD.

I did notice a bit more logging output this time, and I note that the cut scene is actually a .pmf movie that's being played. The movie plays out in its entirety, and the hang happens when ppsspp tries to transition back to normal game play after the end of the movie.

This is the first point during gameplay where a .pmf movie is played.

13:13:158 MyThread-Mai I[SCEKERNEL]: HLE/sceKernelThread.cpp:1999 478=sceKernelCreateThread(MyThread-Sound-Bgm2, 08932eb8, 00000021, 32768, 00000000, 00000000)
13:13:158 MyThread-Mai I[SCEKERNEL]: HLE/sceKernelThread.cpp:2096 0=sceKernelStartThread(478, 4, 09fcb8c0)
13:13:158 MyThread-Sou I[SCEKERNEL]: HLE/sceKernelThread.cpp:1999 479=sceKernelCreateThread(MyThread-Sound-Sub2, 08932e68, 00000011, 32768, 00000000, 00000000)
13:13:158 MyThread-Sou I[SCEKERNEL]: HLE/sceKernelThread.cpp:2096 0=sceKernelStartThread(479, 4, 09fbba30)
13:13:174 MyThread-Dev I[SCEUTIL]: HLE/sceUtility.cpp:543 0=sceUtilityLoadModule(00000303)
13:13:191 MyThread-Dev E[SCEUTIL]: HLE/sceUtility.cpp:516 80111102=sceUtilityLoadModule(00000303): already loaded
13:13:241 MyThread-Dev I[SCEMODULE]: HLE/sceKernelModule.cpp:1167 ~SCE module, skipping header
13:13:241 MyThread-Dev I[SCEMODULE]: HLE/sceKernelModule.cpp:1183 Loading module scePsmf_library with version 0101, devkit 06020010, crc 895d24cc
13:13:241 MyThread-Dev I[LOADER]: ELF/PrxDecrypter.cpp:716 Decrypting tag 457B06F0
13:13:241 MyThread-Dev I[LOADER]: ELF/PrxDecrypter.cpp:770 Decrypting tag 457B06F0
13:13:241 MyThread-Dev I[LOADER]: ELF/PrxDecrypter.cpp:825 Decrypting tag 457B06F0
13:13:241 MyThread-Dev I[SCEMODULE]: HLE/sceKernelModule.cpp:2096 480=sceKernelLoadModule(name=disc0:/PSP_GAME/USRDIR/module/psmf.prx,flag=00000000,(...))
13:13:242 MyThread-Dev I[SCEMODULE]: HLE/sceKernelModule.cpp:2175 sceKernelStartModule(480,asize=00000000,aptr=00000000,retptr=00000000,00000000): faked (undecryptable module)
13:13:273 MyThread-Dev I[SCEMODULE]: HLE/sceKernelModule.cpp:1167 ~SCE module, skipping header
13:13:273 MyThread-Dev I[SCEMODULE]: HLE/sceKernelModule.cpp:1183 Loading module scePsmfP_library with version 0101, devkit 06020010, crc bc337b
13:13:273 MyThread-Dev I[LOADER]: ELF/PrxDecrypter.cpp:716 Decrypting tag 457B06F0
13:13:273 MyThread-Dev I[LOADER]: ELF/PrxDecrypter.cpp:770 Decrypting tag 457B06F0
13:13:273 MyThread-Dev I[LOADER]: ELF/PrxDecrypter.cpp:825 Decrypting tag 457B06F0
13:13:274 MyThread-Dev I[SCEMODULE]: HLE/sceKernelModule.cpp:2096 481=sceKernelLoadModule(name=disc0:/PSP_GAME/USRDIR/module/libpsmfplayer.prx,flag=00000000,(...))
13:13:274 MyThread-Dev I[SCEMODULE]: HLE/sceKernelModule.cpp:2175 sceKernelStartModule(481,asize=00000000,aptr=00000000,retptr=00000000,00000000): faked (undecryptable module)
13:13:275 MyThread-Mai I[ME]: HLE/sceMpeg.cpp:467 sceMpegInit(), mpegLibVersion 0x10a, mpegLibcrc 0
13:13:291 MyThread-Mai I[SCEKERNEL]: HLE/sceKernelThread.cpp:1999 482=sceKernelCreateThread(MyThread-MovieStart, 08932d04, 00000016, 10240, 00000000, 00000000)
13:13:291 MyThread-Mai I[SCEKERNEL]: HLE/sceKernelThread.cpp:2096 0=sceKernelStartThread(482, 0, 00000000)
13:13:325 MyThread-Mov I[ME]: HLE/scePsmf.cpp:1172 psmfplayer create, psmfPlayerLibVersion 0x6020010, psmfPlayerLibcrc bc337b
13:13:326 MyThread-Mov I[ME]: HLE/scePsmf.cpp:2056 scePsmfPlayerConfigPlayer(0921d660, loop, 1)
13:13:326 MyThread-Mov I[ME]: HLE/scePsmf.cpp:2064 scePsmfPlayerConfigPlayer(0921d660, pixelType, 3)
13:13:346 MyThread-Mov I[ME]: HLE/scePsmf.cpp:1312 0=scePsmfPlayerSetPsmf(0921d660, disc0:/PSP_GAME/USRDIR/movie/Leviathan.pmf)
13:13:346 MyThread-Mov W[ME]: HLE/scePsmf.cpp:1443 scePsmfPlayerStart(0921d660, 09248de0, 0 (mode 0, speed 1)
13:13:346 MyThread-Mov E[SCEKERNEL]: HLE/sceKernelThread.cpp:2339 80020197=sceKernelTerminateThread(482): cannot terminate current thread
13:13:346 MyThread-Mov I[SCEKERNEL]: HLE/sceKernelThread.cpp:2187 sceKernelExitDeleteThread(1)
13:13:658 MyThread-Sou I[ME]: HLE/sceAtrac.cpp:1756 0=sceAtracReleaseAtracID(0)

[shalottnet]

HEAD as of 2024-03-10 (GH_TAGNAME=a0aaab9c47bae66fd834354977a562baec581a54) is still broken.

[LunaMoo]

unfortunately, building older version on FreeBSD is currently hampered by now having upgraded to ffmpeg-6 on the base system

This implies you're using system ffmpeg for your builds? In which case might be while other people weren't able to reproduce the problem you have. Can't you build vanilla PPSSPP with the provided FFMPEG?

[hrydgard]

That seems like a likely explanation. The use of any other FFMPEG version than the one provided with PPSSPP is not supported, for reasons we have repeated many times before (including the problem of reproducing reported errors).

[shalottnet]

I don't know why the original FreeBSD maintainer enabled using the system ffmpeg.

I removed USE_SYSTEM_FFMPEG from the CMAKE flags and rebuilt -- no change.

Thanks.

[hrydgard]

Hm, but i'm not sure we have a script to build our own copy of ffmpeg on any BSD systems... So is it really being used? Did you build it manually?

[shalottnet]

Ha, nope:

/usr/ports/emulators/ppsspp-44011# ldd work/stage/usr/local/bin/ppsspp| grep avcod     
        libavcodec.so.60 => /usr/local/lib/libavcodec.so.60 (0x3d8dcb600000)

It is still using the system ffmpeg.