Laggy City Interface

Afforess

Afforess

The White Wizard
Joined
Jul 31, 2007
Messages
12,239
Location
Austin, Texas
I measured the time it takes to select an icon in the city interface and add it to the construction queue and it's taking 2 seconds... in the Renaissance. It gets worse as the game progresses.

I've made a few changes, per EmperorFool's suggestions.

However, I'm thinking about caching some of the CanConstruct code that doesn't change in-between turns and just recalculating it turn by turn, instead of several hundred times. Specifically, things I could cache would be the min/max latitude, which never changes, a check for coastal or peak requirements, which never change, prerequisite terrain, which only would change when the city expands culture or loses some borders, prerequisite civics, which only change when a player changes civics, competing buildings, which only change when a new building is constructed, and prerequisite city vicinity resources, which only change when a new resource is discovered. This should eliminate most of the hefty computations... (The compuations are not actually that bad, except that when a function is called ~400 times, it adds up...)

I think I would create 2 new arrays, one for the player, for the player (empire-wide) CanConstruct function and one for each city.

Quick question, how hard is it to add an array with TWO Boolean values for each index? I need to save whether it returns true or false and bTestVisible...
 
I would first recommend that you do the same type of code profiling (timing) in C++ that you did in Python. There is a system function clock() in C that will get you the number of CPU clock cycles since the program started. For your larger loops, grab the value before the loop, grab it again after, and log the difference with a label using logMsg().

Code: 
#include <time.h>
#include "CvBugOptions.h"  // for logMsg()

...

clock_t start = clock();
// code to time
clock_t diff = clock() - start;

logMsg("<label>: %d ms", (int)(diff * 1000 / CLOCKS_PER_SEC));

Optimizing code that you haven't profiled is a recipe for disappointment. You'll spend hours writing really nice caching logic only to find you've shaved 2ms off your 1000ms task. :cry:

Edit: Bah, what am I thinking. Use Firaxis's own PROFILE_FUNC() macros!
 
I am pretty sure you are not describing vanilla behavior. Does the mod in question use canTrain, cannotTrain, canConstruct, cannotConstruct in python? Perhaps you have already done this experiment, but I can't tell from the description: Turn off the callbacks and see what difference this makes. Of course this will make the game play differently. If this makes the lag vanish, perhaps the key project is to migrate that python into sdk. As you know, these particular routines are called thousands of times.
 
davidlallen said:
I am pretty sure you are not describing vanilla behavior. Does the mod in question use canTrain, cannotTrain, canConstruct, cannotConstruct in python? Perhaps you have already done this experiment, but I can't tell from the description: Turn off the callbacks and see what difference this makes. Of course this will make the game play differently. If this makes the lag vanish, perhaps the key project is to migrate that python into sdk. As you know, these particular routines are called thousands of times.
Click to expand...

I use exactly 0 python callbacks. Remember, I was the one who went to the effort to find 15 extra python calls that were unnecessary, create new callbacks, and turn them off?

EmperorFool said:
I would first recommend that you do the same type of code profiling (timing) in C++ that you did in Python. There is a system function clock() in C that will get you the number of CPU clock cycles since the program started. For your larger loops, grab the value before the loop, grab it again after, and log the difference with a label using logMsg().

Code: 
#include <time.h>
#include "CvBugOptions.h"  // for logMsg()

...

clock_t start = clock();
// code to time
clock_t diff = clock() - start;

logMsg("<label>: %d ms", (int)(diff * 1000 / CLOCKS_PER_SEC));
Optimizing code that you haven't profiled is a recipe for disappointment. You'll spend hours writing really nice caching logic only to find you've shaved 2ms off your 1000ms task. :cry:

Edit: Bah, what am I thinking. Use Firaxis's own PROFILE_FUNC() macros!
Click to expand...

Hmm, okay. I just know that my canConstruct is really long, it has a LOT of extra loops, so I suspect it's my love of arrays that is biting me here.

I'll try that profiler.
 
Just profiled it. Apparently, all 404 CanConstruct calls take ~ 10 ms put total. (Each one was ~0 ms). So my canConstruct loop is not the problem. Then what on earth is taking ~2 seconds for the game to do in this small code block?

