[Python-checkins] CVS: python/dist/src/Lib profile.py,1.39,1.40

2001年10月08日 22:31:58 -0700

Update of /cvsroot/python/python/dist/src/Lib
In directory usw-pr-cvs1:/tmp/cvs-serv8331/python/Lib
Modified Files:
	profile.py 
Log Message:
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).
Index: profile.py
===================================================================
RCS file: /cvsroot/python/python/dist/src/Lib/profile.py,v
retrieving revision 1.39
retrieving revision 1.40
diff -C2 -d -r1.39 -r1.40
*** profile.py	2001年10月07日 08:49:02	1.39
--- profile.py	2001年10月09日 05:31:56	1.40
***************
*** 191,196 ****
 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

 if self.dispatch[event](self, frame,t):
--- 191,195 ----
 timer = self.timer
 t = timer()
! t = t[0] + t[1] - self.t # - .00053 calibration constant

 if self.dispatch[event](self, frame,t):
***************
*** 208,212 ****
 def trace_dispatch_i(self, frame, event, arg):
 timer = self.timer
! t = timer() - self.t # - 1 # calibration constant
 if self.dispatch[event](self, frame,t):
 self.t = timer()
--- 207,211 ----
 def trace_dispatch_i(self, frame, event, arg):
 timer = self.timer
! t = timer() - self.t # - 16e-6 # calibration constant
 if self.dispatch[event](self, frame,t):
 self.t = timer()
***************
*** 220,224 ****
 def trace_dispatch_mac(self, frame, event, arg):
 timer = self.timer
! t = timer()/60.0 - self.t # - 1 # Integer calibration constant
 if self.dispatch[event](self, frame,t):
 self.t = timer()/60.0
--- 219,223 ----
 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):
 self.t = timer()/60.0
***************
*** 468,510 ****
 #**************************************************************

! def calibrate(self, m):
! # Modified by Tim Peters
 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

 #****************************************************************************
--- 467,531 ----
 #**************************************************************

! def calibrate(self, m, verbose=0):
 get_time = self.get_time

! # 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

 #****************************************************************************