We should probably have something to work on investigating turn times.

As I understand it, something has been made to test what areas are currently taking so long for the turn times. I wonder if maybe we could post it and have some people process some of the data?

Updates
If you want to help:

Minimal C++ coding
Post 11 (http://forums.civfanatics.com/showpost.php?p=5041880&postcount=11) Need someone to remove the code that allows modders to interface with C++ using python and compile a copy of the AI without that feature.

Moderate coding
Identify all of the high level AI functions and insert a one line command before and after the high level function calls that records the function name and the timestamp (in milliseconds) to a variable. When the AI is done, record that data somehow (perhaps a simple C++ write to file). This would allow us to see which high level functions are taking the longest.

Looks like I was the one misunderstanding. Ignore this post...

We should probably have something to work on investigating turn times.

As I understand it, something has been made to test what areas are currently taking so long for the turn times. I wonder if maybe we could post it and have some people process some of the data?

You are misunderstanding. They made a test (Assets) for basically all of the code. That is what is causing the long turn times. If you don't want long turn times, download the non asset version.

They are doing this to squeeze out the last of the mostly invisible bugs before the 1.0 release.

It is possible to do a build which allows you to generate a log of what functions are taking how much time. It generates a enormous amount of data, it takes some work to sift through it to what is important and what isnt.

I could do such a build, if someone who is good at manipulating logs of data into useful information wants to take a go at it. It is a non-trivial task, particularly because it is not always obvious what is taking a long time because waiting on the human and what is taking a long time because it takes a long time.

-Iustus

It is possible to do a build which allows you to generate a log of what functions are taking how much time. It generates a enormous amount of data, it takes some work to sift through it to what is important and what isnt.

I could do such a build, if someone who is good at manipulating logs of data into useful information wants to take a go at it. It is a non-trivial task, particularly because it is not always obvious what is taking a long time because waiting on the human and what is taking a long time because it takes a long time.

-Iustus
What if we added in some code that timed how long each function of the AI process took. I used to do this (though in a different and much simplified manner) for javascript calls to see what areas were taking so long. Basically you could insert a simple timer before and after each section of the AI processing that would log the time each section took and when it started and stopped. This would give us a rough outline of the AI processing, and when each part took place. This would be relatively simple to program, and based on this data, you could focus on the slowest areas and then time individual aspects inside of there.
What about something like this Iustus?

What if we added in some code that timed how long each function of the AI process took. I used to do this (though in a different and much simplified manner) for javascript calls to see what areas were taking so long. Basically you could insert a simple timer before and after each section of the AI processing that would log the time each section took and when it started and stopped. This would give us a rough outline of the AI processing, and when each part took place. This would be relatively simple to program, and based on this data, you could focus on the slowest areas and then time individual aspects inside of there.
What about something like this Iustus?

That is precisely what I am talking about. It is called 'code profiling', and I can do a build with it turned on. But as I said, it generates an enormous amount of data, someone has to commit to sifting through it, or I am not going to post such a build.

Blake and I have looked at the data from it from time to time, but not in great detail.

-Iustus

That is precisely what I am talking about. It is called 'code profiling', and I can do a build with it turned on. But as I said, it generates an enormous amount of data, someone has to commit to sifting through it, or I am not going to post such a build.

Blake and I have looked at the data from it from time to time, but not in great detail.

-Iustus
Can you give me a copy of the data you got from a game (as well as info on what the game was)... or maybe you could provide the special build for others to run and collect the data on?

BTW, what you are describing sounds infinitely more than what I was looking for. Basically, what I was looking for was something more along the lines of the following:
Let's say the AI goes through the following main areas:
diplomacy
city building
unit movment
planning

The concept is to time when diplomacy starts and when it ends, when city building starts and when it ends.... etc....
Essentially, you'd have only 10 pieces of data (the start and stop time for the 5 major sections mentioned above). From that, you can might be able to quickly see that diplomacy and city building are already very quickly done and that unit movement is the really, really slow part. Thus, you can quickly ignore everything, but unit movement. At that point, you could insert logs into the unit movement section only (piece by piece) to find the slow areas.


----
On yet another note, I believe it was Penjo who said he specifically noticed some inefficient algorithms in the AI code. Maybe he'd be willing to mention which ones those are that he noticed (though I'm not sure has the time or is allowed to)?

