summaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorTim Peters <tim.peters@gmail.com>2001-10-09 05:31:56 (GMT)
committerTim Peters <tim.peters@gmail.com>2001-10-09 05:31:56 (GMT)
commitcce092d04616b27c25ffc8037206135b72b4b7c4 (patch)
tree2e2ba2d8f40e01e8265bd194315a3457373e1432
parent342d8f778029c3e14bcc6f5ef7d6525fd1ab466c (diff)
downloadcpython-cce092d04616b27c25ffc8037206135b72b4b7c4.zip
cpython-cce092d04616b27c25ffc8037206135b72b4b7c4.tar.gz
cpython-cce092d04616b27c25ffc8037206135b72b4b7c4.tar.bz2
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).
-rwxr-xr-xLib/profile.py103
-rw-r--r--Misc/NEWS4
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.