Profiling Spring performance

[el_muchacho]

Hello,

If you are interested in knowing where in the code Spring spends most of its time, I will make some publicity for an excellent profiling tool which works in conjunction with Visual Studio 2002/2003. Its authors (Compuware), besides selling effective development tools, have had the excellent idea to offer a completely free, yet powerful "community edition" which isn't time limited and which is perfect for Spring.

Not only does it instrument the code at line level, but it also shows quite helpful call graphs. One only needs to register on their website to be able to download the package.

Anyway, in case you are wondering, I have done a profiling session on the "Sub operations" test script, which gives a good idea of a game with air, ground and sea operations. Beware, profiling the whole code slows down the performance by a factor of 50 or so. So doing this requires as much power as possible and incresing the priority of the application.

Here are the top 20 methods in my test :

Code: Select all

 Method Name 				 % in Method	% with Child. Called   Average 

 CPathFinder::TestSquare		12.9 	20.2 	          23,164,360   1.4 
 CPathEstimator::TestBlock 		3.7 	4.2 			7,320,960 	1.2 
 CMoveMath::SpeedMod 				2.8 	3.7 			17,580,109 	0.4 
 CVertexArray::AddVertex0 			1.9 	1.9 			40,055,176 	0.1 
 CReadMap::GroundBlocked 			1.3 	1.3 			22,703,597 	0.1 
 CGroundMoveMath::SquareIsBlocked 
											1.0 	1.9 			15,182,654 	0.2 
 CVertexArray::AddVertexTC 		0.8 	0.8 			10,485,512 	0.2 
 CRangedGoalPFD::Heuristic 		0.7 	0.7 			15,765,430 	0.1 
 CGroundMoveMath::SpeedMod 		0.7 	0.7 			10,655,768 	0.2 
 CGroundMoveMath::IsBlocked 		0.6 	3.3 			3,218,695 	0.5 
 CRangedGoalPFD::IsGoal 			0.4 	0.4 			4,785,665 	0.2 
 CMatrix44f::CMatrix44f 			0.4 	0.4 			2,030,254 	0.5 
 CompareProjDist 				0.4 	0.4 			14,835,236 	0.1 
 CCamera::InView 				0.3 	0.3 			2,731,937 	0.3 
 CShipMoveMath::SquareIsBlocked . 0.3 . 0.6 . 		5,291,876 . 0.1 
 CWakeProjectile::Update . 		0.2 . 0.2 . 		3,183,699 	0.2 
 CVertexArray::EndStrip 		 0.1 	0.1 			3,260,311 	0.1 
 CHoverMoveMath::SquareIsBlocked   0.1 	0.3 		2,229,523 	0.1 
 CShipMoveMath::SpeedMod 		0.1 	0.1 			5,000,792 	0.1 
 CMatrix44f::~CMatrix44f 		  0.1 	0.1 			2,996,583 	0.0  
 

Column 1 : % in Method = % of time spent in the method
Column 2 : % with Child. = %of time spent in the method and its callees
Column 3 : Called = number of times the method has been called
Column 4 : Average = average time spent in the method (in microseconds)

One sees that most of the methods belong to the pathfinder.

[Gabba]

Nice. How do you interpret those results?

[10053r]

It means that the game spends 20% of its CPU cycles doing one particular thing related to pathing (CPathFinder:TestSquare). Since that particular method takes up WAY more time than the next one down (20% vs. 4.2%), it means that someone should take it apart and see if it can be sped up in any way. Since it is related to pathfinding, it will probably make things much smoother in games with lot of units.

[SJ]

Rerun the test on the pathfinder I checked in today and see if there is a difference, although the new version is mostly meant to fix all the bugs in the pathfinder not so much for speed. But there should be some speedup effect from some of the bugfixes

[jouninkomiko]

good work, el muchacho :)

[el_muchacho]

[Sean Mirrsen]

The amount of CPU going to pathfinding is increasing with several things: the number of units you have, the amount of time they spend navigating the map, and the size of the map itself.

When I tested a rather flat map (Comet Catcher to be precise), with around 800 units total for both sides, the pathfinding took more CPU time than drawing the lot to the screen.

Btw, in that listing AddVertex0 has been called like.. 40 million times, and it still is only the fourth in the list.

[el_muchacho]

It's difficult to achieve consistent results between runs.