mirror of
https://github.com/python/cpython.git
synced 2024-12-10 02:04:28 +08:00
f0dfc7ac5c
(From SF patch #810751)
703 lines
28 KiB
Plaintext
703 lines
28 KiB
Plaintext
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------------------------------------------------------------------
|