libretro / LRPS2

GNU General Public License v2.0
165 stars 48 forks source link

Function _ApplySettings in gui-libretro/AppCoreThread.cpp called multiple times #36

Open SeventySixx opened 3 years ago

SeventySixx commented 3 years ago

I found that the function _ApplySettings in gui-libretro/AppCoreThread.cpp is called multiple times at the content loading. I did some tests and this function is called 2 times "normally" if widescreen patch option is disabled, otherwise is called 4 time.

This could be the cause of long boot time of the content when widescreen patches are enabled, because the zip file with the patches is scanned 4 times.

I don't think this is the normal behaviour of pcsx2 code, could be a problem due to the porting. I tested the standalone pcsx2 and the boot with widescreen patches enabled is immediate, and from its log it seems that the archive is scanned only one time.

Not sure, but could be that something (maybe the core thread?) is run twice or more...

covey-j commented 3 years ago

That is strange. It's worth pointing out that there's an AppCoreThread.cpp in both gui and gui-libretro, whereas in the standalone there's just the one in gui. Have you verified that it's the _ApplySettings in gui-libretro/AppCoreThread.cpp getting called each time? I'm curious whether it's possible that both https://github.com/libretro/pcsx2/blob/6435b95c76f2ff1587e4b2b7c01c4b755e0c7697/pcsx2/gui-libretro/AppCoreThread.cpp#L372 and https://github.com/libretro/pcsx2/blob/6435b95c76f2ff1587e4b2b7c01c4b755e0c7697/pcsx2/gui/AppCoreThread.cpp#L359 are getting called.

Also, do you know how many times this line https://github.com/libretro/pcsx2/blob/6435b95c76f2ff1587e4b2b7c01c4b755e0c7697/pcsx2/gui-libretro/AppCoreThread.cpp#L507 gets hit with widescreen patches enabled?

EDIT: Did some debugging and found that it is the _ApplySettings in gui-libretro/AppCoreThread.cpp getting called 4 times. This line https://github.com/libretro/pcsx2/blob/6435b95c76f2ff1587e4b2b7c01c4b755e0c7697/pcsx2/gui-libretro/AppCoreThread.cpp#L507 is actually getting hit 4 times. If I time, I'll see if I can figure out why.

SeventySixx commented 3 years ago

Yes, this is rather strange. It will not surprise me if some of the problems about core stability are due to this issue.

covey-j commented 3 years ago

Oddly enough, this appears to be the same behavior as in the standalone. In my debugging, I found that both called _ApplySettings four times when widescreen patches were enabled. The TODO in this code block explains part of the issue:

https://github.com/libretro/pcsx2/blob/6435b95c76f2ff1587e4b2b7c01c4b755e0c7697/pcsx2/gui-libretro/AppCoreThread.cpp#L549-L565

SeventySixx commented 3 years ago

So it's seems a workaround needed by the recompiler for apply the patch at the right time.... thanks for taking a look on it! So the problem is why on the core it takes a lot to boot a game if ws patch is enabled, while in the standalone is quite immediate.. or maybe this problem happens just to me?

SeventySixx commented 3 years ago

The strange thing is also that the in the log of the standalone, I seen only one time this log here below, so it seems that the program hits only one time this part of code. But maybe I seen wrong, I will check again.

(pcsx2/pcsx2/gui-libretro/AppCoreThread.cpp line 508 - sorry no idea how to create code blocks ref as you did :) ) PatchesCon->WriteLn(Color_Green, "(Wide Screen Cheats DB) Patches Loaded: %d", numberDbfCheatsLoaded);
gameWsHacks.Printf(L" [%d widescreen hacks]", numberDbfCheatsLoaded);

bslenul commented 3 years ago

I wanted to open an issue about contradicting notifications I'm having when using ws patches, but it looks like this could be related?

image

I have the .pnach files in the "cheats_ws" folder directly, I'm not using a .zip if that matters. Same thing happens with Castlevania - Lament of Innocence and the 2 Maximo games, haven't tried any other games yet. To be clear the patches work fine, it's just the notifications being weird, like "Sorry no patch found! But we found and applied a patch!" :p

And thanks to you 2 for your recent PRs, the core is getting better and better every day! ❤️

edit:

(pcsx2/pcsx2/gui-libretro/AppCoreThread.cpp line 508 - sorry no idea how to create code blocks ref as you did :) )

Click the number of the 1st line, hold Shift key, click the number of the last line, then click the 3 dots, click "Copy permalink" and paste the link in the issue:

image

https://github.com/libretro/pcsx2/blob/7a79821cff48352f811ffc57811f80fd43bae299/pcsx2/gui-libretro/AppCoreThread.cpp#L508-L509

SeventySixx commented 3 years ago

Thanks for the feedback, and thanks for the tips about permalink ;)

Yes this is contradicting, could be related to this issue. I'm going to look about it

covey-j commented 3 years ago

So the problem is why on the core it takes a lot to boot a game if ws patch is enabled, while in the standalone is quite immediate.. or maybe this problem happens just to me?

It's not just you. I've been able to replicate this issue, though it's a bit inconsistent. I've yet to find necessary and sufficient conditions for this problem to happen.

I'll start with the expected behavior. With widescreen patches enabled in the standalone, it's normal for it to hang for a few seconds after the bios sequence (i.e. after the PlayStation logo disappears in a full boot). My debugging suggested that the repeated scanning of the zip file doesn't actually account for much of that time in the standalone. Most of the additional boot time is the recompiler doing its work.

