Crash Tag Team Racing reported stuck on memory stick screen

[hrydgard]

"After the android update crash tag team racing gets stuck at the memory stick screen. Any workaround for this?"

[unknownbrackets]

Could be the same truncate issue as LittleBigPlanet.

-[Unknown]

[raven02]

Yep , stucks here

15:34:116 user_main I[UTIL]: Dialog\PSPSaveDialog.cpp:67 sceUtilitySavedataInitStart(08e6c220) : Mode = 0
15:34:425 user_main E[UTIL]: Dialog\PSPSaveDialog.cpp:54 A save request is already running, not starting a new one

[raven02]

Comment out the return ERROR code (of course may be wrong , just test it out) , the game goes in-game

// Ignore if already running
if (GetStatus() != SCE_UTILITY_STATUS_NONE) {
    ERROR_LOG_REPORT(SCEUTILITY, "A save request is already running, not starting a new one");
    // return SCE_ERROR_UTILITY_INVALID_STATUS;
}

[raven02]

Tried to log it , the status at that moment is SCE_UTILITY_STATUS_SHUTDOWN

// Ignore if already running
if (GetStatus() != SCE_UTILITY_STATUS_NONE) {
    INFO_LOG(HLE, "status = %i", GetStatus());
    ERROR_LOG_REPORT(SCEUTILITY, "A save request is already running, not starting a new one");
    return SCE_ERROR_UTILITY_INVALID_STATUS;
}

[unknownbrackets]

Maybe it has shutdown too slowly. Can you post the debug log between sceUtilitySavedataShutdownStart() and the sceUtilitySavedataInitStart() that fails?

-[Unknown]

[raven02]

Yep you are right .It is shutdown delay , reduced to lower value let say 0 or 100 , it is okay

const static int SAVEDATA_SHUTDOWN_DELAY_US = 100;

Note : >= 120 is not gonna work

[unknownbrackets]

Hmm, that is an extremely small number, much faster than anything I can reproduce. Would still be nice to see the log, maybe something else is expected to take more time but doesn't.

-[Unknown]

[raven02]

Sure let me grep it .

[raven02]

These are the logs from them .

45:07:512 user_main W[UTIL]: HLE\sceUtility.cpp:126 00000000=sceUtilitySavedataInitStart(08e6c220)
45:07:822 user_main W[UTIL]: HLE\sceUtility.cpp:139 00000000=sceUtilitySavedataShutdownStart()
45:07:822 user_main E[UTIL]: Dialog\PSPSaveDialog.cpp:55 A save request is already running, not starting a new one
45:07:822 user_main W[UTIL]: HLE\sceUtility.cpp:126 80110001=sceUtilitySavedataInitStart(08e6c220)

[unknownbrackets]

This is a debug log? Does that mean it does absolutely nothing (syscall wise) between the two calls?

-[Unknown]

[raven02]

This is the debug log that taken when stucks

