diff -r 6917402c6191 Doc/library/profile.rst --- a/Doc/library/profile.rst Sun Feb 10 09:48:22 2013 -0500 +++ b/Doc/library/profile.rst Sun Feb 10 18:28:31 2013 -0500 @@ -4,12 +4,8 @@ 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`, :source:`Lib/cProfile.py`, +:source:`Modules/_lsprof.c` and :source:`Lib/pstats.py` -------------- @@ -22,14 +18,13 @@ single: deterministic profiling single: profiling, deterministic -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 examine the results of a profile operation. +:mod:`cProfile` and :mod:`profile` provide :dfn:`deterministic profiling` of +Python programs. A :dfn:`profile` is a set of statistics that describes how +often and for how long various parts of the program executed. These statistics +can be formatted into reports via the :mod:`pstats` module. -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 reasonable overhead that makes it suitable for profiling long-running @@ -37,14 +32,9 @@ Czotter. 2. :mod:`profile`, a pure Python module whose interface is imitated by - :mod:`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. - -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. + :mod:`cProfile`, but which 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. .. note:: @@ -65,57 +55,90 @@ 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:: +To profile function ``foo`` that takes a single integer argument, you would +add the following to your module:: import cProfile - cProfile.run('foo()') + x = 2 + cProfile.run('foo(x)') (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:: +The above action would run ``foo`` and print profile results like the +following:: + + 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 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 ``43/3``), +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 - cProfile.run('foo()', 'fooprof') + cProfile.run('foo(x)', 'fooprof') -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:: - 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). -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:: +The :mod:`pstats` module's :class:`~pstats.Stats` class has a variety of methods +for manipulating and printing the data saved into a profile results file:: 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: - -.. (this is to comply with the semantics of the old profiler). - -:: +The :meth:`~pstats.Stats.strip_dirs` method removed the extraneous path from all the module +names. The :meth:`~pstats.Stats.sort_stats` method sorted all the entries according to the +standard module/line/name string that is printed. The :meth:`~pstats.Stats.print_stats` method +printed out all the statistics. You might try the following sort calls:: p.sort_stats('name') p.print_stats() @@ -170,6 +193,303 @@ reading and examining profile dumps. It has a simple line-oriented interface (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 specifed + 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; 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:: 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: @@ -204,296 +524,7 @@ 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=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: +.. _profile-limitations: Limitations =========== @@ -532,11 +563,11 @@ 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). :: +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 :ref:`profile-limitations`). :: import profile pr = profile.Profile() @@ -570,54 +601,52 @@ 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. +.. _profile-timers: -.. _profiler-extensions: +Using a customer timer +====================== -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`. +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:: + + pr = profile.Profile(your_time_func) + +The resulting profiler will then call ``your_time_func``. Depending on +whether you are using :class:`profile.Profile` or +:class:`cProfile.Profile`, ``your_time_func``'s return value will be +interpreted differently: :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. + ``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. + timer function that you choose (see :ref:`profile-calibration`). + 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 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, you would construct the - :class:`Profile` instance as follows:: + ``your_time_func`` should return a single number. If it returns + integers, you can also invoke the class constructor with a second argument + specifying the real duration of one unit of time. For example, if + ``your_integer_time_func`` returns times measured in thousands of seconds, + you would construct the :class:`Profile` instance as follows:: 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. + 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. + +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`.