Cards loading slower with V2.5 on Wine/Proton

[leucome]

Update: Confirmed to be affecting Wine/Proton more than Windows and it happens with illusion API 1.35 and up.

I am posting this just in case somebody already know the culprit. I guess it can also be a new feature that take more time or something.

What I noticed is that loading cards in the maker is 3 to 4 time slower than before. The cards loading time is still near instantaneous in game. Before card loading time was about 2 to 3 seconds now it is 7 to 12 sec. The game setting menu also take a while to open.

I did try to find what plugins is causing this by enabling disabling batch of plugins but it is still inconclusive and an ongoing process. It looks like there is not a single culprit. Maybe every single plug-ins is a bit slower and the delay is adding up or something. I know that disabling the HS2API.dll make it fast but it also disable almost everything.

I use Linux with Wine-Ge 8. So it can be a wine specific issue. ( edit: confirmed to be wine/proton issue) I already tried multiple version of Wine/Linux kernel and Mesa driver and also compared between Fsync/Esync and no sync. These sometime cause unexpected slow down.

Other than that My system is a Ryzen 5 with Nvme drive and a 7900xt.

I'll probably try to copy the game to the Ntfs drive to give it a try on Windows. If it is wine specific then we can probably let the wine dev find what is going on.

Edit: Yes card loading time is back to the usual 2/3 sec when launched on Windows. So this seem to be specific to using Wine. I took a look to see if there is a difference between Mono and .net with a PFX with no .net installed. It looks the same.

[ManlyMarco]

Probably a wine issue with the file watcher. Not sure which plugins use them, BrowserFolders uses one but there may be more.

[leucome]

I tried to stark back with an older backup of bepinex then apply update incrementally until it slow down. It was fine until the API v1.35. Looks like I was still using the API 1.34 before I got HF patch 2.5.

So at least using API 1.34 is a temporary solution if somebody else want the cards and the other affected things to load at normal speed on Wine/Proton.

[ManlyMarco]

By itself the API update shouldn't have any effect on your issue, it's much more likely that downgrading the API causes some other plugin to crash or not load, like for example BrowserFolders. https://github.com/IllusionMods/IllusionModdingAPI/compare/v1.34...v1.35

[leucome]

Yes maybe something is disabled, I wonder if it could be only a feature instead of a whole plugins. I did not see any obvious error in the log about a plugin failing to start. Still there is a couple of message that I dont know the meaning. I also carefully tested BrowserFolder. This one had similar issue with wine before so I test it first.

When I found about API 1.34 vs 1.35/1.36, I did not downgrade to 1.35 I upgraded to 1.35. I started back with my bepinex backup from what looks like to be HF 2.2 or 2.3 with ABMX 5 and API 1.34 . The API was among the first plugins I upgraded. So the other plugins were still from the older HF patch . I redid it the test from scratch to be sure. I added 1.35 first on the old the bepinex folder backup and it slowed down right away. I saved the logs to this time.

HF2.5 with Browser v2.6.2+API 1.34. also run normally and I do not see errors about a plugin failing to load.

There the logs maybe you can see something I missed. Also I already tested with no zipmod. So the zipmod error that come from AI and HS2 sharing the same mod folder have no impact on this.

The old bepinex folder with old plugins and api 1.34, normal card loading. HS2-With-old-Pluins.txt

Old plugins +1.35, slow card loading, The only change is upgrading to 1.35. HS2-With-old-Pluins+API-1.35.txt

Then this one is the HF patch 2.5 downgraded to API 1.34 and BF v2.6.2, This one also load card normally. HS2log.txt

[ManlyMarco]

There's nothing materially different in the log. Using a profiler might be your best bet at catching the difference. https://github.com/BepInEx/BepInEx.Debug#simple-mono-profiler

[leucome]

So I got two profile one with 1.36 and one with 1.34. I started the profiling just before loading a card to keep the files smaller. characustom and AIchara and things related to system.IO stand out. They take significantly more time to do their task.