09:12:365 user_main D[KERNEL]: hle\scekernelsemaphore.cpp:413 0=sceKernelWaitSema(295, 1, 0)
09:12:365 user_main D[KERNEL]: hle\scekernelsemaphore.cpp:303 sceKernelSignalSema(295, 1) (count: 0 -> 1)
09:12:365 user_main D[UTIL]: hle\sceutility.cpp:152 00000000=sceUtilitySavedataGetStatus()
09:12:365 user_main D[KERNEL]: hle\scekerneltime.cpp:81 14264080=sceKernelGetSystemTimeWide()
09:12:365 user_main D[KERNEL]: hle\scekerneltime.cpp:81 14264088=sceKernelGetSystemTimeWide()
09:12:365 user_main D[KERNEL]: hle\scekerneltime.cpp:81 14264089=sceKernelGetSystemTimeWide()
09:12:365 user_main D[KERNEL]: hle\scekerneltime.cpp:81 14264093=sceKernelGetSystemTimeWide()
09:12:365 user_main D[CTRL]: hle\scectrl.cpp:459 sceCtrlReadBufferPositive(0bfed410, 1) - waiting
09:12:365 idle0 D[KERNEL]: hle\scekernelthread.cpp:3207 Context switch: user_main -> idle0 (276->272, pc: 08a776f0->08000000, ctrl buffer waite
d) +577us
09:12:365 idle0 D[DISP]: hle\scedisplay.cpp:627 Leave VBlank 854
09:12:365 user_main D[KERNEL]: hle\scekernelthread.cpp:3207 Context switch: idle0 -> user_main (272->276, pc: 08000000->08a776f0, idle) +153us
09:12:365 user_main D[KERNEL]: hle\scekerneltime.cpp:81 14264254=sceKernelGetSystemTimeWide()
09:12:365 user_main D[SCEGE]: hle\scege.cpp:396 sceGeDrawSync(mode=0) (0=wait for completion, 1=peek)
09:12:365 idle0 D[KERNEL]: hle\scekernelthread.cpp:3207 Context switch: user_main -> idle0 (276->272, pc: 08a228cc->08000000, vblank start wait
ed) +28us
09:12:365 Audio Mix Th D[KERNEL]: hle\scekernelthread.cpp:3207 Context switch: idle0 -> Audio Mix Thread (272->310, pc: 08000000->08b28d88, idle) +195
3us
09:12:365 Audio Mix Th D[SCESAS]: hle\scesas.cpp:127 sceSasCore(08c253c0, 08f39dc0)
09:12:365 idle0 D[KERNEL]: hle\scekernelthread.cpp:3207 Context switch: Audio Mix Thread -> idle0 (310->272, pc: 08b2a13c->08000000, sas core)
+0us
09:12:365 Audio Mix Th D[KERNEL]: hle\scekernelthread.cpp:3207 Context switch: idle0 -> Audio Mix Thread (272->310, pc: 08000000->08b2a13c, idle) +240
us
09:12:365 Audio Mix Th D[AUDIO]: hle\sceaudio.cpp:120 00000100 = sceAudioOutputPannedBlocking(00000006, 00008000, 00008000, 08f39dc0)
09:12:365 idle0 D[KERNEL]: hle\scekernelthread.cpp:3207 Context switch: Audio Mix Thread -> idle0 (310->272, pc: 08b28d88->08000000, blocking a
udio) +0us
09:12:365 Audio Mix Th D[KERNEL]: hle\scekernelthread.cpp:3207 Context switch: idle0 -> Audio Mix Thread (272->310, pc: 08000000->08b28d88, idle) +556
3us
09:12:365 Audio Mix Th D[SCESAS]: hle\scesas.cpp:127 sceSasCore(08c253c0, 08f397c0)
09:12:365 idle0 D[KERNEL]: hle\scekernelthread.cpp:3207 Context switch: Audio Mix Thread -> idle0 (310->272, pc: 08b2a13c->08000000, sas core)
+0us
09:12:365 Audio Mix Th D[KERNEL]: hle\scekernelthread.cpp:3207 Context switch: idle0 -> Audio Mix Thread (272->310, pc: 08000000->08b2a13c, idle) +240
us
09:12:365 Audio Mix Th D[AUDIO]: hle\sceaudio.cpp:120 00000100 = sceAudioOutputPannedBlocking(00000006, 00008000, 00008000, 08f397c0)
09:12:365 idle0 D[KERNEL]: hle\scekernelthread.cpp:3207 Context switch: Audio Mix Thread -> idle0 (310->272, pc: 08b28d88->08000000, blocking a
udio) +0us
09:12:366 Audio Mix Th D[KERNEL]: hle\scekernelthread.cpp:3207 Context switch: idle0 -> Audio Mix Thread (272->310, pc: 08000000->08b28d88, idle) +556
3us
09:12:366 Audio Mix Th D[SCESAS]: hle\scesas.cpp:127 sceSasCore(08c253c0, 08f39dc0)
09:12:366 idle0 D[KERNEL]: hle\scekernelthread.cpp:3207 Context switch: Audio Mix Thread -> idle0 (310->272, pc: 08b2a13c->08000000, sas core)
+0us
09:12:366 Audio Mix Th D[KERNEL]: hle\scekernelthread.cpp:3207 Context switch: idle0 -> Audio Mix Thread (272->310, pc: 08000000->08b2a13c, idle) +240
us
09:12:366 Audio Mix Th D[AUDIO]: hle\sceaudio.cpp:120 00000100 = sceAudioOutputPannedBlocking(00000006, 00008000, 00008000, 08f39dc0)
09:12:366 idle0 D[KERNEL]: hle\scekernelthread.cpp:3207 Context switch: Audio Mix Thread -> idle0 (310->272, pc: 08b28d88->08000000, blocking a
udio) +0us
09:12:366 idle0 D[DISP]: hle\scedisplay.cpp:531 Enter VBlank 855
09:12:366 idle0 D[SCEGE]: gles\framebuffer.cpp:1053 Displaying FBO 00000000
09:12:382 user_main D[KERNEL]: hle\scekernelthread.cpp:3207 Context switch: idle0 -> user_main (272->276, pc: 08000000->08a228cc, idle) +2121us

