Initial revision
This commit is contained in:
Guido van Rossum
parent
6f1f39188c
commit
8176258421
|
|
@ -0,0 +1,74 @@
|
|||
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.
|
||||
|
|
@ -0,0 +1,405 @@
|
|||
#
|
||||
# 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()')
|
||||
Loading…
Reference in New Issue