From edb5ffb2c145fc52df2195c22688db51034b08d5 Mon Sep 17 00:00:00 2001 From: Fred Drake Date: Fri, 8 Jun 2001 04:25:24 +0000 Subject: [PATCH] Performance improvements to the profiler: Ensure that all the default timers are called as functions, not an expensive method wrapper around a variety of different functions. Agressively avoid dictionary lookups. Modify the dispatch scheme (Profile.trace_dispatch_*(), where * is not 'call', 'exception' or 'return') so that the callables dispatched to are simple functions and not bound methods -- this reduces the number of layers of Python call machinery that gets touched. Remove a couple of duplicate imports from the "if __name__ == ..." section. This closes SF patch #430948. --- Lib/profile.py | 150 ++++++++++++++++++++++++++++++------------------- 1 file changed, 93 insertions(+), 57 deletions(-) diff --git a/Lib/profile.py b/Lib/profile.py index a32a1c1bc44..a6d56376c03 100755 --- a/Lib/profile.py +++ b/Lib/profile.py @@ -89,6 +89,16 @@ def help(): print 'along the Python search path' +if os.name == "mac": + def _get_time_mac(timer=MacOS.GetTicks): + return timer() / 60.0 + +if hasattr(os, "times"): + def _get_time_times(timer=os.times): + t = timer() + return t[0] + t[1] + + class Profile: """Profiler class. @@ -132,62 +142,60 @@ def __init__(self, timer=None): self.cur = None self.cmd = "" - self.dispatch = { \ - 'call' : self.trace_dispatch_call, \ - 'return' : self.trace_dispatch_return, \ - 'exception': self.trace_dispatch_exception, \ - } - if not timer: if os.name == 'mac': import MacOS self.timer = MacOS.GetTicks self.dispatcher = self.trace_dispatch_mac - self.get_time = self.get_time_mac + self.get_time = _get_time_mac elif hasattr(time, 'clock'): - self.timer = time.clock + self.timer = self.get_time = time.clock self.dispatcher = self.trace_dispatch_i elif hasattr(os, 'times'): self.timer = os.times self.dispatcher = self.trace_dispatch + self.get_time = _get_time_times else: - self.timer = time.time + self.timer = self.get_time = time.time self.dispatcher = self.trace_dispatch_i else: self.timer = timer t = self.timer() # test out timer function try: - if len(t) == 2: + length = len(t) + except TypeError: + self.get_time = timer + self.dispatcher = self.trace_dispatch_i + else: + if length == 2: self.dispatcher = self.trace_dispatch else: self.dispatcher = self.trace_dispatch_l - except TypeError: - self.dispatcher = self.trace_dispatch_i + # This get_time() implementation needs to be defined + # here to capture the passed-in timer in the parameter + # list (for performance). Note that we can't assume + # the timer() result contains two values in all + # cases. + def get_time_timer(timer=timer, + reduce=reduce, reducer=operator.add): + return reduce(reducer, timer(), 0) + self.get_time = get_time_timer self.t = self.get_time() self.simulate_call('profiler') - - def get_time(self): # slow simulation of method to acquire time - t = self.timer() - if type(t) == type(()) or type(t) == type([]): - t = reduce(lambda x,y: x+y, t, 0) - return t - - def get_time_mac(self): - return self.timer()/60.0 - # Heavily optimized dispatch routine for os.times() timer def trace_dispatch(self, frame, event, arg): - t = self.timer() + timer = self.timer + t = timer() t = t[0] + t[1] - self.t # No Calibration constant # t = t[0] + t[1] - self.t - .00053 # Calibration constant - if self.dispatch[event](frame,t): - t = self.timer() + if self.dispatch[event](self, frame,t): + t = timer() self.t = t[0] + t[1] else: - r = self.timer() + r = timer() self.t = r[0] + r[1] - t # put back unrecorded delta return @@ -196,33 +204,37 @@ def trace_dispatch(self, frame, event, arg): # Dispatch routine for best timer program (return = scalar integer) def trace_dispatch_i(self, frame, event, arg): - t = self.timer() - self.t # - 1 # Integer calibration constant - if self.dispatch[event](frame,t): - self.t = self.timer() + timer = self.timer + t = timer() - self.t # - 1 # Integer calibration constant + if self.dispatch[event](self, frame,t): + self.t = timer() else: - self.t = self.timer() - t # put back unrecorded delta + self.t = timer() - t # put back unrecorded delta return - # Dispatch routine for macintosh (timer returns time in ticks of 1/60th second) + # Dispatch routine for macintosh (timer returns time in ticks of + # 1/60th second) def trace_dispatch_mac(self, frame, event, arg): - t = self.timer()/60.0 - self.t # - 1 # Integer calibration constant - if self.dispatch[event](frame,t): - self.t = self.timer()/60.0 + timer = self.timer + t = timer()/60.0 - self.t # - 1 # Integer calibration constant + if self.dispatch[event](self, frame,t): + self.t = timer()/60.0 else: - self.t = self.timer()/60.0 - t # put back unrecorded delta + self.t = timer()/60.0 - t # put back unrecorded delta return # SLOW generic dispatch routine for timer returning lists of numbers def trace_dispatch_l(self, frame, event, arg): - t = self.get_time() - self.t + get_time = self.get_time + t = get_time() - self.t - if self.dispatch[event](frame,t): - self.t = self.get_time() + if self.dispatch[event](self, frame,t): + self.t = get_time() else: - self.t = self.get_time()-t # put back unrecorded delta + self.t = get_time() - t # put back unrecorded delta return @@ -237,11 +249,12 @@ def trace_dispatch_call(self, frame, t): fcode = frame.f_code fn = (fcode.co_filename, fcode.co_firstlineno, fcode.co_name) self.cur = (t, 0, 0, fn, frame, self.cur) - if self.timings.has_key(fn): - cc, ns, tt, ct, callers = self.timings[fn] - self.timings[fn] = cc, ns + 1, tt, ct, callers + timings = self.timings + if timings.has_key(fn): + cc, ns, tt, ct, callers = timings[fn] + timings[fn] = cc, ns + 1, tt, ct, callers else: - self.timings[fn] = 0, 0, 0, 0, {} + timings[fn] = 0, 0, 0, 0, {} return 1 def trace_dispatch_return(self, frame, t): @@ -257,7 +270,8 @@ def trace_dispatch_return(self, frame, t): pt, ptt, pct, pfn, pframe, pcur = rcur self.cur = pt, ptt+rt, pct+sft, pfn, pframe, pcur - cc, ns, tt, ct, callers = self.timings[rfn] + timings = self.timings + cc, ns, tt, ct, callers = timings[rfn] if not ns: ct = ct + sft cc = cc + 1 @@ -268,10 +282,18 @@ def trace_dispatch_return(self, frame, t): # courtesy of this call. else: callers[pfn] = 1 - self.timings[rfn] = cc, ns - 1, tt+rtt, ct, callers + timings[rfn] = cc, ns - 1, tt+rtt, ct, callers return 1 + + dispatch = { + "call": trace_dispatch_call, + "exception": trace_dispatch_exception, + "return": trace_dispatch_return, + } + + # The next few function play with self.cmd. By carefully preloading # our parallel stack, we can force the profiled result to include # an arbitrary string as the name of the calling function. @@ -305,20 +327,21 @@ def simulate_call(self, name): else: pframe = None frame = self.fake_frame(code, pframe) - a = self.dispatch['call'](frame, 0) + a = self.dispatch['call'](self, frame, 0) return # collect stats from pending stack, including getting final # timings for self.cmd frame. def simulate_cmd_complete(self): - t = self.get_time() - self.t + get_time = self.get_time + t = get_time() - self.t while self.cur[-1]: # We *can* cause assertion errors here if # dispatch_trace_return checks for a frame match! - a = self.dispatch['return'](self.cur[-2], t) + a = self.dispatch['return'](self, self.cur[-2], t) t = 0 - self.t = self.get_time() - t + self.t = get_time() - t def print_stats(self): @@ -365,11 +388,11 @@ def runctx(self, cmd, globals, locals): return self # This method is more useful to profile a single function call. - def runcall(self, func, *args): + def runcall(self, func, *args, **kw): self.set_cmd(`func`) sys.setprofile(self.dispatcher) try: - return apply(func, args) + return apply(func, args, kw) finally: sys.setprofile(None) @@ -419,21 +442,22 @@ def runcall(self, func, *args): def calibrate(self, m): # Modified by Tim Peters + get_time = self.get_time n = m - s = self.get_time() + s = get_time() while n: self.simple() n = n - 1 - f = self.get_time() + f = get_time() my_simple = f - s #print "Simple =", my_simple, n = m - s = self.get_time() + s = get_time() while n: self.instrumented() n = n - 1 - f = self.get_time() + f = get_time() my_inst = f - s # print "Instrumented =", my_inst avg_cost = (my_inst - my_simple)/m @@ -503,6 +527,13 @@ def trace_dispatch_return(self, frame, t): return 1 + dispatch = { + "call": trace_dispatch_call, + "exception": trace_dispatch_exception, + "return": trace_dispatch_return, + } + + def snapshot_stats(self): self.stats = {} for func in self.timings.keys(): @@ -549,6 +580,13 @@ def trace_dispatch_return(self, frame, t): return 1 + dispatch = { + "call": trace_dispatch_call, + "exception": trace_dispatch_exception, + "return": trace_dispatch_return, + } + + def snapshot_stats(self): self.stats = {} for func in self.timings.keys(): @@ -564,8 +602,6 @@ def Stats(*args): # When invoked as main program, invoke the profiler on a script if __name__ == '__main__': - import sys - import os if not sys.argv[1:]: print "usage: profile.py scriptfile [arg] ..." sys.exit(2)