Allow the profiler's calibration constant to be specified in the constructor

call, or via setting an instance or class vrbl.
Rewrote the calibration docs.
Modern boxes are so friggin' fast, and a profiler event does so much work
anyway, that the cost of looking up an instance vrbl (the bias constant)
per profile event just isn't a big deal.

Doc/lib/libprofile.tex

@@ -553,75 +553,55 @@ calibration.
 
 \section{Calibration \label{profile-calibration}}
 
-The profiler class has a hard coded constant that is added to each
+The profiler subtracts a constant from each
 event handling time to compensate for the overhead of calling the time
-function, and socking away the results.  The following procedure can
+function, and socking away the results.  By default, the constant is 0.
-be used to obtain this constant for a given platform (see discussion
+The following procedure can
+be used to obtain a better constant for a given platform (see discussion
 in section Limitations above).
 
 \begin{verbatim}
 import profile
 pr = profile.Profile()
-print pr.calibrate(100)
+for i in range(5):
-print pr.calibrate(100)
+    print pr.calibrate(10000)
-print pr.calibrate(100)
 \end{verbatim}
 
-The argument to \method{calibrate()} is the number of times to try to
+The method executes the number of Python calls given by the argument,
-do the sample calls to get the CPU times.  If your computer is
+directly and again under the profiler, measuring the time for both.
-\emph{very} fast, you might have to do:
+It then computes the hidden overhead per profiler event, and returns
-
+that as a float.  For example, on an 800 MHz Pentium running
-\begin{verbatim}
+Windows 2000, and using Python's time.clock() as the timer,
-pr.calibrate(1000)
+the magical number is about 12.5e-6.
-\end{verbatim}
-
-or even:
-
-\begin{verbatim}
-pr.calibrate(10000)
-\end{verbatim}
 
 The object of this exercise is to get a fairly consistent result.
-When you have a consistent answer, you are ready to use that number in
+If your computer is \emph{very} fast, or your timer function has poor
-the source code.  For a Sun Sparcstation 1000 running Solaris 2.3, the
+resolution, you might have to pass 100000, or even 1000000, to get
-magical number is about .00053.  If you have a choice, you are better
+consistent results.
-off with a smaller constant, and your results will ``less often'' show
-up as negative in profile statistics.
 
-The following shows how the trace_dispatch() method in the Profile
+When you have a consistent answer,
-class should be modified to install the calibration constant on a Sun
+there are three ways you can use it:\footnote{Prior to Python 2.2, it
-Sparcstation 1000:
+  was necessary to edit the profiler source code to embed the bias as
+  a literal number.  You still can, but that method is no longer
+  described, because no longer needed.}
 
 \begin{verbatim}
-def trace_dispatch(self, frame, event, arg):
+import profile
-    t = self.timer()
-    t = t[0] + t[1] - self.t - .00053 # Calibration constant
 
-    if self.dispatch[event](frame,t):
+# 1. Apply computed bias to all Profile instances created hereafter.
-        t = self.timer()
+profile.Profile.bias =
-        self.t = t[0] + t[1]
+
-    else:
+# 2. Apply computed bias to a specific Profile instance.
-        r = self.timer()
+pr = profile.Profile()
-        self.t = r[0] + r[1] - t # put back unrecorded delta
+pr.bias = your_computed_bias
-    return
+
+# 3. Specify computed bias in instance constructor.
+pr = profile.Profile(bias=your_computed_bias)
 \end{verbatim}
 
-Note that if there is no calibration constant, then the line
+If you have a choice, you are better off choosing a smaller constant, and
-containing the callibration constant should simply say:
+then your results will ``less often'' show up as negative in profile
-
+statistics.
-\begin{verbatim}
-t = t[0] + t[1] - self.t  # no calibration constant
-\end{verbatim}
-
-You can also achieve the same results using a derived class (and the
-profiler will actually run equally fast!!), but the above method is
-the simplest to use.  I could have made the profiler ``self
-calibrating,'' but it would have made the initialization of the
-profiler class slower, and would have required some \emph{very} fancy
-coding, or else the use of a variable where the constant \samp{.00053}
-was placed in the code shown.  This is a \strong{VERY} critical
-performance section, and there is no reason to use a variable lookup
-at this point, when a constant can be used.
 
 
 \section{Extensions --- Deriving Better Profilers}

Lib/profile.py

@@ -139,11 +139,17 @@ class Profile:
           it was called by us.
     """
 
-    def __init__(self, timer=None):
+    bias = 0  # calibration constant
+
+    def __init__(self, timer=None, bias=None):
         self.timings = {}
         self.cur = None
         self.cmd = ""
 
+        if bias is None:
+            bias = self.bias
+        self.bias = bias     # Materialize in local dict for lookup speed.
+
         if not timer:
             if os.name == 'mac':
                 self.timer = MacOS.GetTicks
@@ -190,7 +196,7 @@ class Profile:
     def trace_dispatch(self, frame, event, arg):
         timer = self.timer
         t = timer()
-        t = t[0] + t[1] - self.t # - .00053 calibration constant
+        t = t[0] + t[1] - self.t - self.bias
 
         if self.dispatch[event](self, frame,t):
             t = timer()
@@ -198,45 +204,39 @@ class Profile:
         else:
             r = timer()
             self.t = r[0] + r[1] - t # put back unrecorded delta
-        return
-
 
     # Dispatch routine for best timer program (return = scalar, fastest if
     # an integer but float works too -- and time.clock() relies on that).
 
     def trace_dispatch_i(self, frame, event, arg):
         timer = self.timer
-        t = timer() - self.t # - 16e-6 # calibration constant
+        t = timer() - self.t - self.bias
         if self.dispatch[event](self, frame,t):
             self.t = timer()
         else:
             self.t = timer() - t  # put back unrecorded delta
-        return
 
     # Dispatch routine for macintosh (timer returns time in ticks of
     # 1/60th second)
 
     def trace_dispatch_mac(self, frame, event, arg):
         timer = self.timer
-        t = timer()/60.0 - self.t # - 1 # calibration constant
+        t = timer()/60.0 - self.t - self.bias
-        if self.dispatch[event](self, frame,t):
+        if self.dispatch[event](self, frame, t):
             self.t = timer()/60.0
         else:
             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):
         get_time = self.get_time
-        t = get_time() - self.t
+        t = get_time() - self.t - self.bias
 
-        if self.dispatch[event](self, frame,t):
+        if self.dispatch[event](self, frame, t):
             self.t = get_time()
         else:
             self.t = get_time() - t # put back unrecorded delta
-        return
 
     # In the event handlers, the first 3 elements of self.cur are unpacked
     # into vrbls w/ 3-letter names.  The last two characters are meant to be
@@ -430,9 +430,9 @@ class Profile:
     # Similarly, there is a delay from the time that the profiler
     # re-starts the stopwatch before the user's code really gets to
     # continue.  The following code tries to measure the difference on
-    # a per-event basis. The result can the be placed in the
+    # a per-event basis.
-    # Profile.dispatch_event() routine for the given platform.  Note
+    #
-    # that this difference is only significant if there are a lot of
+    # Note that this difference is only significant if there are a lot of
     # events, and relatively little user code per event.  For example,
     # code with small functions will typically benefit from having the
     # profiler calibrated for the current platform.  This *could* be
@@ -461,12 +461,20 @@ class Profile:
     # that this additional feature will slow the heavily optimized
     # event/time ratio (i.e., the profiler would run slower, fur a very
     # low "value added" feature.)
-    #
-    # Plugging in the calibration constant doesn't slow down the
-    # profiler very much, and the accuracy goes way up.
     #**************************************************************
 
     def calibrate(self, m, verbose=0):
+        if self.__class__ is not Profile:
+            raise TypeError("Subclasses must override .calibrate().")
+
+        saved_bias = self.bias
+        self.bias = 0
+        try:
+            return self._callibrate_inner(m, verbose)
+        finally:
+            self.bias = saved_bias
+
+    def _callibrate_inner(self, m, verbose):
         get_time = self.get_time
 
         # Set up a test case to be run with and without profiling.  Include

Misc/NEWS

@@ -48,8 +48,17 @@ Library
   without losing information).
 
 - Profile.calibrate() has a new implementation that should deliver
-  a better system-specific calibration constant.  Calibration must still
+  a much better system-specific calibration constant.  The constant can
-  be done manually (see the docs for the profile module).
+  now be specified in an instance constructor, or as a Profile class or
+  instance variable, instead of by editing profile.py's source code.
+  Calibration must still be done manually (see the docs for the profile
+  module).
+
+  Note that Profile.calibrate() must be overriden by subclasses.
+  Improving the accuracy required exploiting detailed knowledge of
+  profiler internals; the earlier method abstracted away the details
+  and measured a simplified model instead, but consequently computed
+  a constant too small by a factor of 2 on some modern machines.
 
 - quopri's encode and decode methods take an optional header parameter,
   which indicates whether output is intended for the header 'Q' encoding.