diff options
| -rw-r--r-- | Doc/lib/libprofile.tex | 84 | ||||
| -rwxr-xr-x | Lib/profile.py | 46 | ||||
| -rw-r--r-- | Misc/NEWS | 13 |
3 files changed, 70 insertions, 73 deletions
diff --git a/Doc/lib/libprofile.tex b/Doc/lib/libprofile.tex index 9e4f91b731..a1634b96ac 100644 --- a/Doc/lib/libprofile.tex +++ b/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 -be used to obtain this constant for a given platform (see discussion +function, and socking away the results. By default, the constant is 0. +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) -print pr.calibrate(100) -print pr.calibrate(100) +for i in range(5): + print pr.calibrate(10000) \end{verbatim} -The argument to \method{calibrate()} is the number of times to try to -do the sample calls to get the CPU times. If your computer is -\emph{very} fast, you might have to do: - -\begin{verbatim} -pr.calibrate(1000) -\end{verbatim} - -or even: - -\begin{verbatim} -pr.calibrate(10000) -\end{verbatim} +The method executes the number of Python calls given by the argument, +directly and again under the profiler, measuring the time for both. +It then computes the hidden overhead per profiler event, and returns +that as a float. For example, on an 800 MHz Pentium running +Windows 2000, and using Python's time.clock() as the timer, +the magical number is about 12.5e-6. 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 -the source code. For a Sun Sparcstation 1000 running Solaris 2.3, the -magical number is about .00053. If you have a choice, you are better -off with a smaller constant, and your results will ``less often'' show -up as negative in profile statistics. +If your computer is \emph{very} fast, or your timer function has poor +resolution, you might have to pass 100000, or even 1000000, to get +consistent results. -The following shows how the trace_dispatch() method in the Profile -class should be modified to install the calibration constant on a Sun -Sparcstation 1000: +When you have a consistent answer, +there are three ways you can use it:\footnote{Prior to Python 2.2, it + 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): - t = self.timer() - t = t[0] + t[1] - self.t - .00053 # Calibration constant - - if self.dispatch[event](frame,t): - t = self.timer() - self.t = t[0] + t[1] - else: - r = self.timer() - self.t = r[0] + r[1] - t # put back unrecorded delta - return -\end{verbatim} +import profile -Note that if there is no calibration constant, then the line -containing the callibration constant should simply say: +# 1. Apply computed bias to all Profile instances created hereafter. +profile.Profile.bias = -\begin{verbatim} -t = t[0] + t[1] - self.t # no calibration constant +# 2. Apply computed bias to a specific Profile instance. +pr = profile.Profile() +pr.bias = your_computed_bias + +# 3. Specify computed bias in instance constructor. +pr = profile.Profile(bias=your_computed_bias) \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. +If you have a choice, you are better off choosing a smaller constant, and +then your results will ``less often'' show up as negative in profile +statistics. \section{Extensions --- Deriving Better Profilers} diff --git a/Lib/profile.py b/Lib/profile.py index 6c1edea2f7..db4079093e 100755 --- a/Lib/profile.py +++ b/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 - if self.dispatch[event](self, frame,t): + t = timer()/60.0 - self.t - self.bias + 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 - # Profile.dispatch_event() routine for the given platform. Note - # that this difference is only significant if there are a lot of + # a per-event basis. + # + # 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 @@ -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 - be done manually (see the docs for the profile module). + a much better system-specific calibration constant. The constant can + 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. |