Edit: Though thanks to that I figured out that this slowdown seem to happen only on my main NVME drive formatted in f2fs. The IO slowdown made me think to test that. And I already had a copy on NTFS to try and it load at normal speed. Maybe even a bit faster.

I currently copying the game to other Files system to confirm what one are affected.

1.36.MonoProfilerOutput_2023-12-12_16-12-46.csv

1.34.MonoProfilerOutput_2023-12-12_16-39-03.csv

[ManlyMarco]

Try this build bin.zip

[leucome]

Try this build bin.zip

I'll try right away. Also I updated my previous comment I noticed something related the IO.

[leucome]

Yes the new build load cards at normal speed on my main drive.

I also confirmed that the game with 1.36 load fine on BTRFS and NTFS. Edit: nope false positive for Btrfs I just forgot to swap the API files. Though if it was affecting only F2FS BTRFS it can explain why nobody else reported yet. Not many people use that. I dont have ext4 to try.

What did you change ?

[ManlyMarco]

Well, that makes no sense, all the removed code does is store the card path into a dictionary which should be instant.

Try this I guess bin.zip

[leucome]

Hum... I wonder if I could use a character that is illegal in windows. So wine would have to waste time converting so many path because I have a lot of cards. Then on my NTFS drive I only have Windows compatible character because it is literally NTFS.

[leucome]

The new binary is slow again.

Edit: I tried simplifying the path and reducing the number of cards then moved it to the wine path C:\HoneySelect_2DX instead of Z:_Wine-Prefix\HoneySelect_2_DX

No change. And also why it is working on the NTFS drive. If it is just about files path, then Like you said, that makes no sense...

[ManlyMarco]

What about this one? bin.zip

[leucome]

Yes this one is fast.

[ManlyMarco]

How about these two? bin1.zip bin2.zip

[leucome]

Yes these two also work.

[ManlyMarco]

That makes even less sense. Can you give this a try and send the resulting log? Just the last print with ms timings is fine. bin.zip

[leucome]

That makes even less sense. Can you give this a try and send the resulting log? Just the last print with ms timings is fine. bin.zip

Log with the profiler ?

[ManlyMarco]

No just normal game log or bepinex console output.

[leucome]

4ms 0ms 1ms

But I will include the whole log because it looks like every time a character is loaded it take longer almost 1ms added each time. HS2-Log-multiple-loading.txt

I have a question though does your function try to store every card path or just the one loaded. Because I managed to make a character folder with 220 cards that dont cause the slowdown. But I had already tried that with even less card and it was also slow. So maybe there are specific cards that cause the slow down. Then your function just happen to trigger it or something.

[leucome]

That said the entire card folder in the NTFS drive then symlinked to the game on the BTRFS drive also load card normally. So the issue with the cards it is resolved by being on a NTFS drive then it come back if a copy the cards back to BTRFS. I dont really understand how and why.

I dont know if that help on make thing even more confusing. Though

[ManlyMarco]

Paths are stored in a dictionary, and from the log that takes 3ms in total. The only thing that changed between working and not working builds is basically a few cycles of cpu delay. It sounds like some serious jank in the filesystem, like some weird race condition or a deadlock.

[leucome]

Yeah there is definitively something weird in the files system. And thanks now there are some API build I can use that load card at normal speed.

[ManlyMarco]

The issue is likely to crop up again in the future until you find the root cause, but at least it works for now. Some plugins in the future might not work properly with the version of kkapi I sent you once they start using this new API.

[leucome]

I missed something important in my test. This also happen on Windows the difference is that It require more cards in the folder to make it obvious. Something like 1000 cards in the root female folder should be enough to see the effects.

The behaviors are virtually the same, the cards load slower and it also get worse the longer we play. Then it get fixed by going back to API 1.34.

[ManlyMarco]

Can you check if this plugin fixes the issue?

[leucome]

Yes, really effective.

[ManlyMarco]

Nice, it will be included in the next patch update.