+++ /dev/null
-profile.doc last updated 6/23/94 [by Guido]
-
- PROFILER DOCUMENTATION and (mini) USER'S MANUAL
-
-Copyright 1994, by InfoSeek Corporation, all rights reserved.
-Written by James Roskind
-
-Permission to use, copy, modify, and distribute this Python software
-and its associated documentation for any purpose (subject to the
-restriction in the following sentence) without fee is hereby granted,
-provided that the above copyright notice appears in all copies, and
-that both that copyright notice and this permission notice appear in
-supporting documentation, and that the name of InfoSeek not be used in
-advertising or publicity pertaining to distribution of the software
-without specific, written prior permission. This permission is
-explicitly restricted to the copying and modification of the software
-to remain in Python, compiled Python, or other languages (such as C)
-wherein the modified or derived code is exclusively imported into a
-Python module.
-
-INFOSEEK CORPORATION DISCLAIMS ALL WARRANTIES WITH REGARD TO THIS
-SOFTWARE, INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY AND
-FITNESS. IN NO EVENT SHALL INFOSEEK CORPORATION BE LIABLE FOR ANY
-SPECIAL, INDIRECT OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER
-RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF
-CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN
-CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.
-
-
-The profiler was written after only programming in Python for 3 weeks.
-As a result, it is probably clumsy code, but I don't know for sure yet
-'cause I'm a beginner :-). I did work hard to make the code run fast,
-so that profiling would be a reasonable thing to do. I tried not to
-repeat code fragments, but I'm sure I did some stuff in really awkward
-ways at times. Please send suggestions for improvements to:
-jar@infoseek.com. I won't promise *any* support. ...but I'd
-appreciate the feedback.
-
-
-SECTION HEADING LIST:
- INTRODUCTION
- HOW IS THIS profile DIFFERENT FROM THE OLD profile MODULE?
- INSTANT USERS MANUAL
- WHAT IS DETERMINISTIC PROFILING?
- REFERENCE MANUAL
- FUNCTION profile.run(string, filename_opt)
- CLASS Stats(filename, ...)
- METHOD strip_dirs()
- METHOD add(filename, ...)
- METHOD sort_stats(key, ...)
- METHOD reverse_order()
- METHOD print_stats(restriction, ...)
- METHOD print_callers(restrictions, ...)
- METHOD print_callees(restrictions, ...)
- METHOD ignore()
- LIMITATIONS
- CALIBRATION
- EXTENSIONS: Deriving Better Profilers
-
-
-
-INTRODUCTION
-
-A "profiler" is a program that describes the run time performance of a
-program, providing a variety of statistics. This documentation
-describes the profiler functionality provided in the modules
-"profile" and "pstats." This profiler provides "deterministic
-profiling" of any Python programs. It also provides a series of
-report generation tools to allow users to rapidly examine the results
-of a profile operation.
-
-
-HOW IS THIS profile DIFFERENT FROM THE OLD profile MODULE?
-
-The big changes from standard profiling module are that you get more
-information, and you pay less CPU time. It's not a trade-off, it's a
-trade-up.
-
-To be specific:
-
- bugs removed: local stack frame is no longer molested, execution time
- is now charged to correct functions, ....
-
- accuracy increased: profiler execution time is no longer charged to
- user's code, calibration for platform is supported, file reads
- are not done *by* profiler *during* profiling (and charged to
- user's code!), ...
-
- speed increased: Overhead CPU cost was reduced by more than a factor of
- two (perhaps a factor of five), lightweight profiler module is
- all that must be loaded, and the report generating module
- (pstats) is not needed during profiling.
-
- recursive functions support: cumulative times in recursive functions
- are correctly calculated; recursive entries are counted; ...
-
- large growth in report generating UI: distinct profiles runs can be added
- together forming a comprehensive report; functions that import
- statistics take arbitrary lists of files; sorting criteria is now
- based on keywords (instead of 4 integer options); reports shows
- what functions were profiled as well as what profile file was
- referenced; output format has been improved, ...
-
-
-INSTANT USERS MANUAL
-
-This section is provided for users that "don't want to read the
-manual." It provides a very brief overview, and allows a user to
-rapidly perform profiling on an existing application.
-
-To profile an application with a main entry point of "foo()", you
-would add the following to your module:
-
- import profile
- profile.run("foo()")
-
-The above action would cause "foo()" to be run, and a series of
-informative lines (the profile) to be printed. The above approach is
-most useful when working with the interpreter. If you would like to
-save the results of a profile into a file for later examination, you
-can supply a file name as the second argument to the run() function:
-
- import profile
- profile.run("foo()", 'fooprof')
-
-When you wish to review the profile, you should use the methods in the
-pstats module. Typically you would load the statistics data as
-follows:
-
- import pstats
- p = pstats.Stats('fooprof')
-
-The class "Stats" (the above code just created an instance of this
-class) has a variety of methods for manipulating and printing the data
-that was just read into "p". When you ran profile.run() above, what
-was printed was the result of three method calls:
-
- p.strip_dirs().sort_stats(-1).print_stats()
-
-The first method removed the extraneous path from all the module
-names. The second method sorted all the entries according to the
-standard module/line/name string that is printed (this is to comply
-with the semantics of the old profiler). The third method printed out
-all the statistics. You might try the following sort calls:
-
- p.sort_stats('name')
- p.print_stats()
-
-The first call will actually sort the list by function name, and the
-second call will print out the statistics. The following are some
-interesting calls to experiment with:
-
- p.sort_stats('cumulative').print_stats(10)
-
-This sorts the profile by cumulative time in a function, and then only
-prints the ten most significant lines. If you want to understand what
-algorithms are taking time, the above line is what you would use.
-
-If you were looking to see what functions were looping a lot, and
-taking a lot of time, you would do:
-
- p.sort_stats('time').print_stats(10)
-
-to sort according to time spent within each function, and then print
-the statistics for the top ten functions.
-
-You might also try:
-
- p.sort_stats('file').print_stats('__init__')
-
-This will sort all the statistics by file name, and then print out
-statistics for only the class init methods ('cause they are spelled
-with "__init__" in them). As one final example, you could try:
-
- p.sort_stats('time', 'cum').print_stats(.5, 'init')
-
-This line sorts stats with a primary key of time, and a secondary key
-of cumulative time, and then prints out some of the statistics. To be
-specific, the list is first culled down to 50% (re: .5) of its
-original size, then only lines containing "init" are maintained, and
-that sub-sub-list is printed.
-
-If you wondered what functions called the above functions, you could
-now (p is still sorted according to the last criteria) do:
-
- p.print_callers(.5, 'init')
-
-and you would get a list of callers for each of the listed functions.
-
-If you want more functionality, you're going to have to read the
-manual (or guess) what the following functions do:
-
- p.print_callees()
- p.add('fooprof')
-
-
-WHAT IS DETERMINISTIC PROFILING?
-
-"Deterministic profiling" is meant to reflect the fact that all
-"function call", "function return", and "exception" events are
-monitored, and precise timings are made for the intervals between
-these events (during which time the user's code is executing). In
-contrast, "statistical profiling" (which is not done by this module)
-randomly samples the effective instruction pointer, and deduces where
-time is being spent. The latter technique traditionally involves less
-overhead (as the code does not need to be instrumented), but provides
-only relative indications of where time is being spent.
-
-In Python, since there is an interpreter active during execution, the
-presence of instrumented code is not required to do deterministic
-profiling. Python automatically provides a hook (optional callback)
-for each event. In addition, the interpreted nature of Python tends
-to add so much overhead to execution, that deterministic profiling
-tends to only add small processing overhead, in typical applications.
-The result is that deterministic profiling is not that expensive, but
-yet provides extensive run time statistics about the execution of a
-Python program.
-
-Call count statistics can be used to identify bugs in code (surprising
-counts), and to identify possible inline-expansion points (high call
-counts). Internal time statistics can be used to identify hot loops
-that should be carefully optimized. Cumulative time statistics should
-be used to identify high level errors in the selection of algorithms.
-Note that the unusual handling of cumulative times in this profiler
-allows statistics for recursive implementations of algorithms to be
-directly compared to iterative implementations.
-
-
-REFERENCE MANUAL
-
-The primary entry point for the profiler is the global function
-profile.run(). It is typically used to create any profile
-information. The reports are formatted and printed using methods for
-the class pstats.Stats. The following is a description of all of
-these standard entry points and functions. For a more in-depth view
-of some of the code, consider reading the later section on "Profiler
-Extensions," which includes discussion of how to derive "better"
-profilers from the classes presented, or reading the source code for
-these modules.
-
-
-FUNCTION profile.run(string, filename_opt)
-
-This function takes a single argument that has 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. The following is a typical output from such a call:
-
-cut here----
-
- main()
- 2706 function calls (2004 primitive calls) in 4.504 CPU seconds
-
- Ordered by: standard name
-
- ncalls tottime percall cumtime percall filename:lineno(function)
- 2 0.006 0.003 0.953 0.477 pobject.py:75(save_objects)
- 43/3 0.533 0.012 0.749 0.250 pobject.py:99(evaluate)
- ...
-
-cut here----
-
-The first line indicates that this profile was generated by the call:
-profile.run('main()'), and hence the exec'ed string is 'main()'. The
-second line indicates that 2706 calls were monitored. Of those calls,
-2004 were "primitive." We define "primitive" to mean that the call
-was not induced via recursion. The next line: "Ordered by: standard
-name", indicates that the text string in the far right column was used
-to sort the output. The column headings include:
-
- "ncalls" for the number of calls,
- "tottime" for the total time spent in the given function
- (and excluding time made in calls to sub-functions),
- "percall" is the quotient of "tottime" divided by "ncalls"
- "cumtime" is the total time spent in this and all subfunctions
- (i.e., from invocation till exit). This figure is
- accurate *even* for recursive functions.
- "percall" is the quotient of "cumtime" divided by primitive
- calls
- "filename:lineno(function)" provides the respective data of
- each function
-
-When there are two numbers in the first column (e.g.: 43/3), then the
-latter is the number of primitive calls, and the former is the actual
-number of calls. Note that when the function does not recurse, these
-two values are the same, and only the single figure is printed.
-
-
-CLASS Stats(filename, ...)
-
-This class constructor creates an instance of a statistics object from
-a filename (or set of filenames). Stats objects are manipulated by
-methods, in order to print useful reports.
-
-The file selected by the above constructor must have been created by
-the corresponding version of profile. To be specific, there is *NO*
-file compatibility guaranteed with future versions of this profiler,
-and there is no compatibility with files produced by other profilers
-(e.g., the standard system profiler).
-
-If several files are provided, all the statistics for identical
-functions will be coalesced, so that an overall view of several
-processes can be considered in a single report. If additional files
-need to be combined with data in an existing Stats object, the add()
-method can be used.
-
-
-METHOD strip_dirs()
-
-This method for the Stats class removes all leading path information
-from file names. It is very useful in reducing the size of the
-printout to fit within (close to) 80 columns. This method modifies
-the object, and the striped information is lost. After performing a
-strip operation, the object is considered to have its entries in a
-"random" order, as it was just after object initialization and
-loading. If strip_dir() causes two function names to be
-indistinguishable (i.e., they are on the same line of the same
-filename, and have the same function name), then the statistics for
-these two entries are accumulated into a single entry.
-
-
-METHOD add(filename, ...)
-
-This methods of the Stats class accumulates additional profiling
-information into the current profiling object. Its arguments should
-refer to filenames created my the corresponding version of
-profile.run(). Statistics for identically named (re: file, line,
-name) functions are automatically accumulated into single function
-statistics.
-
-
-METHOD sort_stats(key, ...)
-
-This method modifies the Stats object by sorting it according to the
-supplied criteria. The argument is typically a string identifying the
-basis of a sort (example: "time" or "name").
-
-When more than one key is provided, then additional keys are used as
-secondary criteria when there is equality in all keys selected
-before them. For example, sort_stats('name', 'file') will sort all
-the entries according to their function name, and resolve all ties
-(identical function names) by sorting by file name.
-
-Abbreviations can be used for any key names, as long as the
-abbreviation is unambiguous. The following are the keys currently
-defined:
-
- Valid Arg Meaning
- "calls" call count
- "cumulative" cumulative time
- "file" file name
- "module" file name
- "pcalls" primitive call count
- "line" line number
- "name" function name
- "nfl" name/file/line
- "stdname" standard name
- "time" internal time
-
-Note that all sorts on statistics are in descending order (placing most
-time consuming items first), where as name, file, and line number
-searches are in ascending order (i.e., alphabetical). The subtle
-distinction between "nfl" and "stdname" is that the standard name is a
-sort of the name as printed, which means that the embedded line
-numbers get compared in an odd way. For example, lines 3, 20, and 40
-would (if the file names were the same) appear in the string order
-"20" "3" and "40". In contrast, "nfl" does a numeric compare of the
-line numbers. In fact, sort_stats("nfl") is the same as
-sort_stats("name", "file", "line").
-
-For compatibility with the standard profiler, the numeric argument -1,
-0, 1, and 2 are permitted. They are interpreted as "stdname",
-"calls", "time", and "cumulative" respectively. If this old style
-format (numeric) is used, only one sort key (the numeric key) will be
-used, and additionally arguments will be silently ignored.
-
-
-METHOD reverse_order()
-
-This method for the Stats class reverses the ordering of the basic
-list within the object. This method is provided primarily for
-compatibility with the standard profiler. Its utility is questionable
-now that ascending vs descending order is properly selected based on
-the sort key of choice.
-
-
-METHOD print_stats(restriction, ...)
-
-This method for the Stats class prints out a report as described in
-the profile.run() definition.
-
-The order of the printing is based on the last sort_stats() operation
-done on the object (subject to caveats in add() and strip_dirs()).
-
-The arguments provided (if any) can be used to limit the list down to
-the significant entries. Initially, the list is taken to be the
-complete set of profiled functions. Each restriction is either an
-integer (to select a count of lines), or a decimal fraction between
-0.0 and 1.0 inclusive (to select a percentage of lines), or a regular
-expression (to pattern match the standard name that is printed). If
-several restrictions are provided, then they are applied sequentially.
-For example:
-
- print_stats(.1, "foo:")
-
-would first limit the printing to first 10% of list, and then only
-print functions that were part of filename ".*foo:". In contrast, the
-command:
-
- print_stats("foo:", .1)
-
-would limit the list to all functions having file names ".*foo:", and
-then proceed to only print the first 10% of them.
-
-
-METHOD print_callers(restrictions, ...)
-
-This method for the Stats class prints a list of all functions that
-called each function in the profiled database. The ordering is
-identical to that provided by print_stats(), and the definition of the
-restricting argument is also identical. For convenience, a number is
-shown in parentheses after each caller to show how many times this
-specific call was made. A second non-parenthesized number is the
-cumulative time spent in the function at the right.
-
-
-METHOD print_callees(restrictions, ...)
-
-This method for the Stats class prints a list of all function that
-were called by the indicated function. Aside from this reversal of
-direction of calls (re: called vs was called by), the arguments and
-ordering are identical to the print_callers() method.
-
-
-METHOD ignore()
-
-This method of the Stats class is used to dispose of the value
-returned by earlier methods. All standard methods in this class
-return the instance that is being processed, so that the commands can
-be strung together. For example:
-
-pstats.Stats('foofile').strip_dirs().sort_stats('cum').print_stats().ignore()
-
-would perform all the indicated functions, but it would not return
-the final reference to the Stats instance.
-
-
-
-
-LIMITATIONS
-
-There are two fundamental limitations on this profiler. The first is
-that it relies on the Python interpreter to dispatch "call", "return",
-and "exception" events. Compiled C code does not get interpreted,
-and hence is "invisible" to the profiler. All time spent in C code
-(including builtin functions) will be charged to the Python function
-that was invoked the C code. IF the C code calls out to some native
-Python code, then those calls will be profiled properly.
-
-The second limitation has to do with accuracy of timing information.
-There is a fundamental problem with deterministic profilers involving
-accuracy. The most obvious restriction is that the underlying "clock"
-is only ticking at a rate (typically) of about .001 seconds. Hence no
-measurements will be more accurate than that underlying clock. If
-enough measurements are taken, then the "error" will tend to average
-out. Unfortunately, removing this first error induces a second source
-of error...
-
-The second problem is that it "takes a while" from when an event is
-dispatched until the profiler's call to get the time actually *gets*
-the state of the clock. Similarly, there is a certain lag when
-exiting the profiler event handler from the time that the clock's
-value was obtained (and then squirreled away), until the user's code
-is once again executing. As a result, functions that are called many
-times, or call many functions, will typically accumulate this error.
-The error that accumulates in this fashion is typically less than the
-accuracy of the clock (i.e., less than one clock tick), but it *can*
-accumulate and become very significant. This profiler provides a
-means of calibrating itself for a give platform so that this error can
-be probabilistically (i.e., on the average) removed. After the
-profiler is calibrated, it will be more accurate (in a least square
-sense), but it will sometimes produce negative numbers (when call
-counts are exceptionally low, and the gods of probability work against
-you :-). ) Do *NOT* be alarmed by negative numbers in the profile.
-They should *only* appear if you have calibrated your profiler, and
-the results are actually better than without calibration.
-
-
-CALIBRATION
-
-The profiler class has a hard coded constant that is added to 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
-in LIMITATIONS above).
-
- import profile
- pr = profile.Profile()
- pr.calibrate(100)
- pr.calibrate(100)
- pr.calibrate(100)
-
-The argument to calibrate() is the number of times to try to do the
-sample calls to get the CPU times. If your computer is *very* fast,
-you might have to do:
-
- pr.calibrate(1000)
-
-or even:
-
- pr.calibrate(10000)
-
-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.
-
-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:
-
- 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
-
-Note that if there is no calibration constant, then the line
-containing the callibration constant should simply say:
-
- t = t[0] + t[1] - self.t # no calibration constant
-
-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 *very* fancy
-coding, or else the use of a variable where the constant .00053 was
-placed in the code shown. This is a ****VERY**** critical performance
-section, and there is no reason to use a variable lookup at this
-point, when a constant can be used.
-
-
-EXTENSIONS: Deriving Better Profilers
-
-The Profile class of profile was written so that derived classes
-could be developed to extend the profiler. Rather than describing all
-the details of such an effort, I'll just present the following two
-examples of derived classes that can be used to do profiling. If the
-reader is an avid Python programmer, then it should be possible to use
-these as a model and create similar (and perchance better) profile
-classes.
-
-If all you want to do is change how the timer is called, or which
-timer function is used, then the basic class has an option for that in
-the constructor for the class. Consider passing the name of a
-function to call into the constructor:
-
- pr = profile.Profile(your_time_func)
-
-The resulting profiler will call your time function instead of
-os.times(). The function should return either a single number, or a
-list of numbers (like what os.times() returns). If the function
-returns a single time number, or the list of returned numbers has
-length 2, then you will get an especially fast version of the dispatch
-routine.
-
-Be warned that you *should* calibrate the profiler class for the
-timer function that you choose. For most machines, a timer that
-returns a lone integer value will provide the best results in terms of
-low overhead during profiling. (os.times is *pretty* bad, 'cause it
-returns a tuple of floating point values, so all arithmetic is
-floating point in the profiler!). If you want to be substitute a
-better timer in the cleanest fashion, you should derive a class, and
-simply put in the replacement dispatch method that better handles your timer
-call, along with the appropriate calibration constant :-).
-
-
-cut here------------------------------------------------------------------
-#****************************************************************************
-# OldProfile class documentation
-#****************************************************************************
-#
-# The following derived profiler simulates the old style profile, providing
-# errant results on recursive functions. The reason for the usefulness of this
-# profiler is that it runs faster (i.e., less overhead) than the old
-# profiler. It still creates all the caller stats, and is quite
-# useful when there is *no* recursion in the user's code. It is also
-# a lot more accurate than the old profiler, as it does not charge all
-# its overhead time to the user's code.
-#****************************************************************************
-class OldProfile(Profile):
- def trace_dispatch_exception(self, frame, t):
- rt, rtt, rct, rfn, rframe, rcur = self.cur
- if rcur and not rframe is frame:
- return self.trace_dispatch_return(rframe, t)
- return 0
-
- def trace_dispatch_call(self, frame, t):
- fn = `frame.f_code`
-
- self.cur = (t, 0, 0, fn, frame, self.cur)
- if self.timings.has_key(fn):
- tt, ct, callers = self.timings[fn]
- self.timings[fn] = tt, ct, callers
- else:
- self.timings[fn] = 0, 0, {}
- return 1
-
- def trace_dispatch_return(self, frame, t):
- rt, rtt, rct, rfn, frame, rcur = self.cur
- rtt = rtt + t
- sft = rtt + rct
-
- pt, ptt, pct, pfn, pframe, pcur = rcur
- self.cur = pt, ptt+rt, pct+sft, pfn, pframe, pcur
-
- tt, ct, callers = self.timings[rfn]
- if callers.has_key(pfn):
- callers[pfn] = callers[pfn] + 1
- else:
- callers[pfn] = 1
- self.timings[rfn] = tt+rtt, ct + sft, callers
-
- return 1
-
-
- def snapshot_stats(self):
- self.stats = {}
- for func in self.timings.keys():
- tt, ct, callers = self.timings[func]
- nor_func = self.func_normalize(func)
- nor_callers = {}
- nc = 0
- for func_caller in callers.keys():
- nor_callers[self.func_normalize(func_caller)]=\
- callers[func_caller]
- nc = nc + callers[func_caller]
- self.stats[nor_func] = nc, nc, tt, ct, nor_callers
-
-
-
-#****************************************************************************
-# HotProfile class documentation
-#****************************************************************************
-#
-# This profiler is the fastest derived profile example. It does not
-# calculate caller-callee relationships, and does not calculate cumulative
-# time under a function. It only calculates time spent in a function, so
-# it runs very quickly (re: very low overhead). In truth, the basic
-# profiler is so fast, that is probably not worth the savings to give
-# up the data, but this class still provides a nice example.
-#****************************************************************************
-class HotProfile(Profile):
- def trace_dispatch_exception(self, frame, t):
- rt, rtt, rfn, rframe, rcur = self.cur
- if rcur and not rframe is frame:
- return self.trace_dispatch_return(rframe, t)
- return 0
-
- def trace_dispatch_call(self, frame, t):
- self.cur = (t, 0, frame, self.cur)
- return 1
-
- def trace_dispatch_return(self, frame, t):
- rt, rtt, frame, rcur = self.cur
-
- rfn = `frame.f_code`
-
- pt, ptt, pframe, pcur = rcur
- self.cur = pt, ptt+rt, pframe, pcur
-
- if self.timings.has_key(rfn):
- nc, tt = self.timings[rfn]
- self.timings[rfn] = nc + 1, rt + rtt + tt
- else:
- self.timings[rfn] = 1, rt + rtt
-
- return 1
-
-
- def snapshot_stats(self):
- self.stats = {}
- for func in self.timings.keys():
- nc, tt = self.timings[func]
- nor_func = self.func_normalize(func)
- self.stats[nor_func] = nc, nc, tt, 0, {}
-
-
-
-cut here------------------------------------------------------------------
projects / python / commitdiff