Improving game turm time

cde2006

Chieftain
Joined
Jan 7, 2008
Messages
25
After playing with the DLL profiler it seems I have found some huge time consuming function:

Code:
--------------------------------------------------
[19956.037] DBG: Total Frame MS: [B]2934.0[/B]  FPS: 000  Min:067 Max:000 Avg:000  SampleFilter:1.010000
 Time   :   Ave  :  Min% :  Max% : Num : Profile Name
-----------------------------------------------------
[COLOR="Red"] 2934.0 : 100.0 : 100.0 : 100.0 : 001 :    CvGame::doTurn()[/COLOR]
  030.0 : 001.0 : 000.9 : 002.2 : 218 :       CvPlot::updateSymbols
  002.0 : 000.1 : 000.0 : 000.2 : 218 :          CvPlot::updateSymbolDisplay
  376.0 : 012.8 : 012.8 : 036.0 : 214 :       CvPlot::updateFeatureSymbol
 1682.0 : [B]057.3[/B] : 056.9 : 057.6 : 9174 :       CvPlot::updatePlotGroupBonus
...

Meaning that 57.3% of the Frame time (whatever it is) is spend in 9174 calls to the updatePlotGroupBonus function in my huge map at about turn 407....

After investigation all calls to updatePlotGroupBonus comes from a single function: changeRevealAllBonuses(-1) at line 1021 of the CvTeam.cpp in the CvTeam::doTurn() function.

I have created a DLL 050 without the call to changeRevealAllBonuses in CvTeam::doTurn() and basically halved the "Total Frame MS' time:

After (same turn):

Code:
--------------------------------------------------
[20641.490] DBG: Total Frame MS: [B]1259.0[/B]  FPS: 001  Min:071 Max:000 Avg:001  SampleFilter:1.010000
 Time   :   Ave  :  Min% :  Max% : Num : Profile Name
-----------------------------------------------------
[COLOR="Red"] 1259.0 : 100.0 : 099.8 : 100.0 : 001 :    CvGame::doTurn()[/COLOR]
  025.0 : 002.0 : 001.6 : 002.0 : 218 :       CvPlot::updateSymbols
  365.0 : 029.0 : 029.0 : 036.9 : 214 :       CvPlot::updateFeatureSymbol
  016.0 : [B]001.3[/B] : 000.0 : 001.3 : 534 :          CvPlot::updatePlotGroupBonus
  010.0 : 000.8 : 000.8 : 000.9 : 255 :       CvPlayerAI::AI_baseBonusVal
  010.0 : 000.8 : 000.8 : 000.9 : 027 :          CvPlayerAI::AI_baseBonusVal::recalculate
  021.0 : 001.7 : 001.7 : 001.9 : 012 :       CvTeam::doTurn()

I am not sure what is the use of this function but it doesn't seems to impact my game so far.

Also the overall game turn time didn't change much for me but I can see more animation going on during AI turn in the optimized version. I will keep investigating to see if I can find some more interesting candidate.

If you want to activate the profiler, compile the DLL in Release mode (not Final Release) then activate the cheat mode and the logs in the ini .
In game open the debug menu by "ctrl+shift+alt d" then in Profile check "Show DLL Profile" and "Profile Logging" see attached capture.

The profile logs are in the dllprofile.log file in your logs folder.
 

Attachments

  • debugmenu.jpg
    debugmenu.jpg
    46.2 KB · Views: 247
  • CvGameCoreDLL.rar
    1.3 MB · Views: 202
  • AutoSave_Turn_0405.CivBeyondSwordSave
    723.7 KB · Views: 196

Vehem

Modmod Monkey
Joined
Nov 22, 2005
Messages
3,219
After playing with the DLL profiler it seems I have found some huge time consuming function:

...

If you want to activate the profiler, compile the DLL in Release mode (not Final Release) then activate the cheat mode and the logs in the ini .
In game open the debug menu by "ctrl+shift+alt d" then in Profile check "Show DLL Profile" and "Profile Logging" see attached capture.

The profile logs are in the dllprofile.log file in your logs folder.

Thanks for this - I'd seen the functions for the profiler, but never realized that it provided info is such a useful way. changeRevealAllBonuses sounds related to Dowsing possibly if it is being called every turn (think it normally just gets used for WorldBuilder) - though Xienwolf will know better about that.
 

BeefontheBone

Windbag of the sea
Joined
Nov 7, 2005
Messages
2,018
Sounds like Dowsing to me. Isn't that only really of use to human players anyway?
 

xienwolf

Deity
Joined
Oct 4, 2007
Messages
10,589
Location
Location! Location!
Yes, it is dowsing, and I can easily fix that by encasing the call in an if (value > 0) check. Normally I do such things, but I apparently did not on here. Though I am not certain why it is being called for every plot on the map (which the large number would indicate to me)


