Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 1 | .. _profile: |
| 2 | |
| 3 | ******************** |
| 4 | The Python Profilers |
| 5 | ******************** |
| 6 | |
Raymond Hettinger | 469271d | 2011-01-27 20:38:46 +0000 | [diff] [blame] | 7 | **Source code:** :source:`Lib/profile.py` and :source:`Lib/pstats.py` |
| 8 | |
| 9 | -------------- |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 10 | |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 11 | .. _profiler-introduction: |
| 12 | |
| 13 | Introduction to the profilers |
| 14 | ============================= |
| 15 | |
| 16 | .. index:: |
| 17 | single: deterministic profiling |
| 18 | single: profiling, deterministic |
| 19 | |
Ezio Melotti | 075d87c | 2013-04-12 15:42:06 +0300 | [diff] [blame] | 20 | :mod:`cProfile` and :mod:`profile` provide :dfn:`deterministic profiling` of |
| 21 | Python programs. A :dfn:`profile` is a set of statistics that describes how |
| 22 | often and for how long various parts of the program executed. These statistics |
| 23 | can be formatted into reports via the :mod:`pstats` module. |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 24 | |
Ezio Melotti | 075d87c | 2013-04-12 15:42:06 +0300 | [diff] [blame] | 25 | The Python standard library provides two different implementations of the same |
| 26 | profiling interface: |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 27 | |
Georg Brandl | 4eb6597 | 2010-10-14 06:41:42 +0000 | [diff] [blame] | 28 | 1. :mod:`cProfile` is recommended for most users; it's a C extension with |
| 29 | reasonable overhead that makes it suitable for profiling long-running |
| 30 | programs. Based on :mod:`lsprof`, contributed by Brett Rosen and Ted |
| 31 | Czotter. |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 32 | |
Georg Brandl | 4eb6597 | 2010-10-14 06:41:42 +0000 | [diff] [blame] | 33 | 2. :mod:`profile`, a pure Python module whose interface is imitated by |
Ezio Melotti | 075d87c | 2013-04-12 15:42:06 +0300 | [diff] [blame] | 34 | :mod:`cProfile`, but which adds significant overhead to profiled programs. |
| 35 | If you're trying to extend the profiler in some way, the task might be easier |
| 36 | with this module. |
Georg Brandl | 4eb6597 | 2010-10-14 06:41:42 +0000 | [diff] [blame] | 37 | |
| 38 | .. note:: |
| 39 | |
| 40 | The profiler modules are designed to provide an execution profile for a given |
| 41 | program, not for benchmarking purposes (for that, there is :mod:`timeit` for |
Ezio Melotti | b5ff3e4 | 2011-04-03 16:20:21 +0300 | [diff] [blame] | 42 | reasonably accurate results). This particularly applies to benchmarking |
Georg Brandl | 4eb6597 | 2010-10-14 06:41:42 +0000 | [diff] [blame] | 43 | Python code against C code: the profilers introduce overhead for Python code, |
| 44 | but not for C-level functions, and so the C code would seem faster than any |
| 45 | Python one. |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 46 | |
| 47 | |
| 48 | .. _profile-instant: |
| 49 | |
| 50 | Instant User's Manual |
| 51 | ===================== |
| 52 | |
| 53 | This section is provided for users that "don't want to read the manual." It |
| 54 | provides a very brief overview, and allows a user to rapidly perform profiling |
| 55 | on an existing application. |
| 56 | |
Ezio Melotti | 075d87c | 2013-04-12 15:42:06 +0300 | [diff] [blame] | 57 | To profile a function that takes a single argument, you can do:: |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 58 | |
| 59 | import cProfile |
Ezio Melotti | 075d87c | 2013-04-12 15:42:06 +0300 | [diff] [blame] | 60 | import re |
| 61 | cProfile.run('re.compile("foo|bar")') |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 62 | |
| 63 | (Use :mod:`profile` instead of :mod:`cProfile` if the latter is not available on |
| 64 | your system.) |
| 65 | |
Ezio Melotti | 075d87c | 2013-04-12 15:42:06 +0300 | [diff] [blame] | 66 | The above action would run :func:`re.compile` and print profile results like |
| 67 | the following:: |
| 68 | |
| 69 | 197 function calls (192 primitive calls) in 0.002 seconds |
| 70 | |
| 71 | Ordered by: standard name |
| 72 | |
| 73 | ncalls tottime percall cumtime percall filename:lineno(function) |
| 74 | 1 0.000 0.000 0.001 0.001 <string>:1(<module>) |
| 75 | 1 0.000 0.000 0.001 0.001 re.py:212(compile) |
| 76 | 1 0.000 0.000 0.001 0.001 re.py:268(_compile) |
| 77 | 1 0.000 0.000 0.000 0.000 sre_compile.py:172(_compile_charset) |
| 78 | 1 0.000 0.000 0.000 0.000 sre_compile.py:201(_optimize_charset) |
| 79 | 4 0.000 0.000 0.000 0.000 sre_compile.py:25(_identityfunction) |
| 80 | 3/1 0.000 0.000 0.000 0.000 sre_compile.py:33(_compile) |
| 81 | |
| 82 | The first line indicates that 197 calls were monitored. Of those calls, 192 |
| 83 | were :dfn:`primitive`, meaning that the call was not induced via recursion. The |
| 84 | next line: ``Ordered by: standard name``, indicates that the text string in the |
| 85 | far right column was used to sort the output. The column headings include: |
| 86 | |
| 87 | ncalls |
| 88 | for the number of calls, |
| 89 | |
| 90 | tottime |
| 91 | for the total time spent in the given function (and excluding time made in |
| 92 | calls to sub-functions) |
| 93 | |
| 94 | percall |
| 95 | is the quotient of ``tottime`` divided by ``ncalls`` |
| 96 | |
| 97 | cumtime |
| 98 | is the cumulative time spent in this and all subfunctions (from invocation |
| 99 | till exit). This figure is accurate *even* for recursive functions. |
| 100 | |
| 101 | percall |
| 102 | is the quotient of ``cumtime`` divided by primitive calls |
| 103 | |
| 104 | filename:lineno(function) |
| 105 | provides the respective data of each function |
| 106 | |
| 107 | When there are two numbers in the first column (for example ``3/1``), it means |
| 108 | that the function recursed. The second value is the number of primitive calls |
| 109 | and the former is the total number of calls. Note that when the function does |
| 110 | not recurse, these two values are the same, and only the single figure is |
| 111 | printed. |
| 112 | |
| 113 | Instead of printing the output at the end of the profile run, you can save the |
| 114 | results to a file by specifying a filename to the :func:`run` function:: |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 115 | |
| 116 | import cProfile |
Ezio Melotti | 075d87c | 2013-04-12 15:42:06 +0300 | [diff] [blame] | 117 | import re |
| 118 | cProfile.run('re.compile("foo|bar")', 'restats') |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 119 | |
Ezio Melotti | 075d87c | 2013-04-12 15:42:06 +0300 | [diff] [blame] | 120 | The :class:`pstats.Stats` class reads profile results from a file and formats |
| 121 | them in various ways. |
| 122 | |
| 123 | The file :mod:`cProfile` can also be invoked as a script to profile another |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 124 | script. For example:: |
| 125 | |
Ezio Melotti | 075d87c | 2013-04-12 15:42:06 +0300 | [diff] [blame] | 126 | python -m cProfile [-o output_file] [-s sort_order] myscript.py |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 127 | |
Ezio Melotti | 075d87c | 2013-04-12 15:42:06 +0300 | [diff] [blame] | 128 | ``-o`` writes the profile results to a file instead of to stdout |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 129 | |
Ezio Melotti | 075d87c | 2013-04-12 15:42:06 +0300 | [diff] [blame] | 130 | ``-s`` specifies one of the :func:`~pstats.Stats.sort_stats` sort values to sort |
| 131 | the output by. This only applies when ``-o`` is not supplied. |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 132 | |
Ezio Melotti | 075d87c | 2013-04-12 15:42:06 +0300 | [diff] [blame] | 133 | The :mod:`pstats` module's :class:`~pstats.Stats` class has a variety of methods |
| 134 | for manipulating and printing the data saved into a profile results file:: |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 135 | |
| 136 | import pstats |
Ezio Melotti | 075d87c | 2013-04-12 15:42:06 +0300 | [diff] [blame] | 137 | p = pstats.Stats('restats') |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 138 | p.strip_dirs().sort_stats(-1).print_stats() |
| 139 | |
Ezio Melotti | 075d87c | 2013-04-12 15:42:06 +0300 | [diff] [blame] | 140 | The :meth:`~pstats.Stats.strip_dirs` method removed the extraneous path from all |
| 141 | the module names. The :meth:`~pstats.Stats.sort_stats` method sorted all the |
| 142 | entries according to the standard module/line/name string that is printed. The |
| 143 | :meth:`~pstats.Stats.print_stats` method printed out all the statistics. You |
| 144 | might try the following sort calls:: |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 145 | |
| 146 | p.sort_stats('name') |
| 147 | p.print_stats() |
| 148 | |
| 149 | The first call will actually sort the list by function name, and the second call |
| 150 | will print out the statistics. The following are some interesting calls to |
| 151 | experiment with:: |
| 152 | |
| 153 | p.sort_stats('cumulative').print_stats(10) |
| 154 | |
| 155 | This sorts the profile by cumulative time in a function, and then only prints |
| 156 | the ten most significant lines. If you want to understand what algorithms are |
| 157 | taking time, the above line is what you would use. |
| 158 | |
| 159 | If you were looking to see what functions were looping a lot, and taking a lot |
| 160 | of time, you would do:: |
| 161 | |
| 162 | p.sort_stats('time').print_stats(10) |
| 163 | |
| 164 | to sort according to time spent within each function, and then print the |
| 165 | statistics for the top ten functions. |
| 166 | |
| 167 | You might also try:: |
| 168 | |
| 169 | p.sort_stats('file').print_stats('__init__') |
| 170 | |
| 171 | This will sort all the statistics by file name, and then print out statistics |
| 172 | for only the class init methods (since they are spelled with ``__init__`` in |
| 173 | them). As one final example, you could try:: |
| 174 | |
| 175 | p.sort_stats('time', 'cum').print_stats(.5, 'init') |
| 176 | |
| 177 | This line sorts statistics with a primary key of time, and a secondary key of |
| 178 | cumulative time, and then prints out some of the statistics. To be specific, the |
| 179 | list is first culled down to 50% (re: ``.5``) of its original size, then only |
| 180 | lines containing ``init`` are maintained, and that sub-sub-list is printed. |
| 181 | |
| 182 | If you wondered what functions called the above functions, you could now (``p`` |
| 183 | is still sorted according to the last criteria) do:: |
| 184 | |
| 185 | p.print_callers(.5, 'init') |
| 186 | |
| 187 | and you would get a list of callers for each of the listed functions. |
| 188 | |
| 189 | If you want more functionality, you're going to have to read the manual, or |
| 190 | guess what the following functions do:: |
| 191 | |
| 192 | p.print_callees() |
Ezio Melotti | 075d87c | 2013-04-12 15:42:06 +0300 | [diff] [blame] | 193 | p.add('restats') |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 194 | |
| 195 | Invoked as a script, the :mod:`pstats` module is a statistics browser for |
| 196 | reading and examining profile dumps. It has a simple line-oriented interface |
| 197 | (implemented using :mod:`cmd`) and interactive help. |
| 198 | |
Ezio Melotti | 075d87c | 2013-04-12 15:42:06 +0300 | [diff] [blame] | 199 | :mod:`profile` and :mod:`cProfile` Module Reference |
| 200 | ======================================================= |
| 201 | |
| 202 | .. module:: cProfile |
| 203 | .. module:: profile |
| 204 | :synopsis: Python source profiler. |
| 205 | |
| 206 | Both the :mod:`profile` and :mod:`cProfile` modules provide the following |
| 207 | functions: |
| 208 | |
| 209 | .. function:: run(command, filename=None, sort=-1) |
| 210 | |
| 211 | This function takes a single argument that can be passed to the :func:`exec` |
| 212 | function, and an optional file name. In all cases this routine executes:: |
| 213 | |
| 214 | exec(command, __main__.__dict__, __main__.__dict__) |
| 215 | |
| 216 | and gathers profiling statistics from the execution. If no file name is |
| 217 | present, then this function automatically creates a :class:`~pstats.Stats` |
| 218 | instance and prints a simple profiling report. If the sort value is specified |
| 219 | it is passed to this :class:`~pstats.Stats` instance to control how the |
| 220 | results are sorted. |
| 221 | |
| 222 | .. function:: runctx(command, globals, locals, filename=None) |
| 223 | |
| 224 | This function is similar to :func:`run`, with added arguments to supply the |
| 225 | globals and locals dictionaries for the *command* string. This routine |
| 226 | executes:: |
| 227 | |
| 228 | exec(command, globals, locals) |
| 229 | |
| 230 | and gathers profiling statistics as in the :func:`run` function above. |
| 231 | |
| 232 | .. class:: Profile(timer=None, timeunit=0.0, subcalls=True, builtins=True) |
| 233 | |
| 234 | This class is normally only used if more precise control over profiling is |
| 235 | needed than what the :func:`cProfile.run` function provides. |
| 236 | |
| 237 | A custom timer can be supplied for measuring how long code takes to run via |
| 238 | the *timer* argument. This must be a function that returns a single number |
| 239 | representing the current time. If the number is an integer, the *timeunit* |
| 240 | specifies a multiplier that specifies the duration of each unit of time. For |
| 241 | example, if the timer returns times measured in thousands of seconds, the |
| 242 | time unit would be ``.001``. |
| 243 | |
| 244 | Directly using the :class:`Profile` class allows formatting profile results |
| 245 | without writing the profile data to a file:: |
| 246 | |
| 247 | import cProfile, pstats, io |
| 248 | pr = cProfile.Profile() |
| 249 | pr.enable() |
Senthil Kumaran | 21101f7 | 2013-09-07 17:51:58 -0700 | [diff] [blame] | 250 | # ... do something ... |
Ezio Melotti | 075d87c | 2013-04-12 15:42:06 +0300 | [diff] [blame] | 251 | pr.disable() |
| 252 | s = io.StringIO() |
Senthil Kumaran | 21101f7 | 2013-09-07 17:51:58 -0700 | [diff] [blame] | 253 | sortby = 'cumulative' |
| 254 | ps = pstats.Stats(pr, stream=s).sort_stats(sortby) |
| 255 | ps.print_stats() |
| 256 | print(s.getvalue()) |
Ezio Melotti | 075d87c | 2013-04-12 15:42:06 +0300 | [diff] [blame] | 257 | |
| 258 | .. method:: enable() |
| 259 | |
| 260 | Start collecting profiling data. |
| 261 | |
| 262 | .. method:: disable() |
| 263 | |
| 264 | Stop collecting profiling data. |
| 265 | |
| 266 | .. method:: create_stats() |
| 267 | |
| 268 | Stop collecting profiling data and record the results internally |
| 269 | as the current profile. |
| 270 | |
| 271 | .. method:: print_stats(sort=-1) |
| 272 | |
| 273 | Create a :class:`~pstats.Stats` object based on the current |
| 274 | profile and print the results to stdout. |
| 275 | |
| 276 | .. method:: dump_stats(filename) |
| 277 | |
| 278 | Write the results of the current profile to *filename*. |
| 279 | |
| 280 | .. method:: run(cmd) |
| 281 | |
| 282 | Profile the cmd via :func:`exec`. |
| 283 | |
| 284 | .. method:: runctx(cmd, globals, locals) |
| 285 | |
| 286 | Profile the cmd via :func:`exec` with the specified global and |
| 287 | local environment. |
| 288 | |
| 289 | .. method:: runcall(func, *args, **kwargs) |
| 290 | |
| 291 | Profile ``func(*args, **kwargs)`` |
| 292 | |
| 293 | .. _profile-stats: |
| 294 | |
| 295 | The :class:`Stats` Class |
| 296 | ======================== |
| 297 | |
| 298 | Analysis of the profiler data is done using the :class:`~pstats.Stats` class. |
| 299 | |
| 300 | .. module:: pstats |
| 301 | :synopsis: Statistics object for use with the profiler. |
| 302 | |
| 303 | .. class:: Stats(*filenames or profile, stream=sys.stdout) |
| 304 | |
| 305 | This class constructor creates an instance of a "statistics object" from a |
| 306 | *filename* (or list of filenames) or from a :class:`Profile` instance. Output |
| 307 | will be printed to the stream specified by *stream*. |
| 308 | |
| 309 | The file selected by the above constructor must have been created by the |
| 310 | corresponding version of :mod:`profile` or :mod:`cProfile`. To be specific, |
| 311 | there is *no* file compatibility guaranteed with future versions of this |
| 312 | profiler, and there is no compatibility with files produced by other |
| 313 | profilers. If several files are provided, all the statistics for identical |
| 314 | functions will be coalesced, so that an overall view of several processes can |
| 315 | be considered in a single report. If additional files need to be combined |
| 316 | with data in an existing :class:`~pstats.Stats` object, the |
| 317 | :meth:`~pstats.Stats.add` method can be used. |
| 318 | |
| 319 | Instead of reading the profile data from a file, a :class:`cProfile.Profile` |
| 320 | or :class:`profile.Profile` object can be used as the profile data source. |
| 321 | |
| 322 | :class:`Stats` objects have the following methods: |
| 323 | |
| 324 | .. method:: strip_dirs() |
| 325 | |
| 326 | This method for the :class:`Stats` class removes all leading path |
| 327 | information from file names. It is very useful in reducing the size of |
| 328 | the printout to fit within (close to) 80 columns. This method modifies |
| 329 | the object, and the stripped information is lost. After performing a |
| 330 | strip operation, the object is considered to have its entries in a |
| 331 | "random" order, as it was just after object initialization and loading. |
| 332 | If :meth:`~pstats.Stats.strip_dirs` causes two function names to be |
| 333 | indistinguishable (they are on the same line of the same filename, and |
| 334 | have the same function name), then the statistics for these two entries |
| 335 | are accumulated into a single entry. |
| 336 | |
| 337 | |
| 338 | .. method:: add(*filenames) |
| 339 | |
| 340 | This method of the :class:`Stats` class accumulates additional profiling |
| 341 | information into the current profiling object. Its arguments should refer |
| 342 | to filenames created by the corresponding version of :func:`profile.run` |
| 343 | or :func:`cProfile.run`. Statistics for identically named (re: file, line, |
| 344 | name) functions are automatically accumulated into single function |
| 345 | statistics. |
| 346 | |
| 347 | |
| 348 | .. method:: dump_stats(filename) |
| 349 | |
| 350 | Save the data loaded into the :class:`Stats` object to a file named |
| 351 | *filename*. The file is created if it does not exist, and is overwritten |
| 352 | if it already exists. This is equivalent to the method of the same name |
| 353 | on the :class:`profile.Profile` and :class:`cProfile.Profile` classes. |
| 354 | |
| 355 | |
| 356 | .. method:: sort_stats(*keys) |
| 357 | |
| 358 | This method modifies the :class:`Stats` object by sorting it according to |
| 359 | the supplied criteria. The argument is typically a string identifying the |
| 360 | basis of a sort (example: ``'time'`` or ``'name'``). |
| 361 | |
| 362 | When more than one key is provided, then additional keys are used as |
| 363 | secondary criteria when there is equality in all keys selected before |
| 364 | them. For example, ``sort_stats('name', 'file')`` will sort all the |
| 365 | entries according to their function name, and resolve all ties (identical |
| 366 | function names) by sorting by file name. |
| 367 | |
| 368 | Abbreviations can be used for any key names, as long as the abbreviation |
| 369 | is unambiguous. The following are the keys currently defined: |
| 370 | |
| 371 | +------------------+----------------------+ |
| 372 | | Valid Arg | Meaning | |
| 373 | +==================+======================+ |
| 374 | | ``'calls'`` | call count | |
| 375 | +------------------+----------------------+ |
| 376 | | ``'cumulative'`` | cumulative time | |
| 377 | +------------------+----------------------+ |
| 378 | | ``'cumtime'`` | cumulative time | |
| 379 | +------------------+----------------------+ |
| 380 | | ``'file'`` | file name | |
| 381 | +------------------+----------------------+ |
| 382 | | ``'filename'`` | file name | |
| 383 | +------------------+----------------------+ |
| 384 | | ``'module'`` | file name | |
| 385 | +------------------+----------------------+ |
| 386 | | ``'ncalls'`` | call count | |
| 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 | | ``'tottime'`` | internal time | |
| 401 | +------------------+----------------------+ |
| 402 | |
| 403 | Note that all sorts on statistics are in descending order (placing most |
| 404 | time consuming items first), where as name, file, and line number searches |
| 405 | are in ascending order (alphabetical). The subtle distinction between |
| 406 | ``'nfl'`` and ``'stdname'`` is that the standard name is a sort of the |
| 407 | name as printed, which means that the embedded line numbers get compared |
| 408 | in an odd way. For example, lines 3, 20, and 40 would (if the file names |
| 409 | were the same) appear in the string order 20, 3 and 40. In contrast, |
| 410 | ``'nfl'`` does a numeric compare of the line numbers. In fact, |
| 411 | ``sort_stats('nfl')`` is the same as ``sort_stats('name', 'file', |
| 412 | 'line')``. |
| 413 | |
| 414 | For backward-compatibility reasons, the numeric arguments ``-1``, ``0``, |
| 415 | ``1``, and ``2`` are permitted. They are interpreted as ``'stdname'``, |
| 416 | ``'calls'``, ``'time'``, and ``'cumulative'`` respectively. If this old |
| 417 | style format (numeric) is used, only one sort key (the numeric key) will |
| 418 | be used, and additional arguments will be silently ignored. |
| 419 | |
| 420 | .. For compatibility with the old profiler. |
| 421 | |
| 422 | |
| 423 | .. method:: reverse_order() |
| 424 | |
| 425 | This method for the :class:`Stats` class reverses the ordering of the |
| 426 | basic list within the object. Note that by default ascending vs |
| 427 | descending order is properly selected based on the sort key of choice. |
| 428 | |
| 429 | .. This method is provided primarily for compatibility with the old |
| 430 | profiler. |
| 431 | |
| 432 | |
| 433 | .. method:: print_stats(*restrictions) |
| 434 | |
| 435 | This method for the :class:`Stats` class prints out a report as described |
| 436 | in the :func:`profile.run` definition. |
| 437 | |
| 438 | The order of the printing is based on the last |
| 439 | :meth:`~pstats.Stats.sort_stats` operation done on the object (subject to |
| 440 | caveats in :meth:`~pstats.Stats.add` and |
| 441 | :meth:`~pstats.Stats.strip_dirs`). |
| 442 | |
| 443 | The arguments provided (if any) can be used to limit the list down to the |
| 444 | significant entries. Initially, the list is taken to be the complete set |
| 445 | of profiled functions. Each restriction is either an integer (to select a |
| 446 | count of lines), or a decimal fraction between 0.0 and 1.0 inclusive (to |
| 447 | select a percentage of lines), or a regular expression (to pattern match |
| 448 | the standard name that is printed. If several restrictions are provided, |
| 449 | then they are applied sequentially. For example:: |
| 450 | |
| 451 | print_stats(.1, 'foo:') |
| 452 | |
| 453 | would first limit the printing to first 10% of list, and then only print |
| 454 | functions that were part of filename :file:`.\*foo:`. In contrast, the |
| 455 | command:: |
| 456 | |
| 457 | print_stats('foo:', .1) |
| 458 | |
| 459 | would limit the list to all functions having file names :file:`.\*foo:`, |
| 460 | and then proceed to only print the first 10% of them. |
| 461 | |
| 462 | |
| 463 | .. method:: print_callers(*restrictions) |
| 464 | |
| 465 | This method for the :class:`Stats` class prints a list of all functions |
| 466 | that called each function in the profiled database. The ordering is |
| 467 | identical to that provided by :meth:`~pstats.Stats.print_stats`, and the |
| 468 | definition of the restricting argument is also identical. Each caller is |
| 469 | reported on its own line. The format differs slightly depending on the |
| 470 | profiler that produced the stats: |
| 471 | |
| 472 | * With :mod:`profile`, a number is shown in parentheses after each caller |
| 473 | to show how many times this specific call was made. For convenience, a |
| 474 | second non-parenthesized number repeats the cumulative time spent in the |
| 475 | function at the right. |
| 476 | |
| 477 | * With :mod:`cProfile`, each caller is preceded by three numbers: the |
| 478 | number of times this specific call was made, and the total and |
| 479 | cumulative times spent in the current function while it was invoked by |
| 480 | this specific caller. |
| 481 | |
| 482 | |
| 483 | .. method:: print_callees(*restrictions) |
| 484 | |
| 485 | This method for the :class:`Stats` class prints a list of all function |
| 486 | that were called by the indicated function. Aside from this reversal of |
| 487 | direction of calls (re: called vs was called by), the arguments and |
| 488 | ordering are identical to the :meth:`~pstats.Stats.print_callers` method. |
| 489 | |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 490 | |
| 491 | .. _deterministic-profiling: |
| 492 | |
| 493 | What Is Deterministic Profiling? |
| 494 | ================================ |
| 495 | |
| 496 | :dfn:`Deterministic profiling` is meant to reflect the fact that all *function |
| 497 | call*, *function return*, and *exception* events are monitored, and precise |
| 498 | timings are made for the intervals between these events (during which time the |
| 499 | user's code is executing). In contrast, :dfn:`statistical profiling` (which is |
| 500 | not done by this module) randomly samples the effective instruction pointer, and |
| 501 | deduces where time is being spent. The latter technique traditionally involves |
| 502 | less overhead (as the code does not need to be instrumented), but provides only |
| 503 | relative indications of where time is being spent. |
| 504 | |
| 505 | In Python, since there is an interpreter active during execution, the presence |
| 506 | of instrumented code is not required to do deterministic profiling. Python |
| 507 | automatically provides a :dfn:`hook` (optional callback) for each event. In |
| 508 | addition, the interpreted nature of Python tends to add so much overhead to |
| 509 | execution, that deterministic profiling tends to only add small processing |
| 510 | overhead in typical applications. The result is that deterministic profiling is |
| 511 | not that expensive, yet provides extensive run time statistics about the |
| 512 | execution of a Python program. |
| 513 | |
| 514 | Call count statistics can be used to identify bugs in code (surprising counts), |
| 515 | and to identify possible inline-expansion points (high call counts). Internal |
| 516 | time statistics can be used to identify "hot loops" that should be carefully |
| 517 | optimized. Cumulative time statistics should be used to identify high level |
| 518 | errors in the selection of algorithms. Note that the unusual handling of |
| 519 | cumulative times in this profiler allows statistics for recursive |
| 520 | implementations of algorithms to be directly compared to iterative |
| 521 | implementations. |
| 522 | |
| 523 | |
Ezio Melotti | 075d87c | 2013-04-12 15:42:06 +0300 | [diff] [blame] | 524 | .. _profile-limitations: |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 525 | |
| 526 | Limitations |
| 527 | =========== |
| 528 | |
| 529 | One limitation has to do with accuracy of timing information. There is a |
| 530 | fundamental problem with deterministic profilers involving accuracy. The most |
| 531 | obvious restriction is that the underlying "clock" is only ticking at a rate |
| 532 | (typically) of about .001 seconds. Hence no measurements will be more accurate |
| 533 | than the underlying clock. If enough measurements are taken, then the "error" |
| 534 | will tend to average out. Unfortunately, removing this first error induces a |
| 535 | second source of error. |
| 536 | |
| 537 | The second problem is that it "takes a while" from when an event is dispatched |
| 538 | until the profiler's call to get the time actually *gets* the state of the |
| 539 | clock. Similarly, there is a certain lag when exiting the profiler event |
| 540 | handler from the time that the clock's value was obtained (and then squirreled |
| 541 | away), until the user's code is once again executing. As a result, functions |
| 542 | that are called many times, or call many functions, will typically accumulate |
| 543 | this error. The error that accumulates in this fashion is typically less than |
| 544 | the accuracy of the clock (less than one clock tick), but it *can* accumulate |
| 545 | and become very significant. |
| 546 | |
| 547 | The problem is more important with :mod:`profile` than with the lower-overhead |
| 548 | :mod:`cProfile`. For this reason, :mod:`profile` provides a means of |
| 549 | calibrating itself for a given platform so that this error can be |
| 550 | probabilistically (on the average) removed. After the profiler is calibrated, it |
| 551 | will be more accurate (in a least square sense), but it will sometimes produce |
| 552 | negative numbers (when call counts are exceptionally low, and the gods of |
| 553 | probability work against you :-). ) Do *not* be alarmed by negative numbers in |
| 554 | the profile. They should *only* appear if you have calibrated your profiler, |
| 555 | and the results are actually better than without calibration. |
| 556 | |
| 557 | |
| 558 | .. _profile-calibration: |
| 559 | |
| 560 | Calibration |
| 561 | =========== |
| 562 | |
| 563 | The profiler of the :mod:`profile` module subtracts a constant from each event |
| 564 | handling time to compensate for the overhead of calling the time function, and |
| 565 | socking away the results. By default, the constant is 0. The following |
| 566 | procedure can be used to obtain a better constant for a given platform (see |
Ezio Melotti | 075d87c | 2013-04-12 15:42:06 +0300 | [diff] [blame] | 567 | :ref:`profile-limitations`). :: |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 568 | |
| 569 | import profile |
| 570 | pr = profile.Profile() |
| 571 | for i in range(5): |
Georg Brandl | 6911e3c | 2007-09-04 07:15:32 +0000 | [diff] [blame] | 572 | print(pr.calibrate(10000)) |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 573 | |
| 574 | The method executes the number of Python calls given by the argument, directly |
| 575 | and again under the profiler, measuring the time for both. It then computes the |
| 576 | hidden overhead per profiler event, and returns that as a float. For example, |
Ezio Melotti | 075d87c | 2013-04-12 15:42:06 +0300 | [diff] [blame] | 577 | on a 1.8Ghz Intel Core i5 running Mac OS X, and using Python's time.clock() as |
| 578 | the timer, the magical number is about 4.04e-6. |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 579 | |
| 580 | The object of this exercise is to get a fairly consistent result. If your |
| 581 | computer is *very* fast, or your timer function has poor resolution, you might |
| 582 | have to pass 100000, or even 1000000, to get consistent results. |
| 583 | |
Georg Brandl | e6bcc91 | 2008-05-12 18:05:20 +0000 | [diff] [blame] | 584 | 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] | 585 | |
| 586 | import profile |
| 587 | |
| 588 | # 1. Apply computed bias to all Profile instances created hereafter. |
| 589 | profile.Profile.bias = your_computed_bias |
| 590 | |
| 591 | # 2. Apply computed bias to a specific Profile instance. |
| 592 | pr = profile.Profile() |
| 593 | pr.bias = your_computed_bias |
| 594 | |
| 595 | # 3. Specify computed bias in instance constructor. |
| 596 | pr = profile.Profile(bias=your_computed_bias) |
| 597 | |
| 598 | If you have a choice, you are better off choosing a smaller constant, and then |
| 599 | your results will "less often" show up as negative in profile statistics. |
| 600 | |
Ezio Melotti | 075d87c | 2013-04-12 15:42:06 +0300 | [diff] [blame] | 601 | .. _profile-timers: |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 602 | |
Georg Brandl | c2b17b2 | 2013-10-06 09:17:43 +0200 | [diff] [blame] | 603 | Using a custom timer |
| 604 | ==================== |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 605 | |
Ezio Melotti | 075d87c | 2013-04-12 15:42:06 +0300 | [diff] [blame] | 606 | If you want to change how current time is determined (for example, to force use |
| 607 | of wall-clock time or elapsed process time), pass the timing function you want |
| 608 | to the :class:`Profile` class constructor:: |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 609 | |
Ezio Melotti | 075d87c | 2013-04-12 15:42:06 +0300 | [diff] [blame] | 610 | pr = profile.Profile(your_time_func) |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 611 | |
Ezio Melotti | 075d87c | 2013-04-12 15:42:06 +0300 | [diff] [blame] | 612 | The resulting profiler will then call ``your_time_func``. Depending on whether |
| 613 | you are using :class:`profile.Profile` or :class:`cProfile.Profile`, |
| 614 | ``your_time_func``'s return value will be interpreted differently: |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 615 | |
| 616 | :class:`profile.Profile` |
Ezio Melotti | 075d87c | 2013-04-12 15:42:06 +0300 | [diff] [blame] | 617 | ``your_time_func`` should return a single number, or a list of numbers whose |
| 618 | sum is the current time (like what :func:`os.times` returns). If the |
| 619 | function returns a single time number, or the list of returned numbers has |
| 620 | length 2, then you will get an especially fast version of the dispatch |
| 621 | routine. |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 622 | |
Ezio Melotti | 075d87c | 2013-04-12 15:42:06 +0300 | [diff] [blame] | 623 | Be warned that you should calibrate the profiler class for the timer function |
| 624 | that you choose (see :ref:`profile-calibration`). For most machines, a timer |
| 625 | that returns a lone integer value will provide the best results in terms of |
| 626 | low overhead during profiling. (:func:`os.times` is *pretty* bad, as it |
| 627 | returns a tuple of floating point values). If you want to substitute a |
| 628 | better timer in the cleanest fashion, derive a class and hardwire a |
| 629 | replacement dispatch method that best handles your timer call, along with the |
| 630 | appropriate calibration constant. |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 631 | |
| 632 | :class:`cProfile.Profile` |
Ezio Melotti | 075d87c | 2013-04-12 15:42:06 +0300 | [diff] [blame] | 633 | ``your_time_func`` should return a single number. If it returns integers, |
| 634 | you can also invoke the class constructor with a second argument specifying |
| 635 | the real duration of one unit of time. For example, if |
| 636 | ``your_integer_time_func`` returns times measured in thousands of seconds, |
| 637 | you would construct the :class:`Profile` instance as follows:: |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 638 | |
Ezio Melotti | 075d87c | 2013-04-12 15:42:06 +0300 | [diff] [blame] | 639 | pr = cProfile.Profile(your_integer_time_func, 0.001) |
Georg Brandl | 116aa62 | 2007-08-15 14:28:22 +0000 | [diff] [blame] | 640 | |
Ezio Melotti | 075d87c | 2013-04-12 15:42:06 +0300 | [diff] [blame] | 641 | As the :mod:`cProfile.Profile` class cannot be calibrated, custom timer |
| 642 | functions should be used with care and should be as fast as possible. For |
| 643 | the best results with a custom timer, it might be necessary to hard-code it |
| 644 | in the C source of the internal :mod:`_lsprof` module. |
| 645 | |
| 646 | Python 3.3 adds several new functions in :mod:`time` that can be used to make |
| 647 | precise measurements of process or wall-clock time. For example, see |
| 648 | :func:`time.perf_counter`. |