2007-08-15 11:28:01 -03:00
|
|
|
.. _profile:
|
|
|
|
|
|
|
|
********************
|
|
|
|
The Python Profilers
|
|
|
|
********************
|
|
|
|
|
|
|
|
.. sectionauthor:: James Roskind
|
|
|
|
|
2009-11-12 04:29:46 -04:00
|
|
|
.. module:: profile
|
|
|
|
:synopsis: Python source profiler.
|
2007-08-15 11:28:01 -03:00
|
|
|
|
2011-08-18 21:14:03 -03:00
|
|
|
**Source code:** :source:`Lib/profile.py` and :source:`Lib/pstats.py`
|
|
|
|
|
|
|
|
--------------
|
2007-08-15 11:28:01 -03:00
|
|
|
|
|
|
|
.. _profiler-introduction:
|
|
|
|
|
|
|
|
Introduction to the profilers
|
|
|
|
=============================
|
|
|
|
|
|
|
|
.. index::
|
|
|
|
single: deterministic profiling
|
|
|
|
single: profiling, deterministic
|
|
|
|
|
2008-04-18 15:39:55 -03:00
|
|
|
A :dfn:`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
|
|
|
|
:mod:`cProfile`, :mod:`profile` and :mod:`pstats`. This profiler
|
|
|
|
provides :dfn:`deterministic profiling` of Python programs. It also
|
|
|
|
provides a series of report generation tools to allow users to rapidly
|
2007-08-15 11:28:01 -03:00
|
|
|
examine the results of a profile operation.
|
|
|
|
|
|
|
|
The Python standard library provides three different profilers:
|
|
|
|
|
2009-01-03 16:55:06 -04:00
|
|
|
#. :mod:`cProfile` is recommended for most users; it's a C extension
|
2008-04-18 15:39:55 -03:00
|
|
|
with reasonable overhead
|
2009-01-03 16:55:06 -04:00
|
|
|
that makes it suitable for profiling long-running programs.
|
2008-04-18 15:39:55 -03:00
|
|
|
Based on :mod:`lsprof`,
|
2009-01-03 16:55:06 -04:00
|
|
|
contributed by Brett Rosen and Ted Czotter.
|
2007-08-15 11:28:01 -03:00
|
|
|
|
2008-04-18 15:39:55 -03:00
|
|
|
.. versionadded:: 2.5
|
2007-08-15 11:28:01 -03:00
|
|
|
|
2008-04-18 15:39:55 -03:00
|
|
|
#. :mod:`profile`, a pure Python module whose interface is imitated by
|
2009-01-03 16:55:06 -04:00
|
|
|
:mod:`cProfile`. Adds significant overhead to profiled programs.
|
|
|
|
If you're trying to extend
|
2008-04-18 15:39:55 -03:00
|
|
|
the profiler in some way, the task might be easier with this module.
|
2007-08-15 11:28:01 -03:00
|
|
|
|
2008-04-18 15:39:55 -03:00
|
|
|
.. versionchanged:: 2.4
|
|
|
|
Now also reports the time spent in calls to built-in functions and methods.
|
2007-08-15 11:28:01 -03:00
|
|
|
|
2008-04-18 15:39:55 -03:00
|
|
|
#. :mod:`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.
|
2009-01-03 16:55:06 -04:00
|
|
|
|
2007-08-15 11:28:01 -03:00
|
|
|
|
|
|
|
.. versionchanged:: 2.5
|
2008-04-18 15:39:55 -03:00
|
|
|
The results should be more meaningful than in the past: the timing core
|
2007-08-15 11:28:01 -03:00
|
|
|
contained a critical bug.
|
|
|
|
|
|
|
|
The :mod:`profile` and :mod:`cProfile` modules export the same interface, so
|
2008-04-18 15:39:55 -03:00
|
|
|
they are mostly interchangeable; :mod:`cProfile` has a much lower overhead but
|
|
|
|
is newer and might not be available on all systems.
|
2007-08-15 11:28:01 -03:00
|
|
|
:mod:`cProfile` is really a compatibility layer on top of the internal
|
2008-04-18 15:39:55 -03:00
|
|
|
:mod:`_lsprof` module. The :mod:`hotshot` module is reserved for specialized
|
|
|
|
usage.
|
2007-08-15 11:28:01 -03:00
|
|
|
|
|
|
|
|
|
|
|
.. _profile-instant:
|
|
|
|
|
|
|
|
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 :func:`foo`, you would add
|
|
|
|
the following to your module::
|
|
|
|
|
|
|
|
import cProfile
|
|
|
|
cProfile.run('foo()')
|
|
|
|
|
|
|
|
(Use :mod:`profile` instead of :mod:`cProfile` if the latter is not available on
|
|
|
|
your system.)
|
|
|
|
|
|
|
|
The above action would cause :func:`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 :func:`run` function::
|
|
|
|
|
|
|
|
import cProfile
|
|
|
|
cProfile.run('foo()', 'fooprof')
|
|
|
|
|
|
|
|
The file :file:`cProfile.py` can also be invoked as a script to profile another
|
|
|
|
script. For example::
|
|
|
|
|
|
|
|
python -m cProfile myscript.py
|
|
|
|
|
|
|
|
:file:`cProfile.py` accepts two optional arguments on the command line::
|
|
|
|
|
|
|
|
cProfile.py [-o output_file] [-s sort_order]
|
|
|
|
|
2010-01-23 04:47:54 -04:00
|
|
|
``-s`` only applies to standard output (``-o`` is not supplied).
|
2007-08-15 11:28:01 -03:00
|
|
|
Look in the :class:`Stats` documentation for valid sort values.
|
|
|
|
|
|
|
|
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
|
|
|
|
p = pstats.Stats('fooprof')
|
|
|
|
|
|
|
|
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()
|
|
|
|
|
|
|
|
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:
|
|
|
|
|
2007-12-29 06:57:00 -04:00
|
|
|
.. (this is to comply with the semantics of the old profiler).
|
2007-08-15 11:28:01 -03:00
|
|
|
|
|
|
|
::
|
|
|
|
|
|
|
|
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 :mod:`pstats` module is a statistics browser for
|
|
|
|
reading and examining profile dumps. It has a simple line-oriented interface
|
|
|
|
(implemented using :mod:`cmd`) and interactive help.
|
|
|
|
|
|
|
|
|
|
|
|
.. _deterministic-profiling:
|
|
|
|
|
|
|
|
What Is Deterministic Profiling?
|
|
|
|
================================
|
|
|
|
|
|
|
|
:dfn:`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, :dfn:`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 :dfn:`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.
|
|
|
|
|
|
|
|
|
|
|
|
Reference Manual -- :mod:`profile` and :mod:`cProfile`
|
|
|
|
======================================================
|
|
|
|
|
|
|
|
.. 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])
|
|
|
|
|
|
|
|
This function takes a single argument that can be passed to the
|
|
|
|
:keyword:`exec` statement, and an optional file name. In all cases this
|
|
|
|
routine attempts to :keyword:`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:
|
|
|
|
|
2009-01-03 16:55:06 -04:00
|
|
|
ncalls
|
2007-08-15 11:28:01 -03:00
|
|
|
for the number of calls,
|
|
|
|
|
2009-01-03 16:55:06 -04:00
|
|
|
tottime
|
2007-08-15 11:28:01 -03:00
|
|
|
for the total time spent in the given function (and excluding time made in calls
|
|
|
|
to sub-functions),
|
|
|
|
|
2009-01-03 16:55:06 -04:00
|
|
|
percall
|
2007-08-15 11:28:01 -03:00
|
|
|
is the quotient of ``tottime`` divided by ``ncalls``
|
|
|
|
|
2009-01-03 16:55:06 -04:00
|
|
|
cumtime
|
2007-08-15 11:28:01 -03:00
|
|
|
is the total time spent in this and all subfunctions (from invocation till
|
|
|
|
exit). This figure is accurate *even* for recursive functions.
|
|
|
|
|
2009-01-03 16:55:06 -04:00
|
|
|
percall
|
2007-08-15 11:28:01 -03:00
|
|
|
is the quotient of ``cumtime`` divided by primitive calls
|
|
|
|
|
2009-01-03 16:55:06 -04:00
|
|
|
filename:lineno(function)
|
2007-08-15 11:28:01 -03:00
|
|
|
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.
|
|
|
|
|
|
|
|
|
|
|
|
.. function:: runctx(command, globals, locals[, filename])
|
|
|
|
|
|
|
|
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:`Stats` class.
|
|
|
|
|
|
|
|
.. note::
|
|
|
|
|
|
|
|
The :class:`Stats` class is defined in the :mod:`pstats` module.
|
|
|
|
|
|
|
|
|
|
|
|
.. module:: pstats
|
|
|
|
:synopsis: Statistics object for use with the profiler.
|
|
|
|
|
|
|
|
|
2012-05-22 05:27:40 -03:00
|
|
|
.. class:: Stats(filename, stream=sys.stdout[, ...])
|
2007-08-15 11:28:01 -03:00
|
|
|
|
|
|
|
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.
|
|
|
|
|
2007-12-29 06:57:00 -04:00
|
|
|
.. (such as the old system profiler).
|
2007-08-15 11:28:01 -03:00
|
|
|
|
|
|
|
.. versionchanged:: 2.5
|
|
|
|
The *stream* parameter was added.
|
|
|
|
|
|
|
|
|
|
|
|
.. _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(filename[, ...])
|
|
|
|
|
|
|
|
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.
|
|
|
|
|
|
|
|
.. versionadded:: 2.3
|
|
|
|
|
|
|
|
|
|
|
|
.. method:: Stats.sort_stats(key[, ...])
|
|
|
|
|
|
|
|
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 |
|
|
|
|
+------------------+----------------------+
|
|
|
|
| ``'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.
|
|
|
|
|
2007-12-29 06:57:00 -04:00
|
|
|
.. For compatibility with the old profiler,
|
2007-08-15 11:28:01 -03:00
|
|
|
|
|
|
|
|
|
|
|
.. 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.
|
|
|
|
|
2007-12-29 06:57:00 -04:00
|
|
|
.. This method is provided primarily for compatibility with the old profiler.
|
2007-08-15 11:28:01 -03:00
|
|
|
|
|
|
|
|
|
|
|
.. method:: Stats.print_stats([restriction, ...])
|
|
|
|
|
|
|
|
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([restriction, ...])
|
|
|
|
|
|
|
|
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.
|
|
|
|
|
2008-02-22 08:31:45 -04:00
|
|
|
* With :mod:`cProfile`, each caller is preceded by three numbers: the number of
|
2007-08-15 11:28:01 -03:00
|
|
|
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([restriction, ...])
|
|
|
|
|
|
|
|
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
|
|
|
|
===========
|
|
|
|
|
|
|
|
One 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 the 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 (less than one clock tick), but it *can* accumulate
|
|
|
|
and become very significant.
|
|
|
|
|
|
|
|
The problem is more important with :mod:`profile` than with the lower-overhead
|
|
|
|
:mod:`cProfile`. For this reason, :mod:`profile` provides a means of
|
|
|
|
calibrating itself for a given platform so that this error can be
|
|
|
|
probabilistically (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.
|
|
|
|
|
|
|
|
|
|
|
|
.. _profile-calibration:
|
|
|
|
|
|
|
|
Calibration
|
|
|
|
===========
|
|
|
|
|
|
|
|
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
|
|
|
|
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
|
|
|
|
discussion in section Limitations above). ::
|
|
|
|
|
|
|
|
import profile
|
|
|
|
pr = profile.Profile()
|
|
|
|
for i in range(5):
|
|
|
|
print pr.calibrate(10000)
|
|
|
|
|
|
|
|
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
|
|
|
|
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
|
|
|
|
the timer, the magical number is about 12.5e-6.
|
|
|
|
|
|
|
|
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
|
|
|
|
have to pass 100000, or even 1000000, to get consistent results.
|
|
|
|
|
|
|
|
When you have a consistent answer, there are three ways you can use it: [#]_ ::
|
|
|
|
|
|
|
|
import profile
|
|
|
|
|
|
|
|
# 1. Apply computed bias to all Profile instances created hereafter.
|
|
|
|
profile.Profile.bias = your_computed_bias
|
|
|
|
|
|
|
|
# 2. Apply computed bias to a specific Profile instance.
|
|
|
|
pr = profile.Profile()
|
|
|
|
pr.bias = your_computed_bias
|
|
|
|
|
|
|
|
# 3. Specify computed bias in instance constructor.
|
|
|
|
pr = profile.Profile(bias=your_computed_bias)
|
|
|
|
|
|
|
|
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.
|
|
|
|
|
|
|
|
|
|
|
|
.. _profiler-extensions:
|
|
|
|
|
|
|
|
Extensions --- Deriving Better Profilers
|
|
|
|
========================================
|
|
|
|
|
|
|
|
The :class:`Profile` class of both modules, :mod:`profile` and :mod:`cProfile`,
|
|
|
|
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
|
|
|
|
force use of wall-clock time or elapsed process time), pass the timing function
|
|
|
|
you want to the :class:`Profile` class constructor::
|
|
|
|
|
|
|
|
pr = profile.Profile(your_time_func)
|
|
|
|
|
|
|
|
The resulting profiler will then call :func:`your_time_func`.
|
|
|
|
|
|
|
|
:class:`profile.Profile`
|
|
|
|
:func:`your_time_func` should return a single number, or a list of numbers whose
|
|
|
|
sum is the current time (like what :func:`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.
|
|
|
|
(:func:`os.times` is *pretty* bad, as it returns a tuple of floating point
|
|
|
|
values). If you want to substitute a better timer in the cleanest fashion,
|
|
|
|
derive a class and hardwire a replacement dispatch method that best handles your
|
|
|
|
timer call, along with the appropriate calibration constant.
|
|
|
|
|
|
|
|
:class:`cProfile.Profile`
|
|
|
|
:func:`your_time_func` should return a single number. If it returns plain
|
|
|
|
integers, you can also invoke the class constructor with a second argument
|
|
|
|
specifying the real duration of one unit of time. For example, if
|
|
|
|
:func:`your_integer_time_func` returns times measured in thousands of seconds,
|
2010-10-06 06:32:48 -03:00
|
|
|
you would construct the :class:`Profile` instance as follows::
|
2007-08-15 11:28:01 -03:00
|
|
|
|
|
|
|
pr = profile.Profile(your_integer_time_func, 0.001)
|
|
|
|
|
|
|
|
As the :mod:`cProfile.Profile` class cannot be calibrated, custom timer
|
|
|
|
functions should be used with care and should be as fast as possible. For the
|
|
|
|
best results with a custom timer, it might be necessary to hard-code it in the C
|
|
|
|
source of the internal :mod:`_lsprof` module.
|
|
|
|
|
|
|
|
|
2012-07-01 04:40:16 -03:00
|
|
|
.. rubric:: Footnotes
|
2007-08-15 11:28:01 -03:00
|
|
|
|
2012-07-01 04:40:16 -03:00
|
|
|
.. [#] Prior to Python 2.2, it was necessary to edit the profiler source code to
|
|
|
|
embed the bias as a literal number. You still can, but that method is no longer
|
2007-08-15 11:28:01 -03:00
|
|
|
described, because no longer needed.
|
|
|
|
|