Measuring Mod Performance in SDK

stmartin · Jul 21, 2009

In order to improve performance of HoTK Mod, I'm going to measure the performance (aka. time used) of each part of the game code. I think this kind of job is best done in SDK.

I could use time library of C++. I also notices in SDK there's a header file 'FProfiler.h' which seems to have something to do with performance tweaking. The only thing is I don't understand that file a tiny bit more, so I have no clue how to use it.

Anyone has some good ideas about measuring performance of Civ4? I'd love to hear that! Thanks.

davidlallen · Jul 21, 2009

I'm not sure if you are using python, but I have used the following approach to find performance hogs. The idea is to print the total elapsed time to a file every 10 turns. Then, by turning on or off certain features, you can see which has a runtime impact on the game. Features which have a high runtime impact can then be redesigned to be more efficient.

In python, you can add an onGameTurnEnd callback, check if (turn % 10) is zero, and then use time.strftime() to write the current time into a file.

Your mileage may vary.

stmartin · Jul 21, 2009

Thanks, I'll try that right now.

EmperorFool · Jul 21, 2009

If you're measuring Python code, check out the Timer class in BUG's BugUtil.py module. You could copy that class alone to a new module for use in your mod if it's not already based on BUG. Just change the debug() calls to CvUtil.PyPrint() for logging the times.

Code:

timer = BugUtil.Timer("Check for prereqs")
... code to time ...
timer.log()

This allows you to time long tasks. You can also measure each iteration in a loop:

Code:

timer = BugUtil.Timer('draw loop', False)  # don't start timer yet
for/while ...
	timer.start()
	... code to time ...
	timer.log()
timer.logTotal()

It prints out the time in milliseconds. You could use this to time C++ code, but you'd be timing the entire function call.

Code profiling is a little different and much better. It constantly tracks what part of code is being executed as it runs and then shows you where most time is spent. You don't normally need to add anything to your code to profile it except the profiling tool itself.

I suspect that FProfile.h is actually just a timer like BUG's because wherever I see it being used it simply starts it at the beginning of a function and stops it at the end. This is typical timer stuff and doesn't tell you exactly where in the function the time is taken. It can narrow down to which function on a whole is costing the most time, however. That's sometimes enough information to allow you to make a good performance fix.

xienwolf · Jul 22, 2009

Yes, the Profiler (FProfiler.h) allows you to use in-built timing features to check DLL performance. At the start of many functions you'll notice a line saying PROFILE_FUNC(); or similar but with a text key in it. These are where the profiler hooks in, and thus the functions that get timed.

When you compile, there are certain things that are DEFINED for the compile process, and you'll run into statements in the code saying "ifdef XXXX_XXX" and later something which ends the ifdef statement, or does an else for it. Essentially all of FProfiler.h is wrapped in a massive ifdef, so if you activate that define (normally done in a Release (not Final Release) build type) then your profiler is enabled.

You can also force the define by placing early in FProfiler.h a statement which defines exactly what the ifdef checks for, or by removing the ifdef so that it ALWAYS does it. Then Profiler is always enabled. But that slows down your mod a tad bit for the users who don't care to profile things and also increases the size of the DLL, and thus your download size.

To use the profiler... I think it saves in your Logs folder. You might need to have chipotle enabled and go into the debug menu (CTRL+D) and click on the "enable profiler" checkbox as well to trigger things off. I know that doing that without a debug DLL (which has the profiler enabled) tends to cause an instant crash, so it does require the profiler to be turned on to function properly.

stmartin · Jul 22, 2009

Thanks EF and Xienwolf, as always. I compiled a Debug DLL, enabled profile system, got some result. However, the result confused me.

Some of the functions, such as CvGame::update(), only start to appear in log after about 50+ turns, and will not always appear each turn after that. Is there a way to make it appear every turn?