It's been tricky so far to diagnose the underlying issue since its presence seems to depend on the relative timing of the various threads. On my machine, the issue appeared when running the program normally, but when debugging, it depended on how the code was stepped through. One interesting find was that when the issue did appear, the program hung for several seconds the second time this line was run: https://github.com/libretro/pcsx2/blob/6435b95c76f2ff1587e4b2b7c01c4b755e0c7697/pcsx2/gui-libretro/AppCoreThread.cpp#L507

Both the first and second calls to LoadPatchesFromZip scan through every entry in the zip file since gameCRC is L"00000000" at that point. However, the iterations of this loop in the second call took more than an order of magnitude longer than the first https://github.com/libretro/pcsx2/blob/7a79821cff48352f811ffc57811f80fd43bae299/pcsx2/Patch.cpp#L224-L236

This, together with the dependence on the relative timings of the threads, suggests to me we might be dealing with a race condition.

SeventySixx commented 3 years ago

thanks for your deep analysis, so this issue is not an easy one to solve....

SeventySixx commented 3 years ago

@bslenul I just fixed in the new PR the message, the problem was in effect related to this issue, the quick solution was to remove the "negative" message. Now you receive a message only if a pacth is found

SeventySixx commented 3 years ago

@crumpmasterjc on my system I had the patches only in the archive, and it did take a lot of time (for Maximo almost a minute from the run command and the screen with language selection). I just tried to extract the zip in the ws folder, and to be sure I also renamed the zip file, and now wow, it's unbelively quick to load.

covey-j commented 3 years ago

It probably won't be easy to fix the race condition, but it seems like it'd be straightforward to work around.

As I mentioned, gameCRC is typically L"00000000" the first two times LoadPatchesFromZip is called. This doesn't match any CRC in the zip, so it scans through the entire archive unnecessarily. This could be optimized by skipping the call to LoadPatchesFromZip when gameCRC == L"00000000". That way, even if scanning through the zip is slow due to multiple threads competing over the zip, the scanning only happens twice and even when it does scan, we avoid worst-case runtime since the CRC would typically match something in the zip.

bslenul commented 3 years ago

Thank you SeventySixx for the quick fix! Good luck with the rest!

SeventySixx commented 3 years ago

@crumpmasterjc Great, good find! This optimization could lowering a lot the time needed to load patches directly from the archive 👍

SeventySixx commented 3 years ago

Thank you SeventySixx for the quick fix! Good luck with the rest!

You're welcome, and thanks to you!

covey-j commented 3 years ago

Hmm, that optimization cuts down the boot time, but not by as much as I was hoping. I did find a behavioral difference between the libretro core and the standalone, though.

In the standalone, the first and fourth calls to _ApplySettings occur in the main thread, while the second and third occur in the EE Core thread. Freezing the main thread during the second and third calls doesn't appear to interfere with the execution.

In the libretro core, the first call to _ApplySettings occurs in the main thread, while subsequent calls occur in the EE Core thread. Freezing the main thread at the beginning of the second call to _ApplySettings causes a hang at this line: https://github.com/libretro/pcsx2/blob/7a79821cff48352f811ffc57811f80fd43bae299/pcsx2/Patch.cpp#L223

So the main thread and the EE Core thread are competing over the zip file, as I suspected might be the case.

EDIT: OK, so it seems like the problem is that the EE Core thread executes this line for every entry in the zip file https://github.com/libretro/pcsx2/blob/7a79821cff48352f811ffc57811f80fd43bae299/3rdparty/wxwidgets3.0-libretro/src/common/zipstrm.cpp#L1038 which shares a resource somewhere with something in this function https://github.com/libretro/pcsx2/blob/7a79821cff48352f811ffc57811f80fd43bae299/pcsx2/MTGS.cpp#L281 which gets called in the main thread every video frame. Almost all the long boot time is due to synchronization between the main thread and EE Core thread.

EDIT 2: fixed typos

SeventySixx commented 3 years ago

So, not an easy thing to fix, I suppose.. at the moment I unzipped the patches in the folder and i removed the zip archive, with this workaround it works very well. Anyway, thanks for your time!

covey-j commented 3 years ago

Yes, that's a good workaround for now!

It probably won't be easy to fix this, but it's important nonetheless as this probably isn't the only thing affected by the underlying issue. It would take far more debugging to confirm this either way, but I have a slight suspicion this issue might share a common underlying cause with one (or both) of these issues:

  • There’s a bug that can happen right now upon closing content or exiting RetroArch with the PCSX2 core on Windows – the RetroArch process might not completely cleanly shut itself off and you might still be able to see a 0% CPU process remaining in the Task Manager. We have not been able to figure out how to fix that yet as the PCSX2 codebase is a definite case of ‘here be dragons’, but for now when this happens, you can just bring up the Task Manager and close it manually. It shouldn’t have a real detriment on performance but it is of course far from ideal and hopefully something we can fix soon with the help of some contributors. We have found this happens the most with the Direct3D 11 renderers.
  • Switching resolution at runtime right now can be a bit unstable, so does switching fullscreen resolution. We might just make resolution switching require a restart since this tends to be too unstable for now.

(Quoted from https://www.libretro.com/index.php/libretro-cores-updates-pcsx2-alpha-release-for-windows-and-more/)

SeventySixx commented 3 years ago

Yeah, big chances that the problems are related. If can be fixed, it will be a good step forward for this core :-)