diff options
Diffstat (limited to 'lib/python2.7/profile.py')
| -rwxr-xr-x | lib/python2.7/profile.py | 610 |
1 files changed, 0 insertions, 610 deletions
diff --git a/lib/python2.7/profile.py b/lib/python2.7/profile.py deleted file mode 100755 index 297aa04..0000000 --- a/lib/python2.7/profile.py +++ /dev/null @@ -1,610 +0,0 @@ -#! /usr/bin/env python -# -# Class for profiling python code. rev 1.0 6/2/94 -# -# Written by James Roskind -# Based on prior profile module by Sjoerd Mullender... -# which was hacked somewhat by: Guido van Rossum - -"""Class for profiling Python code.""" - -# Copyright Disney Enterprises, Inc. All Rights Reserved. -# Licensed to PSF under a Contributor Agreement -# -# Licensed under the Apache License, Version 2.0 (the "License"); -# you may not use this file except in compliance with the License. -# You may obtain a copy of the License at -# -# http://www.apache.org/licenses/LICENSE-2.0 -# -# Unless required by applicable law or agreed to in writing, software -# distributed under the License is distributed on an "AS IS" BASIS, -# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, -# either express or implied. See the License for the specific language -# governing permissions and limitations under the License. - - -import sys -import os -import time -import marshal -from optparse import OptionParser - -__all__ = ["run", "runctx", "help", "Profile"] - -# Sample timer for use with -#i_count = 0 -#def integer_timer(): -# global i_count -# i_count = i_count + 1 -# return i_count -#itimes = integer_timer # replace with C coded timer returning integers - -#************************************************************************** -# The following are the static member functions for the profiler class -# Note that an instance of Profile() is *not* needed to call them. -#************************************************************************** - -def run(statement, filename=None, sort=-1): - """Run statement under profiler optionally saving results in filename - - This function takes a single argument that can be passed to the - "exec" statement, and an optional file name. In all cases this - routine attempts to "exec" its first argument and gather profiling - statistics from the execution. If no file name is present, then this - function automatically prints a simple profiling report, sorted by the - standard name string (file/line/function-name) that is presented in - each line. - """ - prof = Profile() - try: - prof = prof.run(statement) - except SystemExit: - pass - if filename is not None: - prof.dump_stats(filename) - else: - return prof.print_stats(sort) - -def runctx(statement, globals, locals, filename=None, sort=-1): - """Run statement under profiler, supplying your own globals and locals, - optionally saving results in filename. - - statement and filename have the same semantics as profile.run - """ - prof = Profile() - try: - prof = prof.runctx(statement, globals, locals) - except SystemExit: - pass - - if filename is not None: - prof.dump_stats(filename) - else: - return prof.print_stats(sort) - -# Backwards compatibility. -def help(): - print "Documentation for the profile module can be found " - print "in the Python Library Reference, section 'The Python Profiler'." - -if hasattr(os, "times"): - def _get_time_times(timer=os.times): - t = timer() - return t[0] + t[1] - -# Using getrusage(3) is better than clock(3) if available: -# on some systems (e.g. FreeBSD), getrusage has a higher resolution -# Furthermore, on a POSIX system, returns microseconds, which -# wrap around after 36min. -_has_res = 0 -try: - import resource - resgetrusage = lambda: resource.getrusage(resource.RUSAGE_SELF) - def _get_time_resource(timer=resgetrusage): - t = timer() - return t[0] + t[1] - _has_res = 1 -except ImportError: - pass - -class Profile: - """Profiler class. - - self.cur is always a tuple. Each such tuple corresponds to a stack - frame that is currently active (self.cur[-2]). The following are the - definitions of its members. We use this external "parallel stack" to - avoid contaminating the program that we are profiling. (old profiler - used to write into the frames local dictionary!!) Derived classes - can change the definition of some entries, as long as they leave - [-2:] intact (frame and previous tuple). In case an internal error is - detected, the -3 element is used as the function name. - - [ 0] = Time that needs to be charged to the parent frame's function. - It is used so that a function call will not have to access the - timing data for the parent frame. - [ 1] = Total time spent in this frame's function, excluding time in - subfunctions (this latter is tallied in cur[2]). - [ 2] = Total time spent in subfunctions, excluding time executing the - frame's function (this latter is tallied in cur[1]). - [-3] = Name of the function that corresponds to this frame. - [-2] = Actual frame that we correspond to (used to sync exception handling). - [-1] = Our parent 6-tuple (corresponds to frame.f_back). - - Timing data for each function is stored as a 5-tuple in the dictionary - self.timings[]. The index is always the name stored in self.cur[-3]. - The following are the definitions of the members: - - [0] = The number of times this function was called, not counting direct - or indirect recursion, - [1] = Number of times this function appears on the stack, minus one - [2] = Total time spent internal to this function - [3] = Cumulative time that this function was present on the stack. In - non-recursive functions, this is the total execution time from start - to finish of each invocation of a function, including time spent in - all subfunctions. - [4] = A dictionary indicating for each function name, the number of times - it was called by us. - """ - - bias = 0 # calibration constant - - def __init__(self, timer=None, bias=None): - self.timings = {} - self.cur = None - self.cmd = "" - self.c_func_name = "" - - if bias is None: - bias = self.bias - self.bias = bias # Materialize in local dict for lookup speed. - - if not timer: - if _has_res: - self.timer = resgetrusage - self.dispatcher = self.trace_dispatch - self.get_time = _get_time_resource - elif hasattr(time, 'clock'): - self.timer = self.get_time = time.clock - self.dispatcher = self.trace_dispatch_i - elif hasattr(os, 'times'): - self.timer = os.times - self.dispatcher = self.trace_dispatch - self.get_time = _get_time_times - else: - self.timer = self.get_time = time.time - self.dispatcher = self.trace_dispatch_i - else: - self.timer = timer - t = self.timer() # test out timer function - try: - length = len(t) - except TypeError: - self.get_time = timer - self.dispatcher = self.trace_dispatch_i - else: - if length == 2: - self.dispatcher = self.trace_dispatch - else: - self.dispatcher = self.trace_dispatch_l - # This get_time() implementation needs to be defined - # here to capture the passed-in timer in the parameter - # list (for performance). Note that we can't assume - # the timer() result contains two values in all - # cases. - def get_time_timer(timer=timer, sum=sum): - return sum(timer()) - self.get_time = get_time_timer - self.t = self.get_time() - self.simulate_call('profiler') - - # Heavily optimized dispatch routine for os.times() timer - - def trace_dispatch(self, frame, event, arg): - timer = self.timer - t = timer() - t = t[0] + t[1] - self.t - self.bias - - if event == "c_call": - self.c_func_name = arg.__name__ - - if self.dispatch[event](self, frame,t): - t = timer() - self.t = t[0] + t[1] - else: - r = timer() - self.t = r[0] + r[1] - t # put back unrecorded delta - - # 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 - self.bias - - if event == "c_call": - self.c_func_name = arg.__name__ - - if self.dispatch[event](self, frame, t): - self.t = timer() - else: - self.t = timer() - t # put back unrecorded delta - - # 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 - self.bias - - if event == "c_call": - self.c_func_name = arg.__name__ - - if self.dispatch[event](self, frame, t): - self.t = timer()/60.0 - else: - self.t = timer()/60.0 - t # put back unrecorded delta - - # 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 - self.bias - - if event == "c_call": - self.c_func_name = arg.__name__ - - if self.dispatch[event](self, frame, t): - self.t = get_time() - else: - self.t = get_time() - t # put back unrecorded delta - - # 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 - # mnemonic: - # _pt self.cur[0] "parent time" time to be charged to parent frame - # _it self.cur[1] "internal time" time spent directly in the function - # _et self.cur[2] "external time" time spent in subfunctions - - def trace_dispatch_exception(self, frame, t): - rpt, rit, ret, rfn, rframe, rcur = self.cur - if (rframe is not frame) and rcur: - return self.trace_dispatch_return(rframe, t) - self.cur = rpt, rit+t, ret, rfn, rframe, rcur - return 1 - - - def trace_dispatch_call(self, frame, t): - if self.cur and frame.f_back is not self.cur[-2]: - rpt, rit, ret, rfn, rframe, rcur = self.cur - if not isinstance(rframe, Profile.fake_frame): - assert rframe.f_back is frame.f_back, ("Bad call", rfn, - rframe, rframe.f_back, - frame, frame.f_back) - self.trace_dispatch_return(rframe, 0) - assert (self.cur is None or \ - frame.f_back is self.cur[-2]), ("Bad call", - self.cur[-3]) - fcode = frame.f_code - fn = (fcode.co_filename, fcode.co_firstlineno, fcode.co_name) - self.cur = (t, 0, 0, fn, frame, self.cur) - timings = self.timings - if fn in timings: - cc, ns, tt, ct, callers = timings[fn] - timings[fn] = cc, ns + 1, tt, ct, callers - else: - timings[fn] = 0, 0, 0, 0, {} - return 1 - - def trace_dispatch_c_call (self, frame, t): - fn = ("", 0, self.c_func_name) - self.cur = (t, 0, 0, fn, frame, self.cur) - timings = self.timings - if fn in timings: - cc, ns, tt, ct, callers = timings[fn] - timings[fn] = cc, ns+1, tt, ct, callers - else: - timings[fn] = 0, 0, 0, 0, {} - return 1 - - def trace_dispatch_return(self, frame, t): - if frame is not self.cur[-2]: - assert frame is self.cur[-2].f_back, ("Bad return", self.cur[-3]) - self.trace_dispatch_return(self.cur[-2], 0) - - # Prefix "r" means part of the Returning or exiting frame. - # Prefix "p" means part of the Previous or Parent or older frame. - - rpt, rit, ret, rfn, frame, rcur = self.cur - rit = rit + t - frame_total = rit + ret - - ppt, pit, pet, pfn, pframe, pcur = rcur - self.cur = ppt, pit + rpt, pet + frame_total, pfn, pframe, pcur - - timings = self.timings - cc, ns, tt, ct, callers = timings[rfn] - if not ns: - # This is the only occurrence of the function on the stack. - # Else this is a (directly or indirectly) recursive call, and - # its cumulative time will get updated when the topmost call to - # it returns. - ct = ct + frame_total - cc = cc + 1 - - if pfn in callers: - callers[pfn] = callers[pfn] + 1 # hack: gather more - # stats such as the amount of time added to ct courtesy - # of this specific call, and the contribution to cc - # courtesy of this call. - else: - callers[pfn] = 1 - - timings[rfn] = cc, ns - 1, tt + rit, ct, callers - - return 1 - - - dispatch = { - "call": trace_dispatch_call, - "exception": trace_dispatch_exception, - "return": trace_dispatch_return, - "c_call": trace_dispatch_c_call, - "c_exception": trace_dispatch_return, # the C function returned - "c_return": trace_dispatch_return, - } - - - # The next few functions play with self.cmd. By carefully preloading - # our parallel stack, we can force the profiled result to include - # an arbitrary string as the name of the calling function. - # We use self.cmd as that string, and the resulting stats look - # very nice :-). - - def set_cmd(self, cmd): - if self.cur[-1]: return # already set - self.cmd = cmd - self.simulate_call(cmd) - - class fake_code: - def __init__(self, filename, line, name): - self.co_filename = filename - self.co_line = line - self.co_name = name - self.co_firstlineno = 0 - - def __repr__(self): - return repr((self.co_filename, self.co_line, self.co_name)) - - class fake_frame: - def __init__(self, code, prior): - self.f_code = code - self.f_back = prior - - def simulate_call(self, name): - code = self.fake_code('profile', 0, name) - if self.cur: - pframe = self.cur[-2] - else: - pframe = None - frame = self.fake_frame(code, pframe) - self.dispatch['call'](self, frame, 0) - - # collect stats from pending stack, including getting final - # timings for self.cmd frame. - - def simulate_cmd_complete(self): - get_time = self.get_time - t = get_time() - self.t - while self.cur[-1]: - # We *can* cause assertion errors here if - # dispatch_trace_return checks for a frame match! - self.dispatch['return'](self, self.cur[-2], t) - t = 0 - self.t = get_time() - t - - - def print_stats(self, sort=-1): - import pstats - pstats.Stats(self).strip_dirs().sort_stats(sort). \ - print_stats() - - def dump_stats(self, file): - f = open(file, 'wb') - self.create_stats() - marshal.dump(self.stats, f) - f.close() - - def create_stats(self): - self.simulate_cmd_complete() - self.snapshot_stats() - - def snapshot_stats(self): - self.stats = {} - for func, (cc, ns, tt, ct, callers) in self.timings.iteritems(): - callers = callers.copy() - nc = 0 - for callcnt in callers.itervalues(): - nc += callcnt - self.stats[func] = cc, nc, tt, ct, callers - - - # The following two methods can be called by clients to use - # a profiler to profile a statement, given as a string. - - def run(self, cmd): - import __main__ - dict = __main__.__dict__ - return self.runctx(cmd, dict, dict) - - def runctx(self, cmd, globals, locals): - self.set_cmd(cmd) - sys.setprofile(self.dispatcher) - try: - exec cmd in globals, locals - finally: - sys.setprofile(None) - return self - - # This method is more useful to profile a single function call. - def runcall(self, func, *args, **kw): - self.set_cmd(repr(func)) - sys.setprofile(self.dispatcher) - try: - return func(*args, **kw) - finally: - sys.setprofile(None) - - - #****************************************************************** - # The following calculates the overhead for using a profiler. The - # problem is that it takes a fair amount of time for the profiler - # to stop the stopwatch (from the time it receives an event). - # 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. - # - # 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 - # done on the fly during init() time, but it is not worth the - # effort. Also note that if too large a value specified, then - # execution time on some functions will actually appear as a - # negative number. It is *normal* for some functions (with very - # low call counts) to have such negative stats, even if the - # calibration figure is "correct." - # - # One alternative to profile-time calibration adjustments (i.e., - # adding in the magic little delta during each event) is to track - # more carefully the number of events (and cumulatively, the number - # of events during sub functions) that are seen. If this were - # done, then the arithmetic could be done after the fact (i.e., at - # display time). Currently, we track only call/return events. - # These values can be deduced by examining the callees and callers - # vectors for each functions. Hence we *can* almost correct the - # internal time figure at print time (note that we currently don't - # track exception event processing counts). Unfortunately, there - # is currently no similar information for cumulative sub-function - # time. It would not be hard to "get all this info" at profiler - # time. Specifically, we would have to extend the tuples to keep - # counts of this in each frame, and then extend the defs of timing - # tuples to include the significant two figures. I'm a bit fearful - # 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.) - #************************************************************** - - 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._calibrate_inner(m, verbose) - finally: - self.bias = saved_bias - - def _calibrate_inner(self, m, verbose): - 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 - -#**************************************************************************** -def Stats(*args): - print 'Report generating functions are in the "pstats" module\a' - -def main(): - usage = "profile.py [-o output_file_path] [-s sort] scriptfile [arg] ..." - parser = OptionParser(usage=usage) - parser.allow_interspersed_args = False - parser.add_option('-o', '--outfile', dest="outfile", - help="Save stats to <outfile>", default=None) - parser.add_option('-s', '--sort', dest="sort", - help="Sort order when printing to stdout, based on pstats.Stats class", - default=-1) - - if not sys.argv[1:]: - parser.print_usage() - sys.exit(2) - - (options, args) = parser.parse_args() - sys.argv[:] = args - - if len(args) > 0: - progname = args[0] - sys.path.insert(0, os.path.dirname(progname)) - with open(progname, 'rb') as fp: - code = compile(fp.read(), progname, 'exec') - globs = { - '__file__': progname, - '__name__': '__main__', - '__package__': None, - } - runctx(code, globs, None, options.outfile, options.sort) - else: - parser.print_usage() - return parser - -# When invoked as main program, invoke the profiler on a script -if __name__ == '__main__': - main() |