Koshling, here's my current game.
I'm pretty isolated atm and will have to wait for optics to expand further.
Turntimes on my laptop (i3, win7, 4GB Ram, decent Video card) are short of a minute.
Thanks in advance.
Turns out that I was only partially correct about the pathing changes being at the root of it. Basically the new pathing is about 20% slower than the old (until I get to phase 2, after which it'll be faster). In most game turns pathing accounts for around 25% of the total turn time, so the new pathing is costing us about 5% (which I deemed acceptable for this release, and phase two work will happen as soon as v22 is out).
However, in some circumstances, inefficiencies in the USE of the pathing engine (not its implementation) mean that a lot more path generation is requested than normal (and of a lot longer paths). It was these cases, which have been in the code for a very long time, which we're being amplified by the pathing change. DRJ's example was actually more pronounced than yours, so I ended up using his save as my test case for profiling after verifying that both profiles showed the same effect (though yours less so). In DRJ's save pathing calculations were well over half the turn time, so adding an extra 20% to that was amplified accordingly.
I have now eliminated the worst causes of this that the saves pointed out, though some of the lesser causes will probably warrant further work at some future point.
For comparison (and because DRJ asked about profiling generally), I have attached before and after profiles of the same end turn in DRJs stuck-unit save position. You'll need Excel or some other spreadsheet that can read Excel files to view these if you're interested.
Each spreadsheet is just output from the profiler logging, which I've sorted in Excel by time, so that the most time consuming functions are at the top. Each row has the following columns:
Fn: name of a function that has a profiling point associated with it in the code
Time: time spent executing that function within the end turn execution (in milliseconds). This includes time in funtions that this one calls, and their descendants.
Avg Time: average time per call
#Calls: number of times that function was called
Child time: time spent in calls made by this function
Self time: (time - child time) - so time spent in this function itself
Parent: first seen caller of this fucntion in the call tree
As you can see from the results, the main offender is pathing (CvSelectionGroup::generatePath) taking over 90 seconds in the base (before fix) profile, but more important is where many of those calls were from. The noteable functions that are hot here, and would not be expected to contribute so much, are CvUnitAI::AI_Group (taking 45 seconds, mostly in its path generation), and AI_pickTargetCity (taking 20). AI_counterMove() calls AI_Group() which is why it is high (it's AI_Group() that is the fundamental offender), and similarly AI_attckCityMove() calls AI_pickTargetCity().
Anyway, turning to the second profile, you'll see that I managed to reduce the 40 + 20 seconds to a more reasonable 2.2 + 0.2.
And thx for explaining how you find the hot spots, would you mind making a documentation about that at some time, maybe? Like how to use a profile build for analyzing?
I like the
btw. makes it easier to understand^^
I'll post something in the modders documentation section sometime on how to use the profiling build.