NFL Street 3 stuck at autosave screen

[Sinatez]

Game or games this happens in

ULUS-10135 - NFL Street 3

What area of the game / PPSSPP

When trying to run the game it hangs at the first autosave screen.

What should happen

It should go past this screen to the create a profile screen.

Logs

No response

Platform

Android

Mobile device model or graphics card (GPU)

NVIDIA SHIELD PRO 2019

PPSSPP version affected

V 1.18.1

Last working version

0.9

Graphics backend (3D API)

Vulkan

Checklist

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

[anr2me]

Have you tried changing the I/O Timing method?

[Sinatez]

Have you tried changing the I/O Timing method?

I just gave that a shot, tried every option but still hanging on that first screen.

[sum2012]

I test no problem in windows 11 23h2

[anr2me]

may be scoped storage issue?

@Sinatez have you tried using legacy version from https://www.ppsspp.org/devbuilds/ ?

[hrydgard]

Hm, we do have another issue where it works on Windows but not on any other platform (#13781 ).

Might be another case and hopefully we'll get some clues, could someone try this on say Linux or Mac?

[anr2me]

When i tried to run ./PPSSPPSDL of the latest ubuntu artifact, i'm getting this error:

adamn@ASPIRE6:~/ppsspp$ ./PPSSPPSDL
./PPSSPPSDL: /lib/x86_64-linux-gnu/libm.so.6: version `GLIBC_2.38' not found (required by ./PPSSPPSDL)
./PPSSPPSDL: /lib/x86_64-linux-gnu/libstdc++.so.6: version `GLIBCXX_3.4.32' not found (required by ./PPSSPPSDL)
./PPSSPPSDL: /lib/x86_64-linux-gnu/libc.so.6: version `GLIBC_2.38' not found (required by ./PPSSPPSDL)

it's no longer running :( even after sudo apt update/upgrade

PS: i don't have ppsspp source code on my local storage
i'm using Ubuntu 22.04.5 LTS on WSL2 btw, it used to run fine when i tested infrastructure artifacts recently.
i guess this is one of the reason why we need Flatpak/AppImage bundle

[sum2012]

Confirm the problem in my black shark 5 phone.
Tested Normal build and legacy version.

windows log
ppsspplogv1.18.1-1024-gd5bd7d24aa.txt.zip

[anr2me]

Btw, why did you post the Windows logs instead of Android logs? it didn't have any issue on Windows, right?

[sum2012]

Yes, windows version no problem

Fail to use Android studio to build
A build operation failed.
Could not create task ':android:compileNormalDebugAndroidTestJavaWithJavac'.
Could not create task ':android:compileNormalDebugAndroidTestJavaWithJavac'.
Failed to calculate the value of task ':android:compileNormalDebugAndroidTestJavaWithJavac' property 'javaCompiler'.
Cannot find a Java installation on your machine matching this tasks requirements: {languageVersion=17, vendor=any vendor, implementation=vendor-specific} for WINDOWS on x86_64.
No locally installed toolchains match and toolchain download repositories have not been configured.

[anr2me]

Btw is this stuck happened before reaching the "Press START button" screen?
I tried to build artifacts with Ubuntu 22.04 and i can reached the main menu screen without getting stuck:

Is this mean the issue didn't exist on Linux?

Edit: nevermind, i tested it on Android and it stuck with 0/0 FPS as soon as something shows up on screen.

Unfortunately i couldn't click anything on the Debugger, even with a bluetooth mouse.
But the logs stopped on that Error "A save request is already running"

[anr2me]

Hmm.. strange, it also happened on Windows just now:

Probably something rare to happen on Windows, since this is the first time i got stuck after many tries a few days ago.
And i didn't see that error "A save request is already running" in the Windows logs

Edit:
Looks like it got infinite loop at 089DD10C:

It never reached the 2nd breakpoint (at 089DD114)

May be similar issue to #15068 (comment) where the status' change can get overridden immediately on a single update call (ie. 2x status changes on a single update call), thus skipping one of the status' change without giving the game a chance to read it (as i remembered)

Edit2: Looks like it can be reproduced quite often on Windows now with any I/O Timing methods (but Fast seems to have lower chance to trigger this issue)

Edit3: Apparently it's easily reproduced on Windows because i have "Force real clock sync" enabled

[anr2me]

@sum2012 try enabling "Force real clock sync", it should shows the same issue on Windows too!

Edit: changing the CPU clock to 50 or 200 no longer stuck on Android.
So i guess this is timing issue.

[sum2012]

@anr2me But the default setting both "Force real clock sync" is disabled.
So that timing code in android ?

[sum2012]

I solve android build by enable change of registry key in installing OpenJDK 17
EDIT: I still get error

edit2: DeepSeek is helping me

[sum2012]

A hint https://gist.github.com/sum2012/4b2a2a2cb159743bba4ae237dfa04685

[hrydgard]

Huh, I'm surprised that Real clock sync can affect it. Then the game must be querying the real time and depending on it somehow, or we have some bug in timing... Anyway, good clue.

[anr2me]

Since the loop between sceUtilitySavedataGetStatus and sceUtilitySavedataUpdate is pretty tight without any other syscalls in between (which should've caught all the status changes), i still suspected that we changed status from 2/3 to 4/0 way too fast (ie. overridden immediately) on some situation (as i remembered it was due to fading time ended at the same time when the status were supposed to be changed from 2 to 3 but ended with 4/0 instead on #15068 (comment))

So, may be we should ensure to only update the status once and exited the update syscall to let the game read the status first before changing it to the next status on the next update call?

PS: We may also need to checked whether another thread kicked in during the loop and taking too long before switching back to the looping thread, not sure how to do this test (may be we should have "Next Thread" button on Debugger?)
Then again it would probably too late to find out which thread consuming too much time while the game is waiting for status = 3, since the status is already became 0 when we noticed that it stuck waiting for status = 3.

[anr2me]

Btw, what could be the cause of this SCE_KERNEL_ERROR_UTILITY_INVALID_STATUS=sceUtilitySavedataUpdate(1)
The Logs is flooded with it while the game is looping to wait for status = 3

I tried to logs the status that changes to 3 or further on this branch ANR2MERefork#24, but while it stuck in an infinite loop my logs didn't shows up, and the strange thing is during the loop how did the status became 0 while it never go to 3+ and sceUtilitySavedataUpdate always returning SCE_KERNEL_ERROR_UTILITY_INVALID_STATUS O.o
As we can see in the logs, at the start it already got status = 1 but still returning SCE_KERNEL_ERROR_UTILITY_INVALID_STATUS and never got to 3+ (since my logs didn't shows up)
When my logs did shows up on some attempts to retry the game, it only shows up when the game isn't stuck.

Edit: it seems Update only consider the status as valid when it's at running (2) state, this explained the flooding INVALID_STATUS since the status is 1 (initialized), but still strange for the game to get status = 0 from sceUtilitySavedataGetStatus while it stuck in the loop (where it should be 1).

PS: since i edited those files directly at github to add the logs, not sure whether i missed some of the FINISHED/SHUTDOWN changes or not, as it's hard to find the reference (in case the logs didn't shows up because i missed some of the ChangeStatus)

[anr2me]

I tried to logs the oldStatus -> status value during the SCE_KERNEL_ERROR_UTILITY_INVALID_STATUS=sceUtilitySavedataUpdate(1)
It's strange that the status value suddenly became 0, but this only happened when the game stuck in the loop, while it didn't goes to 0 when the game didn't stuck.

Something seems to cause the status to changed, but i couldn't see the live logs in between those changes (a bug in the logging system?)

[anr2me]

I tried to create the ppsspplog.txt and i think i was right that the status changed from 2 -> 3 -> 4 way too fast

41:41:454 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:468 SCE_KERNEL_ERROR_UTILITY_INVALID_STATUS=sceUtilitySavedataUpdate(1)
41:41:454 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:473 sceUtilitySaveDialog status: 1 -> 1
41:41:454 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:468 SCE_KERNEL_ERROR_UTILITY_INVALID_STATUS=sceUtilitySavedataUpdate(1)
41:41:454 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:473 sceUtilitySaveDialog status: 1 -> 1
41:41:454 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:468 SCE_KERNEL_ERROR_UTILITY_INVALID_STATUS=sceUtilitySavedataUpdate(1)
41:41:454 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:473 sceUtilitySaveDialog status: 1 -> 1
41:41:454 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:468 SCE_KERNEL_ERROR_UTILITY_INVALID_STATUS=sceUtilitySavedataUpdate(1)
41:41:454 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:473 sceUtilitySaveDialog status: 1 -> 1
41:41:454 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:468 SCE_KERNEL_ERROR_UTILITY_INVALID_STATUS=sceUtilitySavedataUpdate(1)
41:41:454 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:473 sceUtilitySaveDialog status: 1 -> 1
41:41:454 ScePafJob    D[SCEUTIL]: HLE\sceUtility.cpp:402 0=__UtilityInitDialog(1)
41:41:454 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:468 0=sceUtilitySavedataUpdate(1)
41:41:454 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:458 2=sceUtilitySavedataGetStatus()
41:41:455 SaveIO       I[SCEUTIL]: Dialog\SavedataParam.cpp:1210 GetSize: usedSpaceKB: 320 (str: 320 KB) (clusters: 10)
41:41:455 SaveIO       I[SCEUTIL]: Dialog\SavedataParam.cpp:1211 GetSize: usedSpace32KB: 320 (str32: 320 KB)
41:41:455 user_main    I[SCEUTIL]: Dialog\PSPSaveDialog.cpp:1045 sceUtilitySavedata StatusChanged: 2 -> 3 (within 0)
41:41:455 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:468 0=sceUtilitySavedataUpdate(1)
41:41:455 SND_SAS      D[SCEAUDIO]: HLE\sceAudio.cpp:122 00000100=sceAudioOutputPannedBlocking(5, 00008000, 00008000, 08d32240)
41:41:456 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:458 3=sceUtilitySavedataGetStatus()
41:41:456 user_main    I[SCEUTIL]: Dialog\PSPDialog.cpp:191 sceUtility StatusChanged: 3 -> 4 (within 0)
41:41:456 user_main    I[SCEUTIL]: Dialog\PSPDialog.cpp:162 sceUtility StatusChanged: 4 -> 4 (within 0)
41:41:456 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:444 0=sceUtilitySavedataShutdownStart()
41:41:456 user_main    E[SCEUTIL]: Dialog\PSPSaveDialog.cpp:92 A save request is already running, not starting a new one
41:41:456 user_main    I[HTTP]: Net\HTTPRequest.cpp:15 HTTP POST request: http://report.ppsspp.org:80/report/message ()
41:41:456 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:434 SCE_KERNEL_ERROR_UTILITY_INVALID_STATUS=sceUtilitySavedataInitStart(09ffe6d4)
41:41:456 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:468 SCE_KERNEL_ERROR_UTILITY_INVALID_STATUS=sceUtilitySavedataUpdate(1)
41:41:456 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:473 sceUtilitySaveDialog status: -1 -> 4
41:41:456 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:458 4=sceUtilitySavedataGetStatus()
41:41:456 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:468 SCE_KERNEL_ERROR_UTILITY_INVALID_STATUS=sceUtilitySavedataUpdate(1)
41:41:456 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:473 sceUtilitySaveDialog status: 4 -> 4
41:41:456 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:468 SCE_KERNEL_ERROR_UTILITY_INVALID_STATUS=sceUtilitySavedataUpdate(1)
41:41:457 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:473 sceUtilitySaveDialog status: 4 -> 4
41:41:457 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:468 SCE_KERNEL_ERROR_UTILITY_INVALID_STATUS=sceUtilitySavedataUpdate(1)
41:41:457 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:473 sceUtilitySaveDialog status: 4 -> 4
...
41:41:486 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:468 SCE_KERNEL_ERROR_UTILITY_INVALID_STATUS=sceUtilitySavedataUpdate(1)
41:41:486 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:473 sceUtilitySaveDialog status: 4 -> 4
41:41:486 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:468 SCE_KERNEL_ERROR_UTILITY_INVALID_STATUS=sceUtilitySavedataUpdate(1)
41:41:486 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:473 sceUtilitySaveDialog status: 4 -> 4
41:41:486 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:468 SCE_KERNEL_ERROR_UTILITY_INVALID_STATUS=sceUtilitySavedataUpdate(1)
41:41:486 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:473 sceUtilitySaveDialog status: 4 -> 4
41:41:486 ScePafJob    I[SCEUTIL]: Dialog\PSPDialog.cpp:144 sceUtility StatusChanged: 4 -> 0 (within 0)
41:41:487 ScePafJob    D[SCEUTIL]: HLE\sceUtility.cpp:411 0=__UtilityFinishDialog(1)
41:41:487 idle0        D[CPU]: HLE\sceKernelInterrupt.cpp:147 Entering interrupt handler 08a587f0
41:41:487 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:468 SCE_KERNEL_ERROR_UTILITY_INVALID_STATUS=sceUtilitySavedataUpdate(1)
41:41:487 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:473 sceUtilitySaveDialog status: 4 -> 0
41:41:487 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:458 0=sceUtilitySavedataGetStatus()
41:41:487 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:468 SCE_KERNEL_ERROR_UTILITY_INVALID_STATUS=sceUtilitySavedataUpdate(1)
41:41:487 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:473 sceUtilitySaveDialog status: 0 -> 0
41:41:487 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:468 SCE_KERNEL_ERROR_UTILITY_INVALID_STATUS=sceUtilitySavedataUpdate(1)
41:41:487 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:473 sceUtilitySaveDialog status: 0 -> 0
41:41:487 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:468 SCE_KERNEL_ERROR_UTILITY_INVALID_STATUS=sceUtilitySavedataUpdate(1)
41:41:487 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:473 sceUtilitySaveDialog status: 0 -> 0
41:41:487 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:468 SCE_KERNEL_ERROR_UTILITY_INVALID_STATUS=sceUtilitySavedataUpdate(1)
41:41:487 user_main    D[SCEUTIL]: HLE\sceUtility.cpp:473 sceUtilitySaveDialog status: 0 -> 0

ppsspplog.zip
PS: The logs have SCEKERNEL set to INFO because it's hard to reproduce the issue when the emulation is being slowed down due to writing too many kernel logs, mostly due to my slow HDD and CPU.

I guess that "A save request is already running" error was because the game tried to start a new one while the previous one hasn't fully shutdown yet, and the stuck loop where the game expecting status = 3 in order to exit is probably occurred after that error, which ended with status = 0 for infinity.

Based on the Disassembly screenshot on my previous comment, we can see that the game is ignoring the failing sceUtilitySavedataInitStart and still trying to progress, thus ended stuck.

So, may be if the status = 4, instead of returning SCE_KERNEL_ERROR_UTILITY_INVALID_STATUS during sceUtilitySavedataInitStart we should blocked the thread and waited until the previous Savedata fully shutdown (status = 0), or forced it to shutdown.