• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
1.. _profile:
2
3********************
4The Python Profilers
5********************
6
7**Source code:** :source:`Lib/profile.py` and :source:`Lib/pstats.py`
8
9--------------
10
11.. _profiler-introduction:
12
13Introduction 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
21Python programs. A :dfn:`profile` is a set of statistics that describes how
22often and for how long various parts of the program executed. These statistics
23can be formatted into reports via the :mod:`pstats` module.
24
25The Python standard library provides two different implementations of the same
26profiling interface:
27
281. :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
332. :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
50Instant User's Manual
51=====================
52
53This section is provided for users that "don't want to read the manual." It
54provides a very brief overview, and allows a user to rapidly perform profiling
55on an existing application.
56
57To 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
64your system.)
65
66The above action would run :func:`re.compile` and print profile results like
67the 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
82The first line indicates that 197 calls were monitored.  Of those calls, 192
83were :dfn:`primitive`, meaning that the call was not induced via recursion. The
84next line: ``Ordered by: standard name``, indicates that the text string in the
85far right column was used to sort the output. The column headings include:
86
87ncalls
88   for the number of calls,
89
90tottime
91    for the total time spent in the given function (and excluding time made in
92    calls to sub-functions)
93
94percall
95   is the quotient of ``tottime`` divided by ``ncalls``
96
97cumtime
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
101percall
102   is the quotient of ``cumtime`` divided by primitive calls
103
104filename:lineno(function)
105   provides the respective data of each function
106
107When there are two numbers in the first column (for example ``3/1``), it means
108that the function recursed.  The second value is the number of primitive calls
109and the former is the total number of calls.  Note that when the function does
110not recurse, these two values are the same, and only the single figure is
111printed.
112
113Instead of printing the output at the end of the profile run, you can save the
114results 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
120The :class:`pstats.Stats` class reads profile results from a file and formats
121them in various ways.
122
123The file :mod:`cProfile` can also be invoked as a script to profile another
124script.  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
131the output by. This only applies when ``-o`` is not supplied.
132
133The :mod:`pstats` module's :class:`~pstats.Stats` class has a variety of methods
134for 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
140The :meth:`~pstats.Stats.strip_dirs` method removed the extraneous path from all
141the module names. The :meth:`~pstats.Stats.sort_stats` method sorted all the
142entries 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
144might try the following sort calls::
145
146   p.sort_stats('name')
147   p.print_stats()
148
149The first call will actually sort the list by function name, and the second call
150will print out the statistics.  The following are some interesting calls to
151experiment with::
152
153   p.sort_stats('cumulative').print_stats(10)
154
155This sorts the profile by cumulative time in a function, and then only prints
156the ten most significant lines.  If you want to understand what algorithms are
157taking time, the above line is what you would use.
158
159If you were looking to see what functions were looping a lot, and taking a lot
160of time, you would do::
161
162   p.sort_stats('time').print_stats(10)
163
164to sort according to time spent within each function, and then print the
165statistics for the top ten functions.
166
167You might also try::
168
169   p.sort_stats('file').print_stats('__init__')
170
171This will sort all the statistics by file name, and then print out statistics
172for only the class init methods (since they are spelled with ``__init__`` in
173them).  As one final example, you could try::
174
175   p.sort_stats('time', 'cumulative').print_stats(.5, 'init')
176
177This line sorts statistics with a primary key of time, and a secondary key of
178cumulative time, and then prints out some of the statistics. To be specific, the
179list is first culled down to 50% (re: ``.5``) of its original size, then only
180lines containing ``init`` are maintained, and that sub-sub-list is printed.
181
182If you wondered what functions called the above functions, you could now (``p``
183is still sorted according to the last criteria) do::
184
185   p.print_callers(.5, 'init')
186
187and you would get a list of callers for each of the listed functions.
188
189If you want more functionality, you're going to have to read the manual, or
190guess what the following functions do::
191
192   p.print_callees()
193   p.add('restats')
194
195Invoked as a script, the :mod:`pstats` module is a statistics browser for
196reading 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
206Both the :mod:`profile` and :mod:`cProfile` modules provide the following
207functions:
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
295The :class:`Stats` Class
296========================
297
298Analysis 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
494What Is Deterministic Profiling?
495================================
496
497:dfn:`Deterministic profiling` is meant to reflect the fact that all *function
498call*, *function return*, and *exception* events are monitored, and precise
499timings are made for the intervals between these events (during which time the
500user's code is executing).  In contrast, :dfn:`statistical profiling` (which is
501not done by this module) randomly samples the effective instruction pointer, and
502deduces where time is being spent.  The latter technique traditionally involves
503less overhead (as the code does not need to be instrumented), but provides only
504relative indications of where time is being spent.
505
506In Python, since there is an interpreter active during execution, the presence
507of instrumented code is not required to do deterministic profiling.  Python
508automatically provides a :dfn:`hook` (optional callback) for each event.  In
509addition, the interpreted nature of Python tends to add so much overhead to
510execution, that deterministic profiling tends to only add small processing
511overhead in typical applications.  The result is that deterministic profiling is
512not that expensive, yet provides extensive run time statistics about the
513execution of a Python program.
514
515Call count statistics can be used to identify bugs in code (surprising counts),
516and to identify possible inline-expansion points (high call counts).  Internal
517time statistics can be used to identify "hot loops" that should be carefully
518optimized.  Cumulative time statistics should be used to identify high level
519errors in the selection of algorithms.  Note that the unusual handling of
520cumulative times in this profiler allows statistics for recursive
521implementations of algorithms to be directly compared to iterative
522implementations.
523
524
525.. _profile-limitations:
526
527Limitations
528===========
529
530One limitation has to do with accuracy of timing information. There is a
531fundamental problem with deterministic profilers involving accuracy.  The most
532obvious 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
534than the underlying clock.  If enough measurements are taken, then the "error"
535will tend to average out. Unfortunately, removing this first error induces a
536second source of error.
537
538The second problem is that it "takes a while" from when an event is dispatched
539until the profiler's call to get the time actually *gets* the state of the
540clock.  Similarly, there is a certain lag when exiting the profiler event
541handler from the time that the clock's value was obtained (and then squirreled
542away), until the user's code is once again executing.  As a result, functions
543that are called many times, or call many functions, will typically accumulate
544this error. The error that accumulates in this fashion is typically less than
545the accuracy of the clock (less than one clock tick), but it *can* accumulate
546and become very significant.
547
548The problem is more important with :mod:`profile` than with the lower-overhead
549:mod:`cProfile`.  For this reason, :mod:`profile` provides a means of
550calibrating itself for a given platform so that this error can be
551probabilistically (on the average) removed. After the profiler is calibrated, it
552will be more accurate (in a least square sense), but it will sometimes produce
553negative numbers (when call counts are exceptionally low, and the gods of
554probability work against you :-). )  Do *not* be alarmed by negative numbers in
555the profile.  They should *only* appear if you have calibrated your profiler,
556and the results are actually better than without calibration.
557
558
559.. _profile-calibration:
560
561Calibration
562===========
563
564The profiler of the :mod:`profile` module subtracts a constant from each event
565handling time to compensate for the overhead of calling the time function, and
566socking away the results.  By default, the constant is 0. The following
567procedure 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
575The method executes the number of Python calls given by the argument, directly
576and again under the profiler, measuring the time for both. It then computes the
577hidden overhead per profiler event, and returns that as a float.  For example,
578on a 1.8Ghz Intel Core i5 running Mac OS X, and using Python's time.clock() as
579the timer, the magical number is about 4.04e-6.
580
581The object of this exercise is to get a fairly consistent result. If your
582computer is *very* fast, or your timer function has poor resolution, you might
583have to pass 100000, or even 1000000, to get consistent results.
584
585When 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
599If you have a choice, you are better off choosing a smaller constant, and then
600your results will "less often" show up as negative in profile statistics.
601
602.. _profile-timers:
603
604Using a custom timer
605====================
606
607If you want to change how current time is determined (for example, to force use
608of wall-clock time or elapsed process time), pass the timing function you want
609to the :class:`Profile` class constructor::
610
611    pr = profile.Profile(your_time_func)
612
613The resulting profiler will then call ``your_time_func``. Depending on whether
614you 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
647Python 3.3 adds several new functions in :mod:`time` that can be used to make
648precise measurements of process or wall-clock time. For example, see
649:func:`time.perf_counter`.
650