The result has some strange points. Such as CvPlayerAI::AI_getAttitudeVal() got called 40000+ times and takes 20+ seconds per turn. Also sometimes CvPlot::updatePlotGroup(player) got called 5 digit times and took 10+ seconds per turn, but sometimes it only got called single digit time and took less than 0.001 second.

I've pasted the log result for one turn in a HoTK Mod scenario game. If anyone's interested in interpreting the result, I'm all ears.

I've also attached a more complete version of the log.

Spoiler :

davidlallen · Jul 22, 2009

stmartin said:
If anyone's interested in interpreting the result, I'm all ears.

That is exactly the problem. Some of these discussions turn into software engineering philosophy. I am not sure that function by function profiling will get you what you want. What I think you want is to find out which features you have added in your mod are consuming too much runtime, right? Function profiling will detect if there is a function deep in the engine which is called very often and takes a long time. But there is no way to figure out why, or what to do about it; it is not like you are going to reimplement that engine function more efficiently. This type of profiling is handy for the engine developers at Firaxis, but IMHO is not the best approach for modders.

I proposed a slightly higher level of profiling. Suppose there are 10 features you have added in your mod. Invoke the mod and save a game at turn 0. Now autoplay 100, or 200 turns of the game and look at the total elapsed time. Now remove a couple of features from the mod which may consume a lot of runtime, and rerun. How much time did it save? What you are looking for is minor features which, when removed, make the game run a lot faster. These can be removed. If you find a major feature which costs major time, you need to decide whether to remove it, or you need to find a more efficient way to implement it.

I did this for Dune Wars; some details at this post.

stmartin · Jul 22, 2009

@davidlallen

Allow me to explain why I tried function profiling first.

HoTK did all their changes in SDK. When we did our job, we keep performance in mind, so the code in Python is very unlikely to be heavy. We think we have done the best we can to put performance cost to minimum. But the game is still a bit slow. Because our players love scenarios much more than random map, and scenarios have many players, cities and units.

So we want to see what on earth is consuming all that time. This insight can only be gained by function profiling.

Another reason is, sometimes disabling feature is simply too costly. For example, in HoTK we added many more combat variables. Some of these modify a unit's strength, adding lots of code to CvUnit::maxCombatStr(). Disabling all of them would be painful. Also, if we found the game is slightly faster without all the extra variables, should be remove that feature? That's a tough decision to make. By function profiling, luckily, the result shows that maxCombatStr() is not very time consuming in the big picture.

Yes, I agree with you it's unlikely we could make the Civ 4 engine more efficient. However, at a small price, we could make the game run much faster. The function profiling result shows CvPlayerAI::AI_getAttitudeVal() is the big boss, and CvTeamAI:AI_isLandTarget() is one of the small bosses. So I just made a decision: cache the result of those both functions, calculate them only once per turn per player/team instead of thousands of times, at a cost of more memory usage and less real-time values. I still don't know if there's any hidden cost here. Nevertheless, HoTK now runs MUCH faster now.

davidlallen · Jul 22, 2009

I'm glad you were able to get useful results. The method I described happens to use python to measure the data, but you can use the same method even if you have added many features into the sdk instead of python. In fact, one of the major problems we found using this method was that some of the graphic effects attached to some of the units were slowing down runtime. We re-measured the runtime after replacing the unit with an empty nif, and proved that this was a major factor. I don't think profiling would reveal that.

phungus420 · Jul 22, 2009

stmartin said:
... The function profiling result shows CvPlayerAI::AI_getAttitudeVal() is the big boss, and CvTeamAI:AI_isLandTarget() is one of the small bosses. So I just made a decision: cache the result of those both functions, calculate them only once per turn per player/team instead of thousands of times, at a cost of more memory usage and less real-time values. I still don't know if there's any hidden cost here. Nevertheless, HoTK now runs MUCH faster now.

Please share this result and code with BetterAI, or maybe even the unofficial patch. This sounds like a great improvement in code.

xienwolf · Jul 22, 2009

