v143 save load times

I was just loading a mid-late game (turn 240 or so) standard size game and as noted in another thread, I believe it ended up taking around 5+ minutes to load. It definitely has never been instant but I'd say even later in the game subjectively speaking it was probably only 2-3 minutes.

Is it possible to print out the current system time to the log file with LUA? If so, we could implement crude profiling at key steps in the load save logic and see if there's something obvious that could be optimized to help load times.

The lua "os" operating system library is disabled for mods in Civ, probably for security reasons. It's the library containing time and date functions, file access, the capability to start programs, and so on. The time/date functions are innocent but the others could be used to make malware. There's usually a choice between loading things when the game starts, or loading it during an active game. I put most of the work up-front since we can go away from keyboard while things load. It keeps lag as low as possible while we're playing.

All that said, there's some tools in the tuner which might be useful for this sort of task. I think there's something which shows the time it takes for threads to run - could use that to track down the most critical points. I do plan on making a pass through the code sometime in the upcoming weeks to improve efficiency where possible.

Thalassicus said:

All that said, there's some tools in the tuner which might be useful for this sort of task. I think there's something which shows the time it takes for threads to run - could use that to track down the most critical points. I do plan on making a pass through the code sometime in the upcoming weeks to improve efficiency where possible.

Click to expand...

That totally makes sense about disabling all the OS-local features for safety purposes.

If there's an easy way I can use the tuner to help get timing numbers for save loading I'd be happy to help.

Alternately is there a way to trick the game into printing the time somewhere, say by loading a dummy resource or game database update query?

I'm not sure; I haven't done much research in this area.

You can use os.clock(), we have access to it.

Yes I noticed that my loading times have doubled or tripled in the latest version.

I actually shut off one of my games because I thought it had crashed. Then I read this post gave it a little while longer and it popped up.

Seems that the later tha game goes the longer the save and load times. I have to play on smaller than Standard maps due to late game crashes I have been associating with poor computer performance.

Gedemon said:

You can use os.clock(), we have access to it.

Click to expand...

I could have sworn print(tostring(os)) returned "nil"... I must have done something wrong. I tried to use os.date for an April 1st joke.

In v146.3 I added time information to all the places I could find where the mod loads data at the start of the game.

1. Enable logging.
2. After loading the save with a long load time (such as 1 or more minutes), attach a zip file containing your lua.log to a post in this thread. It will contain information like below:

I've attached the files lua.go and system_init.log. I've used v146.5 of VEM.

The savegame has loaded in (last line of system_init.log):
[5234.457] DBG: SystemInit: LoadGameState_TOTAL(): 243357 Milliseconds (about 4 minutes!)

It's a total of 7.4 seconds to load all the vem data:

[4989.863] LoadScreen: WARN Turn 619 0.008 seconds loading TurnAcquired
[4989.863] LoadScreen: WARN Turn 619 0.005 seconds loading PlotCostExtra
[4989.894] LoadScreen: WARN Turn 619 0.018 seconds loading UnitXP
[4990.019] LoadScreen: WARN Turn 619 0.002 seconds loading Yields
[4994.496] LoadScreen: WARN Turn 619 4.479 seconds loading PlotYields
[5011.516] CiVUP_Events: WARN Turn 619 2.66 seconds loading HasTerrainCulture
[5011.734] CiVUP_Events: WARN Turn 619 0.227 seconds loading FreeFlavorBuilding
[5011.797] TriggerPopup: WARN Turn 619 0.037 seconds loading Triggers
[5011.859] WWGD_Events: WARN Turn 619 0.006 seconds loading DidWarVsHuman

When I dropped the system_init file you provided into a spreadsheet:



The total load time is literally greater than the sum of its parts. Something strange is going on here... 84% of the load time is coming from an unknown source. I'll ask around in the main modding forum to see if anyone knows where the balance might be coming from. Could you also upload your stopwatch.log file?

I don't know how os.clock() works in LUA but if it's measuring CPU time and not wall clock time then it's almost certainly blocked on I/O (reading/writing disk and memory).

Good point. Even so... the vem loading procedure visibly takes just a fraction of a second to execute and print output to the console.

Well, I've beaten my own load time record: 28 minutes! (It seems Civ 5 is hunged up but it's processing...).

I've attached the logs (v147.2).

The savegame occupies 2,66 MB. I think is very long compared to vanilla savegames. Maybe it's the problem. If someone wants to test it, I can make some space in my account and upload it.

