A brand new implementation of Profile.calibrate(). This measures an

actual run of the profiler, instead of timing a simplified simulation of
part of what the profiler does.  It computes a constant about 60% higher
on my Win98SE box than the old method, and the new constant appears much
more realistic.  Deleted the undocumented simple(), instrumented(), and
profiler_simulation() methods (which existed only to support the previous
calibration method).

2 files changed, 66 insertions, 41 deletions

diff --git a/Lib/profile.py b/Lib/profile.py
index a9eb113..6c1edea 100755
--- a/Lib/profile.py
+++ b/Lib/profile.py
@@ -190,8 +190,7 @@ class Profile:
     def trace_dispatch(self, frame, event, arg):
         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
+        t = t[0] + t[1] - self.t # - .00053 calibration constant
 
         if self.dispatch[event](self, frame,t):
             t = timer()
@@ -207,7 +206,7 @@ class Profile:
 
     def trace_dispatch_i(self, frame, event, arg):
         timer = self.timer
-        t = timer() - self.t # - 1 # calibration constant
+        t = timer() - self.t # - 16e-6 # calibration constant
         if self.dispatch[event](self, frame,t):
             self.t = timer()
         else:
@@ -219,7 +218,7 @@ class Profile:
 
     def trace_dispatch_mac(self, frame, event, arg):
         timer = self.timer
-        t = timer()/60.0 - self.t # - 1 # Integer calibration constant
+        t = timer()/60.0 - self.t # - 1 # calibration constant
         if self.dispatch[event](self, frame,t):
             self.t = timer()/60.0
         else:
@@ -467,45 +466,67 @@ class Profile:
     # profiler very much, and the accuracy goes way up.
     #**************************************************************
 
-    def calibrate(self, m):
-        # Modified by Tim Peters
+    def calibrate(self, m, verbose=0):
         get_time = self.get_time
-        n = m
-        s = get_time()
-        while n:
-            self.simple()
-            n = n - 1
-        f = get_time()
-        my_simple = f - s
-        #print "Simple =", my_simple,
-
-        n = m
-        s = get_time()
-        while n:
-            self.instrumented()
-            n = n - 1
-        f = get_time()
-        my_inst = f - s
-        # print "Instrumented =", my_inst
-        avg_cost = (my_inst - my_simple)/m
-        #print "Delta/call =", avg_cost, "(profiler fixup constant)"
-        return avg_cost
-
-    # simulate a program with no profiler activity
-    def simple(self):
-        a = 1
-        pass
-
-    # simulate a program with call/return event processing
-    def instrumented(self):
-        a = 1
-        self.profiler_simulation(a, a, a)
 
-    # simulate an event processing activity (from user's perspective)
-    def profiler_simulation(self, x, y, z):
-        t = self.timer()
-        ## t = t[0] + t[1]
-        self.ut = t
+        # Set up a test case to be run with and without profiling.  Include
+        # lots of calls, because we're trying to quantify stopwatch overhead.
+        # Do not raise any exceptions, though, because we want to know
+        # exactly how many profile events are generated (one call event, +
+        # one return event, per Python-level call).
+
+        def f1(n):
+            for i in range(n):
+                x = 1
+
+        def f(m, f1=f1):
+            for i in range(m):
+                f1(100)
+
+        f(m)    # warm up the cache
+
+        # elapsed_noprofile <- time f(m) takes without profiling.
+        t0 = get_time()
+        f(m)
+        t1 = get_time()
+        elapsed_noprofile = t1 - t0
+        if verbose:
+            print "elapsed time without profiling =", elapsed_noprofile
+
+        # elapsed_profile <- time f(m) takes with profiling.  The difference
+        # is profiling overhead, only some of which the profiler subtracts
+        # out on its own.
+        p = Profile()
+        t0 = get_time()
+        p.runctx('f(m)', globals(), locals())
+        t1 = get_time()
+        elapsed_profile = t1 - t0
+        if verbose:
+            print "elapsed time with profiling =", elapsed_profile
+
+        # reported_time <- "CPU seconds" the profiler charged to f and f1.
+        total_calls = 0.0
+        reported_time = 0.0
+        for (filename, line, funcname), (cc, ns, tt, ct, callers) in \
+                p.timings.items():
+            if funcname in ("f", "f1"):
+                total_calls += cc
+                reported_time += tt
+
+        if verbose:
+            print "'CPU seconds' profiler reported =", reported_time
+            print "total # calls =", total_calls
+        if total_calls != m + 1:
+            raise ValueError("internal error: total calls = %d" % total_calls)
+
+        # reported_time - elapsed_noprofile = overhead the profiler wasn't
+        # able to measure.  Divide by twice the number of calls (since there
+        # are two profiler events per call in this test) to get the hidden
+        # overhead per event.
+        mean = (reported_time - elapsed_noprofile) / 2.0 / total_calls
+        if verbose:
+            print "mean stopwatch overhead per profile event =", mean
+        return mean
 
 #****************************************************************************
 def Stats(*args):
diff --git a/Misc/NEWS b/Misc/NEWS
index 30f7df6..3da64a5 100644
--- a/Misc/NEWS
+++ b/Misc/NEWS
@@ -47,6 +47,10 @@ Library
   that's a worthy goal we intend to meet via a different approach (but
   without losing information).
 
+- Profile.calibrate() has a new implementation that should deliver
+  a better system-specific calibration constant.  Calibration must still
+  be done manually (see the docs for the profile module).
+
 - quopri's encode and decode methods take an optional header parameter,
   which indicates whether output is intended for the header 'Q' encoding.