blob: 0108b21e5ddb2410fa8c2af57ab6886de5c7974e [file] [log] [blame]
Armin Rigoa871ef22006-02-08 12:53:56 +00001\chapter{The Python Profilers \label{profile}}
Fred Drakeea003fc1999-04-05 21:59:15 +00002
3\sectionauthor{James Roskind}{}
Guido van Rossumdf804f81995-03-02 12:38:39 +00004
Fred Drake4b3f0311996-12-13 22:04:31 +00005Copyright \copyright{} 1994, by InfoSeek Corporation, all rights reserved.
Fred Drake5dabeed1998-04-03 07:02:35 +00006\index{InfoSeek Corporation}
Guido van Rossumdf804f81995-03-02 12:38:39 +00007
Fred Drakeea003fc1999-04-05 21:59:15 +00008Written by James Roskind.\footnote{
Armin Rigoa871ef22006-02-08 12:53:56 +00009 Updated and converted to \LaTeX\ by Guido van Rossum.
10 Further updated by Armin Rigo to integrate the documentation for the new
11 \module{cProfile} module of Python 2.5.}
Guido van Rossumdf804f81995-03-02 12:38:39 +000012
13Permission to use, copy, modify, and distribute this Python software
14and its associated documentation for any purpose (subject to the
15restriction in the following sentence) without fee is hereby granted,
16provided that the above copyright notice appears in all copies, and
17that both that copyright notice and this permission notice appear in
18supporting documentation, and that the name of InfoSeek not be used in
19advertising or publicity pertaining to distribution of the software
20without specific, written prior permission. This permission is
21explicitly restricted to the copying and modification of the software
22to remain in Python, compiled Python, or other languages (such as C)
23wherein the modified or derived code is exclusively imported into a
24Python module.
25
26INFOSEEK CORPORATION DISCLAIMS ALL WARRANTIES WITH REGARD TO THIS
27SOFTWARE, INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY AND
28FITNESS. IN NO EVENT SHALL INFOSEEK CORPORATION BE LIABLE FOR ANY
29SPECIAL, INDIRECT OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER
30RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF
31CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN
32CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.
33
34
35The profiler was written after only programming in Python for 3 weeks.
36As a result, it is probably clumsy code, but I don't know for sure yet
37'cause I'm a beginner :-). I did work hard to make the code run fast,
38so that profiling would be a reasonable thing to do. I tried not to
39repeat code fragments, but I'm sure I did some stuff in really awkward
40ways at times. Please send suggestions for improvements to:
Fred Drake8fa5eb81998-02-27 05:23:37 +000041\email{jar@netscape.com}. I won't promise \emph{any} support. ...but
Guido van Rossumdf804f81995-03-02 12:38:39 +000042I'd appreciate the feedback.
43
44
Armin Rigoa871ef22006-02-08 12:53:56 +000045\section{Introduction to the profilers}
Guido van Rossum86cb0921995-03-20 12:59:56 +000046\nodename{Profiler Introduction}
Guido van Rossumdf804f81995-03-02 12:38:39 +000047
48A \dfn{profiler} is a program that describes the run time performance
49of a program, providing a variety of statistics. This documentation
50describes the profiler functionality provided in the modules
Fred Drake8fa5eb81998-02-27 05:23:37 +000051\module{profile} and \module{pstats}. This profiler provides
Guido van Rossumdf804f81995-03-02 12:38:39 +000052\dfn{deterministic profiling} of any Python programs. It also
53provides a series of report generation tools to allow users to rapidly
54examine the results of a profile operation.
Fred Drake8fa5eb81998-02-27 05:23:37 +000055\index{deterministic profiling}
56\index{profiling, deterministic}
Guido van Rossumdf804f81995-03-02 12:38:39 +000057
Armin Rigoa871ef22006-02-08 12:53:56 +000058The Python standard library provides three different profilers:
59
60\begin{enumerate}
61\item \module{profile}, a pure Python module, described in the sequel.
62 Copyright \copyright{} 1994, by InfoSeek Corporation.
63 \versionchanged[also reports the time spent in calls to built-in
64 functions and methods]{2.4}
65
66\item \module{cProfile}, a module written in C, with a reasonable
67 overhead that makes it suitable for profiling long-running programs.
68 Based on \module{lsprof}, contributed by Brett Rosen and Ted Czotter.
69 \versionadded{2.5}
70
71\item \module{hotshot}, a C module focusing on minimizing the overhead
72 while profiling, at the expense of long data post-processing times.
73 \versionchanged[the results should be more meaningful than in the
74 past: the timing core contained a critical bug]{2.5}
75\end{enumerate}
76
77The \module{profile} and \module{cProfile} modules export the same
78interface, so they are mostly interchangeables; \module{cProfile} has a
79much lower overhead but is not so far as well-tested and might not be
80available on all systems. \module{cProfile} is really a compatibility
81layer on top of the internal \module{_lsprof} module. The
82\module{hotshot} module is reserved to specialized usages.
Guido van Rossumdf804f81995-03-02 12:38:39 +000083
Georg Brandl6c1908d2005-12-26 23:44:29 +000084%\section{How Is This Profiler Different From The Old Profiler?}
85%\nodename{Profiler Changes}
86%
87%(This section is of historical importance only; the old profiler
88%discussed here was last seen in Python 1.1.)
89%
90%The big changes from old profiling module are that you get more
91%information, and you pay less CPU time. It's not a trade-off, it's a
92%trade-up.
93%
94%To be specific:
95%
96%\begin{description}
97%
98%\item[Bugs removed:]
99%Local stack frame is no longer molested, execution time is now charged
100%to correct functions.
101%
102%\item[Accuracy increased:]
103%Profiler execution time is no longer charged to user's code,
104%calibration for platform is supported, file reads are not done \emph{by}
105%profiler \emph{during} profiling (and charged to user's code!).
106%
107%\item[Speed increased:]
108%Overhead CPU cost was reduced by more than a factor of two (perhaps a
109%factor of five), lightweight profiler module is all that must be
110%loaded, and the report generating module (\module{pstats}) is not needed
111%during profiling.
112%
113%\item[Recursive functions support:]
114%Cumulative times in recursive functions are correctly calculated;
115%recursive entries are counted.
116%
117%\item[Large growth in report generating UI:]
118%Distinct profiles runs can be added together forming a comprehensive
119%report; functions that import statistics take arbitrary lists of
120%files; sorting criteria is now based on keywords (instead of 4 integer
121%options); reports shows what functions were profiled as well as what
122%profile file was referenced; output format has been improved.
123%
124%\end{description}
Guido van Rossumdf804f81995-03-02 12:38:39 +0000125
126
Andrew M. Kuchling984bdd72006-04-14 12:07:41 +0000127\section{Instant User's Manual \label{profile-instant}}
Guido van Rossumdf804f81995-03-02 12:38:39 +0000128
129This section is provided for users that ``don't want to read the
130manual.'' It provides a very brief overview, and allows a user to
131rapidly perform profiling on an existing application.
132
Fred Drakefee6f332004-03-23 21:40:07 +0000133To profile an application with a main entry point of \function{foo()},
134you would add the following to your module:
Guido van Rossumdf804f81995-03-02 12:38:39 +0000135
Fred Drake19479911998-02-13 06:58:54 +0000136\begin{verbatim}
Armin Rigoa871ef22006-02-08 12:53:56 +0000137import cProfile
138cProfile.run('foo()')
Fred Drake19479911998-02-13 06:58:54 +0000139\end{verbatim}
Fred Drakeb9f1f6d1999-04-21 21:43:17 +0000140
Armin Rigoa871ef22006-02-08 12:53:56 +0000141(Use \module{profile} instead of \module{cProfile} if the latter is not
142available on your system.)
143
Fred Drakefee6f332004-03-23 21:40:07 +0000144The above action would cause \function{foo()} to be run, and a series of
Guido van Rossumdf804f81995-03-02 12:38:39 +0000145informative lines (the profile) to be printed. The above approach is
146most useful when working with the interpreter. If you would like to
147save the results of a profile into a file for later examination, you
Fred Drake8fa5eb81998-02-27 05:23:37 +0000148can supply a file name as the second argument to the \function{run()}
Guido van Rossumdf804f81995-03-02 12:38:39 +0000149function:
150
Fred Drake19479911998-02-13 06:58:54 +0000151\begin{verbatim}
Armin Rigoa871ef22006-02-08 12:53:56 +0000152import cProfile
153cProfile.run('foo()', 'fooprof')
Fred Drake19479911998-02-13 06:58:54 +0000154\end{verbatim}
Fred Drakeb9f1f6d1999-04-21 21:43:17 +0000155
Armin Rigoa871ef22006-02-08 12:53:56 +0000156The file \file{cProfile.py} can also be invoked as
Guido van Rossumbac80021997-06-02 17:29:12 +0000157a script to profile another script. For example:
Fred Drake8fa5eb81998-02-27 05:23:37 +0000158
159\begin{verbatim}
Armin Rigoa871ef22006-02-08 12:53:56 +0000160python -m cProfile myscript.py
Fred Drake8fa5eb81998-02-27 05:23:37 +0000161\end{verbatim}
Guido van Rossumbac80021997-06-02 17:29:12 +0000162
Armin Rigoa871ef22006-02-08 12:53:56 +0000163\file{cProfile.py} accepts two optional arguments on the command line:
Nicholas Bastin824b1b22004-03-23 18:44:39 +0000164
165\begin{verbatim}
Armin Rigoa871ef22006-02-08 12:53:56 +0000166cProfile.py [-o output_file] [-s sort_order]
Nicholas Bastin824b1b22004-03-23 18:44:39 +0000167\end{verbatim}
168
Fred Drakefee6f332004-03-23 21:40:07 +0000169\programopt{-s} only applies to standard output (\programopt{-o} is
170not supplied). Look in the \class{Stats} documentation for valid sort
171values.
Nicholas Bastin824b1b22004-03-23 18:44:39 +0000172
Guido van Rossumdf804f81995-03-02 12:38:39 +0000173When you wish to review the profile, you should use the methods in the
Fred Drake8fa5eb81998-02-27 05:23:37 +0000174\module{pstats} module. Typically you would load the statistics data as
Guido van Rossumdf804f81995-03-02 12:38:39 +0000175follows:
176
Fred Drake19479911998-02-13 06:58:54 +0000177\begin{verbatim}
Guido van Rossume47da0a1997-07-17 16:34:52 +0000178import pstats
179p = pstats.Stats('fooprof')
Fred Drake19479911998-02-13 06:58:54 +0000180\end{verbatim}
Fred Drakeb9f1f6d1999-04-21 21:43:17 +0000181
Fred Drake8fa5eb81998-02-27 05:23:37 +0000182The class \class{Stats} (the above code just created an instance of
Guido van Rossumdf804f81995-03-02 12:38:39 +0000183this class) has a variety of methods for manipulating and printing the
Fred Drakefee6f332004-03-23 21:40:07 +0000184data that was just read into \code{p}. When you ran
Armin Rigoa871ef22006-02-08 12:53:56 +0000185\function{cProfile.run()} above, what was printed was the result of three
Guido van Rossumdf804f81995-03-02 12:38:39 +0000186method calls:
187
Fred Drake19479911998-02-13 06:58:54 +0000188\begin{verbatim}
Guido van Rossume47da0a1997-07-17 16:34:52 +0000189p.strip_dirs().sort_stats(-1).print_stats()
Fred Drake19479911998-02-13 06:58:54 +0000190\end{verbatim}
Fred Drakeb9f1f6d1999-04-21 21:43:17 +0000191
Guido van Rossumdf804f81995-03-02 12:38:39 +0000192The first method removed the extraneous path from all the module
193names. The second method sorted all the entries according to the
Armin Rigoa871ef22006-02-08 12:53:56 +0000194standard module/line/name string that is printed.
195%(this is to comply with the semantics of the old profiler).
196The third method printed out
Guido van Rossumdf804f81995-03-02 12:38:39 +0000197all the statistics. You might try the following sort calls:
198
Fred Drake19479911998-02-13 06:58:54 +0000199\begin{verbatim}
Guido van Rossume47da0a1997-07-17 16:34:52 +0000200p.sort_stats('name')
201p.print_stats()
Fred Drake19479911998-02-13 06:58:54 +0000202\end{verbatim}
Fred Drakeb9f1f6d1999-04-21 21:43:17 +0000203
Guido van Rossumdf804f81995-03-02 12:38:39 +0000204The first call will actually sort the list by function name, and the
205second call will print out the statistics. The following are some
206interesting calls to experiment with:
207
Fred Drake19479911998-02-13 06:58:54 +0000208\begin{verbatim}
Guido van Rossume47da0a1997-07-17 16:34:52 +0000209p.sort_stats('cumulative').print_stats(10)
Fred Drake19479911998-02-13 06:58:54 +0000210\end{verbatim}
Fred Drakeb9f1f6d1999-04-21 21:43:17 +0000211
Guido van Rossumdf804f81995-03-02 12:38:39 +0000212This sorts the profile by cumulative time in a function, and then only
213prints the ten most significant lines. If you want to understand what
214algorithms are taking time, the above line is what you would use.
215
216If you were looking to see what functions were looping a lot, and
217taking a lot of time, you would do:
218
Fred Drake19479911998-02-13 06:58:54 +0000219\begin{verbatim}
Guido van Rossume47da0a1997-07-17 16:34:52 +0000220p.sort_stats('time').print_stats(10)
Fred Drake19479911998-02-13 06:58:54 +0000221\end{verbatim}
Fred Drakeb9f1f6d1999-04-21 21:43:17 +0000222
Guido van Rossumdf804f81995-03-02 12:38:39 +0000223to sort according to time spent within each function, and then print
224the statistics for the top ten functions.
225
226You might also try:
227
Fred Drake19479911998-02-13 06:58:54 +0000228\begin{verbatim}
Guido van Rossume47da0a1997-07-17 16:34:52 +0000229p.sort_stats('file').print_stats('__init__')
Fred Drake19479911998-02-13 06:58:54 +0000230\end{verbatim}
Fred Drakeb9f1f6d1999-04-21 21:43:17 +0000231
Guido van Rossumdf804f81995-03-02 12:38:39 +0000232This will sort all the statistics by file name, and then print out
Fred Drakefee6f332004-03-23 21:40:07 +0000233statistics for only the class init methods (since they are spelled
234with \code{__init__} in them). As one final example, you could try:
Guido van Rossumdf804f81995-03-02 12:38:39 +0000235
Fred Drake19479911998-02-13 06:58:54 +0000236\begin{verbatim}
Guido van Rossume47da0a1997-07-17 16:34:52 +0000237p.sort_stats('time', 'cum').print_stats(.5, 'init')
Fred Drake19479911998-02-13 06:58:54 +0000238\end{verbatim}
Fred Drakeb9f1f6d1999-04-21 21:43:17 +0000239
Guido van Rossumdf804f81995-03-02 12:38:39 +0000240This line sorts statistics with a primary key of time, and a secondary
241key of cumulative time, and then prints out some of the statistics.
242To be specific, the list is first culled down to 50\% (re: \samp{.5})
243of its original size, then only lines containing \code{init} are
244maintained, and that sub-sub-list is printed.
245
246If you wondered what functions called the above functions, you could
Fred Drakefee6f332004-03-23 21:40:07 +0000247now (\code{p} is still sorted according to the last criteria) do:
Guido van Rossumdf804f81995-03-02 12:38:39 +0000248
Fred Drake19479911998-02-13 06:58:54 +0000249\begin{verbatim}
Guido van Rossume47da0a1997-07-17 16:34:52 +0000250p.print_callers(.5, 'init')
Fred Drake19479911998-02-13 06:58:54 +0000251\end{verbatim}
Fred Drake8fa5eb81998-02-27 05:23:37 +0000252
Tim Peters0a1fc4e2001-10-07 03:12:08 +0000253and you would get a list of callers for each of the listed functions.
Guido van Rossumdf804f81995-03-02 12:38:39 +0000254
255If you want more functionality, you're going to have to read the
256manual, or guess what the following functions do:
257
Fred Drake19479911998-02-13 06:58:54 +0000258\begin{verbatim}
Guido van Rossume47da0a1997-07-17 16:34:52 +0000259p.print_callees()
260p.add('fooprof')
Fred Drake19479911998-02-13 06:58:54 +0000261\end{verbatim}
Fred Drakeb9f1f6d1999-04-21 21:43:17 +0000262
Eric S. Raymond4f3980d2001-04-13 00:23:01 +0000263Invoked as a script, the \module{pstats} module is a statistics
264browser for reading and examining profile dumps. It has a simple
Fred Drakea3e56a62001-04-13 14:34:58 +0000265line-oriented interface (implemented using \refmodule{cmd}) and
Eric S. Raymond4f3980d2001-04-13 00:23:01 +0000266interactive help.
267
Guido van Rossumdf804f81995-03-02 12:38:39 +0000268\section{What Is Deterministic Profiling?}
Guido van Rossum86cb0921995-03-20 12:59:56 +0000269\nodename{Deterministic Profiling}
Guido van Rossumdf804f81995-03-02 12:38:39 +0000270
271\dfn{Deterministic profiling} is meant to reflect the fact that all
Fred Drakea3e56a62001-04-13 14:34:58 +0000272\emph{function call}, \emph{function return}, and \emph{exception} events
Guido van Rossumdf804f81995-03-02 12:38:39 +0000273are monitored, and precise timings are made for the intervals between
274these events (during which time the user's code is executing). In
275contrast, \dfn{statistical profiling} (which is not done by this
276module) randomly samples the effective instruction pointer, and
277deduces where time is being spent. The latter technique traditionally
278involves less overhead (as the code does not need to be instrumented),
279but provides only relative indications of where time is being spent.
280
281In Python, since there is an interpreter active during execution, the
282presence of instrumented code is not required to do deterministic
283profiling. Python automatically provides a \dfn{hook} (optional
284callback) for each event. In addition, the interpreted nature of
285Python tends to add so much overhead to execution, that deterministic
286profiling tends to only add small processing overhead in typical
287applications. The result is that deterministic profiling is not that
288expensive, yet provides extensive run time statistics about the
289execution of a Python program.
290
291Call count statistics can be used to identify bugs in code (surprising
292counts), and to identify possible inline-expansion points (high call
293counts). Internal time statistics can be used to identify ``hot
294loops'' that should be carefully optimized. Cumulative time
295statistics should be used to identify high level errors in the
296selection of algorithms. Note that the unusual handling of cumulative
297times in this profiler allows statistics for recursive implementations
298of algorithms to be directly compared to iterative implementations.
299
300
Armin Rigoa871ef22006-02-08 12:53:56 +0000301\section{Reference Manual -- \module{profile} and \module{cProfile}}
Fred Drakeb91e9341998-07-23 17:59:49 +0000302
Fred Drakeb9f1f6d1999-04-21 21:43:17 +0000303\declaremodule{standard}{profile}
Armin Rigoa871ef22006-02-08 12:53:56 +0000304\declaremodule{standard}{cProfile}
Fred Drakeb9f1f6d1999-04-21 21:43:17 +0000305\modulesynopsis{Python profiler}
Fred Drakeb91e9341998-07-23 17:59:49 +0000306
Guido van Rossumdf804f81995-03-02 12:38:39 +0000307
Guido van Rossumdf804f81995-03-02 12:38:39 +0000308
309The primary entry point for the profiler is the global function
Armin Rigoa871ef22006-02-08 12:53:56 +0000310\function{profile.run()} (resp. \function{cProfile.run()}).
311It is typically used to create any profile
Guido van Rossumdf804f81995-03-02 12:38:39 +0000312information. The reports are formatted and printed using methods of
Fred Drake8fa5eb81998-02-27 05:23:37 +0000313the class \class{pstats.Stats}. The following is a description of all
Guido van Rossumdf804f81995-03-02 12:38:39 +0000314of these standard entry points and functions. For a more in-depth
315view of some of the code, consider reading the later section on
316Profiler Extensions, which includes discussion of how to derive
317``better'' profilers from the classes presented, or reading the source
318code for these modules.
319
Nicholas Bastin1eb4bfc2004-03-22 20:12:56 +0000320\begin{funcdesc}{run}{command\optional{, filename}}
Guido van Rossumdf804f81995-03-02 12:38:39 +0000321
322This function takes a single argument that has can be passed to the
Fred Drake8fa5eb81998-02-27 05:23:37 +0000323\keyword{exec} statement, and an optional file name. In all cases this
324routine attempts to \keyword{exec} its first argument, and gather profiling
Guido van Rossumdf804f81995-03-02 12:38:39 +0000325statistics from the execution. If no file name is present, then this
326function automatically prints a simple profiling report, sorted by the
327standard name string (file/line/function-name) that is presented in
328each line. The following is a typical output from such a call:
329
Fred Drake19479911998-02-13 06:58:54 +0000330\begin{verbatim}
Guido van Rossum96628a91995-04-10 11:34:00 +0000331 2706 function calls (2004 primitive calls) in 4.504 CPU seconds
Guido van Rossumdf804f81995-03-02 12:38:39 +0000332
Guido van Rossum96628a91995-04-10 11:34:00 +0000333Ordered by: standard name
Guido van Rossumdf804f81995-03-02 12:38:39 +0000334
Guido van Rossum96628a91995-04-10 11:34:00 +0000335ncalls tottime percall cumtime percall filename:lineno(function)
336 2 0.006 0.003 0.953 0.477 pobject.py:75(save_objects)
337 43/3 0.533 0.012 0.749 0.250 pobject.py:99(evaluate)
338 ...
Fred Drake19479911998-02-13 06:58:54 +0000339\end{verbatim}
Guido van Rossumdf804f81995-03-02 12:38:39 +0000340
Armin Rigoa871ef22006-02-08 12:53:56 +0000341The first line indicates that 2706 calls were
Guido van Rossumdf804f81995-03-02 12:38:39 +0000342monitored. Of those calls, 2004 were \dfn{primitive}. We define
343\dfn{primitive} to mean that the call was not induced via recursion.
344The next line: \code{Ordered by:\ standard name}, indicates that
345the text string in the far right column was used to sort the output.
346The column headings include:
347
348\begin{description}
349
350\item[ncalls ]
Tim Peters0a1fc4e2001-10-07 03:12:08 +0000351for the number of calls,
Guido van Rossumdf804f81995-03-02 12:38:39 +0000352
353\item[tottime ]
354for the total time spent in the given function (and excluding time
355made in calls to sub-functions),
356
357\item[percall ]
358is the quotient of \code{tottime} divided by \code{ncalls}
359
360\item[cumtime ]
Fred Drake907e76b2001-07-06 20:30:11 +0000361is the total time spent in this and all subfunctions (from invocation
362till exit). This figure is accurate \emph{even} for recursive
Guido van Rossumdf804f81995-03-02 12:38:39 +0000363functions.
364
365\item[percall ]
366is the quotient of \code{cumtime} divided by primitive calls
367
368\item[filename:lineno(function) ]
369provides the respective data of each function
370
371\end{description}
372
Fred Drake907e76b2001-07-06 20:30:11 +0000373When there are two numbers in the first column (for example,
374\samp{43/3}), then the latter is the number of primitive calls, and
375the former is the actual number of calls. Note that when the function
376does not recurse, these two values are the same, and only the single
377figure is printed.
Guido van Rossum96628a91995-04-10 11:34:00 +0000378
Guido van Rossumdf804f81995-03-02 12:38:39 +0000379\end{funcdesc}
380
Nicholas Bastin1eb4bfc2004-03-22 20:12:56 +0000381\begin{funcdesc}{runctx}{command, globals, locals\optional{, filename}}
Armin Rigoa871ef22006-02-08 12:53:56 +0000382This function is similar to \function{run()}, with added
Nicholas Bastin1eb4bfc2004-03-22 20:12:56 +0000383arguments to supply the globals and locals dictionaries for the
384\var{command} string.
385\end{funcdesc}
386
Georg Brandle7d95392006-05-10 15:59:06 +0000387Analysis of the profiler data is done using the \class{Stats} class.
388
389\note{The \class{Stats} class is defined in the \module{pstats} module.}
Fred Drake8fa5eb81998-02-27 05:23:37 +0000390
Fred Drake8fe533e1998-03-27 05:27:08 +0000391% now switch modules....
Fred Drakeb9f1f6d1999-04-21 21:43:17 +0000392% (This \stmodindex use may be hard to change ;-( )
Fred Drake8fe533e1998-03-27 05:27:08 +0000393\stmodindex{pstats}
Fred Drake8fa5eb81998-02-27 05:23:37 +0000394
George Yoshida51a23fe2006-04-22 15:27:14 +0000395\begin{classdesc}{Stats}{filename\optional{, stream=sys.stdout\optional{, \moreargs}}}
Guido van Rossumdf804f81995-03-02 12:38:39 +0000396This class constructor creates an instance of a ``statistics object''
Fred Drake8fa5eb81998-02-27 05:23:37 +0000397from a \var{filename} (or set of filenames). \class{Stats} objects are
Skip Montanaro262fb922006-04-21 02:31:07 +0000398manipulated by methods, in order to print useful reports. You may specify
399an alternate output stream by giving the keyword argument, \code{stream}.
Guido van Rossumdf804f81995-03-02 12:38:39 +0000400
Skip Montanaro262fb922006-04-21 02:31:07 +0000401The file selected by the above constructor must have been created by the
402corresponding version of \module{profile} or \module{cProfile}. To be
403specific, there is \emph{no} file compatibility guaranteed with future
404versions of this profiler, and there is no compatibility with files produced
405by other profilers.
Armin Rigoa871ef22006-02-08 12:53:56 +0000406%(such as the old system profiler).
Guido van Rossumdf804f81995-03-02 12:38:39 +0000407
408If several files are provided, all the statistics for identical
409functions will be coalesced, so that an overall view of several
410processes can be considered in a single report. If additional files
Fred Drake8fa5eb81998-02-27 05:23:37 +0000411need to be combined with data in an existing \class{Stats} object, the
412\method{add()} method can be used.
George Yoshida51a23fe2006-04-22 15:27:14 +0000413
414\versionchanged[The \var{stream} parameter was added]{2.5}
Fred Drake8fa5eb81998-02-27 05:23:37 +0000415\end{classdesc}
Guido van Rossumdf804f81995-03-02 12:38:39 +0000416
417
Fred Drakeb9f1f6d1999-04-21 21:43:17 +0000418\subsection{The \class{Stats} Class \label{profile-stats}}
Guido van Rossumdf804f81995-03-02 12:38:39 +0000419
Fred Drakeb9f1f6d1999-04-21 21:43:17 +0000420\class{Stats} objects have the following methods:
Guido van Rossumdf804f81995-03-02 12:38:39 +0000421
Fred Drakeb9f1f6d1999-04-21 21:43:17 +0000422\begin{methoddesc}[Stats]{strip_dirs}{}
Fred Drake8fa5eb81998-02-27 05:23:37 +0000423This method for the \class{Stats} class removes all leading path
424information from file names. It is very useful in reducing the size
425of the printout to fit within (close to) 80 columns. This method
426modifies the object, and the stripped information is lost. After
427performing a strip operation, the object is considered to have its
428entries in a ``random'' order, as it was just after object
429initialization and loading. If \method{strip_dirs()} causes two
Fred Drake907e76b2001-07-06 20:30:11 +0000430function names to be indistinguishable (they are on the same
Fred Drake8fa5eb81998-02-27 05:23:37 +0000431line of the same filename, and have the same function name), then the
432statistics for these two entries are accumulated into a single entry.
Fred Drake8fe533e1998-03-27 05:27:08 +0000433\end{methoddesc}
Guido van Rossumdf804f81995-03-02 12:38:39 +0000434
435
Fred Drakee05c3e02004-03-23 20:30:59 +0000436\begin{methoddesc}[Stats]{add}{filename\optional{, \moreargs}}
Fred Drake8fa5eb81998-02-27 05:23:37 +0000437This method of the \class{Stats} class accumulates additional
438profiling information into the current profiling object. Its
439arguments should refer to filenames created by the corresponding
Armin Rigoa871ef22006-02-08 12:53:56 +0000440version of \function{profile.run()} or \function{cProfile.run()}.
441Statistics for identically named
Fred Drake8fa5eb81998-02-27 05:23:37 +0000442(re: file, line, name) functions are automatically accumulated into
443single function statistics.
Fred Drake8fe533e1998-03-27 05:27:08 +0000444\end{methoddesc}
Guido van Rossumdf804f81995-03-02 12:38:39 +0000445
Fred Drake126d3662003-05-14 14:29:27 +0000446\begin{methoddesc}[Stats]{dump_stats}{filename}
447Save the data loaded into the \class{Stats} object to a file named
448\var{filename}. The file is created if it does not exist, and is
449overwritten if it already exists. This is equivalent to the method of
Armin Rigoa871ef22006-02-08 12:53:56 +0000450the same name on the \class{profile.Profile} and
451\class{cProfile.Profile} classes.
Fred Drake126d3662003-05-14 14:29:27 +0000452\versionadded{2.3}
453\end{methoddesc}
454
Fred Drakee05c3e02004-03-23 20:30:59 +0000455\begin{methoddesc}[Stats]{sort_stats}{key\optional{, \moreargs}}
Fred Drake8fa5eb81998-02-27 05:23:37 +0000456This method modifies the \class{Stats} object by sorting it according
457to the supplied criteria. The argument is typically a string
Fred Drake2cb824c1998-04-09 18:10:35 +0000458identifying the basis of a sort (example: \code{'time'} or
459\code{'name'}).
Guido van Rossumdf804f81995-03-02 12:38:39 +0000460
461When more than one key is provided, then additional keys are used as
Walter Dörwaldf0dfc7a2003-10-20 14:01:56 +0000462secondary criteria when there is equality in all keys selected
Fred Drakefee6f332004-03-23 21:40:07 +0000463before them. For example, \code{sort_stats('name', 'file')} will sort
Fred Drake8fa5eb81998-02-27 05:23:37 +0000464all the entries according to their function name, and resolve all ties
Guido van Rossumdf804f81995-03-02 12:38:39 +0000465(identical function names) by sorting by file name.
466
467Abbreviations can be used for any key names, as long as the
468abbreviation is unambiguous. The following are the keys currently
Tim Peters0a1fc4e2001-10-07 03:12:08 +0000469defined:
Guido van Rossumdf804f81995-03-02 12:38:39 +0000470
Fred Drakeee601911998-04-11 20:53:03 +0000471\begin{tableii}{l|l}{code}{Valid Arg}{Meaning}
Fred Drake5dabeed1998-04-03 07:02:35 +0000472 \lineii{'calls'}{call count}
473 \lineii{'cumulative'}{cumulative time}
474 \lineii{'file'}{file name}
475 \lineii{'module'}{file name}
476 \lineii{'pcalls'}{primitive call count}
477 \lineii{'line'}{line number}
478 \lineii{'name'}{function name}
479 \lineii{'nfl'}{name/file/line}
480 \lineii{'stdname'}{standard name}
481 \lineii{'time'}{internal time}
Guido van Rossumdf804f81995-03-02 12:38:39 +0000482\end{tableii}
483
484Note that all sorts on statistics are in descending order (placing
485most time consuming items first), where as name, file, and line number
Fred Drake907e76b2001-07-06 20:30:11 +0000486searches are in ascending order (alphabetical). The subtle
Fred Drake2cb824c1998-04-09 18:10:35 +0000487distinction between \code{'nfl'} and \code{'stdname'} is that the
Guido van Rossumdf804f81995-03-02 12:38:39 +0000488standard name is a sort of the name as printed, which means that the
489embedded line numbers get compared in an odd way. For example, lines
4903, 20, and 40 would (if the file names were the same) appear in the
Fred Drake2cb824c1998-04-09 18:10:35 +0000491string order 20, 3 and 40. In contrast, \code{'nfl'} does a numeric
492compare of the line numbers. In fact, \code{sort_stats('nfl')} is the
493same as \code{sort_stats('name', 'file', 'line')}.
Guido van Rossumdf804f81995-03-02 12:38:39 +0000494
Armin Rigoa871ef22006-02-08 12:53:56 +0000495%For compatibility with the old profiler,
496For backward-compatibility reasons, the numeric arguments
Fred Drake2cb824c1998-04-09 18:10:35 +0000497\code{-1}, \code{0}, \code{1}, and \code{2} are permitted. They are
498interpreted as \code{'stdname'}, \code{'calls'}, \code{'time'}, and
499\code{'cumulative'} respectively. If this old style format (numeric)
Guido van Rossumdf804f81995-03-02 12:38:39 +0000500is used, only one sort key (the numeric key) will be used, and
501additional arguments will be silently ignored.
Fred Drake8fe533e1998-03-27 05:27:08 +0000502\end{methoddesc}
Guido van Rossumdf804f81995-03-02 12:38:39 +0000503
504
Fred Drakeb9f1f6d1999-04-21 21:43:17 +0000505\begin{methoddesc}[Stats]{reverse_order}{}
Fred Drake8fa5eb81998-02-27 05:23:37 +0000506This method for the \class{Stats} class reverses the ordering of the basic
Armin Rigoa871ef22006-02-08 12:53:56 +0000507list within the object. %This method is provided primarily for
508%compatibility with the old profiler.
509Note that by default ascending vs descending order is properly selected
510based on the sort key of choice.
Fred Drake8fe533e1998-03-27 05:27:08 +0000511\end{methoddesc}
Guido van Rossumdf804f81995-03-02 12:38:39 +0000512
Fred Drake20006b22001-07-02 21:22:39 +0000513\begin{methoddesc}[Stats]{print_stats}{\optional{restriction, \moreargs}}
Fred Drake8fa5eb81998-02-27 05:23:37 +0000514This method for the \class{Stats} class prints out a report as described
515in the \function{profile.run()} definition.
Guido van Rossumdf804f81995-03-02 12:38:39 +0000516
Fred Drake8fa5eb81998-02-27 05:23:37 +0000517The order of the printing is based on the last \method{sort_stats()}
518operation done on the object (subject to caveats in \method{add()} and
Raymond Hettinger0e53d232003-07-14 18:24:26 +0000519\method{strip_dirs()}).
Guido van Rossumdf804f81995-03-02 12:38:39 +0000520
521The arguments provided (if any) can be used to limit the list down to
522the significant entries. Initially, the list is taken to be the
523complete set of profiled functions. Each restriction is either an
524integer (to select a count of lines), or a decimal fraction between
5250.0 and 1.0 inclusive (to select a percentage of lines), or a regular
Guido van Rossum364e6431997-11-18 15:28:46 +0000526expression (to pattern match the standard name that is printed; as of
527Python 1.5b1, this uses the Perl-style regular expression syntax
Fred Drakeffbe6871999-04-22 21:23:22 +0000528defined by the \refmodule{re} module). If several restrictions are
Guido van Rossum364e6431997-11-18 15:28:46 +0000529provided, then they are applied sequentially. For example:
Guido van Rossumdf804f81995-03-02 12:38:39 +0000530
Fred Drake19479911998-02-13 06:58:54 +0000531\begin{verbatim}
Fred Drake2cb824c1998-04-09 18:10:35 +0000532print_stats(.1, 'foo:')
Fred Drake19479911998-02-13 06:58:54 +0000533\end{verbatim}
Fred Drake8fa5eb81998-02-27 05:23:37 +0000534
Guido van Rossumdf804f81995-03-02 12:38:39 +0000535would first limit the printing to first 10\% of list, and then only
Fred Drakefee6f332004-03-23 21:40:07 +0000536print functions that were part of filename \file{.*foo:}. In
Guido van Rossumdf804f81995-03-02 12:38:39 +0000537contrast, the command:
538
Fred Drake19479911998-02-13 06:58:54 +0000539\begin{verbatim}
Fred Drake2cb824c1998-04-09 18:10:35 +0000540print_stats('foo:', .1)
Fred Drake19479911998-02-13 06:58:54 +0000541\end{verbatim}
Fred Drake8fa5eb81998-02-27 05:23:37 +0000542
Fred Drakefee6f332004-03-23 21:40:07 +0000543would limit the list to all functions having file names \file{.*foo:},
Guido van Rossumdf804f81995-03-02 12:38:39 +0000544and then proceed to only print the first 10\% of them.
Fred Drake8fe533e1998-03-27 05:27:08 +0000545\end{methoddesc}
Guido van Rossumdf804f81995-03-02 12:38:39 +0000546
547
Fred Drake20006b22001-07-02 21:22:39 +0000548\begin{methoddesc}[Stats]{print_callers}{\optional{restriction, \moreargs}}
Fred Drake8fa5eb81998-02-27 05:23:37 +0000549This method for the \class{Stats} class prints a list of all functions
Guido van Rossumdf804f81995-03-02 12:38:39 +0000550that called each function in the profiled database. The ordering is
Fred Drake8fa5eb81998-02-27 05:23:37 +0000551identical to that provided by \method{print_stats()}, and the definition
Armin Rigoa871ef22006-02-08 12:53:56 +0000552of the restricting argument is also identical. Each caller is reported on
553its own line. The format differs slightly depending on the profiler that
554produced the stats:
555
556\begin{itemize}
557\item With \module{profile}, a number is shown in parentheses after each
558 caller to show how many times this specific call was made. For
559 convenience, a second non-parenthesized number repeats the cumulative
560 time spent in the function at the right.
561
562\item With \module{cProfile}, each caller is preceeded by three numbers:
563 the number of times this specific call was made, and the total and
564 cumulative times spent in the current function while it was invoked by
565 this specific caller.
566\end{itemize}
Fred Drake8fe533e1998-03-27 05:27:08 +0000567\end{methoddesc}
Guido van Rossumdf804f81995-03-02 12:38:39 +0000568
Fred Drake20006b22001-07-02 21:22:39 +0000569\begin{methoddesc}[Stats]{print_callees}{\optional{restriction, \moreargs}}
Fred Drake8fa5eb81998-02-27 05:23:37 +0000570This method for the \class{Stats} class prints a list of all function
Guido van Rossumdf804f81995-03-02 12:38:39 +0000571that were called by the indicated function. Aside from this reversal
572of direction of calls (re: called vs was called by), the arguments and
Fred Drake8fa5eb81998-02-27 05:23:37 +0000573ordering are identical to the \method{print_callers()} method.
Fred Drake8fe533e1998-03-27 05:27:08 +0000574\end{methoddesc}
Guido van Rossumdf804f81995-03-02 12:38:39 +0000575
Guido van Rossumdf804f81995-03-02 12:38:39 +0000576
Fred Drakeb9f1f6d1999-04-21 21:43:17 +0000577\section{Limitations \label{profile-limits}}
Guido van Rossumdf804f81995-03-02 12:38:39 +0000578
Raymond Hettingerda264122004-12-19 20:31:46 +0000579One limitation has to do with accuracy of timing information.
Guido van Rossumdf804f81995-03-02 12:38:39 +0000580There is a fundamental problem with deterministic profilers involving
581accuracy. The most obvious restriction is that the underlying ``clock''
582is only ticking at a rate (typically) of about .001 seconds. Hence no
Raymond Hettinger999b57c2003-08-25 04:28:05 +0000583measurements will be more accurate than the underlying clock. If
Guido van Rossumdf804f81995-03-02 12:38:39 +0000584enough measurements are taken, then the ``error'' will tend to average
585out. Unfortunately, removing this first error induces a second source
Fred Drakee05c3e02004-03-23 20:30:59 +0000586of error.
Guido van Rossumdf804f81995-03-02 12:38:39 +0000587
588The second problem is that it ``takes a while'' from when an event is
589dispatched until the profiler's call to get the time actually
590\emph{gets} the state of the clock. Similarly, there is a certain lag
591when exiting the profiler event handler from the time that the clock's
592value was obtained (and then squirreled away), until the user's code
593is once again executing. As a result, functions that are called many
594times, or call many functions, will typically accumulate this error.
595The error that accumulates in this fashion is typically less than the
Fred Drake907e76b2001-07-06 20:30:11 +0000596accuracy of the clock (less than one clock tick), but it
Armin Rigoa871ef22006-02-08 12:53:56 +0000597\emph{can} accumulate and become very significant.
598
599The problem is more important with \module{profile} than with the
600lower-overhead \module{cProfile}. For this reason, \module{profile}
Guido van Rossumdf804f81995-03-02 12:38:39 +0000601provides a means of calibrating itself for a given platform so that
Fred Drake907e76b2001-07-06 20:30:11 +0000602this error can be probabilistically (on the average) removed.
Guido van Rossumdf804f81995-03-02 12:38:39 +0000603After the profiler is calibrated, it will be more accurate (in a least
604square sense), but it will sometimes produce negative numbers (when
605call counts are exceptionally low, and the gods of probability work
Fred Drakeb9f1f6d1999-04-21 21:43:17 +0000606against you :-). ) Do \emph{not} be alarmed by negative numbers in
Guido van Rossumdf804f81995-03-02 12:38:39 +0000607the profile. They should \emph{only} appear if you have calibrated
608your profiler, and the results are actually better than without
609calibration.
610
611
Fred Drakeb9f1f6d1999-04-21 21:43:17 +0000612\section{Calibration \label{profile-calibration}}
Guido van Rossumdf804f81995-03-02 12:38:39 +0000613
Armin Rigoa871ef22006-02-08 12:53:56 +0000614The profiler of the \module{profile} module subtracts a constant from each
Guido van Rossumdf804f81995-03-02 12:38:39 +0000615event handling time to compensate for the overhead of calling the time
Tim Peters659a6032001-10-09 20:51:19 +0000616function, and socking away the results. By default, the constant is 0.
617The following procedure can
618be used to obtain a better constant for a given platform (see discussion
Guido van Rossumdf804f81995-03-02 12:38:39 +0000619in section Limitations above).
620
Fred Drake19479911998-02-13 06:58:54 +0000621\begin{verbatim}
Guido van Rossume47da0a1997-07-17 16:34:52 +0000622import profile
623pr = profile.Profile()
Tim Peters659a6032001-10-09 20:51:19 +0000624for i in range(5):
625 print pr.calibrate(10000)
Fred Drake19479911998-02-13 06:58:54 +0000626\end{verbatim}
Fred Drake8fa5eb81998-02-27 05:23:37 +0000627
Tim Peters659a6032001-10-09 20:51:19 +0000628The method executes the number of Python calls given by the argument,
629directly and again under the profiler, measuring the time for both.
630It then computes the hidden overhead per profiler event, and returns
631that as a float. For example, on an 800 MHz Pentium running
632Windows 2000, and using Python's time.clock() as the timer,
633the magical number is about 12.5e-6.
Fred Drake8fa5eb81998-02-27 05:23:37 +0000634
Guido van Rossumdf804f81995-03-02 12:38:39 +0000635The object of this exercise is to get a fairly consistent result.
Tim Peters659a6032001-10-09 20:51:19 +0000636If your computer is \emph{very} fast, or your timer function has poor
637resolution, you might have to pass 100000, or even 1000000, to get
638consistent results.
Guido van Rossumdf804f81995-03-02 12:38:39 +0000639
Tim Peters659a6032001-10-09 20:51:19 +0000640When you have a consistent answer,
641there are three ways you can use it:\footnote{Prior to Python 2.2, it
642 was necessary to edit the profiler source code to embed the bias as
643 a literal number. You still can, but that method is no longer
644 described, because no longer needed.}
Guido van Rossumdf804f81995-03-02 12:38:39 +0000645
Fred Drake19479911998-02-13 06:58:54 +0000646\begin{verbatim}
Tim Peters659a6032001-10-09 20:51:19 +0000647import profile
Guido van Rossume47da0a1997-07-17 16:34:52 +0000648
Tim Peters659a6032001-10-09 20:51:19 +0000649# 1. Apply computed bias to all Profile instances created hereafter.
Tim Peters8cd015c2001-10-09 20:54:23 +0000650profile.Profile.bias = your_computed_bias
Tim Peters659a6032001-10-09 20:51:19 +0000651
652# 2. Apply computed bias to a specific Profile instance.
653pr = profile.Profile()
654pr.bias = your_computed_bias
655
656# 3. Specify computed bias in instance constructor.
657pr = profile.Profile(bias=your_computed_bias)
Fred Drake19479911998-02-13 06:58:54 +0000658\end{verbatim}
Fred Drake8fa5eb81998-02-27 05:23:37 +0000659
Tim Peters659a6032001-10-09 20:51:19 +0000660If you have a choice, you are better off choosing a smaller constant, and
661then your results will ``less often'' show up as negative in profile
662statistics.
Guido van Rossumdf804f81995-03-02 12:38:39 +0000663
664
Guido van Rossum86cb0921995-03-20 12:59:56 +0000665\section{Extensions --- Deriving Better Profilers}
666\nodename{Profiler Extensions}
Guido van Rossumdf804f81995-03-02 12:38:39 +0000667
Armin Rigoa871ef22006-02-08 12:53:56 +0000668The \class{Profile} class of both modules, \module{profile} and
669\module{cProfile}, were written so that
Tim Peters0a1fc4e2001-10-07 03:12:08 +0000670derived classes could be developed to extend the profiler. The details
671are not described here, as doing this successfully requires an expert
672understanding of how the \class{Profile} class works internally. Study
Armin Rigoa871ef22006-02-08 12:53:56 +0000673the source code of the module carefully if you want to
Tim Peters0a1fc4e2001-10-07 03:12:08 +0000674pursue this.
Guido van Rossumdf804f81995-03-02 12:38:39 +0000675
Tim Peters0a1fc4e2001-10-07 03:12:08 +0000676If all you want to do is change how current time is determined (for
677example, to force use of wall-clock time or elapsed process time),
678pass the timing function you want to the \class{Profile} class
679constructor:
Guido van Rossumdf804f81995-03-02 12:38:39 +0000680
Fred Drake19479911998-02-13 06:58:54 +0000681\begin{verbatim}
Guido van Rossume47da0a1997-07-17 16:34:52 +0000682pr = profile.Profile(your_time_func)
Fred Drake19479911998-02-13 06:58:54 +0000683\end{verbatim}
Fred Drake8fa5eb81998-02-27 05:23:37 +0000684
Armin Rigoa871ef22006-02-08 12:53:56 +0000685The resulting profiler will then call \function{your_time_func()}.
686
687\begin{description}
688\item[\class{profile.Profile}]
689\function{your_time_func()} should return a single number, or a list of
Tim Peters0a1fc4e2001-10-07 03:12:08 +0000690numbers whose sum is the current time (like what \function{os.times()}
691returns). If the function returns a single time number, or the list of
692returned numbers has length 2, then you will get an especially fast
693version of the dispatch routine.
Guido van Rossumdf804f81995-03-02 12:38:39 +0000694
Tim Peters0a1fc4e2001-10-07 03:12:08 +0000695Be warned that you should calibrate the profiler class for the
Guido van Rossumdf804f81995-03-02 12:38:39 +0000696timer function that you choose. For most machines, a timer that
697returns a lone integer value will provide the best results in terms of
Fred Drake8fa5eb81998-02-27 05:23:37 +0000698low overhead during profiling. (\function{os.times()} is
Tim Peters0a1fc4e2001-10-07 03:12:08 +0000699\emph{pretty} bad, as it returns a tuple of floating point values). If
700you want to substitute a better timer in the cleanest fashion,
701derive a class and hardwire a replacement dispatch method that best
Fred Drake8fa5eb81998-02-27 05:23:37 +0000702handles your timer call, along with the appropriate calibration
Fred Drake62f9d7c2001-06-08 05:04:19 +0000703constant.
Armin Rigoa871ef22006-02-08 12:53:56 +0000704
705\item[\class{cProfile.Profile}]
706\function{your_time_func()} should return a single number. If it returns
707plain integers, you can also invoke the class constructor with a second
708argument specifying the real duration of one unit of time. For example,
709if \function{your_integer_time_func()} returns times measured in thousands
710of seconds, you would constuct the \class{Profile} instance as follows:
711
712\begin{verbatim}
713pr = profile.Profile(your_integer_time_func, 0.001)
714\end{verbatim}
715
716As the \module{cProfile.Profile} class cannot be calibrated, custom
717timer functions should be used with care and should be as fast as
718possible. For the best results with a custom timer, it might be
719necessary to hard-code it in the C source of the internal
720\module{_lsprof} module.
721
722\end{description}