CLOUD: Cloud syncing wastes FPS due to excessive save game scanning/checking in Grim Fandango

[raziel-]

ScummVM 2.8.0git (May 15 2023 22:17:09)
Using SDL backend with SDL 2.26.5
Features compiled in: Vorbis FLAC MP3 RGB zLib MPEG2 MikMod Theora VPX AAC A/52 FreeType2 FriBiDi JPEG PNG GIF cloud (servers, local) ENet SDL2 TinyGL OpenGL (with shaders)

I had, for a few months now, a problem with recurring FPS dropouts (from 60 down to 2 in worst case) in the intro of Grim Fandango (full game, classic, non-enhanced, no mods) and *only* with this game.
I thought it may be because of something in my OpenGL implementation at first, then the game/engine on it's own maybe, but i couldn't point a finger to anything obvious (switching the different renderes didn' t show anything either).

Today i let a file snooper run beside the intro and it caught a massive amount of file read/locks on the save states i have (and i have *a lot* - 930 files with approx. 63 MB).

07442 : ScummVM         : o.k. = ChangeFilePosition(0x18B3A2EA [Games:ScummVM/LucasArts/Grim Fandango/DATA000.LAB],12743680,OFFSET_BEGINNING) [21uS]
07443 : ScummVM         : o.k. = ChangeFilePosition(0x18B3A2EA [Games:ScummVM/LucasArts/Grim Fandango/DATA000.LAB],12747248,OFFSET_BEGINNING) [475uS]
07444 : ScummVM         : DIR  = ParentOfFH(0x18B3A2EA) "Games:ScummVM/LucasArts/Grim Fandango/DATA000.LAB" [57uS]
07445 : ScummVM         : o.k. = ExamineObject([FH] "DATA000.LAB") [47uS]
07446 : ScummVM         : o.k. = ExamineObject([SN] "saves") [242uS]
07447 : ScummVM         : o.k. = Lock("saves/",SHARED) [35uS]
07448 : ScummVM         : o.k. = Lock("saves/",SHARED) [197uS]
07449 : ScummVM         : o.k. = Lock("Tools:Games/ScummVM/saves/grimdialog.htm",SHARED) [73uS]
07450 : ScummVM         : o.k. = Open("Tools:Games/ScummVM/saves/grimdialog.htm",OLD) = [0x18B3A2EA] [181uS]
07451 : ScummVM         : o.k. = ExamineObject([FH] "grimdialog.htm") [44uS]
07452 : ScummVM         : FAIL = IsInteractive("Tools:Games/ScummVM/saves/grimdialog.htm")
07453 : ScummVM         : o.k. = IsFileSystem("Tools:") [39uS]
07454 : ScummVM         : o.k. = ExamineObject([FH] "grimdialog.htm") [38uS]
07455 : ScummVM         : o.k. = ExamineObject([FH] "grimdialog.htm") [157uS]
07456 : ScummVM         : o.k. = ChangeFilePosition(0x18B3A2EA [Tools:Games/ScummVM/saves/grimdialog.htm],2,OFFSET_BEGINNING) [45uS]
07457 : ScummVM         : o.k. = ChangeFilePosition(0x18B3A2EA [Tools:Games/ScummVM/saves/grimdialog.htm],0,OFFSET_BEGINNING) [26uS]
07458 : ScummVM         : o.k. = ExamineObject([FH] "grimdialog.htm") [147uS]
07459 : ScummVM         : DIR  = ParentOfFH(0x18B3A2EA) "Tools:Games/ScummVM/saves/grimdialog.htm" [49uS]
07460 : ScummVM         : o.k. = ExamineObject([FH] "grimdialog.htm") [182uS]
07461 : ScummVM         : o.k. = ExamineObject([SN] "saves") [113uS]
07462 : ScummVM         : o.k. = Lock("saves/",SHARED) [28uS]
07463 : ScummVM         : o.k. = Lock("saves/",SHARED) [27uS]
07464 : ScummVM         : o.k. = ExamineObject([SN] "saves") [272uS]
07465 : ScummVM         : o.k. = Lock("saves/",SHARED) [33uS]
07466 : ScummVM         : o.k. = Lock("saves/",SHARED) [51uS]
07467 : AmiDock         : o.k. = [exec] OpenDevice("timer.device",0,0x629237F0,0x00000000) = 0 [10uS]
07468 : ScummVM         : o.k. = ExamineObject([SN] "saves") [363uS]
07469 : ScummVM         : o.k. = Lock("saves/",SHARED) [126uS]
07470 : ScummVM         : o.k. = ObtainDirContext(ctx=0x5211F658  dflags=0x10094) = [0x5211F658] [53uS]
07471 : ScummVM         : o.k. = Lock("richardandalice.999",SHARED) [72uS]
07472 : AmiDock         : o.k. = [exec] OpenDevice("timer.device",0,0x629235B0,0x00000000) = 0 [9uS]
07473 : ScummVM         : o.k. = ExamineObject([LK] "richardandalice.999") [49uS]
07474 : ScummVM         : o.k. = Lock("grimlog00.htm",SHARED) [163uS]
07475 : AmiDock         : o.k. = [exec] OpenDevice("timer.device",0,0x629237F0,0x00000000) = 0 [8uS]
07476 : ScummVM         : o.k. = ExamineObject([LK] "grimlog00.htm") [28uS]
07477 : ScummVM         : o.k. = Lock("grim00.gsv",SHARED) [29uS]
07478 : ScummVM         : o.k. = ExamineObject([LK] "grim00.gsv") [28uS]
07479 : ScummVM         : o.k. = Lock("mythguff-win.000",SHARED) [28uS]
07480 : ScummVM         : o.k. = ExamineObject([LK] "mythguff-win.000") [28uS]
07481 : ScummVM         : o.k. = Lock("kq1agdi.999",SHARED) [29uS]
07482 : ScummVM         : o.k. = ExamineObject([LK] "kq1agdi.999") [28uS]
07483 : ScummVM         : o.k. = Lock("kq1agdi.998",SHARED) [29uS]
07484 : ScummVM         : o.k. = ExamineObject([LK] "kq1agdi.998") [28uS]
07485 : ScummVM         : o.k. = Lock("steam-336130.dat",SHARED) [29uS]
07486 : ScummVM         : o.k. = ExamineObject([LK] "steam-336130.dat") [133uS]
07487 : ScummVM         : o.k. = Lock("shardlight.999",SHARED) [29uS]
07488 : ScummVM         : o.k. = ExamineObject([LK] "shardlight.999") [28uS]
07489 : ScummVM         : o.k. = Lock("hitchhikersguidetothegalaxyremake.000",SHARED) [30uS]
07490 : ScummVM         : o.k. = ExamineObject([LK] "hitchhikersguidetothegalaxyremake.000") [29uS]
07491 : ScummVM         : o.k. = Lock("asecondface.999",SHARED) [29uS]
07492 : ScummVM         : o.k. = ExamineObject([LK] "asecondface.999") [29uS]
07493 : ScummVM         : o.k. = Lock("asecondface.000",SHARED) [29uS]

As you can see after loading the game and the intro starts, ScummVM starts to scan my saves/ dir...but why?
And why does it do that over and over again?
And why does it not simply look for the save states of the game that was run, instead of scanning *all* of them?
And why in the intro, it' s not like i could load or save a game there, shouldn't it scan the saves/ dir on start of ScummVM or while in the launcher?

Next step was to rename the saves/ drawer and starting the game once more...no more FPS dropouts whatsoever.

My question would be, could someone who knows the engine, please check what's going on there and maybe reduce the scan for save states et al or at least to Grim Fandango saves?
That would save me lots of FPS.

@sev suggested to add a trap, but I'd need a step per step guide to use something like that.

Thank you

Grim Fandango (Windows/English)

AmigaOS4 - BigEndian - PPC
gcc (adtools build 11.3.0) 11.3.0

[raziel-]

Added ScummVM version info

Also you can download my set of save files here for testing:
​https://gofile.me/6YNda/t5PP67MuL

Any advice appreciated

Thank you

[wjp]

I wonder if this could be the cloud support code.

The intro script seems to periodically open and write to grimdialog.htm from lua. This calls DefaultSaveFileManager::openForSaving(), which calls DefaultSaveFileManager::loadTimestamps() when cloud support is enabled, which calls DefaultSaveFileManager::updateSavefilesList() to clear _saveFileCache, and then repopulates the full cache by calling listSavefiles()

I'm not at all familiar with the cloud sync logic, but this seems rather excessive for updating a single timestamp...

[raziel-]

@wjp

...and it would probably count as a second bug, as I have cloud support disabled (built-in, but unused)?

[wjp]

Cloud support only needs to be compiled into scummvm for this code to be triggered; you don't need to have syncing set up or be actually using it.

[raziel-]

Ah, ok
That would explain it.

Then I could try and build a binary without cloud support?
Can it be turned off in configure?

[wjp]

Yes, you can disable it by passing --disable-cloud to configure. Would be good to know if that indeed removes the slowdowns for you.

[raziel-]

I'll do that once I get back home and report here.

Thanks a lot for taking a look

[raziel-]

@wjp

Confirmed.

Once --disable-cloud removes cloud support completely, the FPS drops are gone aswell

[aquadran]

This is rather performance issue for scanning a lot of files in save game directory.
I guess maybe there is a way to improve this.

As it's not Grim engine specific. I'm changing component to "Cloud"

[sev-]

We need to check how cloud syncing is checking for newer files. E.g. does it read directory contents in one go and then caches it.

It also might be related to the specific implementation of this functionality by the Amiga backend.