1 .. _profile: 2 3 ******************** 4 The Python Profilers 5 ******************** 6 7 **Source code:** :source:`Lib/profile.py` and :source:`Lib/pstats.py` 8 9 -------------- 10 11 .. _profiler-introduction: 12 13 Introduction to the profilers 14 ============================= 15 16 .. index:: 17 single: deterministic profiling 18 single: profiling, deterministic 19 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. 24 25 The Python standard library provides two different implementations of the same 26 profiling interface: 27 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. 32 33 2. :mod:`profile`, a pure Python module whose interface is imitated by 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. Originally designed and written by Jim Roskind. 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 42 reasonably accurate results). This particularly applies to benchmarking 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. 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 57 To profile a function that takes a single argument, you can do:: 58 59 import cProfile 60 import re 61 cProfile.run('re.compile("foo|bar")') 62 63 (Use :mod:`profile` instead of :mod:`cProfile` if the latter is not available on 64 your system.) 65 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:: 115 116 import cProfile 117 import re 118 cProfile.run('re.compile("foo|bar")', 'restats') 119 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 124 script. For example:: 125 126 python -m cProfile [-o output_file] [-s sort_order] myscript.py 127 128 ``-o`` writes the profile results to a file instead of to stdout 129 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. 132 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:: 135 136 import pstats 137 p = pstats.Stats('restats') 138 p.strip_dirs().sort_stats(-1).print_stats() 139 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:: 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', 'cumulative').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() 193 p.add('restats') 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 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() 250 # ... do something ... 251 pr.disable() 252 s = io.StringIO() 253 sortby = 'cumulative' 254 ps = pstats.Stats(pr, stream=s).sort_stats(sortby) 255 ps.print_stats() 256 print(s.getvalue()) 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 string that will interpreted as a 448 regular expression (to pattern match the standard name that is printed). 449 If several restrictions are provided, then they are applied sequentially. 450 For example:: 451 452 print_stats(.1, 'foo:') 453 454 would first limit the printing to first 10% of list, and then only print 455 functions that were part of filename :file:`.\*foo:`. In contrast, the 456 command:: 457 458 print_stats('foo:', .1) 459 460 would limit the list to all functions having file names :file:`.\*foo:`, 461 and then proceed to only print the first 10% of them. 462 463 464 .. method:: print_callers(*restrictions) 465 466 This method for the :class:`Stats` class prints a list of all functions 467 that called each function in the profiled database. The ordering is 468 identical to that provided by :meth:`~pstats.Stats.print_stats`, and the 469 definition of the restricting argument is also identical. Each caller is 470 reported on its own line. The format differs slightly depending on the 471 profiler that produced the stats: 472 473 * With :mod:`profile`, a number is shown in parentheses after each caller 474 to show how many times this specific call was made. For convenience, a 475 second non-parenthesized number repeats the cumulative time spent in the 476 function at the right. 477 478 * With :mod:`cProfile`, each caller is preceded by three numbers: the 479 number of times this specific call was made, and the total and 480 cumulative times spent in the current function while it was invoked by 481 this specific caller. 482 483 484 .. method:: print_callees(*restrictions) 485 486 This method for the :class:`Stats` class prints a list of all function 487 that were called by the indicated function. Aside from this reversal of 488 direction of calls (re: called vs was called by), the arguments and 489 ordering are identical to the :meth:`~pstats.Stats.print_callers` method. 490 491 492 .. _deterministic-profiling: 493 494 What Is Deterministic Profiling? 495 ================================ 496 497 :dfn:`Deterministic profiling` is meant to reflect the fact that all *function 498 call*, *function return*, and *exception* events are monitored, and precise 499 timings are made for the intervals between these events (during which time the 500 user's code is executing). In contrast, :dfn:`statistical profiling` (which is 501 not done by this module) randomly samples the effective instruction pointer, and 502 deduces where time is being spent. The latter technique traditionally involves 503 less overhead (as the code does not need to be instrumented), but provides only 504 relative indications of where time is being spent. 505 506 In Python, since there is an interpreter active during execution, the presence 507 of instrumented code is not required to do deterministic profiling. Python 508 automatically provides a :dfn:`hook` (optional callback) for each event. In 509 addition, the interpreted nature of Python tends to add so much overhead to 510 execution, that deterministic profiling tends to only add small processing 511 overhead in typical applications. The result is that deterministic profiling is 512 not that expensive, yet provides extensive run time statistics about the 513 execution of a Python program. 514 515 Call count statistics can be used to identify bugs in code (surprising counts), 516 and to identify possible inline-expansion points (high call counts). Internal 517 time statistics can be used to identify "hot loops" that should be carefully 518 optimized. Cumulative time statistics should be used to identify high level 519 errors in the selection of algorithms. Note that the unusual handling of 520 cumulative times in this profiler allows statistics for recursive 521 implementations of algorithms to be directly compared to iterative 522 implementations. 523 524 525 .. _profile-limitations: 526 527 Limitations 528 =========== 529 530 One limitation has to do with accuracy of timing information. There is a 531 fundamental problem with deterministic profilers involving accuracy. The most 532 obvious restriction is that the underlying "clock" is only ticking at a rate 533 (typically) of about .001 seconds. Hence no measurements will be more accurate 534 than the underlying clock. If enough measurements are taken, then the "error" 535 will tend to average out. Unfortunately, removing this first error induces a 536 second source of error. 537 538 The second problem is that it "takes a while" from when an event is dispatched 539 until the profiler's call to get the time actually *gets* the state of the 540 clock. Similarly, there is a certain lag when exiting the profiler event 541 handler from the time that the clock's value was obtained (and then squirreled 542 away), until the user's code is once again executing. As a result, functions 543 that are called many times, or call many functions, will typically accumulate 544 this error. The error that accumulates in this fashion is typically less than 545 the accuracy of the clock (less than one clock tick), but it *can* accumulate 546 and become very significant. 547 548 The problem is more important with :mod:`profile` than with the lower-overhead 549 :mod:`cProfile`. For this reason, :mod:`profile` provides a means of 550 calibrating itself for a given platform so that this error can be 551 probabilistically (on the average) removed. After the profiler is calibrated, it 552 will be more accurate (in a least square sense), but it will sometimes produce 553 negative numbers (when call counts are exceptionally low, and the gods of 554 probability work against you :-). ) Do *not* be alarmed by negative numbers in 555 the profile. They should *only* appear if you have calibrated your profiler, 556 and the results are actually better than without calibration. 557 558 559 .. _profile-calibration: 560 561 Calibration 562 =========== 563 564 The profiler of the :mod:`profile` module subtracts a constant from each event 565 handling time to compensate for the overhead of calling the time function, and 566 socking away the results. By default, the constant is 0. The following 567 procedure can be used to obtain a better constant for a given platform (see 568 :ref:`profile-limitations`). :: 569 570 import profile 571 pr = profile.Profile() 572 for i in range(5): 573 print(pr.calibrate(10000)) 574 575 The method executes the number of Python calls given by the argument, directly 576 and again under the profiler, measuring the time for both. It then computes the 577 hidden overhead per profiler event, and returns that as a float. For example, 578 on a 1.8Ghz Intel Core i5 running Mac OS X, and using Python's time.clock() as 579 the timer, the magical number is about 4.04e-6. 580 581 The object of this exercise is to get a fairly consistent result. If your 582 computer is *very* fast, or your timer function has poor resolution, you might 583 have to pass 100000, or even 1000000, to get consistent results. 584 585 When you have a consistent answer, there are three ways you can use it:: 586 587 import profile 588 589 # 1. Apply computed bias to all Profile instances created hereafter. 590 profile.Profile.bias = your_computed_bias 591 592 # 2. Apply computed bias to a specific Profile instance. 593 pr = profile.Profile() 594 pr.bias = your_computed_bias 595 596 # 3. Specify computed bias in instance constructor. 597 pr = profile.Profile(bias=your_computed_bias) 598 599 If you have a choice, you are better off choosing a smaller constant, and then 600 your results will "less often" show up as negative in profile statistics. 601 602 .. _profile-timers: 603 604 Using a custom timer 605 ==================== 606 607 If you want to change how current time is determined (for example, to force use 608 of wall-clock time or elapsed process time), pass the timing function you want 609 to the :class:`Profile` class constructor:: 610 611 pr = profile.Profile(your_time_func) 612 613 The resulting profiler will then call ``your_time_func``. Depending on whether 614 you are using :class:`profile.Profile` or :class:`cProfile.Profile`, 615 ``your_time_func``'s return value will be interpreted differently: 616 617 :class:`profile.Profile` 618 ``your_time_func`` should return a single number, or a list of numbers whose 619 sum is the current time (like what :func:`os.times` returns). If the 620 function returns a single time number, or the list of returned numbers has 621 length 2, then you will get an especially fast version of the dispatch 622 routine. 623 624 Be warned that you should calibrate the profiler class for the timer function 625 that you choose (see :ref:`profile-calibration`). For most machines, a timer 626 that returns a lone integer value will provide the best results in terms of 627 low overhead during profiling. (:func:`os.times` is *pretty* bad, as it 628 returns a tuple of floating point values). If you want to substitute a 629 better timer in the cleanest fashion, derive a class and hardwire a 630 replacement dispatch method that best handles your timer call, along with the 631 appropriate calibration constant. 632 633 :class:`cProfile.Profile` 634 ``your_time_func`` should return a single number. If it returns integers, 635 you can also invoke the class constructor with a second argument specifying 636 the real duration of one unit of time. For example, if 637 ``your_integer_time_func`` returns times measured in thousands of seconds, 638 you would construct the :class:`Profile` instance as follows:: 639 640 pr = cProfile.Profile(your_integer_time_func, 0.001) 641 642 As the :class:`cProfile.Profile` class cannot be calibrated, custom timer 643 functions should be used with care and should be as fast as possible. For 644 the best results with a custom timer, it might be necessary to hard-code it 645 in the C source of the internal :mod:`_lsprof` module. 646 647 Python 3.3 adds several new functions in :mod:`time` that can be used to make 648 precise measurements of process or wall-clock time. For example, see 649 :func:`time.perf_counter`. 650