Thanks for including instructions on how to manage the profiler. I am guessing you use Codeblocks though? I'm not set up so far for a normal Release Mode with VS2008, but I would assume most of it will be fairly intuitive (just the Makefile might be a PITA). Awesome to hear that the CSA+D screen can work properly at all, I wondered why so many functions either did nothing or crashed the game on me.
 

cde2006

Chieftain
Joined
Jan 7, 2008
Messages
25
just the Makefile might be a PITA

Here is my makefile as well as the VS2008 project ^^ (Just remove .txt)

If you want the profiler in Final Release your can also remove the lines:
Code:
#ifndef FINAL_RELEASE
#ifndef FP_PROFILE_ENABLE 
	#define FP_PROFILE_ENABLE 
#endif
#endif

and replace with:

Code:
#define FP_PROFILE_ENABLE

In FProfiler.h
 

Attachments

  • Makefile.txt
    108.9 KB · Views: 67
  • CvGameCoreDLL.vcproj.txt
    16.5 KB · Views: 207

cde2006

Chieftain
Joined
Jan 7, 2008
Messages
25
I am guessing you use Codeblocks though?

No, I just used VS2008, which is quite heavy on HD...might give a try to CodeBlocks later whem I am more familiar with the DLL.

You can profile any function by adding PROFILE() macro at the beginning of the function:
Code:
void yourfunction()
{
	PROFILE("yourfunction");

        /* Your code here */
}

One thing I am not sure is how to interpret the first profiler log column. What is the unit? Because if it is milliseconds it's quite short. On my machine the turn 406 take about 20 seconds so where are the 17 missing seconds?
And if you remember my previous python profiling, the python time was also quite small, so would it be inside the game engine itself that all the time is spend?
Maybe in graphic update or anything else?
 

xienwolf

Deity
Joined
Oct 4, 2007
Messages
10,589
Location
Location! Location!
I would guess graphics and/or file access. Maybe also some non-profiled functions. I had wondered what exactly all the PROFILE and FUNC_PROFILE bits were about when I encountered them before.


Any good reason NOT to enable Profiling in the final release? (Larger file, interrupts gameplay...)?

And I would advise against switching BACK to codeblocks. VS2008 is most certainly a step better. I think the only thing I miss from Codeblocks was easily adding new files (no Makefile to edit) and the ability to duplicate lines with CTRL+D (but you could only do 1 line at a time, so it wasn't THAT useful). In VS2008 though, I can actually make a debug DLL, and I can retain more than 1 item in the clipboard (CTRL+SHIFT+INSERT)


I'll probably add profiling to a couple dozen functions of mine which I expect take up exorbient amounts of time. It'd be nice to know that they don't, or at least be able to say for certain that I am willing to accept the time cost.
 

cde2006

Chieftain
Joined
Jan 7, 2008
Messages
25
I would guess graphics and/or file access.

Yes, graphics can be easily limited by setting the SetMaxFrameRate to let say 1 or 2 in the ini file :p

For I/O, I will do some measurement with process explorer or similar tools.

I will also re-enable the python profiler to see if anything strange.

Any good reason NOT to enable Profiling in the final release? (Larger file, interrupts gameplay...)?

It must have some impact, we can measure it if we compare the turn time between profiler enabled in all functions and profiler only enabled in CvGame::doTurn() for example.

I am not sure this function is the only entry point in the DLL but worth trying.

And I would advise against switching BACK to codeblocks.

Alright, I will play with VS2008 then.

Do you know if there is any mean to compile the DLL in native VS2008 without passing by the VS2003 toolkit?
It may also improve the performance as the compiler in VS2008 may generate better binaries. It tried once but the VS2008 DLL refuses to load in the civ executable. I must have missed something. (Like managed and unmanaged DLL and other weirdness from MS...)
 

Opera

Deity
Joined
Sep 21, 2008
Messages
4,643
I tried the .dll. It reduces turn time but it also disables the possibility of creating new units.
Any idea why?

Edit: Added savegame. FF050e used.
 

Attachments

  • Opera Turn_0002.CivBeyondSwordSave
    85.4 KB · Views: 192

Vehem

Modmod Monkey
Joined
Nov 22, 2005
Messages
3,219
I tried the .dll. It reduces turn time but it also disables the possibility of creating new units.
Any idea why?

Edit: Added savegame. FF050e used.

The DLL he posted was mostly for reference - I don't know if it was setup to be a usable replacement. In anycase, Xienwolf has fixed the Dowsing code to avoid the slowdown noted (and the method that cde2006 mentioned is going to be very helpful in the future...), so the next patch should be a little quicker...
 

cde2006

Chieftain
Joined
Jan 7, 2008
Messages
25
The DLL he posted was mostly for reference - I don't know if it was setup to be a usable replacement. In anycase, Xienwolf has fixed the Dowsing code to avoid the slowdown noted (and the method that cde2006 mentioned is going to be very helpful in the future...), so the next patch should be a little quicker...

Yes the DLL is not for play as I just simply removed the function call there may be some adverse effect I didn't notice. The purpose was to do some measurement with the profiler.
 
Top Bottom