On yet another note, I believe it was Penjo who said he specifically noticed some inefficient algorithms in the AI code. Maybe he'd be willing to mention which ones those are that he noticed (though I'm not sure has the time or is allowed to)?

The code was not written for speed. Take one look at it and there are a ton of optimizations that come to mind to speed things up. However, the biggest gains often involve the biggest changes.

I think I deleted my last log, I will see about making a new log and posting a bit of it so you can see what it looks like.

-Iustus

The code was not written for speed. Take one look at it and there are a ton of optimizations that come to mind to speed things up. However, the biggest gains often involve the biggest changes.

I think I deleted my last log, I will see about making a new log and posting a bit of it so you can see what it looks like.

-Iustus
If you want to post the build to create a log (as well as instructions on how to use it) feel free.

BTW, do you think the other method mentioned might be more useful in finding out what is taking up times? Just add in a few log messages at key points in the code and see if any key areas are excessively long compared to the others and then add in special logs into that section only to narrow things down.

Maybe I should clarify this better.
The concept is not to find out exactly what the problem is right away. First off, we gotta simply find what broad areas to focus on... thus, I am suggesting that you try an approach of gradually narrowing in on the problem.
* First off, the goal is to just find out which branch of the AI is taking up so much time and which are not (diplomacy? unit movement? cities? border adjustment?). So, the concept is to just insert a 1 line piece of code before and after each high level AI function that records the function name and a timestamp in milliseconds. Then, when the AI is done, record this data to a file using basic C++ file operations.
This would be very simple code; it would also let us know if certain high level areas of the AI can be basically ignored since they are already so fast anyways. It might also reveal more definitevly the areas that are taking up so much time.
2. From this point, you can then focus on the ares that are so slow (assuming it is just a select few), and you can gradually profile more and more sections to narrow down the problem area(s).



BTW, Iustus, can you provide a complete log and/or a copy of the files to generate such a log on this test game: http://forums.civfanatics.com/downloads.php?do=file&id=3727

I don't know how relevant this is, but one item that I've noticed (playing vanilla civ) is AI unit patrolling. Not specific to Better AI, of course, but a definite slowdown between turns.

Does this benefit the AI in any respect rather than having unused units sit still? If not, a lot of time could be saved, that could be used for AI computations without annoying the human player so much.

Something simple to check in the code if anyone is willing to:

I am told there is somewhere in the AI code where it makes calls back to the Python code to check on things (like whether you changed if a unit can move to a certain tile or not). Supposedly, this process may be very time consuming and is supposedly done thousands of times.
If someone would be willing to compile a copy of the AI without this check so that one of us could run a simple comparison test, that would be great.

Today's build (building as we speak) will have profiling enabled (in both versions). It actually should have always been enabled in the assert version. (You should test with the non-assert version to get more accurate numbers).

Hold down ctrl-shift-alt-D and you will get the debug menu (you need chipotle enabled):
http://forums.civfanatics.com/uploads/95686/debugmenu.jpg

Go to the profile tab, and turn on profiling for the DLL.

Every turn, the file "dllprofile.txt" in your "My Games\Warlords\Logs" directory will get another turn's worth of data.

You are going to want to use something like excel to make sense of the data.