So it seems to be getting a bit longer as I go along. Last night it was just about 10 minutes. Played about 100 turns, today it was right around 13 minutes.

I have never seen load times like this.

Ram
Siam
Turn 375
Continents +
Standard
Prince
Epic
12:15 PM - 12:28 PM

That's very odd because my load time for a standard-size map at turn 100 is about 30 seconds. In pep's log, 98% of the load time is coming from an unreported source. I've started a thread on the main modding forum asking what that might be.

Out of curiosity, did you delete the cache before loading these unusually-long loadtime saves?

Thal....

I am experiencing the same issues with load times as well. Normal load times for me were measured in seconds under a minute (certainly never waited longer than that before even for large maps). At first I did a ton of stuff thinking it was something game related or vid card related because of the event description I got after a long wait and CAD out....


Problem Event Name: AppHangB1
Application Name: CivilizationV_DX11.exe
Application Version: 1.0.1.511
Application Timestamp: 4ee9bec2
Hang Signature: 9c34
Hang Type: 2048
OS Version: 6.1.7601.2.1.0.256.48
Locale ID: 1033
Additional Hang Signature 1: 9c3499b1fae4cfbf58b8e035e962c4de
Additional Hang Signature 2: a73a
Additional Hang Signature 3: a73aa461a471e477dd53341709cf28e3
Additional Hang Signature 4: 9c34
Additional Hang Signature 5: 9c3499b1fae4cfbf58b8e035e962c4de
Additional Hang Signature 6: a73a
Additional Hang Signature 7: a73aa461a471e477dd53341709cf28e3


Then I just decided to wait the events out in the loading screen and do some testing myself to see how they were related to size. I now am seeing some sort of correlation between file size for the save and load times (which are very short for a starting file at 15 or so seconds, and for a 1.6 mg file are in the 3-4 minute range).

I am not as computer/tech savy as many here are, but if there is something I can do to log stuff just let me know and I will try to help.

BTW...fantastic job with the work you do. Your mod is a true must have as far as I am concerned.

Per: http://forums.civfanatics.com/showthread.php?p=11422921#post11422921

Did a little testing…
1] Enabled logging: \Documents\My Games\Sid Meier's Civilization 5\config.ini
···; Enable the logging system
···LoggingEnabled = 1
2] Loaded Steam/CivV after verifying game cache, clearing CivV cache, starting & stopping Steam/CivV, defragmenting cache folder, restart computer
3] Loaded earlier save from Eliz… 198 turns (1,228,775 bytes). About 3 minutes.
4] Zipped …\Logs and \Logs\Lua.log in CivV-Liz-198 Folder.
5] Loaded Steam/CivV after verifying game cache, clearing CivV cache, starting & stopping Steam/CivV, defragmenting cache folder, restart computer
6] Loaded save from Eliz… 280 turns (1,582,561 bytes). About 15 minutes.
7] @6min took scree shot of Mon1 with Procexp & TaskManager
8] Zipped …\Logs and \Logs\Lua.log in CivV-Liz-280 Folder.

SysInfo: Windows Vista (TM) Ultimate, 64-bit (Service Pack 2); DirectX version: 11.0; GeForce GTX 560 Ti 1024 MB GDDR5; EVGA__132-YW-E178-FTW; Processor: Intel(R) Core(TM)2 Quad CPU @ 2.66GHz (4 CPUs), ~2.7GHz; Memory: 8190MB DDR2 1066MHz RAM System Disk: SATA 150 GB 10Krpm; Steam Program Disk SATA 320 GB 7.2Krpm

Attached: 198 turns 198-Lua.zip, 280 turns 280-Lua.zip

Both zipped Logs folders & screen shot available if you like

keepitsimpleeng said:

6] Loaded save from Eliz… 280 turns (1,582,561 bytes). About 15 minutes.

Click to expand...

If you 1) load the save 2) exit to the main menu 3) load the save again... does the second load take the same amount of time as the first?

Thalassicus said:

If you 1) load the save 2) exit to the main menu 3) load the save again... does the second load take the same amount of time as the first?

Click to expand...

The times were identical: 12min18sec

It's not a cache issue then, and it's not the vem loading procedure. The games I play load in under 1 minute. I asked in the main modding forum what the unknown source of the time might be. I got no responses, so I don't have any leads at this point.