[unknownbrackets]

Well, the reason I'm asking is this:

Imagine there is a man. The man makes a purchase at store, and uses up all his money in his bank account doing so.

The man then goes to the bank to deposit more money.

The man then goes to a restaurant and when trying to pay, his card is declined. Dismayed, he complains to his bank, since he had deposited more money already.

The above situation is exactly like what's happening in the game. Here's the important part I'm asking about: how long did it take the man to get to the restaurant after going to the bank? Did he go home and go to sleep, and go to the restaurant in the morning? Or did he go there, speeding at 100km/h, trying as best he could to make it there before the deposit was available on his card?

So, that's why I'm asking: am I correct that it calls zero syscalls between sceUtilitySavedataShutdownStart() and sceUtilitySavedataInitStart()? Or was that just from a release log (because it looked like a release log, it's hard to believe it didn't call anything else in between.)

I really don't care what it does after sceUtilitySavedataInitStart() fails, not unless it is meant to fail and the game is not recovering from the error properly due to a bug somewhere else. I don't think that's likely.

-[Unknown]

[raven02]

This is the full set debug log .

[rename to zip and extract ]

[unknownbrackets]

Okay, so as I thought, it's doing stuff:

50:12:822 user_main    D[UTIL]: hle\sceutility.cpp:139 00000000=sceUtilitySavedataShutdownStart()
50:12:823 user_main    D[SCEGE]: hle\scege.cpp:396 sceGeDrawSync(mode=0)  (0=wait for completion, 1=peek)
50:12:823 user_main    D[HLE]: hle\scepower.cpp:300 sceKernelVolatileMemLock(0, 08dc2e4c, 08dc2e50) - success
50:12:824 user_main    E[UTIL]: dialog\pspsavedialog.cpp:54 A save request is already running, not starting a new one
50:12:824 user_main    D[UTIL]: hle\sceutility.cpp:126 80110001=sceUtilitySavedataInitStart(08e6c220)

It's quite likely that both of those ought to take longer than they are currently taking in PPSSPP.

-[Unknown]

[raven02]

Can we somehow set a lower delay here for shutdown ?

[unknownbrackets]

But that's not what happens on the PSP. Maybe it's that locking the volatile RAM always takes a certain amount of time, or that the drawsync is completing too early (it says wait for completion, but apparently is not waiting.)

The delays fixed games, games that were expecting the value to switch from 4 to 0 naturally and other games that were expecting it to stay at 4 for a while. If we decrease the delay, we'll just be having this conversation again about another game.

-[Unknown]

[raven02]

Yep , agreed.

[sum2012]