Code: 
# Buildings to construct
				for i in range ( g_NumBuildingClassInfos ):
					if (not isLimitedWonderClass(i)):
						eLoopBuilding = gc.getCivilizationInfo(pHeadSelectedCity.getCivilizationType()).getCivilizationBuildings(i)

						if (pHeadSelectedCity.canConstruct(eLoopBuilding, False, True, False)):
							screen.appendMultiListButton( "BottomButtonContainer", gc.getBuildingInfo(eLoopBuilding).getButton(), iRow, WidgetTypes.WIDGET_CONSTRUCT, i, -1, False )
							screen.show( "BottomButtonContainer" )
							
							if ( not pHeadSelectedCity.canConstruct(eLoopBuilding, False, False, False) ):
								screen.disableMultiListButton( "BottomButtonContainer", iRow, iCount, gc.getBuildingInfo(eLoopBuilding).getButton() )

							iCount = iCount + 1
							bFound = True

				iCount = 0
				if (bFound):
					iRow = iRow + 1
				bFound = False
 
Yes, I recall that you have dug into callbacks, but from your OP it was not clear if this is the same mod or a different one. I often look into mods where I do not initially understand how all the components relate, so I wanted to check the easy stuff first.

How did you determine that *this* code block takes two seconds? For example did you comment out just this block, and the lag goes away? I am often surprised that code I think is the problem, isn't really. Again, just checking the easy stuff first.
 
He used BugUtil.Timer() to time each of the major blocks in the function that draws all the build buttons. The total time was 2.0s IIRC and this one block posted was 1.6s.

You can test each iteration to see if it's one building in particular that is lagging. The Timer class supports this. There is an example for how to do this in the comment for the class in that module. Or you can test each call inside the loop. You could do this by creating one Timer for each call so you can see the totals across calls as well as per call.
 
EmperorFool said:
He used BugUtil.Timer() to time each of the major blocks in the function that draws all the build buttons. The total time was 2.0s IIRC and this one block posted was 1.6s.

You can test each iteration to see if it's one building in particular that is lagging. The Timer class supports this. There is an example for how to do this in the comment for the class in that module. Or you can test each call inside the loop. You could do this by creating one Timer for each call so you can see the totals across calls as well as per call.
Click to expand...

Awesome. Sometimes I wonder if BUG adds code just for me. :lol:

Okay, here are the results. They are very intriguing. Most of the buildings (90%) took 0 ms. I assume those buildings were ones I couldn't construct so no button was needed. About 8% took between 14 and 16 seconds EACH. Seems a bit high, considering that the game drew all 20 units I could train out of ~700 in only 23 ms TOTAL. Then there were 1-2% buildings that took a long time, between 50 and 75ms, but one was as long as 100 ms. I don't understand why they would be taking so long...

Alright, here's some more data. I moved the timer to only time this block of code, print each part and the total:

Code: 
screen.appendMultiListButton( "BottomButtonContainer", gc.getBuildingInfo(eLoopBuilding).getButton(), iRow, WidgetTypes.WIDGET_CONSTRUCT, i, -1, False )
                            screen.show( "BottomButtonContainer" )
                            
                            if ( not pHeadSelectedCity.canConstruct(eLoopBuilding, False, False, False) ):
                                screen.disableMultiListButton( "BottomButtonContainer", iRow, iCount, gc.getBuildingInfo(eLoopBuilding).getButton() )

                            iCount = iCount + 1
                            bFound = True

Since we know the canConstruct call takes ~0ms to compute, the buttons must be taking the rest of the time. The timer still showed that each part took 16+ ms to compute... The plot thickens...

Except for the simple fact that they can't be taking as long as the data makes me suspect. I put a timer around the individual button displays for units (The CanTrain loop looks identical to the canConstruct one, except for the function call. I know the CanTrain call in my mod is LONGER than the CanConstruct call, I've profiled it in the past. ) Each unit that was displayed took 0 ms each, so displaying the button takes none of the time up either.

Now, since we can eliminate the function calls to display the button and the canConstruct calls as possible culprits, it leaves with nothing. I've eliminated everything inside the timed area... WHERE IS THE MYSTERIOUS TIME DELAY COMING FROM!? :mad:
 
I would not eliminate the display function without knowing more.
If the problem only occurs with new buildings, i would check the buttons itself, maybe there's the problem.
I don't know, if for smaller buttons maybe the scaling needs some time, or maybe filetype makes a difference...or...or..
 
Afforess said:
Since we know the canConstruct call takes ~0ms to compute
Click to expand...

I don't think you can safely assume this. Note that timing in Python is a less accurate when the times are very small. This is why I suggested profiling in the SDK at this point. Start by profiling the entire canConstruct() function to see if it's the culprit.
 
EmperorFool said:
I don't think you can safely assume this. Note that timing in Python is a less accurate when the times are very small. This is why I suggested profiling in the SDK at this point. Start by profiling the entire canConstruct() function to see if it's the culprit.
Click to expand...

