Initial revision

Lib/profile.doc

+The Python Profiler
+
+To use the profiler in its simplest form:
+
+	>>> import profile
+	>>> profile.run(statement)
+
+This will execute the statement and print statistics.  To get more
+information out of the profiler, use:
+
+	>>> import profile
+	>>> profile.run(statement, dump_file)
+
+where dump_file is a string naming a file to which the (binary)
+profile statistics is to be dumped.  The binary format is a dump of a
+dictionary.  The key is the function name in the format described
+above; the value is a tuple consisting of, in order, number of calls,
+total time spent in the function, total time spent in the function and
+all functions called from it, a list of functions called by this
+function, and a list of functions that called this function.  The dump
+can be read back using the following code:
+
+	>>> import marshal
+	>>> f = open(dump_file, 'r')
+	>>> dict = marshal.load(f)
+	>>> f.close()
+
+An easier way of doing this is by using the class `Stats' which is
+also defined in profile:
+
+	>>> import profile
+	>>> s = profile.Stats().init(dump_file)
+
+The following methods are defined for instances of `Stats':
+
+	print_stats()	-- Print the statistics in a format similar to
+			   the format profile.run() uses.
+	print_callers()	-- For each function, print all functions
+			   which it calls.
+	print_callees()	-- For each function, print all functions from
+			   which it is called.
+	sort_stats(n)	-- Sort the statistics for subsequent
+			   printing.  The argument determines on which
+			   field the output should be sorted.
+			   Possibilities are
+				-1	function name
+				0	number of calls
+				1	total time spent in a function
+				2	total time spent in a function
+					plus all functions it called
+	strip_dirs()	-- Strip the directory names off of the file
+			   names which are part of the function names.
+			   This undoes the effect of sort_stats(), but
+			   a subsequent sort_stats() does work.
+
+The methods sort_stats and strip_dirs may change in the future.
+
+Output of profile.run(statement) and of the print_stats() method of
+the `Stats' class consists of the following fields.
+
+	Number of times the function was called.
+	Total time spent in the function.
+	Mean time per function call (second field divided by first).
+	Total time spent in the function and all functions it called,
+		recursively.
+	Mean time time spent in the function and all functions it
+		called (fourth field divided by first).
+	Name of the function in the format
+		<file name>:<line number>(<function name>)
+
+The output of the print_callers and print_callees methods consists of
+the name of the function and the names of all function it called or
+was called from.  The latter names are followed by a parenthesised
+number which is the number of calls for this function.

Lib/profile.py

+#
+# Class for profiling python code.
+# Author: Sjoerd Mullender
+#
+# See the accompanying document profile.doc for more information.
+
+import sys
+import codehack
+import posix
+
+class Profile():
+
+	def init(self):
+		self.timings = {}
+		self.debug = None
+		self.call_level = 0
+		self.profile_func = None
+		self.profiling = 0
+		return self
+
+	def profile(self, funcname):
+		if not self.profile_func:
+			self.profile_func = {}
+		self.profile_func[funcname] = 1
+
+	def trace_dispatch(self, frame, event, arg):
+		if event == 'call':
+			funcname = codehack.getcodename(frame.f_code)
+			if self.profile_func and not self.profiling:
+				if self.profile_func.has_key(funcname):
+					return
+				self.profiling = 1
+			t = posix.times()
+			t = t[0] + t[1]
+			lineno = codehack.getlineno(frame.f_code)
+			filename = frame.f_code.co_filename
+			key = filename + ':' + `lineno` + '(' + funcname + ')'
+			self.call_level = depth(frame)
+			self.cur_frame = frame
+			pframe = frame.f_back
+			if self.debug:
+				s0 = 'call: ' + key + ' depth: ' + `self.call_level` + ' time: ' + `t`
+			if pframe:
+				pkey = pframe.f_code.co_filename + ':' + \
+					  `codehack.getlineno(pframe.f_code)` + '(' + \
+					  codehack.getcodename(pframe.f_code) + ')'
+				if self.debug:
+					s1 = 'parent: ' + pkey
+				if pframe.f_locals.has_key('__start_time'):
+					st = pframe.f_locals['__start_time']
+					nc, tt, ct, callers, callees = self.timings[pkey]
+					if self.debug:
+						s1 = s1+' before: st='+`st`+' nc='+`nc`+' tt='+`tt`+' ct='+`ct`
+					if callers.has_key(key):
+						callers[key] = callers[key] + 1
+					else:
+						callers[key] = 1
+					if self.debug:
+						s1 = s1+' after: st='+`st`+' nc='+`nc`+' tt='+`tt+(t-st)`+' ct='+`ct`
+					self.timings[pkey] = nc, tt + (t - st), ct, callers, callees
+			if self.timings.has_key(key):
+				nc, tt, ct, callers, callees = self.timings[key]
+			else:
+				nc, tt, ct, callers, callees = 0, 0, 0, {}, {}
+			if self.debug:
+				s0 = s0+' before: nc='+`nc`+' tt='+`tt`+' ct='+`ct`
+				s0 = s0+' after: nc='+`nc+1`+' tt='+`tt`+' ct='+`ct`
+			if pframe:
+				if callees.has_key(pkey):
+					callees[pkey] = callees[pkey] + 1
+				else:
+					callees[pkey] = 1
+			self.timings[key] = nc + 1, tt, ct, callers, callees
+			frame.f_locals['__start_time'] = t
+			if self.debug:
+				print s0
+				print s1
+			return
+		if event == 'return':
+			if self.profile_func:
+				if not self.profiling:
+					return
+				if self.profile_func.has_key(codehack.getcodename(frame.f_code)):
+					self.profiling = 0
+			self.call_level = depth(frame)
+			self.cur_frame = frame
+			pframe = frame.f_back
+			if self.debug:
+				s0 = 'return: '
+			else:
+				s0 = None
+			self.handle_return(pframe, frame, s0)
+			return
+		if event == 'exception':
+			if self.profile_func and not self.profiling:
+				return
+			call_level = depth(frame)
+			if call_level < self.call_level:
+				if call_level <> self.call_level - 1:
+					print 'heh!',call_level,self.call_level
+				if self.debug:
+					s0 = 'exception: '
+				else:
+					s0 = None
+				self.handle_return(self.cur_frame, frame, s0)
+			self.call_level = call_level
+			self.cur_frame = frame
+			return
+		print 'profile.Profile.dispatch: unknown debugging event:', `event`
+		return
+
+	def handle_return(self, pframe, frame, s0):
+		t = posix.times()
+		t = t[0] + t[1]
+		funcname = codehack.getcodename(frame.f_code)
+		lineno = codehack.getlineno(frame.f_code)
+		filename = frame.f_code.co_filename
+		key = filename + ':' + `lineno` + '(' + funcname + ')'
+		if self.debug:
+			s0 = s0 + key + ' depth: ' + `self.call_level` + ' time: ' + `t`
+		if pframe:
+			funcname = codehack.getcodename(frame.f_code)
+			lineno = codehack.getlineno(frame.f_code)
+			filename = frame.f_code.co_filename
+			pkey = filename + ':' + `lineno` + '(' + funcname + ')'
+			if self.debug:
+				s1 = 'parent: '+pkey
+			if pframe.f_locals.has_key('__start_time') and \
+				  self.timings.has_key(pkey):
+				st = pframe.f_locals['__start_time']
+				nc, tt, ct, callers, callees = self.timings[pkey]
+				if self.debug:
+					s1 = s1+' before: st='+`st`+' nc='+`nc`+' tt='+`tt`+' ct='+`ct`
+					s1 = s1+' after: st='+`t`+' nc='+`nc`+' tt='+`tt`+' ct='+`ct+(t-st)`
+				self.timings[pkey] = nc, tt, ct + (t - st), callers, callees
+				pframe.f_locals['__start_time'] = t
+		if self.timings.has_key(key):
+			nc, tt, ct, callers, callees = self.timings[key]
+		else:
+			nc, tt, ct, callers, callees = 0, 0, 0, {}, {}
+		if frame.f_locals.has_key('__start_time'):
+			st = frame.f_locals['__start_time']
+		else:
+			st = t
+		if self.debug:
+			s0 = s0+' before: st='+`st`+' nc='+`nc`+' tt='+`tt`+' ct='+`ct`
+			s0 = s0+' after: nc='+`nc`+' tt='+`tt+(t-st)`+' ct='+`ct+(t-st)`
+			print s0
+			print s1
+		self.timings[key] = nc, tt + (t - st), ct + (t - st), callers, callees
+
+	def print_stats(self):
+		import string
+		s = string.rjust('# calls', 8)
+		s = s + ' ' + string.rjust('tot time', 8)
+		s = s + ' ' + string.rjust('per call', 8)
+		s = s + ' ' + string.rjust('cum time', 8)
+		s = s + ' ' + string.rjust('per call', 8)
+		print s + ' filename(function)'
+		for key in self.timings.keys():
+			nc, tt, ct, callers, callees = self.timings[key]
+			if nc == 0:
+				continue
+			s = string.rjust(`nc`, 8)
+			s = s + ' ' + string.rjust(`tt`, 8)
+			s = s + ' ' + string.rjust(`tt/nc`, 8)
+			s = s + ' ' + string.rjust(`ct`, 8)
+			s = s + ' ' + string.rjust(`ct/nc`, 8)
+			print s + ' ' + key
+
+	def dump_stats(self, file):
+		import marshal
+		f = open(file, 'w')
+		marshal.dump(self.timings, f)
+		f.close()
+
+	# The following two functions can be called by clients to use
+	# a debugger to debug a statement, given as a string.
+	
+	def run(self, cmd):
+		import __main__
+		dict = __main__.__dict__
+		self.runctx(cmd, dict, dict)
+	
+	def runctx(self, cmd, globals, locals):
+##		self.reset()
+		sys.setprofile(self.trace_dispatch)
+		try:
+##			try:
+				exec(cmd + '\n', globals, locals)
+##			except ProfQuit:
+##				pass
+		finally:
+##			self.quitting = 1
+			sys.setprofile(None)
+		# XXX What to do if the command finishes normally?
+
+def depth(frame):
+	d = 0
+	while frame:
+		d = d + 1
+		frame = frame.f_back
+	return d
+
+def run(statement, *args):
+	prof = Profile().init()
+	try:
+		prof.run(statement)
+	except SystemExit:
+		pass
+	if len(args) == 0:
+		prof.print_stats()
+	else:
+		prof.dump_stats(args[0])
+
+def cv_float(val, width):
+	import string
+	s = `val`
+	try:
+		e = string.index(s, 'e')
+		exp = s[e+1:]
+		s = s[:e]
+		width = width - len(exp) - 1
+	except string.index_error:
+		exp = ''
+	try:
+		d = string.index(s, '.')
+		frac = s[d+1:]
+		s = s[:d]
+		width = width - len(s) - 1
+	except string.index_error:
+		if exp <> '':
+			return s + 'e' + exp
+		else:
+			return s
+	if width < 0:
+		width = 0
+	while width < len(frac):
+		c = frac[width]
+		frac = frac[:width]
+		if ord(c) >= ord('5'):
+			carry = 1
+			for i in range(width-1, -1, -1):
+				if frac[i] == '9':
+					frac = frac[:i]
+					# keep if trailing zeroes are wanted
+					# + '0' + frac[i+1:width]
+				else:
+					frac = frac[:i] + chr(ord(frac[i])+1) + frac[i+1:width]
+					carry = 0
+					break
+			if carry:
+				for i in range(len(s)-1, -1, -1):
+					if s[i] == '9':
+						s = s[:i] + '0' + s[i+1:]
+						if i == 0:
+							# gets one wider, so
+							# should shorten
+							# fraction by one
+							s = '1' + s
+							if width > 0:
+								width = width - 1
+					else:
+						s = s[:i] + chr(ord(s[i])+1) + s[i+1:]
+						break
+	# delete trailing zeroes
+	for i in range(len(frac)-1, -1, -1):
+		if frac[i] == '0':
+			frac = frac[:i]
+		else:
+			break
+	# build up the number
+	if width > 0 and len(frac) > 0:
+		s = s + '.' + frac[:width]
+	if exp <> '':
+		s = s + 'e' + exp
+	return s
+
+def print_line(nc, tt, ct, callers, callees, key):
+	import string
+	s = string.rjust(cv_float(nc,8), 8)
+	s = s + ' ' + string.rjust(cv_float(tt,8), 8)
+	if nc == 0:
+		s = s + ' '*9
+	else:
+		s = s + ' ' + string.rjust(cv_float(tt/nc,8), 8)
+	s = s + ' ' + string.rjust(cv_float(ct,8), 8)
+	if nc == 0:
+		s = s + ' '*9
+	else:
+		s = s + ' ' + string.rjust(cv_float(ct/nc,8), 8)
+	print s + ' ' + key
+
+class Stats():
+	def init(self, file):
+		import marshal
+		f = open(file, 'r')
+		self.stats = marshal.load(f)
+		f.close()
+		self.stats_list = None
+		return self
+
+	def print_stats(self):
+		import string
+		s = string.rjust('# calls', 8)
+		s = s + ' ' + string.rjust('tot time', 8)
+		s = s + ' ' + string.rjust('per call', 8)
+		s = s + ' ' + string.rjust('cum time', 8)
+		s = s + ' ' + string.rjust('per call', 8)
+		print s + ' filename(function)'
+		if self.stats_list:
+			for i in range(len(self.stats_list)):
+				nc, tt, ct, callers, callees, key = self.stats_list[i]
+				print_line(nc, tt, ct, callers, callees, key)
+		else:
+			for key in self.stats.keys():
+				nc, tt, ct, callers, callees = self.stats[key]
+				print_line(nc, tt, ct, callers, callees, key)
+
+	def print_callers(self):
+		if self.stats_list:
+			for i in range(len(self.stats_list)):
+				nc, tt, ct, callers, callees, key = self.stats_list[i]
+				print key,
+				for func in callers.keys():
+					print func+'('+`callers[func]`+')',
+				print
+		else:
+			for key in self.stats.keys():
+				nc, tt, ct, callers, callees = self.stats[key]
+				print key,
+				for func in callers.keys():
+					print func+'('+`callers[func]`+')',
+				print
+
+	def print_callees(self):
+		if self.stats_list:
+			for i in range(len(self.stats_list)):
+				nc, tt, ct, callers, callees, key = self.stats_list[i]
+				print key,
+				for func in callees.keys():
+					print func+'('+`callees[func]`+')',
+				print
+		else:
+			for key in self.stats.keys():
+				nc, tt, ct, callers, callees = self.stats[key]
+				print key,
+				for func in callees.keys():
+					print func+'('+`callees[func]`+')',
+				print
+
+	def sort_stats(self, field):
+		stats_list = []
+		for key in self.stats.keys():
+			t = self.stats[key]
+			nt = ()
+			for i in range(len(t)):
+				if i == field:
+					nt = (t[i],) + nt[:]
+				else:
+					nt = nt[:] + (t[i],)
+			if field == -1:
+				nt = (key,) + nt
+			else:
+				nt = nt + (key,)
+			stats_list.append(nt)
+		stats_list.sort()
+		self.stats_list = []
+		for i in range(len(stats_list)):
+			t = stats_list[i]
+			if field == -1:
+				nt = t[1:] + t[0:1]
+			else:
+				nt = t[1:]
+				nt = nt[:field] + t[0:1] + nt[field:]
+			self.stats_list.append(nt)
+
+	def strip_dirs(self):
+		import os
+		newstats = {}
+		for key in self.stats.keys():
+			nc, tt, ct, callers, callees = self.stats[key]
+			newkey = os.path.basename(key)
+			newcallers = {}
+			for c in callers.keys():
+				newcallers[os.path.basename(c)] = callers[c]
+			newcallees = {}
+			for c in callees.keys():
+				newcallees[os.path.basename(c)] = callees[c]
+			newstats[newkey] = nc, tt, ct, newcallers, newcallees
+		self.stats = newstats
+		self.stats_list = None
+
+# test command
+def debug():
+	prof = Profile().init()
+	prof.debug = 1
+	try:
+		prof.run('import x; x.main()')
+	except SystemExit:
+		pass
+	prof.print_stats()
+
+def test():
+	run('import x; x.main()')