Profiling stuff that may be useful for the devs

[ender[fdn]]

Hey guys, here's a quick scope timer implementation I put together that might be useful for tracking down places that are causing lag:

profiling.py:

Code: Select all

################################################
## Andrew Burke ([email protected])

import sys, traceback, time

def timeSort( lhs, rhs ):
	return int( lhs[ 'totalTime' ] - rhs[ 'totalTime' ] )

class Profiler:
	def __init__( self ):
		self.records = {}
		
	def AddRecord( self, scopeName, runTime ):
		if ( scopeName not in self.records ):
			self.records[ scopeName ] = []

		self.records[ scopeName ].append( runTime )
		
	def PrintReport( self ):
		scopeInfo = []
		
		for scopeName in self.records:
			totalRuns = 0
			totalTime = 0
			
			for runTime in self.records[ scopeName ]:
				totalTime += runTime
				totalRuns += 1
		
			averageTime = totalTime / totalRuns
			
			scopeInfo.append( { 'scopeName' : scopeName, 'totalRuns' : totalRuns, 'totalTime' : totalTime, 'averageTime' : averageTime } )
		
		scopeInfo.sort( timeSort )
		scopeInfo.reverse()
		
		print "[ %10s ] [ %10s ] [ %6s ] [ Scope ]" % ( 'Total', 'Avg', 'Runs' )
		for info in scopeInfo:
			print "[ %0.8f ] [ %0.8f ] [ %06d ] [ %s ]" % ( info[ 'totalTime' ], info[ 'averageTime' ], info[ 'totalRuns' ], info[ 'scopeName' ] )

class ScopeTimer:
	def __init__( self, profiler, scopeName = 'Unknown' ):
		self.scopeName = str( scopeName )
		self.profiler = profiler
		self.startTime = time.clock()

	def __del__( self ):
		timeDelta = time.clock() - self.startTime
		self.profiler.AddRecord( self.scopeName, timeDelta )
		

example.py

Code: Select all

from profiling import Profiler, ScopeTimer
import time

p = Profiler()

def test1():
	s = ScopeTimer( p, 'test1' )
	
	time.sleep( 1 )
	
def test2():
	s = ScopeTimer( p, 'test2' )
	
	time.sleep( 3 )
	

test1()
test1()
test2()
test2()
test1()
test1()
test2()	

p.PrintReport()

example output:

Code: Select all

[      Total ] [        Avg ] [   Runs ] [ Scope ]
[ 9.00093084 ] [ 3.00031028 ] [ 000003 ] [ test2 ]
[ 3.99950524 ] [ 0.99987631 ] [ 000004 ] [ test1 ]

As you can see, this gives you profiling information in decreasing order by time spent in that scope. This is usually a nice way to attack this problem because it's at easy as adding one of those ScopeTimer objects to whatever scope you want to time. When it goes out of scope, it logs how much time it spent in that scope into the given Profiler. I'll probably be trying to figure out a way to guess a scope as an improvement, but that will likely only work at the function level if I can even find a way to do it.

I have some other debugging stuff that I've found useful for working on a TK punishment system that I'll be posting soon, but thought you might find a use for this stuff right now with the lag issues going on with .5.

Let me know if you have any questions or need any additional features, I'd love to help out any way I can.

[Wasteland]

Cool. Talk about deeds not words.

[ender[fdn]]

It occurred to me that I should show a second example:

Code: Select all

from profiling import Profiler, ScopeTimer
from whrandom import randint
import time

p = Profiler()

def test1():
	s = ScopeTimer( p, 'test1' )
	
	time.sleep( 1 )
	
	if ( randint( 0, 1 ) ):
		s2 = ScopeTimer( p, 'test1:conditional' )
		time.sleep( 1 )
	
def test2():
	s = ScopeTimer( p, 'test2' )
	
	time.sleep( 3 )
	

test1()
test1()
test2()
test2()
test1()
test1()
test2()	

p.PrintReport()

As you can see, I've put another ScopeTimer in the conditional in test1. This results in the following output:

Code: Select all

[      Total ] [        Avg ] [   Runs ] [ Scope ]
[ 9.00048721 ] [ 3.00016240 ] [ 000003 ] [ test2 ]
[ 4.99985054 ] [ 1.24996263 ] [ 000004 ] [ test1 ]
[ 1.00001313 ] [ 1.00001313 ] [ 000001 ] [ test1:conditional ]

That new scope was only hit 1 time and took about 1 second, as you would expect. The point is just to show that the ScopeTimer will time whatever scope it's in, and you can have many of them within a single function.

You can also see that the 'test1' scope takes into account the sub-scopes. It spent 5 seconds total in 'test1' due to the one hit on 'test1:conditional'.

Anyway, hopefully I haven't managed to confuse the issue more with this post. Again, if you have questions or need something to make this more useful for use with PR, just let me know, I'd love to help out.

[Griffon2-6]

Wow, they're gonna appreciate this. They might just stick a prefix before your name.

[KingofCamelot]

Interesting. I was actually just screwing around with the built-in Python profile module and got it to work with BF2 so thats what I've been using, and you're right, it does add a ton of helpful information.

Already detected some problems.

Thanks a ton for posting though, after the 0.5 release rush dies down we may have a job for you.

[Ghostrider]

Thanks a lot ender[fdn]. We really appreciate your contribution as the team continues to address the lag issues.

If you're interested in helping out in any way you can, you can check this thread out for more info.


-Ghost

[ender[fdn]]

Hmm, one more change:

Code: Select all

def timeSort( lhs, rhs ):
	return int( lhs[ 'totalTime' ] - rhs[ 'totalTime' ] )

class Profiler:
	def __init__( self, enabled ):
		self.enabled = enabled
		self.records = {}
		
	def AddRecord( self, scopeName, runTime ):
		if ( not self.enabled ): return
		if ( scopeName not in self.records ):
			self.records[ scopeName ] = []

		self.records[ scopeName ].append( runTime )
		
	def PrintReport( self ):
		scopeInfo = []
		
		for scopeName in self.records:
			totalRuns = 0
			totalTime = 0
			
			for runTime in self.records[ scopeName ]:
				totalTime += runTime
				totalRuns += 1
		
			averageTime = totalTime / totalRuns
			
			scopeInfo.append( { 'scopeName' : scopeName, 'totalRuns' : totalRuns, 'totalTime' : totalTime, 'averageTime' : averageTime } )
		
		scopeInfo.sort( timeSort )
		scopeInfo.reverse()
		
		print "[ %10s ] [ %10s ] [ %6s ] [ Scope ]" % ( 'Total', 'Avg', 'Runs' )
		for info in scopeInfo:
			print "[ %0.8f ] [ %0.8f ] [ %06d ] [ %s ]" % ( info[ 'totalTime' ], info[ 'averageTime' ], info[ 'totalRuns' ], info[ 'scopeName' ] )

class ScopeTimer:
	def __init__( self, profiler, scopeName = 'Unknown' ):
		self.scopeName = str( scopeName )
		self.profiler = profiler
		self.startTime = time.clock()

	def __del__( self ):
		timeDelta = time.clock() - self.startTime
		self.profiler.AddRecord( self.scopeName, timeDelta )
		

So, adding an enabled boolean to the profiler so you can easily turn it off:

Code: Select all

PROFILE_ENABLED = 1

...

p = Profiler( PROFILE_ENABLED )
...

[Wipeout]

Holy poop. (lol!)

I might just have to look into coding....

[Griffon2-6]

That's python, and to learn that, you'd have to learn the whole language. BF2 n00b coding is a lot easier, and I learned how to do it in a few days (it is very limited)