26.4. The Python Profilers
26.4.1. Introduction to the profilers
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
cProfile, profile and pstats. This profiler
provides deterministic profiling of Python programs. It also
provides a series of report generation tools to allow users to rapidly
examine the results of a profile operation.
The Python standard library provides three different profilers:
cProfile is recommended for most users; it’s a C extension
with reasonable overhead
that makes it suitable for profiling long-running programs.
Based on lsprof,
contributed by Brett Rosen and Ted Czotter.
New in version 2.5:
New in version 2.5.
profile, a pure Python module whose interface is imitated by
cProfile. Adds significant overhead to profiled programs.
If you’re trying to extend
the profiler in some way, the task might be easier with this module.
Changed in version 2.4:
Changed in version 2.4: Now also reports the time spent in calls to built-in functions and methods.
hotshot was an experimental C module that focused on minimizing
the overhead of profiling, at the expense of longer data
post-processing times. It is no longer maintained and may be
dropped in a future version of Python.
Changed in version 2.5:
Changed in version 2.5: The results should be more meaningful than in the past: the timing core
contained a critical bug.
The profile and cProfile modules export the same interface, so
they are mostly interchangeable; cProfile has a much lower overhead but
is newer and might not be available on all systems.
cProfile is really a compatibility layer on top of the internal
_lsprof module. The hotshot module is reserved for specialized
usage.
26.4.2. Instant User’s 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 cProfile
cProfile.run('foo()')
(Use profile instead of cProfile if the latter is not available on
your system.)
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 cProfile
cProfile.run('foo()', 'fooprof')
The file cProfile.py can also be invoked as a script to profile another
script. For example:
python -m cProfile myscript.py
cProfile.py accepts two optional arguments on the command line:
cProfile.py [-o output_file] [-s sort_order]
-s only applies to standard output (-o is not supplied).
Look in the Stats documentation for valid sort values.
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 cProfile.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. 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 (since 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 statistics 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')
Invoked as a script, the pstats module is a statistics browser for
reading and examining profile dumps. It has a simple line-oriented interface
(implemented using cmd) and interactive help.
26.4.3. 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, 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.
-
Stats.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 (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 backward-compatibility reasons, the numeric arguments -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
additional arguments will be silently ignored.