Now that you have it actually WORKING, some pointers/observations from my own VERY limited use of the function:

Just as with Assert messages, if you don't understand why something is being profiled, it does you no good at all. So pruning all of the existing profile messages is potentially a good start.

Since you are worried about the new functions you have written, except in places where they are mostly inserted into already profiled functions, add a profile call to your function itself. Actually even if mostly just called from one already profiled function, add a call anyway (if you know that your function should be called twice each time that ::maxCombatStr() is called, check if that is the case by comparing call counts).

For functions that confuse you as to why they take so long, find any loops in them and place a profiler in something called within that loop. I am not sure if you can just place a profile call inside the loop with a text key and have it re-trigger, but it makes sense you SHOULD be able to.

As for some functions not showing up every turn which you KNOW are running each turn: Maybe this is just the top offender list? (I don't find that likely, the list is long and some entries are brief) I'm really not completely sure on that one to be honest. It probably varies per function, like some CvGame functions may span multiple turns.

Specifically: CvPlot::updatePlotGroup(player), this one as I recall is processed for every plot on the map when any team learns a new tech, to find if a bonus should be revealed or traderoutes updated or some such. But is also processed on individual tiles when a road is built to see if it linked two groups. Hence sometimes running 5 digit number of times and sometimes running once.

All said, the big trick is that the profiler just points you in the right direction to analyze, then you have to pick apart WHY. If a function is called a ton of times with a low average processing speed, then use the Caller's Graph (In VS2008, I right click on the function name and the first option is for caller's graph, choose to "display callers" and it shows everywhere in the code that calls that function. Sometimes it is priceless, sometimes it is useless. If the results don't make sense, compare it with a FIND ALL search to see if the Intellisense is screwing with you). Many functions are called from places they don't need to be, or can be nested in a conditional to prevent the call if it isn't needed. For others, like AttitudeValue, you may want to consider creating a Cache system where you update the value from scratch at the start of each turn, and force reference to a static variable during the turn. This is done for BestBuildValue in CvCity/CvPlot as I recall if you need an example to work from.

EDIT: Yeah, sometimes reading comprehension is your friend. I skimmed near the end of your post and missed that you already DID move to a cache system. Only caught it when reading the crosspost of phungus... geez I can be dense

EmperorFool · Jul 22, 2009

Given that actions taken during the turn that alter the attitude would not take effect until the next turn, I wouldn't want to see this caching solution in the UP or BBAI as-is. However, with a little grunt work you could add a call to invalidate the cache for a given player pair whenever any of the values that make up the total attitude change.

Most should be fairly easy: when anyone declares war on an AI, invalidate everyone's attitude toward that player. Hmm, you also need to account for shared war, but I don't know when that kicks in. Plus it increases over time, but your per-turn invalidation will catch that.

To make sure the human always sees the correct attitudes you could ignore the cache when the human is the active player.

stmartin · Jul 23, 2009

davidlallen said:
I'm glad you were able to get useful results. The method I described happens to use python to measure the data, but you can use the same method even if you have added many features into the sdk instead of python. In fact, one of the major problems we found using this method was that some of the graphic effects attached to some of the units were slowing down runtime. We re-measured the runtime after replacing the unit with an empty nif, and proved that this was a major factor. I don't think profiling would reveal that.

I've checked your post about performance experiment with Dune Wars again. What do you mean by an empty nif?

I noticed the spice nif you used to use cost much time. It's a resource, right? How frequently would it appear on map? I'm very curious as a single resource graphic could make such huge difference.

stmartin · Jul 23, 2009

Thanks phungus, Xienwolf and EF for noticing my little 'achievement'. I agree with EF completely that this little modification is not up to the standard of UP or BBAI, because AI is actually using attitude value of last turn.

Then I noticed a large part (about 85% percent) of time AI_getAttitudeVal() consumes comes from a function called AI_calculateStolenCityRadiusPlots(). It calculates how many plots other players 'steal' from your cities using culture. This value will change very little from turn to turn, so I cached that value instead of the whole AI_getAttitudeVal(). The performance increase in not as good as caching the whole attitude, but is substantial enough.

I will try to make some further improvements if I can then tell jdog about it.

EmperorFool · Jul 23, 2009

Caching that value--and invalidating it when things change it during the turn--seems pretty reasonable. And saving 85% of a costly routine is rather significant. :goodjob:

Off the top of my head:

Use Great Artist for a Great Work
Perform Spy's "Spread Culture" mission

Does anything else add culture or switch ownership of tiles?

God-Emperor · Jul 23, 2009

EmperorFool said:
Caching that value--and invalidating it when things change it during the turn--seems pretty reasonable. And saving 85% of a costly routine is rather significant. Off the top of my head:

Use Great Artist for a Great Work

Perform Spy's "Spread Culture" mission

Does anything else add culture or switch ownership of tiles?

How about giving/trading a city or creating a colony?

davidlallen · Jul 23, 2009

stmartin said:
I've checked your post about performance experiment with Dune Wars again. What do you mean by an empty nif?

I noticed the spice nif you used to use cost much time. It's a resource, right? How frequently would it appear on map? I'm very curious as a single resource graphic could make such huge difference.

In general, people find that high poly count models, or models with complex particle effect animations, can slow down the game. In the particular case of Dune Wars and the spice resource, about 15% of the map is covered with this bonus, so a huge map could have a hundred or more. A slightly older screenshot is at this link. It used to also have a smoke effect, along the lines of an unhappy city. This may be an exceptionally bad case, but generally artists do try to minimize the poly count and effect to avoid hurting runtime.

The Dune Wars Art God, deliverator, made a nif which is literally empty, with no objects or anything inside. By changing the artdef from the complex smoky animation to the empty nif, I could measure the runtime before and after, and prove whether this animation was causing a slow runtime. As you can see from later in the thread of the post I quoted, replacing the model with a less complex one did make a significant improvement in the runtime. This is one example where I am pretty sure a profiler would not provide any insight.

In case it is helpful, the empty nif is attached in this post.

The_J · Jul 23, 2009

stmartin said:
Then I noticed a large part (about 85% percent) of time AI_getAttitudeVal() consumes comes from a function called AI_calculateStolenCityRadiusPlots(). It calculates how many plots other players 'steal' from your cities using culture. This value will change very little from turn to turn, so I cached that value instead of the whole AI_getAttitudeVal(). The performance increase in not as good as caching the whole attitude, but is substantial enough.

I don't know where, but there has to be a function, which is called after a culture expansion, because there's a python function onCultureExpansion in the CvEventManager.
-> So the simplest way (from logic, not from the programming effort) would be, to let the function be called from there.

xienwolf · Jul 24, 2009

EmperorFool said:
Caching that value--and invalidating it when things change it during the turn--seems pretty reasonable. And saving 85% of a costly routine is rather significant. Off the top of my head:

Use Great Artist for a Great Work

Perform Spy's "Spread Culture" mission

Does anything else add culture or switch ownership of tiles?

The value is all about how many plots THEY were able to work which now YOU are working. So you simply place a check in CvPlot::changeOwner() or whatever such a function is called which tests if the plot is in the working radius of a city before the change, and if it is owned by a player after the change. If so, invalidate this cache value.

stmartin · Jul 25, 2009

Thanks everyone for giving me suggestions, but I seems to have made a mistake, in original BTS close border attitude value is already cached...Looks like I have to check it more carefully.

Measuring Mod Performance in SDK

aka. poyuzhe

Deity

aka. poyuzhe

Deity

Deity

aka. poyuzhe

Attachments

Deity

aka. poyuzhe

Deity

Deity

Deity

Deity

aka. poyuzhe

aka. poyuzhe

Deity

Deity

Deity

Say No 2 Net Validations

Deity

aka. poyuzhe

Similar threads