[11806.781] DBG: Total Frame MS: 18825.0 FPS: 000 Min:000 Max:000 Avg:000 SampleFilter:1.010000
Time : Ave : Min% : Max% : Num : Profile Name
-----------------------------------------------------
11139.0 : 000.0 : 000.0 : 000.0 : 008 : CvPlayer::doTurn
2330.0 : 012.4 : 000.1 : 012.4 : 1069584 : CvGlobals::getDefineINT
060.0 : 000.0 : 000.0 : 000.0 : 008 : CvPlayerAI::AI_doTurnPre
4364.0 : 000.0 : 000.0 : 000.0 : 269021 : CvPlayer::isResearch
024.0 : 000.0 : 000.0 : 000.0 : 004 : CvTeam::setHasTech
005.0 : 000.0 : 000.0 : 000.0 : 17472 : CvTeam::setHasTech() 1
003.0 : 000.0 : 000.0 : 000.0 : 17472 : CvTeam::setHasTech() 2
003.0 : 000.0 : 000.0 : 000.0 : 004 : CvTeam::processTech
004.0 : 000.0 : 000.0 : 000.0 : 004 : CvTeam::setHasTech() 3
004.0 : 000.0 : 000.0 : 000.0 : 180 : CvPlayer::canDoCivics
9208.0 : 000.0 : 000.0 : 000.0 : 041 : CvCity::doTurn()
6206.0 : 000.0 : 000.0 : 000.0 : 041 : CvCityAI::AI_doTurn
10321.0 : 000.0 : 000.0 : 000.0 : 056 : CvCityAI::AI_assignWorkingPlots
084.0 : 000.4 : 000.4 : 000.5 : 901 : CvPlot::updateSymbolDisplay
063.0 : 000.3 : 000.0 : 000.9 : 14873 : CvGlobals::getDefineFLOAT
037.0 : 000.0 : 000.0 : 000.0 : 1147 : CvCityAI::angryPopulation
10243.0 : 000.0 : 000.0 : 000.0 : 845 : CvCityAI::AI_addBestCitizen
019.0 : 000.0 : 000.0 : 000.0 : 845 : CvCityAI::AI_avoidGrowth
022.0 : 000.0 : 000.0 : 000.0 : 845 : CvCityAI::AI_ignoreGrowth
020.0 : 000.0 : 000.0 : 000.0 : 845 : CvCityAI::AI_foodAvailable
5303.0 : 000.0 : 000.0 : 000.0 : 4476 : CvCityAI::AI_specialistValue
7428.0 : 000.0 : 000.0 : 000.0 : 11919 : CvCityAI::AI_yieldValue
9456.0 : 000.0 : 000.0 : 000.0 : 269009 : CvPlayer::canResearch
4844.0 : 000.0 : 000.0 : 000.0 : 7443 : CvCityAI::AI_plotValue
007.0 : 000.0 : 000.0 : 000.0 : 1793 : CvPlayerAI::AI_plotTargetMissionAIs
029.0 : 000.2 : 000.1 : 000.2 : 29474 : CvPlot::calculateNatureYield
049.0 : 000.0 : 000.0 : 000.0 : 683 : CvCityAI::AI_bestPlotBuild
033.0 : 000.2 : 000.0 : 000.2 : 30350 : CvPlayer::canBuild
023.0 : 000.1 : 000.0 : 000.1 : 30350 : CvPlot::canBuild
123.0 : 000.7 : 000.0 : 000.7 : 21236 : CvPlot::calculateImprovementYieldChange
032.0 : 000.0 : 000.0 : 000.0 : 16540 : CvPlayer::getBestRoute
050.0 : 000.0 : 000.0 : 000.0 : 2613 : CvPlayerAI::AI_getPlotDanger
2728.0 : 000.0 : 000.0 : 000.0 : 023 : CvCityAI::AI_chooseProduction
974.0 : 000.0 : 000.0 : 000.0 : 007 : CvCityAI::AI_buildGovernorChooseProduction
002.0 : 000.0 : 000.0 : 000.0 : 3330 : CvTeam::countNumCitiesByArea
076.0 : 000.0 : 000.0 : 000.0 : 5138 : CvPlayer::canConstruct
2295.0 : 000.0 : 000.0 : 000.0 : 555 : CvCityAI::AI_buildingValueThreshold
012.0 : 000.0 : 000.0 : 000.0 : 17734 : CvPlot::isCoastalLand
579.0 : 000.0 : 000.0 : 000.0 : 63079 : CvPlayer::canTrain
057.0 : 000.0 : 000.0 : 000.0 : 541 : CvPlot::doImprovement
015.0 : 000.0 : 000.0 : 000.0 : 027 : CvPlayer::countUnimprovedBonuses
005.0 : 000.0 : 000.0 : 000.0 : 4422 : CvPlot::calculateCulturalOwner()
265.0 : 000.0 : 000.0 : 000.0 : 4381 : CvPlot::setOwner
018.0 : 000.0 : 000.0 : 000.0 : 6011 : CvPlot::changeVisibilityCount
014.0 : 000.0 : 000.0 : 000.0 : 582 : CvPlot::changeVisibilityCount 1
006.0 : 000.0 : 000.0 : 000.0 : 298 : CvPlot::changeVisibilityCount 2
003.0 : 000.0 : 000.0 : 000.0 : 11058 : CvPlot::changeVisibilityCount 4
002.0 : 000.0 : 000.0 : 000.0 : 160 : CvPlot::updateCenterUnit
009.0 : 000.0 : 000.0 : 000.0 : 243 : CvPlot::updatePlotGroupBonus
020.0 : 000.0 : 000.0 : 000.0 : 023 : CvPlot::updateIrrigated()
373.0 : 000.0 : 000.0 : 000.0 : 161 : CvPlot::updatePlotGroup
019.0 : 000.1 : 000.1 : 002.2 : 036 : CvPlot::updateSymbols
005.0 : 000.0 : 000.0 : 000.0 : 095 : addVisiblePlots
360.0 : 000.0 : 000.0 : 000.0 : 028 : CvPlotGroup::recalculatePlots()
067.0 : 000.0 : 000.0 : 000.0 : 005 : CvPlayer::initUnit
262.0 : 000.0 : 000.0 : 000.0 : 625 : CvPlayerAI::AI_bonusVal
1833.0 : 000.0 : 000.0 : 000.0 : 008 : CvPlayerAI::AI_doTurnPost
328.0 : 000.0 : 000.0 : 000.0 : 008 : CvPlayer::doTurnUnits
248.0 : 000.0 : 000.0 : 000.0 : 008 : CvPlayerAI::AI_doTurnUnitsPre
203.0 : 000.0 : 000.0 : 000.0 : 008 : CvPlayerAI::AI_updateFoundValues
191.0 : 000.0 : 000.0 : 000.0 : 22352 : CvPlayerAI::AI_foundValue()
029.0 : 000.0 : 000.0 : 000.0 : 2646 : CvPlayerAI::AI_foundValue() 1
148.0 : 000.0 : 000.0 : 000.0 : 2646 : CvPlayerAI::AI_foundValue() 2
146.0 : 000.0 : 000.0 : 000.0 : 1860 : CvPlayerAI::AI_foundValue() 3
145.0 : 000.0 : 000.0 : 000.0 : 213 : CvPlayerAI::AI_foundValue() 4
666.0 : 000.0 : 000.0 : 000.0 : 1479 : CvPlayerAI::AI_getAttitude
669.0 : 000.0 : 000.0 : 000.0 : 1495 : CvPlayerAI::AI_getAttitudeVal
394.0 : 000.0 : 000.0 : 000.0 : 1481 : CvPlayerAI::AI_calculateStolenCityRadiusPlots
010.0 : 000.0 : 000.0 : 000.0 : 216 : CvSelectionGroup::doTurn()
003.0 : 000.0 : 000.0 : 000.0 : 218 : CvUnit::doTurn()
070.0 : 000.0 : 000.0 : 000.0 : 008 : CvPlayerAI::AI_doTurnUnitsPost
013.0 : 000.0 : 000.0 : 000.0 : 165 : CvUnitAI::AI_promote
060.0 : 000.0 : 000.0 : 000.0 : 192 : CvUnitAI::AI_upgrade
1995.0 : 000.0 : 000.0 : 000.0 : 007 : CvPlayerAI::AI_unitUpdate
1994.0 : 000.0 : 000.0 : 000.0 : 162 : CvSelectionGroupAI::AI_update
1984.0 : 000.0 : 000.0 : 000.0 : 145 : CvUnitAI::AI_update
281.0 : 000.0 : 000.0 : 000.0 : 013 : CvUnitAI::AI_workerMove
088.0 : 000.0 : 000.0 : 000.0 : 444425 : CvUnitAI::AI_plotValid
039.0 : 000.0 : 000.0 : 000.0 : 015 : CvUnitAI::AI_improveBonus
175.0 : 000.0 : 000.0 : 000.0 : 013 : CvUnitAI::AI_improveCity
057.0 : 000.0 : 000.0 : 000.0 : 017 : CvUnitAI::AI_bestCityBuild
510.0 : 000.0 : 000.0 : 000.0 : 1566 : CvSelectionGroup::generatePath()
018.0 : 000.0 : 000.0 : 000.0 : 16177 : pathAdd
009.0 : 000.0 : 000.0 : 000.0 : 1566 : pathDestValid
304.0 : 000.0 : 000.0 : 000.0 : 97616 : pathValid
103.0 : 000.0 : 000.0 : 000.0 : 78142 : pathCost
059.0 : 000.0 : 000.0 : 000.0 : 96539 : CvPlot::movementCost
060.0 : 000.0 : 000.0 : 000.0 : 96294 : pathValid 4
107.0 : 000.0 : 000.0 : 000.0 : 96294 : pathValid 5
322.0 : 000.0 : 000.0 : 000.0 : 157 : CvSelectionGroup::pushMission
105.0 : 000.0 : 000.0 : 000.0 : 059 : CvSelectionGroup::groupMove
637.0 : 000.0 : 000.0 : 000.0 : 010 : CvUnitAI::AI_exploreMove
007.0 : 000.0 : 000.0 : 000.0 : 038 : CvUnitAI::AI_cityAttack
002.0 : 000.0 : 000.0 : 000.0 : 059 : CvUnitAI::AI_anyAttack
009.0 : 000.0 : 000.0 : 000.0 : 030 : CvUnitAI::AI_pillageRange
772.0 : 000.0 : 000.0 : 000.0 : 011 : CvUnitAI::AI_exploreRange
737.0 : 000.0 : 000.0 : 000.0 : 011 : CvUnitAI::AI_getBestExplorePlot
736.0 : 000.0 : 000.0 : 000.0 : 10464 : AI_getBestExplorePlot 1
584.0 : 000.0 : 000.0 : 000.0 : 13943 : CvUnitAI::AI_explorePlotValue
416.0 : 002.2 : 000.0 : 002.2 : 3452 : addVisiblePlots
402.0 : 000.0 : 000.0 : 000.0 : 86300 : addVisiblePlots(CvPlotRegion) 1
160.0 : 000.0 : 000.0 : 000.0 : 1400 : AI_getBestExplorePlot 2
154.0 : 000.0 : 000.0 : 000.0 : 1400 : AI_getBestExplorePlot 3
335.0 : 000.0 : 000.0 : 000.0 : 010 : CvUnitAI::AI_explore
309.0 : 000.0 : 000.0 : 000.0 : 43680 : AI_explore 1
019.0 : 000.0 : 000.0 : 000.0 : 010 : CvUnitAI::AI_pillage
024.0 : 000.0 : 000.0 : 000.0 : 010 : CvUnitAI::AI_fogbust
009.0 : 000.0 : 000.0 : 000.0 : 073 : CvUnitAI::AI_fogbustPlotDifference
129.0 : 000.0 : 000.0 : 000.0 : 024 : CvUnitAI::AI_collateralMove
180.0 : 000.0 : 000.0 : 000.0 : 109 : CvUnitAI::AI_guardCity
178.0 : 000.0 : 000.0 : 000.0 : 223 : CvCityAI::AI_isDefended
203.0 : 000.0 : 000.0 : 000.0 : 257 : CvCityAI::AI_neededDefenders
137.0 : 000.0 : 000.0 : 000.0 : 037 : CvPlayerAI::AI_getTotalFloatingDefendersNeeded
192.0 : 000.0 : 000.0 : 000.0 : 063 : CvPlayerAI::AI_getTotalAreaCityThreat
217.0 : 000.0 : 000.0 : 000.0 : 316 : CvCityAI::AI_cityThreat
024.0 : 000.0 : 000.0 : 000.0 : 037 : CvPlayerAI::AI_countNumAreaHostileUnits
003.0 : 000.0 : 000.0 : 000.0 : 002 : CvUnitAI::AI_protect
147.0 : 000.0 : 000.0 : 000.0 : 006 : CvUnitAI::AI_retreatToCity
051.0 : 000.0 : 000.0 : 000.0 : 016 : CvUnitAI::AI_attackMove
017.0 : 000.0 : 000.0 : 000.0 : 016 : CvUnitAI::AI_attackMove() 1
038.0 : 000.0 : 000.0 : 000.0 : 034 : CvUnitAI::AI_reserveMove
005.0 : 000.0 : 000.0 : 000.0 : 015 : CvUnitAI::AI_guardCityAirlift
062.0 : 000.0 : 000.0 : 000.0 : 041 : CvUnitAI::AI_group
034.0 : 000.0 : 000.0 : 000.0 : 004 : CvUnitAI::AI_attackMove() 2
020.0 : 000.0 : 000.0 : 000.0 : 018 : CvUnitAI::AI_cityDefenseMove
037.0 : 000.0 : 000.0 : 000.0 : 016 : CvUnitAI::AI_cityDefenseExtraMove
017.0 : 000.0 : 000.0 : 000.0 : 004 : CvUnitAI::AI_settleMove
025.0 : 000.0 : 000.0 : 000.0 : 002 : CvUnitAI::AI_foundRange
002.0 : 000.0 : 000.0 : 000.0 : 3016 : pathValid 2
004.0 : 000.0 : 000.0 : 000.0 : 125 : CvPlayerAI::AI_civicValue
182.0 : 000.0 : 000.0 : 000.0 : 026 : CvCityAI::AI_doDraft
1833.0 : 000.0 : 000.0 : 000.0 : 006 : CvPlayerAI::AI_doDiplo
023.0 : 000.0 : 000.0 : 000.0 : 024 : CvTeamAI::AI_surrenderTrade
005.0 : 000.0 : 000.0 : 000.0 : 008 : CvTeamAI::AI_openBordersTrade
1616.0 : 000.0 : 000.0 : 000.0 : 774 : CvTeamAI::AI_techTrade
014.0 : 000.0 : 000.0 : 000.0 : 039 : CvPlayerAI::AI_bonusTrade
224.0 : 000.0 : 000.0 : 000.0 : 004 : CvUnitAI::AI_settlerSeaMove
077.0 : 000.4 : 000.4 : 000.4 : 001 : CvUnitAI::AI_settlerSeaTransport
018.0 : 000.1 : 000.1 : 000.1 : 77696 : pathValid 1
041.0 : 000.2 : 000.2 : 000.2 : 003 : CvUnitAI::AI_nextCityToImprove
017.0 : 000.1 : 000.1 : 000.1 : 004 : CvUnitAI::AI_routeTerritory
003.0 : 000.0 : 000.0 : 000.0 : 002 : CvUnitAI::AI_routeCity
003.0 : 000.0 : 000.0 : 000.0 : 002 : CvUnitAI::AI_irrigateTerritory
017.0 : 000.1 : 000.1 : 000.1 : 002 : CvUnitAI::AI_attackCityMove
086.0 : 000.5 : 000.5 : 004.1 : 009 : CvPlot::updateRouteSymbol
003.0 : 000.0 : 000.0 : 020.2 : 001 : CvPlot::updateFeatureSymbol
021.0 : 000.1 : 000.1 : 000.1 : 001 : CvPlayerAI::AI_bestTech
529.0 : 002.8 : 002.8 : 002.8 : 001 : CvUnitAI::AI_exploreSeaMove
007.0 : 000.0 : 000.0 : 000.0 : 32986 : pathValid 3
601.0 : 003.2 : 003.2 : 003.2 : 001 : CvGame::doTurn()
010.0 : 000.1 : 000.1 : 000.1 : 342 : CvPlayer::calculateScore
078.0 : 000.4 : 000.4 : 000.4 : 008 : CvTeam::doTurn()
020.0 : 000.1 : 000.1 : 000.1 : 008 : CvTeamAI::AI_updateWorstEnemy
007.0 : 000.0 : 000.0 : 000.0 : 108 : CvTeamAI::AI_calculateAreaAIType
006.0 : 000.0 : 000.0 : 000.0 : 010 : CvTeam::countEnemyDangerByArea
052.0 : 000.3 : 000.3 : 000.3 : 006 : CvTeamAI::AI_doWar
304.0 : 001.6 : 001.6 : 001.6 : 001 : CvMap::doTurn()
304.0 : 001.6 : 001.6 : 001.6 : 4368 : CvPlot::doTurn
036.0 : 000.2 : 000.2 : 000.2 : 4368 : CvPlot::doFeature()
257.0 : 001.4 : 001.4 : 001.4 : 4368 : CvPlot::doCulture()
--------------------------------------------------


