Temporary Optimization Defeat

Following the release of v0.15.1 I've received a few reports that the game is proving to be very slow to load on some machines. Particularly strange are reports that starting the game from the generated build is painfully slow but starting it from the Ren'py launcher is silky smooth. I've noticed on my own machine that it can take a minute or so to launch the game or reinitialize it when testing, so I decided it was time to nail down this problem and solve it once and for all. If only it ended up being that easy.

The first step to solving any problem is to define what the problem is in the first place. Qualitatively Lab Rats 2 was taking too long to load, but "too long" is a subjective thing and I wanted hard data. After a few cycles starting and quitting the game on my own machine I had a baseline startup time of 1:17 from the moment I hit "Launch" to the main menu appearing. With that knowledge I set off looking for likely problems that would be causing the slowdown.

My first assumption was that the cause of the slowdown would be somewhere inside my own initialization code, looping over too many clothing items  or something of that nature. Renpy code that is run at initialization is all given a priority number and then run from lowest to highest. Instead of going through all of my code line by line I decided to narrow down the search by identifying which init phase was taking the longest. I added some extra init code sprinkled between init -5 to 5 (the priorities inside of which all my code is run) that would log when that phase was reached and ran it to see what would be reported. Strangely, my log showed all of the watched phase being completed in under a second. I widened the range I was watching, going all the way up to init 999 - the documented limit for what the init numbers should be. The result was the same, no measured delay in running the code.

This was strange. There was a ~90 second delay when starting the game but no measured delay in my own code. I enabled some Ren'py debug logging and confirmed that the "running init" section was taking up 87 of the 90 second delay. On a hunch I expanded the range of my own init logging outside of the range suggested and discovered that the expected run time took place on init phase 1100. None of my code touches that part of the game, so there must be some internal Ren'py code that is running then. Thus began the multi-day hunt to determine what, exactly, was triggering this behaviour in Ren'py and how could it be avoided.

I did some more testing and determined that it was something related to indexing or caching the game images. images/character_images currently contains upwards of 22,000 individual files, and when those files were temporarily moved there was no delay. I searched the documentation for any references to indexing or caching and experimented with many of the available config options but had no success.

I had the idea of storing all of the LR2 character images inside of an archive that Ren'py wouldn't know how to index. After some trial and error I got this working and succeeded in cutting down load times; Loading time was reduced to a blistering 5 seconds. Unfortunately the overhead required to retrieve the images from the archive introduced a two second lag before each draw statement. This would obviously be highly disruptive to gameplay, so that idea had to be abandoned.

I'm currently working on narrowing down the exact init phase that is taking up all of the startup time with the hope that it will reveal something of use, but I will have to cut my loses soon and turn my attention to other parts of the game. Hopefully giving my brain a rest will help me figure out what to do about this.