From cce092d04616b27c25ffc8037206135b72b4b7c4 Mon Sep 17 00:00:00 2001 From: Tim Peters Date: Tue, 9 Oct 2001 05:31:56 +0000 Subject: [PATCH] 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). --- Lib/profile.py | 97 ++++++++++++++++++++++++++++++-------------------- Misc/NEWS | 4 +++ 2 files changed, 63 insertions(+), 38 deletions(-) diff --git a/Lib/profile.py b/Lib/profile.py index a9eb113feef..6c1edea2f73 100755 --- a/Lib/profile.py +++ b/Lib/profile.py @@ -190,8 +190,7 @@ def get_time_timer(timer=timer, 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 @@ def trace_dispatch(self, frame, event, arg): 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 @@ def trace_dispatch_i(self, frame, event, arg): 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 @@ def runcall(self, func, *args, **kw): # 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 + # 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). - # simulate a program with no profiler activity - def simple(self): - a = 1 - pass + def f1(n): + for i in range(n): + x = 1 - # simulate a program with call/return event processing - def instrumented(self): - a = 1 - self.profiler_simulation(a, a, a) + def f(m, f1=f1): + for i in range(m): + f1(100) - # 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 + 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 30f7df6328b..3da64a52041 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.