deleted

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
 
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
 
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
 
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.
 
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):


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.

Spoiler this is what the data looks like :

[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?

Go download the 1/29 build (not the assert one, the previous build), this is a direct link to the warlords version

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
 
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.
 
Top Bottom