How about change SAVEDATA_SHUTDOWN_DELAY_US = 100 only for this game(for all region) ?

[hrydgard]

I decided to simply have sceKernelVolatileMemLock eat some cycles, it fixes the problem for some reason. Needs proper testing, I really need to get my PSP testing setup up and running again... ce1d449

[unknownbrackets]

It's pretty easy to set up on newer OS's with the latest libusb32. If you have problems just hit me on irc. Last time I tried it, didn't even need to restart iirc.

Have not tested it either but I would not be surprised as I said above if it did eat cycles. That said, could also be gpu or both.

I think there was one game that was using (locking/unlocking) volatile mem a lot, but I can't remember which. But most games probably won't care if it takes a few more cycles.

-[Unknown]

[solarmystic]

@hrydgard @unknownbrackets

Was the change in ce1d449 meant to have any detrimental performance effects?

Some preliminary testing using the usual game suite indicated no performance changes at all.

[hrydgard]

Most games that use the function only use it in initialization. If a game used it every frame the short delay would pretty much break timing though, but that seems very unlikely.

[hrydgard]

Closing, let's reopen if it reappears due to some timing change or another, as the game seems rather sensitive.

[unknownbrackets]

Most likely it's the gpu thing, a brief test seemed to indicate that sceKernelVolatileMemLock takes maybe around ~1200 cycles, not like ~200000.

-[Unknown]

[B2F]

On last android playstore rev, the issue reaappears on xperia Z1 compact.

[ppmeis]

It works fine for me under Windows and Android, latest build:

Windows version

Android version

[unknownbrackets]

I wonder if the playstore version as of the last comment did not include the fix. Otherwise maybe the issue is region specific...

-[Unknown]

[unknownbrackets]

Does this happen still on Android?

-[Unknown]

[sum2012]

I have no problem test on v1.2.2-821-geac1848 on asus zenfone 2
edit:I test USA version

[ManDude]

Having this issue with 1.3 (stable), Windows.

[sum2012]

v1.3-144-g5df685f windows 64 bit do not work
debug log:
https://drive.google.com/file/d/0B3OaSdeV0L8kZk10MnBXVTZ4OUU/view?usp=sharing

[sum2012]

I know now.I was set cpu clok 1000 to test a game.
set back auto can in-game.

[ManDude]

A workaround is disabling memstick before the checking memory stick screen appears, then add the memstick back in after the main menu.

[sum2012]

@ManDude Did you changed cpu clock or something ?

[ppmeis]

Tested with latest build. It works just fine:

[DjDiabolik]

OMG... simply found this thread by GOOGLE.
I have updated my version of ppsspp to 1.4.2 from 1.3......... on 1.3 all it's working but on 1.4.2 the games it's hang at same point.

At this point how i can fix or found a workaround ??

Ah.. all it's on Windows 10 X64............ i have also tryed to use the X86 but i obtain same result...

[ManDude]

Disable memstick before booting the game and enable it at the main menu.

[DjDiabolik]

@ManDude it's workaround.... but it's unfixable ?

[benderscruffy01]

goes ingame no problem
can this be closed now ???

[LunaMoo]

This was solved by a pretty incorrect hack making sceKernelVolatileMemLock eating lots of cycles later changed to a slightly better compat.ini hack [DrawSyncEatCycles] which also solved issues in a bunch of other games pointing out that gpu timings should be improved, but yeah I guess this can be closed now.

[Panderner]

when I overclock this game above 266 MHz same happens

[hrydgard]

Yeah well, don't expect things to function correctly when overclocking - not all games can handle it.

[Panderner]

Here's a log when I overclock the PSP CPU above 266 MHz:

user_main    E[SCEUTIL]: Dialog/PSPSaveDialog.cpp:68 A save request is already running, not starting a new one

[unknownbrackets]

Maybe we should have a compat.ini setting that disables the cpu clock changes in some games?

-[Unknown]

[hrydgard]

Yeah, that's reasonable.