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.

1 files changed, 93 insertions, 57 deletions

diff --git a/Lib/profile.py b/Lib/profile.py
index a32a1c1..a6d5637 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 @@ class Profile:
         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 @@ class Profile:
     # 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 @@ class Profile:
         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 @@ class Profile:
         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 @@ class Profile:
             # 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 @@ class Profile:
         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 @@ class Profile:
         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 @@ class Profile:
 
     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 @@ class OldProfile(Profile):
         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 @@ class HotProfile(Profile):
         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)