mirror of
https://github.com/python/cpython.git
synced 2025-09-26 18:29:57 +00:00
#6696: merge with 3.3.
This commit is contained in:
Ezio Melotti
commit
cbc2d29636
3 changed files with 414 additions and 387 deletions
|
|
@ -4,11 +4,6 @@
|
||||||
The Python Profilers
|
The Python Profilers
|
||||||
********************
|
********************
|
||||||
|
|
||||||
.. sectionauthor:: James Roskind
|
|
||||||
|
|
||||||
.. module:: profile
|
|
||||||
:synopsis: Python source profiler.
|
|
||||||
|
|
||||||
**Source code:** :source:`Lib/profile.py` and :source:`Lib/pstats.py`
|
**Source code:** :source:`Lib/profile.py` and :source:`Lib/pstats.py`
|
||||||
|
|
||||||
--------------
|
--------------
|
||||||
|
|
@ -22,14 +17,13 @@ Introduction to the profilers
|
||||||
single: deterministic profiling
|
single: deterministic profiling
|
||||||
single: profiling, deterministic
|
single: profiling, deterministic
|
||||||
|
|
||||||
A :dfn:`profiler` is a program that describes the run time performance of a
|
:mod:`cProfile` and :mod:`profile` provide :dfn:`deterministic profiling` of
|
||||||
program, providing a variety of statistics. This documentation describes the
|
Python programs. A :dfn:`profile` is a set of statistics that describes how
|
||||||
profiler functionality provided in the modules :mod:`cProfile`, :mod:`profile`
|
often and for how long various parts of the program executed. These statistics
|
||||||
and :mod:`pstats`. This profiler provides :dfn:`deterministic profiling` of
|
can be formatted into reports via the :mod:`pstats` module.
|
||||||
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 two different profilers:
|
The Python standard library provides two different implementations of the same
|
||||||
|
profiling interface:
|
||||||
|
|
||||||
1. :mod:`cProfile` is recommended for most users; it's a C extension with
|
1. :mod:`cProfile` is recommended for most users; it's a C extension with
|
||||||
reasonable overhead that makes it suitable for profiling long-running
|
reasonable overhead that makes it suitable for profiling long-running
|
||||||
|
|
@ -37,14 +31,9 @@ The Python standard library provides two different profilers:
|
||||||
Czotter.
|
Czotter.
|
||||||
|
|
||||||
2. :mod:`profile`, a pure Python module whose interface is imitated by
|
2. :mod:`profile`, a pure Python module whose interface is imitated by
|
||||||
:mod:`cProfile`. Adds significant overhead to profiled programs. If you're
|
:mod:`cProfile`, but which adds significant overhead to profiled programs.
|
||||||
trying to extend the profiler in some way, the task might be easier with this
|
If you're trying to extend the profiler in some way, the task might be easier
|
||||||
module.
|
with this module.
|
||||||
|
|
||||||
The :mod:`profile` and :mod:`cProfile` modules export the same interface, so
|
|
||||||
they are mostly interchangeable; :mod:`cProfile` has a much lower overhead but
|
|
||||||
is newer and might not be available on all systems. :mod:`cProfile` is really a
|
|
||||||
compatibility layer on top of the internal :mod:`_lsprof` module.
|
|
||||||
|
|
||||||
.. note::
|
.. note::
|
||||||
|
|
||||||
|
|
@ -65,57 +54,94 @@ 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
|
provides a very brief overview, and allows a user to rapidly perform profiling
|
||||||
on an existing application.
|
on an existing application.
|
||||||
|
|
||||||
To profile an application with a main entry point of :func:`foo`, you would add
|
To profile a function that takes a single argument, you can do::
|
||||||
the following to your module::
|
|
||||||
|
|
||||||
import cProfile
|
import cProfile
|
||||||
cProfile.run('foo()')
|
import re
|
||||||
|
cProfile.run('re.compile("foo|bar")')
|
||||||
|
|
||||||
(Use :mod:`profile` instead of :mod:`cProfile` if the latter is not available on
|
(Use :mod:`profile` instead of :mod:`cProfile` if the latter is not available on
|
||||||
your system.)
|
your system.)
|
||||||
|
|
||||||
The above action would cause :func:`foo` to be run, and a series of informative
|
The above action would run :func:`re.compile` and print profile results like
|
||||||
lines (the profile) to be printed. The above approach is most useful when
|
the following::
|
||||||
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
|
197 function calls (192 primitive calls) in 0.002 seconds
|
||||||
second argument to the :func:`run` function::
|
|
||||||
|
Ordered by: standard name
|
||||||
|
|
||||||
|
ncalls tottime percall cumtime percall filename:lineno(function)
|
||||||
|
1 0.000 0.000 0.001 0.001 <string>:1(<module>)
|
||||||
|
1 0.000 0.000 0.001 0.001 re.py:212(compile)
|
||||||
|
1 0.000 0.000 0.001 0.001 re.py:268(_compile)
|
||||||
|
1 0.000 0.000 0.000 0.000 sre_compile.py:172(_compile_charset)
|
||||||
|
1 0.000 0.000 0.000 0.000 sre_compile.py:201(_optimize_charset)
|
||||||
|
4 0.000 0.000 0.000 0.000 sre_compile.py:25(_identityfunction)
|
||||||
|
3/1 0.000 0.000 0.000 0.000 sre_compile.py:33(_compile)
|
||||||
|
|
||||||
|
The first line indicates that 197 calls were monitored. Of those calls, 192
|
||||||
|
were :dfn:`primitive`, meaning 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 cumulative time spent in this and all subfunctions (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 (for example ``3/1``), it means
|
||||||
|
that the function recursed. The second value is the number of primitive calls
|
||||||
|
and the former is the total number of calls. Note that when the function does
|
||||||
|
not recurse, these two values are the same, and only the single figure is
|
||||||
|
printed.
|
||||||
|
|
||||||
|
Instead of printing the output at the end of the profile run, you can save the
|
||||||
|
results to a file by specifying a filename to the :func:`run` function::
|
||||||
|
|
||||||
import cProfile
|
import cProfile
|
||||||
cProfile.run('foo()', 'fooprof')
|
import re
|
||||||
|
cProfile.run('re.compile("foo|bar")', 'restats')
|
||||||
|
|
||||||
The file :file:`cProfile.py` can also be invoked as a script to profile another
|
The :class:`pstats.Stats` class reads profile results from a file and formats
|
||||||
|
them in various ways.
|
||||||
|
|
||||||
|
The file :mod:`cProfile` can also be invoked as a script to profile another
|
||||||
script. For example::
|
script. For example::
|
||||||
|
|
||||||
python -m cProfile myscript.py
|
python -m cProfile [-o output_file] [-s sort_order] myscript.py
|
||||||
|
|
||||||
:file:`cProfile.py` accepts two optional arguments on the command line::
|
``-o`` writes the profile results to a file instead of to stdout
|
||||||
|
|
||||||
cProfile.py [-o output_file] [-s sort_order]
|
``-s`` specifies one of the :func:`~pstats.Stats.sort_stats` sort values to sort
|
||||||
|
the output by. This only applies when ``-o`` is not supplied.
|
||||||
|
|
||||||
``-s`` only applies to standard output (``-o`` is not supplied).
|
The :mod:`pstats` module's :class:`~pstats.Stats` class has a variety of methods
|
||||||
Look in the :class:`Stats` documentation for valid sort values.
|
for manipulating and printing the data saved into a profile results file::
|
||||||
|
|
||||||
When you wish to review the profile, you should use the methods in the
|
|
||||||
:mod:`pstats` module. Typically you would load the statistics data as follows::
|
|
||||||
|
|
||||||
import pstats
|
import pstats
|
||||||
p = pstats.Stats('fooprof')
|
p = pstats.Stats('restats')
|
||||||
|
|
||||||
The class :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 :func:`cProfile.run` above, what was printed was
|
|
||||||
the result of three method calls::
|
|
||||||
|
|
||||||
p.strip_dirs().sort_stats(-1).print_stats()
|
p.strip_dirs().sort_stats(-1).print_stats()
|
||||||
|
|
||||||
The first method removed the extraneous path from all the module names. The
|
The :meth:`~pstats.Stats.strip_dirs` method removed the extraneous path from all
|
||||||
second method sorted all the entries according to the standard module/line/name
|
the module names. The :meth:`~pstats.Stats.sort_stats` method sorted all the
|
||||||
string that is printed. The third method printed out all the statistics. You
|
entries according to the standard module/line/name string that is printed. The
|
||||||
might try the following sort calls:
|
:meth:`~pstats.Stats.print_stats` method printed out all the statistics. You
|
||||||
|
might try the following sort calls::
|
||||||
.. (this is to comply with the semantics of the old profiler).
|
|
||||||
|
|
||||||
::
|
|
||||||
|
|
||||||
p.sort_stats('name')
|
p.sort_stats('name')
|
||||||
p.print_stats()
|
p.print_stats()
|
||||||
|
|
@ -164,12 +190,301 @@ If you want more functionality, you're going to have to read the manual, or
|
||||||
guess what the following functions do::
|
guess what the following functions do::
|
||||||
|
|
||||||
p.print_callees()
|
p.print_callees()
|
||||||
p.add('fooprof')
|
p.add('restats')
|
||||||
|
|
||||||
Invoked as a script, the :mod:`pstats` module is a statistics browser for
|
Invoked as a script, the :mod:`pstats` module is a statistics browser for
|
||||||
reading and examining profile dumps. It has a simple line-oriented interface
|
reading and examining profile dumps. It has a simple line-oriented interface
|
||||||
(implemented using :mod:`cmd`) and interactive help.
|
(implemented using :mod:`cmd`) and interactive help.
|
||||||
|
|
||||||
|
:mod:`profile` and :mod:`cProfile` Module Reference
|
||||||
|
=======================================================
|
||||||
|
|
||||||
|
.. module:: cProfile
|
||||||
|
.. module:: profile
|
||||||
|
:synopsis: Python source profiler.
|
||||||
|
|
||||||
|
Both the :mod:`profile` and :mod:`cProfile` modules provide the following
|
||||||
|
functions:
|
||||||
|
|
||||||
|
.. function:: run(command, filename=None, sort=-1)
|
||||||
|
|
||||||
|
This function takes a single argument that can be passed to the :func:`exec`
|
||||||
|
function, and an optional file name. In all cases this routine executes::
|
||||||
|
|
||||||
|
exec(command, __main__.__dict__, __main__.__dict__)
|
||||||
|
|
||||||
|
and gathers profiling statistics from the execution. If no file name is
|
||||||
|
present, then this function automatically creates a :class:`~pstats.Stats`
|
||||||
|
instance and prints a simple profiling report. If the sort value is specified
|
||||||
|
it is passed to this :class:`~pstats.Stats` instance to control how the
|
||||||
|
results are sorted.
|
||||||
|
|
||||||
|
.. function:: runctx(command, globals, locals, filename=None)
|
||||||
|
|
||||||
|
This function is similar to :func:`run`, with added arguments to supply the
|
||||||
|
globals and locals dictionaries for the *command* string. This routine
|
||||||
|
executes::
|
||||||
|
|
||||||
|
exec(command, globals, locals)
|
||||||
|
|
||||||
|
and gathers profiling statistics as in the :func:`run` function above.
|
||||||
|
|
||||||
|
.. class:: Profile(timer=None, timeunit=0.0, subcalls=True, builtins=True)
|
||||||
|
|
||||||
|
This class is normally only used if more precise control over profiling is
|
||||||
|
needed than what the :func:`cProfile.run` function provides.
|
||||||
|
|
||||||
|
A custom timer can be supplied for measuring how long code takes to run via
|
||||||
|
the *timer* argument. This must be a function that returns a single number
|
||||||
|
representing the current time. If the number is an integer, the *timeunit*
|
||||||
|
specifies a multiplier that specifies the duration of each unit of time. For
|
||||||
|
example, if the timer returns times measured in thousands of seconds, the
|
||||||
|
time unit would be ``.001``.
|
||||||
|
|
||||||
|
Directly using the :class:`Profile` class allows formatting profile results
|
||||||
|
without writing the profile data to a file::
|
||||||
|
|
||||||
|
import cProfile, pstats, io
|
||||||
|
pr = cProfile.Profile()
|
||||||
|
pr.enable()
|
||||||
|
... do something ...
|
||||||
|
pr.disable()
|
||||||
|
s = io.StringIO()
|
||||||
|
ps = pstats.Stats(pr, stream=s)
|
||||||
|
ps.print_results()
|
||||||
|
|
||||||
|
.. method:: enable()
|
||||||
|
|
||||||
|
Start collecting profiling data.
|
||||||
|
|
||||||
|
.. method:: disable()
|
||||||
|
|
||||||
|
Stop collecting profiling data.
|
||||||
|
|
||||||
|
.. method:: create_stats()
|
||||||
|
|
||||||
|
Stop collecting profiling data and record the results internally
|
||||||
|
as the current profile.
|
||||||
|
|
||||||
|
.. method:: print_stats(sort=-1)
|
||||||
|
|
||||||
|
Create a :class:`~pstats.Stats` object based on the current
|
||||||
|
profile and print the results to stdout.
|
||||||
|
|
||||||
|
.. method:: dump_stats(filename)
|
||||||
|
|
||||||
|
Write the results of the current profile to *filename*.
|
||||||
|
|
||||||
|
.. method:: run(cmd)
|
||||||
|
|
||||||
|
Profile the cmd via :func:`exec`.
|
||||||
|
|
||||||
|
.. method:: runctx(cmd, globals, locals)
|
||||||
|
|
||||||
|
Profile the cmd via :func:`exec` with the specified global and
|
||||||
|
local environment.
|
||||||
|
|
||||||
|
.. method:: runcall(func, *args, **kwargs)
|
||||||
|
|
||||||
|
Profile ``func(*args, **kwargs)``
|
||||||
|
|
||||||
|
.. _profile-stats:
|
||||||
|
|
||||||
|
The :class:`Stats` Class
|
||||||
|
========================
|
||||||
|
|
||||||
|
Analysis of the profiler data is done using the :class:`~pstats.Stats` class.
|
||||||
|
|
||||||
|
.. module:: pstats
|
||||||
|
:synopsis: Statistics object for use with the profiler.
|
||||||
|
|
||||||
|
.. class:: Stats(*filenames or profile, stream=sys.stdout)
|
||||||
|
|
||||||
|
This class constructor creates an instance of a "statistics object" from a
|
||||||
|
*filename* (or list of filenames) or from a :class:`Profile` instance. Output
|
||||||
|
will be printed to the stream specified by *stream*.
|
||||||
|
|
||||||
|
The file selected by the above constructor must have been created by the
|
||||||
|
corresponding version of :mod:`profile` or :mod:`cProfile`. 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. 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 :class:`~pstats.Stats` object, the
|
||||||
|
:meth:`~pstats.Stats.add` method can be used.
|
||||||
|
|
||||||
|
Instead of reading the profile data from a file, a :class:`cProfile.Profile`
|
||||||
|
or :class:`profile.Profile` object can be used as the profile data source.
|
||||||
|
|
||||||
|
:class:`Stats` objects have the following methods:
|
||||||
|
|
||||||
|
.. method:: strip_dirs()
|
||||||
|
|
||||||
|
This method for the :class:`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 stripped 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 :meth:`~pstats.Stats.strip_dirs` causes two function names to be
|
||||||
|
indistinguishable (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(*filenames)
|
||||||
|
|
||||||
|
This method of the :class:`Stats` class accumulates additional profiling
|
||||||
|
information into the current profiling object. Its arguments should refer
|
||||||
|
to filenames created by the corresponding version of :func:`profile.run`
|
||||||
|
or :func:`cProfile.run`. Statistics for identically named (re: file, line,
|
||||||
|
name) functions are automatically accumulated into single function
|
||||||
|
statistics.
|
||||||
|
|
||||||
|
|
||||||
|
.. method:: dump_stats(filename)
|
||||||
|
|
||||||
|
Save the data loaded into the :class:`Stats` object to a file named
|
||||||
|
*filename*. The file is created if it does not exist, and is overwritten
|
||||||
|
if it already exists. This is equivalent to the method of the same name
|
||||||
|
on the :class:`profile.Profile` and :class:`cProfile.Profile` classes.
|
||||||
|
|
||||||
|
|
||||||
|
.. method:: sort_stats(*keys)
|
||||||
|
|
||||||
|
This method modifies the :class:`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 |
|
||||||
|
+------------------+----------------------+
|
||||||
|
| ``'cumtime'`` | cumulative time |
|
||||||
|
+------------------+----------------------+
|
||||||
|
| ``'file'`` | file name |
|
||||||
|
+------------------+----------------------+
|
||||||
|
| ``'filename'`` | file name |
|
||||||
|
+------------------+----------------------+
|
||||||
|
| ``'module'`` | file name |
|
||||||
|
+------------------+----------------------+
|
||||||
|
| ``'ncalls'`` | call count |
|
||||||
|
+------------------+----------------------+
|
||||||
|
| ``'pcalls'`` | primitive call count |
|
||||||
|
+------------------+----------------------+
|
||||||
|
| ``'line'`` | line number |
|
||||||
|
+------------------+----------------------+
|
||||||
|
| ``'name'`` | function name |
|
||||||
|
+------------------+----------------------+
|
||||||
|
| ``'nfl'`` | name/file/line |
|
||||||
|
+------------------+----------------------+
|
||||||
|
| ``'stdname'`` | standard name |
|
||||||
|
+------------------+----------------------+
|
||||||
|
| ``'time'`` | internal time |
|
||||||
|
+------------------+----------------------+
|
||||||
|
| ``'tottime'`` | 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.
|
||||||
|
|
||||||
|
.. For compatibility with the old profiler.
|
||||||
|
|
||||||
|
|
||||||
|
.. method:: reverse_order()
|
||||||
|
|
||||||
|
This method for the :class:`Stats` class reverses the ordering of the
|
||||||
|
basic list within the object. Note that by default ascending vs
|
||||||
|
descending order is properly selected based on the sort key of choice.
|
||||||
|
|
||||||
|
.. This method is provided primarily for compatibility with the old
|
||||||
|
profiler.
|
||||||
|
|
||||||
|
|
||||||
|
.. method:: print_stats(*restrictions)
|
||||||
|
|
||||||
|
This method for the :class:`Stats` class prints out a report as described
|
||||||
|
in the :func:`profile.run` definition.
|
||||||
|
|
||||||
|
The order of the printing is based on the last
|
||||||
|
:meth:`~pstats.Stats.sort_stats` operation done on the object (subject to
|
||||||
|
caveats in :meth:`~pstats.Stats.add` and
|
||||||
|
:meth:`~pstats.Stats.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 :file:`.\*foo:`. In contrast, the
|
||||||
|
command::
|
||||||
|
|
||||||
|
print_stats('foo:', .1)
|
||||||
|
|
||||||
|
would limit the list to all functions having file names :file:`.\*foo:`,
|
||||||
|
and then proceed to only print the first 10% of them.
|
||||||
|
|
||||||
|
|
||||||
|
.. method:: print_callers(*restrictions)
|
||||||
|
|
||||||
|
This method for the :class:`Stats` class prints a list of all functions
|
||||||
|
that called each function in the profiled database. The ordering is
|
||||||
|
identical to that provided by :meth:`~pstats.Stats.print_stats`, and the
|
||||||
|
definition of the restricting argument is also identical. Each caller is
|
||||||
|
reported on its own line. The format differs slightly depending on the
|
||||||
|
profiler that produced the stats:
|
||||||
|
|
||||||
|
* With :mod:`profile`, a number is shown in parentheses after each caller
|
||||||
|
to show how many times this specific call was made. For convenience, a
|
||||||
|
second non-parenthesized number repeats the cumulative time spent in the
|
||||||
|
function at the right.
|
||||||
|
|
||||||
|
* With :mod:`cProfile`, each caller is preceded by three numbers: the
|
||||||
|
number of times this specific call was made, and the total and
|
||||||
|
cumulative times spent in the current function while it was invoked by
|
||||||
|
this specific caller.
|
||||||
|
|
||||||
|
|
||||||
|
.. method:: print_callees(*restrictions)
|
||||||
|
|
||||||
|
This method for the :class:`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 :meth:`~pstats.Stats.print_callers` method.
|
||||||
|
|
||||||
|
|
||||||
.. _deterministic-profiling:
|
.. _deterministic-profiling:
|
||||||
|
|
||||||
|
|
@ -204,296 +519,7 @@ implementations of algorithms to be directly compared to iterative
|
||||||
implementations.
|
implementations.
|
||||||
|
|
||||||
|
|
||||||
Reference Manual -- :mod:`profile` and :mod:`cProfile`
|
.. _profile-limitations:
|
||||||
======================================================
|
|
||||||
|
|
||||||
.. module:: cProfile
|
|
||||||
:synopsis: Python profiler
|
|
||||||
|
|
||||||
|
|
||||||
The primary entry point for the profiler is the global function
|
|
||||||
:func:`profile.run` (resp. :func:`cProfile.run`). It is typically used to create
|
|
||||||
any profile information. The reports are formatted and printed using methods of
|
|
||||||
the class :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:: run(command, filename=None, sort=-1)
|
|
||||||
|
|
||||||
This function takes a single argument that can be passed to the :func:`exec`
|
|
||||||
function, and an optional file name. In all cases this routine attempts to
|
|
||||||
:func:`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::
|
|
||||||
|
|
||||||
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)
|
|
||||||
...
|
|
||||||
|
|
||||||
The first line indicates that 2706 calls were monitored. Of those
|
|
||||||
calls, 2004 were :dfn:`primitive`. We define :dfn:`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 (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 (for example,
|
|
||||||
``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.
|
|
||||||
|
|
||||||
If *sort* is given, it can be one of values allowed for *key*
|
|
||||||
parameter from :meth:`pstats.Stats.sort_stats`.
|
|
||||||
|
|
||||||
|
|
||||||
.. function:: runctx(command, globals, locals, filename=None)
|
|
||||||
|
|
||||||
This function is similar to :func:`run`, with added arguments to supply the
|
|
||||||
globals and locals dictionaries for the *command* string.
|
|
||||||
|
|
||||||
|
|
||||||
Analysis of the profiler data is done using the :class:`pstats.Stats` class.
|
|
||||||
|
|
||||||
|
|
||||||
.. module:: pstats
|
|
||||||
:synopsis: Statistics object for use with the profiler.
|
|
||||||
|
|
||||||
|
|
||||||
.. class:: Stats(*filenames, stream=sys.stdout)
|
|
||||||
|
|
||||||
This class constructor creates an instance of a "statistics object"
|
|
||||||
from a *filename* (or set of filenames). :class:`Stats` objects
|
|
||||||
are manipulated by methods, in order to print useful reports. You
|
|
||||||
may specify an alternate output stream by giving the keyword
|
|
||||||
argument, ``stream``.
|
|
||||||
|
|
||||||
The file selected by the above constructor must have been created
|
|
||||||
by the corresponding version of :mod:`profile` or :mod:`cProfile`.
|
|
||||||
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. 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 :class:`Stats` object, the
|
|
||||||
:meth:`add` method can be used.
|
|
||||||
|
|
||||||
.. (such as the old system profiler).
|
|
||||||
|
|
||||||
|
|
||||||
.. _profile-stats:
|
|
||||||
|
|
||||||
The :class:`Stats` Class
|
|
||||||
------------------------
|
|
||||||
|
|
||||||
:class:`Stats` objects have the following methods:
|
|
||||||
|
|
||||||
|
|
||||||
.. method:: Stats.strip_dirs()
|
|
||||||
|
|
||||||
This method for the :class:`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 stripped 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 :meth:`strip_dirs` causes two
|
|
||||||
function names to be indistinguishable (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:: Stats.add(*filenames)
|
|
||||||
|
|
||||||
This method of the :class:`Stats` class accumulates additional profiling
|
|
||||||
information into the current profiling object. Its arguments should refer to
|
|
||||||
filenames created by the corresponding version of :func:`profile.run` or
|
|
||||||
:func:`cProfile.run`. Statistics for identically named (re: file, line, name)
|
|
||||||
functions are automatically accumulated into single function statistics.
|
|
||||||
|
|
||||||
|
|
||||||
.. method:: Stats.dump_stats(filename)
|
|
||||||
|
|
||||||
Save the data loaded into the :class:`Stats` object to a file named
|
|
||||||
*filename*. The file is created if it does not exist, and is
|
|
||||||
overwritten if it already exists. This is equivalent to the method
|
|
||||||
of the same name on the :class:`profile.Profile` and
|
|
||||||
:class:`cProfile.Profile` classes.
|
|
||||||
|
|
||||||
|
|
||||||
.. method:: Stats.sort_stats(*keys)
|
|
||||||
|
|
||||||
This method modifies the :class:`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 |
|
|
||||||
+------------------+----------------------+
|
|
||||||
| ``'cumtime'`` | cumulative time |
|
|
||||||
+------------------+----------------------+
|
|
||||||
| ``'file'`` | file name |
|
|
||||||
+------------------+----------------------+
|
|
||||||
| ``'filename'`` | file name |
|
|
||||||
+------------------+----------------------+
|
|
||||||
| ``'module'`` | file name |
|
|
||||||
+------------------+----------------------+
|
|
||||||
| ``'ncalls'`` | call count |
|
|
||||||
+------------------+----------------------+
|
|
||||||
| ``'pcalls'`` | primitive call count |
|
|
||||||
+------------------+----------------------+
|
|
||||||
| ``'line'`` | line number |
|
|
||||||
+------------------+----------------------+
|
|
||||||
| ``'name'`` | function name |
|
|
||||||
+------------------+----------------------+
|
|
||||||
| ``'nfl'`` | name/file/line |
|
|
||||||
+------------------+----------------------+
|
|
||||||
| ``'stdname'`` | standard name |
|
|
||||||
+------------------+----------------------+
|
|
||||||
| ``'time'`` | internal time |
|
|
||||||
+------------------+----------------------+
|
|
||||||
| ``'tottime'`` | 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.
|
|
||||||
|
|
||||||
.. For compatibility with the old profiler,
|
|
||||||
|
|
||||||
|
|
||||||
.. method:: Stats.reverse_order()
|
|
||||||
|
|
||||||
This method for the :class:`Stats` class reverses the ordering of
|
|
||||||
the basic list within the object. Note that by default ascending
|
|
||||||
vs descending order is properly selected based on the sort key of
|
|
||||||
choice.
|
|
||||||
|
|
||||||
.. This method is provided primarily for compatibility with the old profiler.
|
|
||||||
|
|
||||||
|
|
||||||
.. method:: Stats.print_stats(*restrictions)
|
|
||||||
|
|
||||||
This method for the :class:`Stats` class prints out a report as
|
|
||||||
described in the :func:`profile.run` definition.
|
|
||||||
|
|
||||||
The order of the printing is based on the last :meth:`sort_stats`
|
|
||||||
operation done on the object (subject to caveats in :meth:`add` and
|
|
||||||
:meth:`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; as of Python 1.5b1, this uses the Perl-style regular
|
|
||||||
expression syntax defined by the :mod:`re` module). 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 :file:`.\*foo:`. In contrast, the
|
|
||||||
command::
|
|
||||||
|
|
||||||
print_stats('foo:', .1)
|
|
||||||
|
|
||||||
would limit the list to all functions having file names :file:`.\*foo:`, and
|
|
||||||
then proceed to only print the first 10% of them.
|
|
||||||
|
|
||||||
|
|
||||||
.. method:: Stats.print_callers(*restrictions)
|
|
||||||
|
|
||||||
This method for the :class:`Stats` class prints a list of all functions that
|
|
||||||
called each function in the profiled database. The ordering is identical to
|
|
||||||
that provided by :meth:`print_stats`, and the definition of the restricting
|
|
||||||
argument is also identical. Each caller is reported on its own line. The
|
|
||||||
format differs slightly depending on the profiler that produced the stats:
|
|
||||||
|
|
||||||
* With :mod:`profile`, a number is shown in parentheses after each caller to
|
|
||||||
show how many times this specific call was made. For convenience, a second
|
|
||||||
non-parenthesized number repeats the cumulative time spent in the function
|
|
||||||
at the right.
|
|
||||||
|
|
||||||
* With :mod:`cProfile`, each caller is preceded by three numbers:
|
|
||||||
the number of times this specific call was made, and the total
|
|
||||||
and cumulative times spent in the current function while it was
|
|
||||||
invoked by this specific caller.
|
|
||||||
|
|
||||||
|
|
||||||
.. method:: Stats.print_callees(*restrictions)
|
|
||||||
|
|
||||||
This method for the :class:`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
|
|
||||||
:meth:`print_callers` method.
|
|
||||||
|
|
||||||
|
|
||||||
.. _profile-limits:
|
|
||||||
|
|
||||||
Limitations
|
Limitations
|
||||||
===========
|
===========
|
||||||
|
|
@ -536,7 +562,7 @@ The profiler of the :mod:`profile` module subtracts a constant from each event
|
||||||
handling time to compensate for the overhead of calling the time function, and
|
handling time to compensate for the overhead of calling the time function, and
|
||||||
socking away the results. By default, the constant is 0. The following
|
socking away the results. By default, the constant is 0. The following
|
||||||
procedure can be used to obtain a better constant for a given platform (see
|
procedure can be used to obtain a better constant for a given platform (see
|
||||||
discussion in section Limitations above). ::
|
:ref:`profile-limitations`). ::
|
||||||
|
|
||||||
import profile
|
import profile
|
||||||
pr = profile.Profile()
|
pr = profile.Profile()
|
||||||
|
|
@ -546,8 +572,8 @@ discussion in section Limitations above). ::
|
||||||
The method executes the number of Python calls given by the argument, directly
|
The method executes the number of Python calls given by the argument, directly
|
||||||
and again under the profiler, measuring the time for both. It then computes the
|
and again under the profiler, measuring the time for both. It then computes the
|
||||||
hidden overhead per profiler event, and returns that as a float. For example,
|
hidden overhead per profiler event, and returns that as a float. For example,
|
||||||
on an 800 MHz Pentium running Windows 2000, and using Python's time.clock() as
|
on a 1.8Ghz Intel Core i5 running Mac OS X, and using Python's time.clock() as
|
||||||
the timer, the magical number is about 12.5e-6.
|
the timer, the magical number is about 4.04e-6.
|
||||||
|
|
||||||
The object of this exercise is to get a fairly consistent result. If your
|
The object of this exercise is to get a fairly consistent result. If your
|
||||||
computer is *very* fast, or your timer function has poor resolution, you might
|
computer is *very* fast, or your timer function has poor resolution, you might
|
||||||
|
|
@ -570,54 +596,51 @@ When you have a consistent answer, there are three ways you can use it::
|
||||||
If you have a choice, you are better off choosing a smaller constant, and then
|
If you have a choice, you are better off choosing a smaller constant, and then
|
||||||
your results will "less often" show up as negative in profile statistics.
|
your results will "less often" show up as negative in profile statistics.
|
||||||
|
|
||||||
|
.. _profile-timers:
|
||||||
|
|
||||||
.. _profiler-extensions:
|
Using a customer timer
|
||||||
|
======================
|
||||||
|
|
||||||
Extensions --- Deriving Better Profilers
|
If you want to change how current time is determined (for example, to force use
|
||||||
========================================
|
of wall-clock time or elapsed process time), pass the timing function you want
|
||||||
|
to the :class:`Profile` class constructor::
|
||||||
|
|
||||||
The :class:`Profile` class of both modules, :mod:`profile` and :mod:`cProfile`,
|
pr = profile.Profile(your_time_func)
|
||||||
were written so that derived classes could be developed to extend the profiler.
|
|
||||||
The details are not described here, as doing this successfully requires an
|
|
||||||
expert understanding of how the :class:`Profile` class works internally. Study
|
|
||||||
the source code of the module carefully if you want to pursue this.
|
|
||||||
|
|
||||||
If all you want to do is change how current time is determined (for example, to
|
The resulting profiler will then call ``your_time_func``. Depending on whether
|
||||||
force use of wall-clock time or elapsed process time), pass the timing function
|
you are using :class:`profile.Profile` or :class:`cProfile.Profile`,
|
||||||
you want to the :class:`Profile` class constructor::
|
``your_time_func``'s return value will be interpreted differently:
|
||||||
|
|
||||||
pr = profile.Profile(your_time_func)
|
|
||||||
|
|
||||||
The resulting profiler will then call :func:`your_time_func`.
|
|
||||||
|
|
||||||
:class:`profile.Profile`
|
:class:`profile.Profile`
|
||||||
:func:`your_time_func` should return a single number, or a list of
|
``your_time_func`` should return a single number, or a list of numbers whose
|
||||||
numbers whose sum is the current time (like what :func:`os.times`
|
sum is the current time (like what :func:`os.times` returns). If the
|
||||||
returns). If the function returns a single time number, or the
|
function returns a single time number, or the list of returned numbers has
|
||||||
list of returned numbers has length 2, then you will get an
|
length 2, then you will get an especially fast version of the dispatch
|
||||||
especially fast version of the dispatch routine.
|
routine.
|
||||||
|
|
||||||
Be warned that you should calibrate the profiler class for the
|
Be warned that you should calibrate the profiler class for the timer function
|
||||||
timer function that you choose. For most machines, a timer that
|
that you choose (see :ref:`profile-calibration`). For most machines, a timer
|
||||||
returns a lone integer value will provide the best results in terms
|
that returns a lone integer value will provide the best results in terms of
|
||||||
of low overhead during profiling. (:func:`os.times` is *pretty*
|
low overhead during profiling. (:func:`os.times` is *pretty* bad, as it
|
||||||
bad, as it returns a tuple of floating point values). If you want
|
returns a tuple of floating point values). If you want to substitute a
|
||||||
to substitute a better timer in the cleanest fashion, derive a
|
better timer in the cleanest fashion, derive a class and hardwire a
|
||||||
class and hardwire a replacement dispatch method that best handles
|
replacement dispatch method that best handles your timer call, along with the
|
||||||
your timer call, along with the appropriate calibration constant.
|
appropriate calibration constant.
|
||||||
|
|
||||||
:class:`cProfile.Profile`
|
:class:`cProfile.Profile`
|
||||||
:func:`your_time_func` should return a single number. If it
|
``your_time_func`` should return a single number. If it returns integers,
|
||||||
returns integers, you can also invoke the class constructor with a
|
you can also invoke the class constructor with a second argument specifying
|
||||||
second argument specifying the real duration of one unit of time.
|
the real duration of one unit of time. For example, if
|
||||||
For example, if :func:`your_integer_time_func` returns times
|
``your_integer_time_func`` returns times measured in thousands of seconds,
|
||||||
measured in thousands of seconds, you would construct the
|
you would construct the :class:`Profile` instance as follows::
|
||||||
:class:`Profile` instance as follows::
|
|
||||||
|
|
||||||
pr = profile.Profile(your_integer_time_func, 0.001)
|
pr = cProfile.Profile(your_integer_time_func, 0.001)
|
||||||
|
|
||||||
As the :mod:`cProfile.Profile` class cannot be calibrated, custom
|
As the :mod:`cProfile.Profile` class cannot be calibrated, custom timer
|
||||||
timer functions should be used with care and should be as fast as
|
functions should be used with care and should be as fast as possible. For
|
||||||
possible. For the best results with a custom timer, it might be
|
the best results with a custom timer, it might be necessary to hard-code it
|
||||||
necessary to hard-code it in the C source of the internal
|
in the C source of the internal :mod:`_lsprof` module.
|
||||||
:mod:`_lsprof` module.
|
|
||||||
|
Python 3.3 adds several new functions in :mod:`time` that can be used to make
|
||||||
|
precise measurements of process or wall-clock time. For example, see
|
||||||
|
:func:`time.perf_counter`.
|
||||||
|
|
|
||||||
|
|
@ -962,6 +962,7 @@ Dan Pierson
|
||||||
Martijn Pieters
|
Martijn Pieters
|
||||||
Anand B. Pillai
|
Anand B. Pillai
|
||||||
François Pinard
|
François Pinard
|
||||||
|
Tom Pinckney
|
||||||
Zach Pincus
|
Zach Pincus
|
||||||
Michael Piotrowski
|
Michael Piotrowski
|
||||||
Antoine Pitrou
|
Antoine Pitrou
|
||||||
|
|
|
||||||
|
|
@ -87,6 +87,9 @@ Tests
|
||||||
- Issue #17692: test_sqlite now works with unittest test discovery.
|
- Issue #17692: test_sqlite now works with unittest test discovery.
|
||||||
Patch by Zachary Ware.
|
Patch by Zachary Ware.
|
||||||
|
|
||||||
|
- Issue #6696: add documentation for the Profile objects, and improve
|
||||||
|
profile/cProfile docs. Patch by Tom Pinckney.
|
||||||
|
|
||||||
|
|
||||||
What's New in Python 3.3.1 release candidate 1?
|
What's New in Python 3.3.1 release candidate 1?
|
||||||
===============================================
|
===============================================
|
||||||
|
|
|
||||||
Loading…
Add table
Add a link
Reference in a new issue