Closed nfjorgebueno closed 3 years ago
unknownbrackets
commented
10 years ago Can you post a debug log? You're using the latest git build, right?
You need to help us by providing something to go on. A black screen is not really "please fix"able. It's not like we need to just change some code that currently says "show a black screen" to "keep playing the game instead of showing a black screen" - we have to have some info on why it's happening to help.
-[Unknown]
nfjorgebueno
commented
10 years ago I can not post a log because I have windows xp I can only tell you honestly what's wrong with the game in latest buids .I saw your message on my email. thank you for your willingness
unknownbrackets
commented
10 years ago Download the latest git build and open "DebugLog.bat". It works fine on Windows XP.
-[Unknown]
nfjorgebueno
commented
10 years ago sorry I could not put all the log
unknownbrackets
commented
10 years ago Hmm. Somewhere between here:
44:37:140 user_main D[IO]: HLE\sceIo.cpp:1844 39226 = sceIoPollAsync(4, 0bffe4e8)
And here:
45:43:375 FMOD thread E[IO]: HLE\sceIo.cpp:834 sceIoReadAsync: bad file 4
File descriptor 4 turned into a puff of smoke. That's not good. I suppose it means closePending was set. Maybe somehow because of the failed sceIoOpenAsync before it?
-[Unknown]
nfjorgebueno
commented
9 years ago European version works well, thank you for your attention
unknownbrackets
commented
9 years ago While we may not be able to fix this without good feedback, there seems to be an issue here at least in some regions of the game.
-[Unknown]
nfjorgebueno
commented
9 years ago I am a respectful person, maybe too cold, but I value their work and that of the whole team github, greetings, best wishes
daniel229
commented
8 years ago Still hangs on loading save.
By the way,the game has a config inside the iso,allow you to chang the FPS and other funny things.Default is 22,and you can chang to 60.
unknownbrackets
commented
5 years ago I think we fixed something related to closePending some time ago now. Is this still happening?
-[Unknown]
TheRealPSV
commented
4 years ago Still seems to be going to a black screen after loading a savegame in the US version. Here's a log, it seems like there's some "bad file descriptor" error that keeps happening after loading the save. ppsspplog.zip
unknownbrackets
commented
4 years ago Well, this log is more interesting. The basic pattern it's using is this:
4 = sceIoOpenAsync(EN_filename)
sceIoPollAsync(4, &result);
sceIoCloseAsync(4); // bad file descriptorEventually, we get some unlucky timing, where this essentially happens.
// On user_main thread
4=sceIoOpenAsync(disc0:/PSP_GAME/USRDIR/SPIDERM/CARRIER/CARRIER.PSP, 1, 0): file not found
sceIoPollAsync(4, &result);
// On FMOD thread
4 = sceIoOpenAsync(disc0:/PSP_GAME/USRDIR/SPIDERM/TALLY/LOBBY.STR, 1, 0)
// Back on user_main thread
sceIoCloseAsync(4);Might need to verify what happens when opening invalid files and sceIoPoll. Maybe we're releasing the descriptor too early...
-[Unknown]
hrydgard
commented
4 years ago Wow, that's interesting... Maybe an async descriptor should indeed live longer even when bad. Would make sense just to prevent this kind of race.
unknownbrackets
commented
4 years ago Confirmed that if you run poll/asyncwait/asyncstat/whatever, the fd becomes free if async has run.
This is rather a timing issue, but I think for Open I was seeing a lot of variance (likely due to the UMD cache) and wasn't sure, so aimed super low. Going to try to do some benchmarks with a Pro Duo card (pre Mark2) and a faster microSD adapter card, and then compare to UMD.
-[Unknown]
TheRealPSV
commented
4 years ago Let me know if there's anything more I can do to help with testing/logging with this issue.
Panderner
commented
4 years ago This is saving issue when i start the new game it should playable but when i load the save the game stucks at loading
unknownbrackets
commented
3 years ago Is this still happening? #12945 may have helped and would be in latest git builds (not v1.10.3 which is older.)
If it is still happening, a fresh log may help.
-[Unknown]
TheRealPSV
commented
3 years ago @unknownbrackets Grabbed the Win x64 build from this build: https://github.com/hrydgard/ppsspp/actions/runs/495359293
Unfortunately, it looks like the issue is still happening. Here's the log. ppsspplog.zip
anr2me
commented
3 years ago Wow, that's interesting... Maybe an async descriptor should indeed live longer even when bad. Would make sense just to prevent this kind of race.
Isn't normal for a descriptor/handle number to be increased internally even on failure on most Operating System? so they never reuse the same descriptor number
unknownbrackets
commented
3 years ago Isn't normal for a descriptor/handle number to be increased internally even on failure on most Operating System? so they never reuse the same descriptor number
While this makes logical sense, it doesn't matter. We simulate what the PSP firmware actually did, which is to reuse fds if they're free. Interestingly, it does cycle through other things like FPL allocations, but not fds. Unlike Windows/Linux/macOS/etc. it also has a very limited set of fds it's willing to return.
Maybe there's timing of something else that could improve this. Perhaps sceUmdWaitDriveStat / sceUmdWaitDriveStatCB...
-[Unknown]
anr2me
commented
3 years ago I see, i guess PSP manages file descriptor differently than their socket descriptor :)
because when i tested adhoc descriptors on a small homebrew, if the 1st successful socket creation gets number 1, and the 2nd creation failed due to port already used, the 3rd creation (success) will get the number 3 instead of 2. While it's also the same regarding limited number of descriptors even for adhoc sockets, since there are game that treats adhoc descriptors as 8-bit value thus causes a bug if it's larger than 255.
unknownbrackets
commented
3 years ago Right. I confirmed it (and also range of return values etc.) with this:
checkpointNext("Alloc order:");
for (size_t i = 0; i < 32; ++i) {
ids[i] = sceIoOpen("fds.prx", PSP_O_RDONLY, 0);
}
sceIoClose(ids[20]);
ids[33] = sceIoOpen("fds.prx", PSP_O_RDONLY, 0);
checkpoint("Opened: %08x", ids[33]);
ids[34] = sceIoOpen("fds.prx", PSP_O_RDONLY, 0);
checkpoint("Opened: %08x", ids[34]);Unfortunately the pspautotests setup and freopen stuff changes the file descriptors a bit and makes it a bad overall test, since it can't match between emulator and firmware.
I also retested the specific scenario of async for this issue but didn't find any different behavior, so I really hoped it'd be the timing of open (which was definitely pretty far off before #12945.)
-[Unknown]
anr2me
commented
3 years ago @unknownbrackets Grabbed the Win x64 build from this build: https://github.com/hrydgard/ppsspp/actions/runs/495359293
Unfortunately, it looks like the issue is still happening. Here's the log. ppsspplog.zip
Based on this Logs at the start of the endless flood:
45:37:637 FMOD thread D[SCEKERNEL]: HLE\sceKernelThread.cpp:3096 Context switch: idle0 -> FMOD thread for FMOD_NONBLOCKIN (272->412, pc: 08000000->08b561ac, woke from hle delay) +126us
45:37:637 FMOD thread D[SCEKERNEL]: HLE\sceKernelMutex.cpp:562 sceKernelLockMutex(283, 1, 00000000)
45:37:637 FMOD thread D[SCEKERNEL]: HLE\sceKernelMutex.cpp:641 sceKernelUnlockMutex(283, 1)
45:37:637 FMOD thread E[SCEIO]: HLE\sceIo.cpp:1410 80020323=sceIoLseekAsync(0, 00000000000f6000, 0): bad file descriptor
45:37:637 FMOD thread D[SCEKERNEL]: HLE\sceKernelMutex.cpp:562 sceKernelLockMutex(394, 1, 00000000)
45:37:637 FMOD thread E[SCEIO]: HLE\sceIo.cpp:1126 80020323=sceIoReadAsync(0, 08e88e50, 2048): bad file descriptor
45:37:637 FMOD thread D[SCEIO]: HLE\sceUmd.cpp:473 0=sceUmdWaitDriveStatCB(stat = 00000020, timeout = 0)
45:37:637 FMOD thread E[SCEIO]: HLE\sceIo.cpp:1126 80020323=sceIoReadAsync(0, 08e88e50, 2048): bad file descriptor
45:37:637 FMOD thread D[SCEIO]: HLE\sceUmd.cpp:473 0=sceUmdWaitDriveStatCB(stat = 00000020, timeout = 0)
45:37:637 FMOD thread E[SCEIO]: HLE\sceIo.cpp:1126 80020323=sceIoReadAsync(0, 08e88e50, 2048): bad file descriptor
45:37:637 FMOD thread D[SCEIO]: HLE\sceUmd.cpp:473 0=sceUmdWaitDriveStatCB(stat = 00000020, timeout = 0)
45:37:637 FMOD thread E[SCEIO]: HLE\sceIo.cpp:1126 80020323=sceIoReadAsync(0, 08e88e50, 2048): bad file descriptor
45:37:637 FMOD thread D[SCEIO]: HLE\sceUmd.cpp:473 0=sceUmdWaitDriveStatCB(stat = 00000020, timeout = 0)
45:37:637 FMOD thread E[SCEIO]: HLE\sceIo.cpp:1126 80020323=sceIoReadAsync(0, 08e88e50, 2048): bad file descriptor
45:37:637 FMOD thread D[SCEIO]: HLE\sceUmd.cpp:473 0=sceUmdWaitDriveStatCB(stat = 00000020, timeout = 0)~~Is 0 supposed to be a valid file descriptor?
As described here: https://psp2sdk.github.io/fcntl_8h.html#aa40c35536dfada200f9963b51ebc0b0b A non-negative integer is a valid fd, anything else an error~~
Because that 0 fd used on sceIoLseekAsync seems to be the value returned into the result address arg of sceIoWaitAsyncCB right after sceIoOpenAsync of file disc0:/PSP_GAME/USRDIR/SPIDERM/TALLY/LOBBY.STR (sceIoOpenAsync is returning 4 which lead to sceIoWaitAsyncCB)
This is the procedure that return v0 that will be written to the variable/memory used as fd for sceIoLseekAsync
Apparently during this sceIoLseekAsync all 64 elements in fds array are 0
During sceIoWaitAsyncCB have a valid f and f->pendingAsyncResult is true, at this stage which event should i trace? is it __IoAsyncNotify?
within __IoAsyncNotify (only triggered once) it's leading to: // Someone woke up, so it's no longer got one.
where f->asyncResult is 0 and f->closePending is true
also f->fullpath is "disc0:/PSP_GAME/USRDIR/SPIDERM/TALLY/LOBBY.STR"
...
u32 address = __KernelGetWaitValue(threadID, error);
if (HLEKernel::VerifyWait(threadID, WAITTYPE_ASYNCIO, f->GetUID())) {
HLEKernel::ResumeFromWait(threadID, WAITTYPE_ASYNCIO, f->GetUID(), 0);
// Someone woke up, so it's no longer got one.
f->hasAsyncResult = false;
if (Memory::IsValidAddress(address)) {
Memory::Write_U64((u64) f->asyncResult, address);
}
// If this was a sceIoCloseAsync, we should close it at this point.
if (f->closePending) {
__IoFreeFd(fd, error);
}
}
...So the flow is (based on the occurrence of breakpoints on VS2019):
user_main thread (sceIoOpenAsync("CARRIER.PSP",...)) -> SceIoAsync thread (IoAsyncFinish) -> user_main thread (sceIoPollAsync(4,...)) x 3 -> SceIoAsync thread (__IoAsyncNotify) -> user_main thread (sceIoPollAsync(4,...)) ->
FMOD thread (sceIoOpenAsync("LOBBY.STR",...)) -> FMOD Thread (sceIoWaitAsyncCB(4,...)) -> SceIoAsync thread (IoAsyncFinish) -> SceIoAsync thread (__IoAsyncNotify) -> user_main thread (sceIoPollAsync(4,...)) -> user_main thread (sceIoCloseAsync(4)) -> SceIoAsync thread (__IoAsyncNotify)
anr2me
commented
3 years ago This is the sceIo log from JPCSP
Between the sceIoOpenAsync of file CARRIER.PSP (which is not found) on user_main thread to the sceIoLseekAsync of file LOBBY.STR of FMOD thread, there is no sceIoClose or sceIoCloseAsync
PS: JPCSP is too slow (about 1-2 FPS) so i ended closing it without knowing whether it's also stuck or not when loading savedata because it's taking too long on black screen.
unknownbrackets
commented
3 years ago Hmm, I'm not really wanting to compare the timing to JPCSP (which at least in the past has seemed wildly wrong) here, especially if we don't even know if it works there.
The 0 result is different from before. Here's what's happening now:
THREAD1 4=sceIoOpenAsync(disc0:/PSP_GAME/USRDIR/SPIDERM/TALLY/LOBBY.STR, 1, 0)
THREAD1 0=sceIoWaitAsyncCB(4, 09fa6a58[08b56094000100a8]): waiting
THREAD1 *sleep* (wait async result)
fds[4]->asyncResult = fd; // open result
THREAD2 0=sceUmdWaitDriveStat(stat=00000020)
THREAD2 0=sceIoCloseAsync(4)
THREAD2 0=sceKernelDelayThreadCB(00000064)
THREAD2 *sleep* (delay thread)
fds[4]->asyncResult = 0; // close result
THREAD1 sceIoGetstat(disc0:/PSP_GAME/USRDIR/SPIDERM/TALLY/LOBBY.STR, 09fa6a88)
THREAD1 *sleep* (io blocking)
THREAD2 80020323=sceIoPollAsync(4, 09ffe5d8[0000000000000000])
THREAD2 0=sceKernelDelayThreadCB(00000064)
THREAD2 *sleep* (delay thread)
THREAD1 80020323=sceIoLseekAsync(0, 00000000000f6000, 0):
NOTE:
THREAD1 priority = 0x10
THREAD2 priority = 0x20So a few things to test come to mind:
Especially the last one seems likely and might fix the case of a 0/4, but wouldn't get rid of the close/open issue. Of course, it could also be incorrect and not how it should behave, since you won't always have someone waiting after all... I can try to test these later.
-[Unknown]
unknownbrackets
commented
3 years ago I think the other thread wakes because the open takes time. So that makes sense. And the last item is a moot point given the first.
-[Unknown]
unknownbrackets
commented
3 years ago Did that help? It should be in the next build after this comment.
-[Unknown]
anr2me
commented
3 years ago It's working properly now :) nice works
sum2012
commented
3 years ago @ANR2ME jpcsp emulator debug for io-only
In LogSettings.xml add
graphical glitches, black screen when loading level and loading the game please fix. sorry if this is a duplicate but I can not see all the issues