Enjoy,

-Iustus

1. Do I get the latest off of the CVS? (when you are done with the compile)? If not, where?
2. I noticed that the time says something about FPS, and the first number is average and not total time -- rather odd. Is this a misstatement, or does the profiling actually not tell the total time that that function took?

1. Do I get the latest off of the CVS? (when you are done with the compile)? If not, where?
2. I noticed that the time says something about FPS, and the first number is average and not total time -- rather odd. Is this a misstatement, or does the profiling actually not tell the total time that that function took?

Go download the 1/29 build (not the assert one, the previous build), this is a direct link to the warlords version (http://downloads.sourceforge.net/civ4betterai/BetterAI_Warlords_07-01-29.zip?use_mirror=osdn)

The time number is total time, the sum of every call. Divide the "Time" by "Num" to get the "Ave" (average) time one call of the function. Realistically though, the total Time number is just as important, if not more important. A quick function that is called a million times could be more important to optimize than a long function that is only called once.

-Iustus

Go download the 1/29 build (not the assert one, the previous build), this is a direct link to the warlords version (http://downloads.sourceforge.net/civ4betterai/BetterAI_Warlords_07-01-29.zip?use_mirror=osdn)

Thanks for the build. Might be a bit before I can get to it though... just a heads up. Although it would be relatively simple to run the test, it may take some time to process the data depending on how long it is. Approximately how many lines long is yours?
A quick function that is called a million times could be more important to optimize than a long function that is only called once. Indeed... very much so. :) If it had really meant average though, then it sure would have been pretty worthless. :)

Thought this might be of significant interest to this topic:

I did my own "profiling" by adding text to a custom log file (windows up time is posted at the begining of each line). I did this because I am working on a major addition to the game and I was curious as to why my turns started taking so long at a given point in the game. Here is what I discovered:

AI_explore() is used by all exploring AI units when the preceding calls (in AI_ExploreMove() and AI_ExploreSeaMove()) do not push a mission.

THIS METHOD IS EXTREMELY TIME CONSUMING in terms of computer time needed.

This method, when called on a huge map can take as long as 5 seconds PER UNIT!

The reason it does not usually create a problem is because it is not called very often. But I had 3 enemy units behind my lines during peace time (Triremes) which must go along coast. Because they could not explore, attack, or do anything else, these calls were taking 15 seconds per turn!

If you look at the code it is pretty easy to understand why the code takes so long. It cycles through every plot on the map to find the next best area to explore.

I am working on a new method to replace this one but I have to put it aside for now because I have other commitments (and I just decided to remove the units, lowering turn times from 30 to 10 seconds!) to my current project now that I know that it is not the problem!

Anyway... this might be something worth looking into and if anyone wants to help me when I am ready, I could use it. A new approach to finding explorable territory will not be easy even though I have an approach in mind.