Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 1 | |
| 2 | .. _profile: |
| 3 | |
| 4 | ******************** |
| 5 | The Python Profilers |
| 6 | ******************** |
| 7 | |
| 8 | .. sectionauthor:: James Roskind |
| 9 | |
| 10 | |
| 11 | .. index:: single: InfoSeek Corporation |
| 12 | |
| 13 | Copyright © 1994, by InfoSeek Corporation, all rights reserved. |
| 14 | |
| 15 | Written by James Roskind. [#]_ |
| 16 | |
| 17 | Permission to use, copy, modify, and distribute this Python software and its |
| 18 | associated documentation for any purpose (subject to the restriction in the |
| 19 | following sentence) without fee is hereby granted, provided that the above |
| 20 | copyright notice appears in all copies, and that both that copyright notice and |
| 21 | this permission notice appear in supporting documentation, and that the name of |
| 22 | InfoSeek not be used in advertising or publicity pertaining to distribution of |
| 23 | the software without specific, written prior permission. This permission is |
| 24 | explicitly restricted to the copying and modification of the software to remain |
| 25 | in Python, compiled Python, or other languages (such as C) wherein the modified |
| 26 | or derived code is exclusively imported into a Python module. |
| 27 | |
| 28 | INFOSEEK CORPORATION DISCLAIMS ALL WARRANTIES WITH REGARD TO THIS SOFTWARE, |
| 29 | INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS. IN NO EVENT |
| 30 | SHALL INFOSEEK CORPORATION BE LIABLE FOR ANY SPECIAL, INDIRECT OR CONSEQUENTIAL |
| 31 | DAMAGES OR ANY DAMAGES WHATSOEVER RESULTING FROM LOSS OF USE, DATA OR PROFITS, |
| 32 | WHETHER IN AN ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING |
| 33 | OUT OF OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE. |
| 34 | |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 35 | .. _profiler-introduction: |
| 36 | |
| 37 | Introduction to the profilers |
| 38 | ============================= |
| 39 | |
| 40 | .. index:: |
| 41 | single: deterministic profiling |
| 42 | single: profiling, deterministic |
| 43 | |
Christian Heimes | dae2a89 | 2008-04-19 00:55:37 +0000 | [diff] [blame] | 44 | A :dfn:`profiler` is a program that describes the run time performance |
| 45 | of a program, providing a variety of statistics. This documentation |
| 46 | describes the profiler functionality provided in the modules |
| 47 | :mod:`cProfile`, :mod:`profile` and :mod:`pstats`. This profiler |
| 48 | provides :dfn:`deterministic profiling` of Python programs. It also |
| 49 | provides a series of report generation tools to allow users to rapidly |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 50 | examine the results of a profile operation. |
| 51 | |
Fred Drake | 0e474a8 | 2007-10-11 18:01:43 +0000 | [diff] [blame] | 52 | The Python standard library provides two different profilers: |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 53 | |
Georg Brandl | 48310cd | 2009-01-03 21:18:54 +0000 | [diff] [blame] | 54 | #. :mod:`cProfile` is recommended for most users; it's a C extension |
Christian Heimes | dae2a89 | 2008-04-19 00:55:37 +0000 | [diff] [blame] | 55 | with reasonable overhead |
Georg Brandl | 48310cd | 2009-01-03 21:18:54 +0000 | [diff] [blame] | 56 | that makes it suitable for profiling long-running programs. |
Christian Heimes | dae2a89 | 2008-04-19 00:55:37 +0000 | [diff] [blame] | 57 | Based on :mod:`lsprof`, |
Georg Brandl | 48310cd | 2009-01-03 21:18:54 +0000 | [diff] [blame] | 58 | contributed by Brett Rosen and Ted Czotter. |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 59 | |
Christian Heimes | dae2a89 | 2008-04-19 00:55:37 +0000 | [diff] [blame] | 60 | #. :mod:`profile`, a pure Python module whose interface is imitated by |
Georg Brandl | 48310cd | 2009-01-03 21:18:54 +0000 | [diff] [blame] | 61 | :mod:`cProfile`. Adds significant overhead to profiled programs. |
| 62 | If you're trying to extend |
Christian Heimes | dae2a89 | 2008-04-19 00:55:37 +0000 | [diff] [blame] | 63 | the profiler in some way, the task might be easier with this module. |
| 64 | Copyright © 1994, by InfoSeek Corporation. |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 65 | |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 66 | The :mod:`profile` and :mod:`cProfile` modules export the same interface, so |
Christian Heimes | dae2a89 | 2008-04-19 00:55:37 +0000 | [diff] [blame] | 67 | they are mostly interchangeable; :mod:`cProfile` has a much lower overhead but |
| 68 | is newer and might not be available on all systems. |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 69 | :mod:`cProfile` is really a compatibility layer on top of the internal |
Fred Drake | 0e474a8 | 2007-10-11 18:01:43 +0000 | [diff] [blame] | 70 | :mod:`_lsprof` module. |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 71 | |
| 72 | |
| 73 | .. _profile-instant: |
| 74 | |
| 75 | Instant User's Manual |
| 76 | ===================== |
| 77 | |
| 78 | This section is provided for users that "don't want to read the manual." It |
| 79 | provides a very brief overview, and allows a user to rapidly perform profiling |
| 80 | on an existing application. |
| 81 | |
| 82 | To profile an application with a main entry point of :func:`foo`, you would add |
| 83 | the following to your module:: |
| 84 | |
| 85 | import cProfile |
| 86 | cProfile.run('foo()') |
| 87 | |
| 88 | (Use :mod:`profile` instead of :mod:`cProfile` if the latter is not available on |
| 89 | your system.) |
| 90 | |
| 91 | The above action would cause :func:`foo` to be run, and a series of informative |
| 92 | lines (the profile) to be printed. The above approach is most useful when |
| 93 | working with the interpreter. If you would like to save the results of a |
| 94 | profile into a file for later examination, you can supply a file name as the |
| 95 | second argument to the :func:`run` function:: |
| 96 | |
| 97 | import cProfile |
| 98 | cProfile.run('foo()', 'fooprof') |
| 99 | |
| 100 | The file :file:`cProfile.py` can also be invoked as a script to profile another |
| 101 | script. For example:: |
| 102 | |
| 103 | python -m cProfile myscript.py |
| 104 | |
| 105 | :file:`cProfile.py` accepts two optional arguments on the command line:: |
| 106 | |
| 107 | cProfile.py [-o output_file] [-s sort_order] |
| 108 | |
| 109 | :option:`-s` only applies to standard output (:option:`-o` is not supplied). |
| 110 | Look in the :class:`Stats` documentation for valid sort values. |
| 111 | |
| 112 | When you wish to review the profile, you should use the methods in the |
| 113 | :mod:`pstats` module. Typically you would load the statistics data as follows:: |
| 114 | |
| 115 | import pstats |
| 116 | p = pstats.Stats('fooprof') |
| 117 | |
| 118 | The class :class:`Stats` (the above code just created an instance of this class) |
| 119 | has a variety of methods for manipulating and printing the data that was just |
| 120 | read into ``p``. When you ran :func:`cProfile.run` above, what was printed was |
| 121 | the result of three method calls:: |
| 122 | |
| 123 | p.strip_dirs().sort_stats(-1).print_stats() |
| 124 | |
| 125 | The first method removed the extraneous path from all the module names. The |
| 126 | second method sorted all the entries according to the standard module/line/name |
| 127 | string that is printed. The third method printed out all the statistics. You |
| 128 | might try the following sort calls: |
| 129 | |
Christian Heimes | 5b5e81c | 2007-12-31 16:14:33 +0000 | [diff] [blame] | 130 | .. (this is to comply with the semantics of the old profiler). |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 131 | |
| 132 | :: |
| 133 | |
| 134 | p.sort_stats('name') |
| 135 | p.print_stats() |
| 136 | |
| 137 | The first call will actually sort the list by function name, and the second call |
| 138 | will print out the statistics. The following are some interesting calls to |
| 139 | experiment with:: |
| 140 | |
| 141 | p.sort_stats('cumulative').print_stats(10) |
| 142 | |
| 143 | This sorts the profile by cumulative time in a function, and then only prints |
| 144 | the ten most significant lines. If you want to understand what algorithms are |
| 145 | taking time, the above line is what you would use. |
| 146 | |
| 147 | If you were looking to see what functions were looping a lot, and taking a lot |
| 148 | of time, you would do:: |
| 149 | |
| 150 | p.sort_stats('time').print_stats(10) |
| 151 | |
| 152 | to sort according to time spent within each function, and then print the |
| 153 | statistics for the top ten functions. |
| 154 | |
| 155 | You might also try:: |
| 156 | |
| 157 | p.sort_stats('file').print_stats('__init__') |
| 158 | |
| 159 | This will sort all the statistics by file name, and then print out statistics |
| 160 | for only the class init methods (since they are spelled with ``__init__`` in |
| 161 | them). As one final example, you could try:: |
| 162 | |
| 163 | p.sort_stats('time', 'cum').print_stats(.5, 'init') |
| 164 | |
| 165 | This line sorts statistics with a primary key of time, and a secondary key of |
| 166 | cumulative time, and then prints out some of the statistics. To be specific, the |
| 167 | list is first culled down to 50% (re: ``.5``) of its original size, then only |
| 168 | lines containing ``init`` are maintained, and that sub-sub-list is printed. |
| 169 | |
| 170 | If you wondered what functions called the above functions, you could now (``p`` |
| 171 | is still sorted according to the last criteria) do:: |
| 172 | |
| 173 | p.print_callers(.5, 'init') |
| 174 | |
| 175 | and you would get a list of callers for each of the listed functions. |
| 176 | |
| 177 | If you want more functionality, you're going to have to read the manual, or |
| 178 | guess what the following functions do:: |
| 179 | |
| 180 | p.print_callees() |
| 181 | p.add('fooprof') |
| 182 | |
| 183 | Invoked as a script, the :mod:`pstats` module is a statistics browser for |
| 184 | reading and examining profile dumps. It has a simple line-oriented interface |
| 185 | (implemented using :mod:`cmd`) and interactive help. |
| 186 | |
| 187 | |
| 188 | .. _deterministic-profiling: |
| 189 | |
| 190 | What Is Deterministic Profiling? |
| 191 | ================================ |
| 192 | |
| 193 | :dfn:`Deterministic profiling` is meant to reflect the fact that all *function |
| 194 | call*, *function return*, and *exception* events are monitored, and precise |
| 195 | timings are made for the intervals between these events (during which time the |
| 196 | user's code is executing). In contrast, :dfn:`statistical profiling` (which is |
| 197 | not done by this module) randomly samples the effective instruction pointer, and |
| 198 | deduces where time is being spent. The latter technique traditionally involves |
| 199 | less overhead (as the code does not need to be instrumented), but provides only |
| 200 | relative indications of where time is being spent. |
| 201 | |
| 202 | In Python, since there is an interpreter active during execution, the presence |
| 203 | of instrumented code is not required to do deterministic profiling. Python |
| 204 | automatically provides a :dfn:`hook` (optional callback) for each event. In |
| 205 | addition, the interpreted nature of Python tends to add so much overhead to |
| 206 | execution, that deterministic profiling tends to only add small processing |
| 207 | overhead in typical applications. The result is that deterministic profiling is |
| 208 | not that expensive, yet provides extensive run time statistics about the |
| 209 | execution of a Python program. |
| 210 | |
| 211 | Call count statistics can be used to identify bugs in code (surprising counts), |
| 212 | and to identify possible inline-expansion points (high call counts). Internal |
| 213 | time statistics can be used to identify "hot loops" that should be carefully |
| 214 | optimized. Cumulative time statistics should be used to identify high level |
| 215 | errors in the selection of algorithms. Note that the unusual handling of |
| 216 | cumulative times in this profiler allows statistics for recursive |
| 217 | implementations of algorithms to be directly compared to iterative |
| 218 | implementations. |
| 219 | |
| 220 | |
| 221 | Reference Manual -- :mod:`profile` and :mod:`cProfile` |
| 222 | ====================================================== |
| 223 | |
| 224 | .. module:: cProfile |
| 225 | :synopsis: Python profiler |
| 226 | |
| 227 | |
| 228 | The primary entry point for the profiler is the global function |
| 229 | :func:`profile.run` (resp. :func:`cProfile.run`). It is typically used to create |
| 230 | any profile information. The reports are formatted and printed using methods of |
| 231 | the class :class:`pstats.Stats`. The following is a description of all of these |
| 232 | standard entry points and functions. For a more in-depth view of some of the |
| 233 | code, consider reading the later section on Profiler Extensions, which includes |
| 234 | discussion of how to derive "better" profilers from the classes presented, or |
| 235 | reading the source code for these modules. |
| 236 | |
| 237 | |
| 238 | .. function:: run(command[, filename]) |
| 239 | |
| 240 | This function takes a single argument that can be passed to the :func:`exec` |
| 241 | function, and an optional file name. In all cases this routine attempts to |
| 242 | :func:`exec` its first argument, and gather profiling statistics from the |
| 243 | execution. If no file name is present, then this function automatically |
| 244 | prints a simple profiling report, sorted by the standard name string |
| 245 | (file/line/function-name) that is presented in each line. The following is a |
| 246 | typical output from such a call:: |
| 247 | |
| 248 | 2706 function calls (2004 primitive calls) in 4.504 CPU seconds |
| 249 | |
| 250 | Ordered by: standard name |
| 251 | |
| 252 | ncalls tottime percall cumtime percall filename:lineno(function) |
| 253 | 2 0.006 0.003 0.953 0.477 pobject.py:75(save_objects) |
| 254 | 43/3 0.533 0.012 0.749 0.250 pobject.py:99(evaluate) |
| 255 | ... |
| 256 | |
| 257 | The first line indicates that 2706 calls were monitored. Of those calls, 2004 |
| 258 | were :dfn:`primitive`. We define :dfn:`primitive` to mean that the call was not |
| 259 | induced via recursion. The next line: ``Ordered by: standard name``, indicates |
| 260 | that the text string in the far right column was used to sort the output. The |
| 261 | column headings include: |
| 262 | |
Georg Brandl | 48310cd | 2009-01-03 21:18:54 +0000 | [diff] [blame] | 263 | ncalls |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 264 | for the number of calls, |
| 265 | |
Georg Brandl | 48310cd | 2009-01-03 21:18:54 +0000 | [diff] [blame] | 266 | tottime |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 267 | for the total time spent in the given function (and excluding time made in calls |
| 268 | to sub-functions), |
| 269 | |
Georg Brandl | 48310cd | 2009-01-03 21:18:54 +0000 | [diff] [blame] | 270 | percall |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 271 | is the quotient of ``tottime`` divided by ``ncalls`` |
| 272 | |
Georg Brandl | 48310cd | 2009-01-03 21:18:54 +0000 | [diff] [blame] | 273 | cumtime |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 274 | is the total time spent in this and all subfunctions (from invocation till |
| 275 | exit). This figure is accurate *even* for recursive functions. |
| 276 | |
Georg Brandl | 48310cd | 2009-01-03 21:18:54 +0000 | [diff] [blame] | 277 | percall |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 278 | is the quotient of ``cumtime`` divided by primitive calls |
| 279 | |
Georg Brandl | 48310cd | 2009-01-03 21:18:54 +0000 | [diff] [blame] | 280 | filename:lineno(function) |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 281 | provides the respective data of each function |
| 282 | |
| 283 | When there are two numbers in the first column (for example, ``43/3``), then the |
| 284 | latter is the number of primitive calls, and the former is the actual number of |
| 285 | calls. Note that when the function does not recurse, these two values are the |
| 286 | same, and only the single figure is printed. |
| 287 | |
| 288 | |
| 289 | .. function:: runctx(command, globals, locals[, filename]) |
| 290 | |
| 291 | This function is similar to :func:`run`, with added arguments to supply the |
| 292 | globals and locals dictionaries for the *command* string. |
| 293 | |
| 294 | Analysis of the profiler data is done using the :class:`Stats` class. |
| 295 | |
| 296 | .. note:: |
| 297 | |
| 298 | The :class:`Stats` class is defined in the :mod:`pstats` module. |
| 299 | |
| 300 | |
| 301 | .. module:: pstats |
| 302 | :synopsis: Statistics object for use with the profiler. |
| 303 | |
| 304 | |
| 305 | .. class:: Stats(filename[, stream=sys.stdout[, ...]]) |
| 306 | |
| 307 | This class constructor creates an instance of a "statistics object" from a |
| 308 | *filename* (or set of filenames). :class:`Stats` objects are manipulated by |
| 309 | methods, in order to print useful reports. You may specify an alternate output |
| 310 | stream by giving the keyword argument, ``stream``. |
| 311 | |
| 312 | The file selected by the above constructor must have been created by the |
| 313 | corresponding version of :mod:`profile` or :mod:`cProfile`. To be specific, |
| 314 | there is *no* file compatibility guaranteed with future versions of this |
| 315 | profiler, and there is no compatibility with files produced by other profilers. |
| 316 | If several files are provided, all the statistics for identical functions will |
| 317 | be coalesced, so that an overall view of several processes can be considered in |
| 318 | a single report. If additional files need to be combined with data in an |
| 319 | existing :class:`Stats` object, the :meth:`add` method can be used. |
| 320 | |
Christian Heimes | 5b5e81c | 2007-12-31 16:14:33 +0000 | [diff] [blame] | 321 | .. (such as the old system profiler). |
| 322 | |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 323 | |
| 324 | .. _profile-stats: |
| 325 | |
| 326 | The :class:`Stats` Class |
| 327 | ------------------------ |
| 328 | |
| 329 | :class:`Stats` objects have the following methods: |
| 330 | |
| 331 | |
| 332 | .. method:: Stats.strip_dirs() |
| 333 | |
| 334 | This method for the :class:`Stats` class removes all leading path information |
| 335 | from file names. It is very useful in reducing the size of the printout to fit |
| 336 | within (close to) 80 columns. This method modifies the object, and the stripped |
| 337 | information is lost. After performing a strip operation, the object is |
| 338 | considered to have its entries in a "random" order, as it was just after object |
| 339 | initialization and loading. If :meth:`strip_dirs` causes two function names to |
| 340 | be indistinguishable (they are on the same line of the same filename, and have |
| 341 | the same function name), then the statistics for these two entries are |
| 342 | accumulated into a single entry. |
| 343 | |
| 344 | |
| 345 | .. method:: Stats.add(filename[, ...]) |
| 346 | |
| 347 | This method of the :class:`Stats` class accumulates additional profiling |
| 348 | information into the current profiling object. Its arguments should refer to |
| 349 | filenames created by the corresponding version of :func:`profile.run` or |
| 350 | :func:`cProfile.run`. Statistics for identically named (re: file, line, name) |
| 351 | functions are automatically accumulated into single function statistics. |
| 352 | |
| 353 | |
| 354 | .. method:: Stats.dump_stats(filename) |
| 355 | |
| 356 | Save the data loaded into the :class:`Stats` object to a file named *filename*. |
| 357 | The file is created if it does not exist, and is overwritten if it already |
| 358 | exists. This is equivalent to the method of the same name on the |
| 359 | :class:`profile.Profile` and :class:`cProfile.Profile` classes. |
| 360 | |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 361 | |
| 362 | .. method:: Stats.sort_stats(key[, ...]) |
| 363 | |
| 364 | This method modifies the :class:`Stats` object by sorting it according to the |
| 365 | supplied criteria. The argument is typically a string identifying the basis of |
| 366 | a sort (example: ``'time'`` or ``'name'``). |
| 367 | |
| 368 | When more than one key is provided, then additional keys are used as secondary |
| 369 | criteria when there is equality in all keys selected before them. For example, |
| 370 | ``sort_stats('name', 'file')`` will sort all the entries according to their |
| 371 | function name, and resolve all ties (identical function names) by sorting by |
| 372 | file name. |
| 373 | |
| 374 | Abbreviations can be used for any key names, as long as the abbreviation is |
| 375 | unambiguous. The following are the keys currently defined: |
| 376 | |
| 377 | +------------------+----------------------+ |
| 378 | | Valid Arg | Meaning | |
| 379 | +==================+======================+ |
| 380 | | ``'calls'`` | call count | |
| 381 | +------------------+----------------------+ |
| 382 | | ``'cumulative'`` | cumulative time | |
| 383 | +------------------+----------------------+ |
| 384 | | ``'file'`` | file name | |
| 385 | +------------------+----------------------+ |
| 386 | | ``'module'`` | file name | |
| 387 | +------------------+----------------------+ |
| 388 | | ``'pcalls'`` | primitive call count | |
| 389 | +------------------+----------------------+ |
| 390 | | ``'line'`` | line number | |
| 391 | +------------------+----------------------+ |
| 392 | | ``'name'`` | function name | |
| 393 | +------------------+----------------------+ |
| 394 | | ``'nfl'`` | name/file/line | |
| 395 | +------------------+----------------------+ |
| 396 | | ``'stdname'`` | standard name | |
| 397 | +------------------+----------------------+ |
| 398 | | ``'time'`` | internal time | |
| 399 | +------------------+----------------------+ |
| 400 | |
| 401 | Note that all sorts on statistics are in descending order (placing most time |
| 402 | consuming items first), where as name, file, and line number searches are in |
| 403 | ascending order (alphabetical). The subtle distinction between ``'nfl'`` and |
| 404 | ``'stdname'`` is that the standard name is a sort of the name as printed, which |
| 405 | means that the embedded line numbers get compared in an odd way. For example, |
| 406 | lines 3, 20, and 40 would (if the file names were the same) appear in the string |
| 407 | order 20, 3 and 40. In contrast, ``'nfl'`` does a numeric compare of the line |
| 408 | numbers. In fact, ``sort_stats('nfl')`` is the same as ``sort_stats('name', |
| 409 | 'file', 'line')``. |
| 410 | |
| 411 | For backward-compatibility reasons, the numeric arguments ``-1``, ``0``, ``1``, |
| 412 | and ``2`` are permitted. They are interpreted as ``'stdname'``, ``'calls'``, |
| 413 | ``'time'``, and ``'cumulative'`` respectively. If this old style format |
| 414 | (numeric) is used, only one sort key (the numeric key) will be used, and |
| 415 | additional arguments will be silently ignored. |
| 416 | |
Christian Heimes | 5b5e81c | 2007-12-31 16:14:33 +0000 | [diff] [blame] | 417 | .. For compatibility with the old profiler, |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 418 | |
| 419 | |
| 420 | .. method:: Stats.reverse_order() |
| 421 | |
| 422 | This method for the :class:`Stats` class reverses the ordering of the basic list |
| 423 | within the object. Note that by default ascending vs descending order is |
| 424 | properly selected based on the sort key of choice. |
| 425 | |
Christian Heimes | 5b5e81c | 2007-12-31 16:14:33 +0000 | [diff] [blame] | 426 | .. This method is provided primarily for compatibility with the old profiler. |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 427 | |
| 428 | |
| 429 | .. method:: Stats.print_stats([restriction, ...]) |
| 430 | |
| 431 | This method for the :class:`Stats` class prints out a report as described in the |
| 432 | :func:`profile.run` definition. |
| 433 | |
| 434 | The order of the printing is based on the last :meth:`sort_stats` operation done |
| 435 | on the object (subject to caveats in :meth:`add` and :meth:`strip_dirs`). |
| 436 | |
| 437 | The arguments provided (if any) can be used to limit the list down to the |
| 438 | significant entries. Initially, the list is taken to be the complete set of |
| 439 | profiled functions. Each restriction is either an integer (to select a count of |
| 440 | lines), or a decimal fraction between 0.0 and 1.0 inclusive (to select a |
| 441 | percentage of lines), or a regular expression (to pattern match the standard |
| 442 | name that is printed; as of Python 1.5b1, this uses the Perl-style regular |
| 443 | expression syntax defined by the :mod:`re` module). If several restrictions are |
| 444 | provided, then they are applied sequentially. For example:: |
| 445 | |
| 446 | print_stats(.1, 'foo:') |
| 447 | |
| 448 | would first limit the printing to first 10% of list, and then only print |
| 449 | functions that were part of filename :file:`.\*foo:`. In contrast, the |
| 450 | command:: |
| 451 | |
| 452 | print_stats('foo:', .1) |
| 453 | |
| 454 | would limit the list to all functions having file names :file:`.\*foo:`, and |
| 455 | then proceed to only print the first 10% of them. |
| 456 | |
| 457 | |
| 458 | .. method:: Stats.print_callers([restriction, ...]) |
| 459 | |
| 460 | This method for the :class:`Stats` class prints a list of all functions that |
| 461 | called each function in the profiled database. The ordering is identical to |
| 462 | that provided by :meth:`print_stats`, and the definition of the restricting |
| 463 | argument is also identical. Each caller is reported on its own line. The |
| 464 | format differs slightly depending on the profiler that produced the stats: |
| 465 | |
| 466 | * With :mod:`profile`, a number is shown in parentheses after each caller to |
| 467 | show how many times this specific call was made. For convenience, a second |
| 468 | non-parenthesized number repeats the cumulative time spent in the function |
| 469 | at the right. |
| 470 | |
Christian Heimes | c3f30c4 | 2008-02-22 16:37:40 +0000 | [diff] [blame] | 471 | * With :mod:`cProfile`, each caller is preceded by three numbers: the number of |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 472 | times this specific call was made, and the total and cumulative times spent in |
| 473 | the current function while it was invoked by this specific caller. |
| 474 | |
| 475 | |
| 476 | .. method:: Stats.print_callees([restriction, ...]) |
| 477 | |
| 478 | This method for the :class:`Stats` class prints a list of all function that were |
| 479 | called by the indicated function. Aside from this reversal of direction of |
| 480 | calls (re: called vs was called by), the arguments and ordering are identical to |
| 481 | the :meth:`print_callers` method. |
| 482 | |
| 483 | |
| 484 | .. _profile-limits: |
| 485 | |
| 486 | Limitations |
| 487 | =========== |
| 488 | |
| 489 | One limitation has to do with accuracy of timing information. There is a |
| 490 | fundamental problem with deterministic profilers involving accuracy. The most |
| 491 | obvious restriction is that the underlying "clock" is only ticking at a rate |
| 492 | (typically) of about .001 seconds. Hence no measurements will be more accurate |
| 493 | than the underlying clock. If enough measurements are taken, then the "error" |
| 494 | will tend to average out. Unfortunately, removing this first error induces a |
| 495 | second source of error. |
| 496 | |
| 497 | The second problem is that it "takes a while" from when an event is dispatched |
| 498 | until the profiler's call to get the time actually *gets* the state of the |
| 499 | clock. Similarly, there is a certain lag when exiting the profiler event |
| 500 | handler from the time that the clock's value was obtained (and then squirreled |
| 501 | away), until the user's code is once again executing. As a result, functions |
| 502 | that are called many times, or call many functions, will typically accumulate |
| 503 | this error. The error that accumulates in this fashion is typically less than |
| 504 | the accuracy of the clock (less than one clock tick), but it *can* accumulate |
| 505 | and become very significant. |
| 506 | |
| 507 | The problem is more important with :mod:`profile` than with the lower-overhead |
| 508 | :mod:`cProfile`. For this reason, :mod:`profile` provides a means of |
| 509 | calibrating itself for a given platform so that this error can be |
| 510 | probabilistically (on the average) removed. After the profiler is calibrated, it |
| 511 | will be more accurate (in a least square sense), but it will sometimes produce |
| 512 | negative numbers (when call counts are exceptionally low, and the gods of |
| 513 | probability work against you :-). ) Do *not* be alarmed by negative numbers in |
| 514 | the profile. They should *only* appear if you have calibrated your profiler, |
| 515 | and the results are actually better than without calibration. |
| 516 | |
| 517 | |
| 518 | .. _profile-calibration: |
| 519 | |
| 520 | Calibration |
| 521 | =========== |
| 522 | |
| 523 | The profiler of the :mod:`profile` module subtracts a constant from each event |
| 524 | handling time to compensate for the overhead of calling the time function, and |
| 525 | socking away the results. By default, the constant is 0. The following |
| 526 | procedure can be used to obtain a better constant for a given platform (see |
| 527 | discussion in section Limitations above). :: |
| 528 | |
| 529 | import profile |
| 530 | pr = profile.Profile() |
| 531 | for i in range(5): |
Georg Brandl | 6911e3c | 2007-09-04 07:15:32 +0000 | [diff] [blame] | 532 | print(pr.calibrate(10000)) |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 533 | |
| 534 | The method executes the number of Python calls given by the argument, directly |
| 535 | and again under the profiler, measuring the time for both. It then computes the |
| 536 | hidden overhead per profiler event, and returns that as a float. For example, |
| 537 | on an 800 MHz Pentium running Windows 2000, and using Python's time.clock() as |
| 538 | the timer, the magical number is about 12.5e-6. |
| 539 | |
| 540 | The object of this exercise is to get a fairly consistent result. If your |
| 541 | computer is *very* fast, or your timer function has poor resolution, you might |
| 542 | have to pass 100000, or even 1000000, to get consistent results. |
| 543 | |
Georg Brandl | e6bcc91 | 2008-05-12 18:05:20 +0000 | [diff] [blame] | 544 | When you have a consistent answer, there are three ways you can use it:: |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 545 | |
| 546 | import profile |
| 547 | |
| 548 | # 1. Apply computed bias to all Profile instances created hereafter. |
| 549 | profile.Profile.bias = your_computed_bias |
| 550 | |
| 551 | # 2. Apply computed bias to a specific Profile instance. |
| 552 | pr = profile.Profile() |
| 553 | pr.bias = your_computed_bias |
| 554 | |
| 555 | # 3. Specify computed bias in instance constructor. |
| 556 | pr = profile.Profile(bias=your_computed_bias) |
| 557 | |
| 558 | If you have a choice, you are better off choosing a smaller constant, and then |
| 559 | your results will "less often" show up as negative in profile statistics. |
| 560 | |
| 561 | |
| 562 | .. _profiler-extensions: |
| 563 | |
| 564 | Extensions --- Deriving Better Profilers |
| 565 | ======================================== |
| 566 | |
| 567 | The :class:`Profile` class of both modules, :mod:`profile` and :mod:`cProfile`, |
| 568 | were written so that derived classes could be developed to extend the profiler. |
| 569 | The details are not described here, as doing this successfully requires an |
| 570 | expert understanding of how the :class:`Profile` class works internally. Study |
| 571 | the source code of the module carefully if you want to pursue this. |
| 572 | |
| 573 | If all you want to do is change how current time is determined (for example, to |
| 574 | force use of wall-clock time or elapsed process time), pass the timing function |
| 575 | you want to the :class:`Profile` class constructor:: |
| 576 | |
| 577 | pr = profile.Profile(your_time_func) |
| 578 | |
| 579 | The resulting profiler will then call :func:`your_time_func`. |
| 580 | |
| 581 | :class:`profile.Profile` |
| 582 | :func:`your_time_func` should return a single number, or a list of numbers whose |
| 583 | sum is the current time (like what :func:`os.times` returns). If the function |
| 584 | returns a single time number, or the list of returned numbers has length 2, then |
| 585 | you will get an especially fast version of the dispatch routine. |
| 586 | |
| 587 | Be warned that you should calibrate the profiler class for the timer function |
| 588 | that you choose. For most machines, a timer that returns a lone integer value |
| 589 | will provide the best results in terms of low overhead during profiling. |
| 590 | (:func:`os.times` is *pretty* bad, as it returns a tuple of floating point |
| 591 | values). If you want to substitute a better timer in the cleanest fashion, |
| 592 | derive a class and hardwire a replacement dispatch method that best handles your |
| 593 | timer call, along with the appropriate calibration constant. |
| 594 | |
| 595 | :class:`cProfile.Profile` |
Georg Brandl | 95817b3 | 2008-05-11 14:30:18 +0000 | [diff] [blame] | 596 | :func:`your_time_func` should return a single number. If it returns |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 597 | integers, you can also invoke the class constructor with a second argument |
| 598 | specifying the real duration of one unit of time. For example, if |
| 599 | :func:`your_integer_time_func` returns times measured in thousands of seconds, |
| 600 | you would constuct the :class:`Profile` instance as follows:: |
| 601 | |
| 602 | pr = profile.Profile(your_integer_time_func, 0.001) |
| 603 | |
| 604 | As the :mod:`cProfile.Profile` class cannot be calibrated, custom timer |
| 605 | functions should be used with care and should be as fast as possible. For the |
| 606 | best results with a custom timer, it might be necessary to hard-code it in the C |
| 607 | source of the internal :mod:`_lsprof` module. |
| 608 | |
| 609 | .. rubric:: Footnotes |
| 610 | |
| 611 | .. [#] Updated and converted to LaTeX by Guido van Rossum. Further updated by Armin |
| 612 | Rigo to integrate the documentation for the new :mod:`cProfile` module of Python |
| 613 | 2.5. |