diff options
Diffstat (limited to 'Lib')
| -rw-r--r-- | Lib/profile.doc | 74 | ||||
| -rwxr-xr-x | Lib/profile.py | 405 |
2 files changed, 479 insertions, 0 deletions
diff --git a/Lib/profile.doc b/Lib/profile.doc new file mode 100644 index 0000000..753d159 --- /dev/null +++ b/Lib/profile.doc @@ -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. diff --git a/Lib/profile.py b/Lib/profile.py new file mode 100755 index 0000000..1c7a6e2 --- /dev/null +++ b/Lib/profile.py @@ -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()') |