Measure, measure, measure

(Skipping the introductory post for later - maybe.)

Today BrainDamage - developer of the SpringLobby client for the Spring Lobby - showed me some profiles of the Spring engine. Some interesting things can be observed in the profile. That is, if you are in some way involved with, or interested in, Spring engine development :-)


This is the big picture. The red blobs are the program entry point and related functions. From this the call graph branches into CGame::Update (left) and CGame::Draw (right). Let's zoom in to have a clearer picture of this.


Boring eh? Not much happening yet. The left branch (green) goes to CGame::Update, which then branches out to all - synchronized and unsynchronized - non-rendering logic. The right branch (also green) goes to CGame::Draw, which branches out to all rendering code. Update takes 38%, rendering 61%. Rendering is this high because the engine always tries to maintain an as high number of FPS as possible. In other words, all CPU time not spent on logic, is - by definition - spent on rendering. This also explains why it sums to 100% (approximately).


It gets interesting when we dive deeper inside the left part of the graph (click to enlarge). CGame::ClientReadNet is the sole method called by CGame::Update. Due to the networking model, this is the method calling the CGame::SimFrame method - the "main()" of the simulation - whenever a network message arrives instructing it to do so. This part of the tree as a whole took 38% of CPU time, so I'll normalize CPU percentages against this value.

We see a few methods taking single digit CPU percentages, but we see one taking 57% of the entire simulation: CUnitHandler::Update. This isn't too suprising. Lots of units involved in a real time strategy game. Let's see where this time is spent. About a third goes to CUnit::Update - called every frame for every unit. The rest goes to CUnit::SlowUpdate - called every sixteenth frame for every unit. The fact that the least called method of these two eats the most CPU may come as a surprise, but Spring unit simulation code was built taking into account that CPU intensive tasks are better not done every game frame for every unit. This is why SlowUpdate was invented: to perform the heavy tasks only once every few frames. (It's also spread out over all game frames, ie. one sixteenth of all units is SlowUpdated every frame.)


Here we see how CUnit::SlowUpdate spends it's time: it likes to call CAirMoveType::SlowUpdate. A movetype is an abstraction of the movement class of a unit. Each mobile unit has a movetype. Obviously, the CAirMoveType is used for airplanes. So airplanes take about 28% of total simulation time. Compare this to CGroundMoveType, which uses only 3%, even though BrainDamage ensured me he made more ground units then aircraft!

So what is burning the CPU inside CAirMoveType? It's the highlighted node: CLosHandler::MoveUnit. CLosHandler is the class that handles Line Of Sight calculations. Appararently over one third of all the simulation time is spent calculating whether units can see each other, while the other two thirds are fragmented over a lot of different methods.

This sounds like a bottleneck, and who knows, it might be optimizable. (To be continued?)

PS.: for those interested, here is the full graph.