I did profile it in the SDK, with the Logmsg and cool C timer you showed me. The longest any 1 building took was 1 ms. ;)
 
It is often frustrating to compare wall clock time against the profiling time from any profiler. The machine is doing a lot of other stuff which takes wall clock time and does not show in the profiler. Usually, when I am successful with profiling, I find which one of some top level functions takes longer than others, and then improve that one. Usually I do not try to force the totals from the profiler to add up to some observed wall clock time. There are too many other variables.

I wonder if some of the 2 sec may be related to data loading. Suppose you trigger the 2 second action, and it displays some buttons. This should load any data which will need to be loaded. Does the same 2 sec delay occur the second time you trigger the same action? The buttons should not need to be reloaded.

What is the resolution of the timer which is being used? I assume it is 1 ms, which means there is a possible variability of 0.5 ms in each number. If you are adding up a large number of these values, the error itself can mount up. For example, 100 calls which each claim to take 0 ms may take, in aggregate, up to 49 ms.
 
Hmmm, Okay. So in a worst case scenario, the CanConstruct call took ~250 ms total. That still leaves a lot of other time unaccounted for though. I'm going to try to measure the total time it took for it to only display the icons...
 
Comment out both calls to canConstruct() and put "True" in their places. Then run the timing again for the total. This will calculate just the time it takes to load and draw the buttons themselves. Maybe that's what you meant.

Then reverse the situation: replace the canConstruct() calls and comment out the code that adds the icons to the UI. Time it again.
 
Okay, I slowly commented things out, line by line. Nothing affected the time it took to draw the screen, except when I commented this part out:
Code: 
screen.appendMultiListButton( "BottomButtonContainer", gc.getBuildingInfo(eLoopBuilding).getButton(), iRow, WidgetTypes.WIDGET_CONSTRUCT, i, -1, False )

Apparently drawing the button takes between 13-30 ms. Which sucks, as this is in the exe, yes?
(I suspect that, once again, the time has nothing to do with the button, so much as it has to do with the Civ4 C/python inter-language interpreter.)
 
I wonder if there is something not quite right about appendMultiListButton. I get Python "C++" errors when using it. They are extremly rare but seemingly impossible to get rid of.
 
General Tso said:
I wonder if there is something not quite right about appendMultiListButton. I get Python "C++" errors when using it. They are extremly rare but seemingly impossible to get rid of.
Click to expand...

Are you calling it for an invalid building? If you try to look up the button for NO_BUILDING, that would cause issues.
 
Afforess said:
Apparently drawing the button takes between 13-30 ms. Which sucks, as this is in the exe, yes?
Click to expand...

Does vanilla take the same amount of time to draw the same number of buttons? In this case you can blame the C++/python interface. If not, the problem is in the mod. It may not be where you expect, but this would clearly demonstrate whether the mod code has introduced the problem.
 
davidlallen said:
Does vanilla take the same amount of time to draw the same number of buttons? In this case you can blame the C++/python interface. If not, the problem is in the mod. It may not be where you expect, but this would clearly
demonstrate whether the mod code has introduced the problem.
Click to expand...

I used BUG 4.2 as a stand in for vanilla. (Vanilla doesn't have the timer class)

Replicating my experiment, I only had 1ms times for drawing the button, which confirms your theory DavidAllen. (And gives me hope).

What could be slowing this down? My CvMainInterface is very similar to BUG's, the only differences are the revolution bar from RevDCM...
 
Are you calling it for an invalid building? If you try to look up the button for NO_BUILDING, that would cause issues.
Click to expand...

I'm using it to add custom buttons to certain units. In the process of testing the problem I tried using all kinds of passed variables, but nothing worked. I'm currently just trapping out the error, so once every hundred games or so some of the buttons do not show up. :sad:
 
You must log in or register to reply here.

Similar threads

Ferocca
"not a member" problem
Replies
2
Views
255
Ferocca
Ferocca
CSD
[TUTORIAL] How to Set Persistent Variables in Pure Python
Replies
4
Views
556
CSD
CSD
P
Potential Python Optimizations for Civ4 on Intel and AMD CPUs
Replies
11
Views
705
PurpleMelbourne
P
L. Vern
  • Locked
  • Poll
[Vote] (7-22) Allow Non-Recon Units to Pick Up Ancient Ruins
2
Replies
37
Views
2K
CppMaster
CppMaster
Spillsandstains
Getting the XML to accept a double-move doesn't work with custom features
Replies
4
Views
266
Nightinggale
Nightinggale
Top Bottom