Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 1 | \chapter{The Python Profiler} |
Fred Drake | 31ecd50 | 1998-02-18 15:40:11 +0000 | [diff] [blame] | 2 | \label{profile} |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 3 | |
Fred Drake | 4b3f031 | 1996-12-13 22:04:31 +0000 | [diff] [blame] | 4 | Copyright \copyright{} 1994, by InfoSeek Corporation, all rights reserved. |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 5 | |
Fred Drake | eb72a27 | 1998-02-22 20:42:11 +0000 | [diff] [blame] | 6 | Written by James Roskind.% |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 7 | \footnote{ |
Guido van Rossum | 6c4f003 | 1995-03-07 10:14:09 +0000 | [diff] [blame] | 8 | Updated and converted to \LaTeX\ by Guido van Rossum. The references to |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 9 | the old profiler are left in the text, although it no longer exists. |
| 10 | } |
| 11 | |
| 12 | Permission to use, copy, modify, and distribute this Python software |
| 13 | and its associated documentation for any purpose (subject to the |
| 14 | restriction in the following sentence) without fee is hereby granted, |
| 15 | provided that the above copyright notice appears in all copies, and |
| 16 | that both that copyright notice and this permission notice appear in |
| 17 | supporting documentation, and that the name of InfoSeek not be used in |
| 18 | advertising or publicity pertaining to distribution of the software |
| 19 | without specific, written prior permission. This permission is |
| 20 | explicitly restricted to the copying and modification of the software |
| 21 | to remain in Python, compiled Python, or other languages (such as C) |
| 22 | wherein the modified or derived code is exclusively imported into a |
| 23 | Python module. |
| 24 | |
| 25 | INFOSEEK CORPORATION DISCLAIMS ALL WARRANTIES WITH REGARD TO THIS |
| 26 | SOFTWARE, INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY AND |
| 27 | FITNESS. IN NO EVENT SHALL INFOSEEK CORPORATION BE LIABLE FOR ANY |
| 28 | SPECIAL, INDIRECT OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER |
| 29 | RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF |
| 30 | CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN |
| 31 | CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE. |
| 32 | |
| 33 | |
| 34 | The profiler was written after only programming in Python for 3 weeks. |
| 35 | As a result, it is probably clumsy code, but I don't know for sure yet |
| 36 | 'cause I'm a beginner :-). I did work hard to make the code run fast, |
| 37 | so that profiling would be a reasonable thing to do. I tried not to |
| 38 | repeat code fragments, but I'm sure I did some stuff in really awkward |
| 39 | ways at times. Please send suggestions for improvements to: |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 40 | \email{jar@netscape.com}. I won't promise \emph{any} support. ...but |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 41 | I'd appreciate the feedback. |
| 42 | |
| 43 | |
Guido van Rossum | 470be14 | 1995-03-17 16:07:09 +0000 | [diff] [blame] | 44 | \section{Introduction to the profiler} |
Guido van Rossum | 86cb092 | 1995-03-20 12:59:56 +0000 | [diff] [blame] | 45 | \nodename{Profiler Introduction} |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 46 | |
| 47 | A \dfn{profiler} is a program that describes the run time performance |
| 48 | of a program, providing a variety of statistics. This documentation |
| 49 | describes the profiler functionality provided in the modules |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 50 | \module{profile} and \module{pstats}. This profiler provides |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 51 | \dfn{deterministic profiling} of any Python programs. It also |
| 52 | provides a series of report generation tools to allow users to rapidly |
| 53 | examine the results of a profile operation. |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 54 | \index{deterministic profiling} |
| 55 | \index{profiling, deterministic} |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 56 | |
| 57 | |
| 58 | \section{How Is This Profiler Different From The Old Profiler?} |
Guido van Rossum | 86cb092 | 1995-03-20 12:59:56 +0000 | [diff] [blame] | 59 | \nodename{Profiler Changes} |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 60 | |
Guido van Rossum | 364e643 | 1997-11-18 15:28:46 +0000 | [diff] [blame] | 61 | (This section is of historical importance only; the old profiler |
| 62 | discussed here was last seen in Python 1.1.) |
| 63 | |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 64 | The big changes from old profiling module are that you get more |
| 65 | information, and you pay less CPU time. It's not a trade-off, it's a |
| 66 | trade-up. |
| 67 | |
| 68 | To be specific: |
| 69 | |
| 70 | \begin{description} |
| 71 | |
| 72 | \item[Bugs removed:] |
| 73 | Local stack frame is no longer molested, execution time is now charged |
| 74 | to correct functions. |
| 75 | |
| 76 | \item[Accuracy increased:] |
| 77 | Profiler execution time is no longer charged to user's code, |
| 78 | calibration for platform is supported, file reads are not done \emph{by} |
| 79 | profiler \emph{during} profiling (and charged to user's code!). |
| 80 | |
| 81 | \item[Speed increased:] |
| 82 | Overhead CPU cost was reduced by more than a factor of two (perhaps a |
| 83 | factor of five), lightweight profiler module is all that must be |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 84 | loaded, and the report generating module (\module{pstats}) is not needed |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 85 | during profiling. |
| 86 | |
| 87 | \item[Recursive functions support:] |
| 88 | Cumulative times in recursive functions are correctly calculated; |
| 89 | recursive entries are counted. |
| 90 | |
| 91 | \item[Large growth in report generating UI:] |
| 92 | Distinct profiles runs can be added together forming a comprehensive |
| 93 | report; functions that import statistics take arbitrary lists of |
| 94 | files; sorting criteria is now based on keywords (instead of 4 integer |
| 95 | options); reports shows what functions were profiled as well as what |
| 96 | profile file was referenced; output format has been improved. |
| 97 | |
| 98 | \end{description} |
| 99 | |
| 100 | |
| 101 | \section{Instant Users Manual} |
| 102 | |
| 103 | This section is provided for users that ``don't want to read the |
| 104 | manual.'' It provides a very brief overview, and allows a user to |
| 105 | rapidly perform profiling on an existing application. |
| 106 | |
| 107 | To profile an application with a main entry point of \samp{foo()}, you |
| 108 | would add the following to your module: |
| 109 | |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 110 | \begin{verbatim} |
Guido van Rossum | e47da0a | 1997-07-17 16:34:52 +0000 | [diff] [blame] | 111 | import profile |
| 112 | profile.run("foo()") |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 113 | \end{verbatim} |
Guido van Rossum | e47da0a | 1997-07-17 16:34:52 +0000 | [diff] [blame] | 114 | % |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 115 | The above action would cause \samp{foo()} to be run, and a series of |
| 116 | informative lines (the profile) to be printed. The above approach is |
| 117 | most useful when working with the interpreter. If you would like to |
| 118 | save the results of a profile into a file for later examination, you |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 119 | can supply a file name as the second argument to the \function{run()} |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 120 | function: |
| 121 | |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 122 | \begin{verbatim} |
Guido van Rossum | e47da0a | 1997-07-17 16:34:52 +0000 | [diff] [blame] | 123 | import profile |
| 124 | profile.run("foo()", 'fooprof') |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 125 | \end{verbatim} |
Guido van Rossum | e47da0a | 1997-07-17 16:34:52 +0000 | [diff] [blame] | 126 | % |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 127 | The file \file{profile.py} can also be invoked as |
Guido van Rossum | bac8002 | 1997-06-02 17:29:12 +0000 | [diff] [blame] | 128 | a script to profile another script. For example: |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 129 | |
| 130 | \begin{verbatim} |
| 131 | python /usr/local/lib/python1.4/profile.py myscript.py |
| 132 | \end{verbatim} |
Guido van Rossum | bac8002 | 1997-06-02 17:29:12 +0000 | [diff] [blame] | 133 | |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 134 | When you wish to review the profile, you should use the methods in the |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 135 | \module{pstats} module. Typically you would load the statistics data as |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 136 | follows: |
| 137 | |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 138 | \begin{verbatim} |
Guido van Rossum | e47da0a | 1997-07-17 16:34:52 +0000 | [diff] [blame] | 139 | import pstats |
| 140 | p = pstats.Stats('fooprof') |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 141 | \end{verbatim} |
Guido van Rossum | e47da0a | 1997-07-17 16:34:52 +0000 | [diff] [blame] | 142 | % |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 143 | The class \class{Stats} (the above code just created an instance of |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 144 | this class) has a variety of methods for manipulating and printing the |
| 145 | data that was just read into \samp{p}. When you ran |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 146 | \function{profile.run()} above, what was printed was the result of three |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 147 | method calls: |
| 148 | |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 149 | \begin{verbatim} |
Guido van Rossum | e47da0a | 1997-07-17 16:34:52 +0000 | [diff] [blame] | 150 | p.strip_dirs().sort_stats(-1).print_stats() |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 151 | \end{verbatim} |
Guido van Rossum | e47da0a | 1997-07-17 16:34:52 +0000 | [diff] [blame] | 152 | % |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 153 | The first method removed the extraneous path from all the module |
| 154 | names. The second method sorted all the entries according to the |
| 155 | standard module/line/name string that is printed (this is to comply |
| 156 | with the semantics of the old profiler). The third method printed out |
| 157 | all the statistics. You might try the following sort calls: |
| 158 | |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 159 | \begin{verbatim} |
Guido van Rossum | e47da0a | 1997-07-17 16:34:52 +0000 | [diff] [blame] | 160 | p.sort_stats('name') |
| 161 | p.print_stats() |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 162 | \end{verbatim} |
Guido van Rossum | e47da0a | 1997-07-17 16:34:52 +0000 | [diff] [blame] | 163 | % |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 164 | The first call will actually sort the list by function name, and the |
| 165 | second call will print out the statistics. The following are some |
| 166 | interesting calls to experiment with: |
| 167 | |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 168 | \begin{verbatim} |
Guido van Rossum | e47da0a | 1997-07-17 16:34:52 +0000 | [diff] [blame] | 169 | p.sort_stats('cumulative').print_stats(10) |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 170 | \end{verbatim} |
Guido van Rossum | e47da0a | 1997-07-17 16:34:52 +0000 | [diff] [blame] | 171 | % |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 172 | This sorts the profile by cumulative time in a function, and then only |
| 173 | prints the ten most significant lines. If you want to understand what |
| 174 | algorithms are taking time, the above line is what you would use. |
| 175 | |
| 176 | If you were looking to see what functions were looping a lot, and |
| 177 | taking a lot of time, you would do: |
| 178 | |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 179 | \begin{verbatim} |
Guido van Rossum | e47da0a | 1997-07-17 16:34:52 +0000 | [diff] [blame] | 180 | p.sort_stats('time').print_stats(10) |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 181 | \end{verbatim} |
Guido van Rossum | e47da0a | 1997-07-17 16:34:52 +0000 | [diff] [blame] | 182 | % |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 183 | to sort according to time spent within each function, and then print |
| 184 | the statistics for the top ten functions. |
| 185 | |
| 186 | You might also try: |
| 187 | |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 188 | \begin{verbatim} |
Guido van Rossum | e47da0a | 1997-07-17 16:34:52 +0000 | [diff] [blame] | 189 | p.sort_stats('file').print_stats('__init__') |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 190 | \end{verbatim} |
Guido van Rossum | e47da0a | 1997-07-17 16:34:52 +0000 | [diff] [blame] | 191 | % |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 192 | This will sort all the statistics by file name, and then print out |
| 193 | statistics for only the class init methods ('cause they are spelled |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 194 | with \samp{__init__} in them). As one final example, you could try: |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 195 | |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 196 | \begin{verbatim} |
Guido van Rossum | e47da0a | 1997-07-17 16:34:52 +0000 | [diff] [blame] | 197 | p.sort_stats('time', 'cum').print_stats(.5, 'init') |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 198 | \end{verbatim} |
Guido van Rossum | e47da0a | 1997-07-17 16:34:52 +0000 | [diff] [blame] | 199 | % |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 200 | This line sorts statistics with a primary key of time, and a secondary |
| 201 | key of cumulative time, and then prints out some of the statistics. |
| 202 | To be specific, the list is first culled down to 50\% (re: \samp{.5}) |
| 203 | of its original size, then only lines containing \code{init} are |
| 204 | maintained, and that sub-sub-list is printed. |
| 205 | |
| 206 | If you wondered what functions called the above functions, you could |
| 207 | now (\samp{p} is still sorted according to the last criteria) do: |
| 208 | |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 209 | \begin{verbatim} |
Guido van Rossum | e47da0a | 1997-07-17 16:34:52 +0000 | [diff] [blame] | 210 | p.print_callers(.5, 'init') |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 211 | \end{verbatim} |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 212 | |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 213 | and you would get a list of callers for each of the listed functions. |
| 214 | |
| 215 | If you want more functionality, you're going to have to read the |
| 216 | manual, or guess what the following functions do: |
| 217 | |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 218 | \begin{verbatim} |
Guido van Rossum | e47da0a | 1997-07-17 16:34:52 +0000 | [diff] [blame] | 219 | p.print_callees() |
| 220 | p.add('fooprof') |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 221 | \end{verbatim} |
Guido van Rossum | e47da0a | 1997-07-17 16:34:52 +0000 | [diff] [blame] | 222 | % |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 223 | \section{What Is Deterministic Profiling?} |
Guido van Rossum | 86cb092 | 1995-03-20 12:59:56 +0000 | [diff] [blame] | 224 | \nodename{Deterministic Profiling} |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 225 | |
| 226 | \dfn{Deterministic profiling} is meant to reflect the fact that all |
| 227 | \dfn{function call}, \dfn{function return}, and \dfn{exception} events |
| 228 | are monitored, and precise timings are made for the intervals between |
| 229 | these events (during which time the user's code is executing). In |
| 230 | contrast, \dfn{statistical profiling} (which is not done by this |
| 231 | module) randomly samples the effective instruction pointer, and |
| 232 | deduces where time is being spent. The latter technique traditionally |
| 233 | involves less overhead (as the code does not need to be instrumented), |
| 234 | but provides only relative indications of where time is being spent. |
| 235 | |
| 236 | In Python, since there is an interpreter active during execution, the |
| 237 | presence of instrumented code is not required to do deterministic |
| 238 | profiling. Python automatically provides a \dfn{hook} (optional |
| 239 | callback) for each event. In addition, the interpreted nature of |
| 240 | Python tends to add so much overhead to execution, that deterministic |
| 241 | profiling tends to only add small processing overhead in typical |
| 242 | applications. The result is that deterministic profiling is not that |
| 243 | expensive, yet provides extensive run time statistics about the |
| 244 | execution of a Python program. |
| 245 | |
| 246 | Call count statistics can be used to identify bugs in code (surprising |
| 247 | counts), and to identify possible inline-expansion points (high call |
| 248 | counts). Internal time statistics can be used to identify ``hot |
| 249 | loops'' that should be carefully optimized. Cumulative time |
| 250 | statistics should be used to identify high level errors in the |
| 251 | selection of algorithms. Note that the unusual handling of cumulative |
| 252 | times in this profiler allows statistics for recursive implementations |
| 253 | of algorithms to be directly compared to iterative implementations. |
| 254 | |
| 255 | |
| 256 | \section{Reference Manual} |
Fred Drake | 8fe533e | 1998-03-27 05:27:08 +0000 | [diff] [blame^] | 257 | \stmodindex{profile} |
| 258 | \label{module-profile} |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 259 | |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 260 | |
| 261 | The primary entry point for the profiler is the global function |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 262 | \function{profile.run()}. It is typically used to create any profile |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 263 | information. The reports are formatted and printed using methods of |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 264 | the class \class{pstats.Stats}. The following is a description of all |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 265 | of these standard entry points and functions. For a more in-depth |
| 266 | view of some of the code, consider reading the later section on |
| 267 | Profiler Extensions, which includes discussion of how to derive |
| 268 | ``better'' profilers from the classes presented, or reading the source |
| 269 | code for these modules. |
| 270 | |
Fred Drake | 8fe533e | 1998-03-27 05:27:08 +0000 | [diff] [blame^] | 271 | \begin{funcdesc}{run}{string\optional{, filename\optional{, ...}}} |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 272 | |
| 273 | This function takes a single argument that has can be passed to the |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 274 | \keyword{exec} statement, and an optional file name. In all cases this |
| 275 | routine attempts to \keyword{exec} its first argument, and gather profiling |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 276 | statistics from the execution. If no file name is present, then this |
| 277 | function automatically prints a simple profiling report, sorted by the |
| 278 | standard name string (file/line/function-name) that is presented in |
| 279 | each line. The following is a typical output from such a call: |
| 280 | |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 281 | \begin{verbatim} |
Guido van Rossum | 96628a9 | 1995-04-10 11:34:00 +0000 | [diff] [blame] | 282 | main() |
| 283 | 2706 function calls (2004 primitive calls) in 4.504 CPU seconds |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 284 | |
Guido van Rossum | 96628a9 | 1995-04-10 11:34:00 +0000 | [diff] [blame] | 285 | Ordered by: standard name |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 286 | |
Guido van Rossum | 96628a9 | 1995-04-10 11:34:00 +0000 | [diff] [blame] | 287 | ncalls tottime percall cumtime percall filename:lineno(function) |
| 288 | 2 0.006 0.003 0.953 0.477 pobject.py:75(save_objects) |
| 289 | 43/3 0.533 0.012 0.749 0.250 pobject.py:99(evaluate) |
| 290 | ... |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 291 | \end{verbatim} |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 292 | |
| 293 | The first line indicates that this profile was generated by the call:\\ |
| 294 | \code{profile.run('main()')}, and hence the exec'ed string is |
| 295 | \code{'main()'}. The second line indicates that 2706 calls were |
| 296 | monitored. Of those calls, 2004 were \dfn{primitive}. We define |
| 297 | \dfn{primitive} to mean that the call was not induced via recursion. |
| 298 | The next line: \code{Ordered by:\ standard name}, indicates that |
| 299 | the text string in the far right column was used to sort the output. |
| 300 | The column headings include: |
| 301 | |
| 302 | \begin{description} |
| 303 | |
| 304 | \item[ncalls ] |
| 305 | for the number of calls, |
| 306 | |
| 307 | \item[tottime ] |
| 308 | for the total time spent in the given function (and excluding time |
| 309 | made in calls to sub-functions), |
| 310 | |
| 311 | \item[percall ] |
| 312 | is the quotient of \code{tottime} divided by \code{ncalls} |
| 313 | |
| 314 | \item[cumtime ] |
| 315 | is the total time spent in this and all subfunctions (i.e., from |
| 316 | invocation till exit). This figure is accurate \emph{even} for recursive |
| 317 | functions. |
| 318 | |
| 319 | \item[percall ] |
| 320 | is the quotient of \code{cumtime} divided by primitive calls |
| 321 | |
| 322 | \item[filename:lineno(function) ] |
| 323 | provides the respective data of each function |
| 324 | |
| 325 | \end{description} |
| 326 | |
| 327 | When there are two numbers in the first column (e.g.: \samp{43/3}), |
| 328 | then the latter is the number of primitive calls, and the former is |
| 329 | the actual number of calls. Note that when the function does not |
| 330 | recurse, these two values are the same, and only the single figure is |
| 331 | printed. |
Guido van Rossum | 96628a9 | 1995-04-10 11:34:00 +0000 | [diff] [blame] | 332 | |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 333 | \end{funcdesc} |
| 334 | |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 335 | Analysis of the profiler data is done using this class from the |
| 336 | \module{pstats} module: |
| 337 | |
Fred Drake | 8fe533e | 1998-03-27 05:27:08 +0000 | [diff] [blame^] | 338 | % now switch modules.... |
| 339 | \stmodindex{pstats} |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 340 | |
Fred Drake | cce1090 | 1998-03-17 06:33:25 +0000 | [diff] [blame] | 341 | \begin{classdesc}{Stats}{filename\optional{, ...}} |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 342 | This class constructor creates an instance of a ``statistics object'' |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 343 | from a \var{filename} (or set of filenames). \class{Stats} objects are |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 344 | manipulated by methods, in order to print useful reports. |
| 345 | |
| 346 | The file selected by the above constructor must have been created by |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 347 | the corresponding version of \module{profile}. To be specific, there is |
| 348 | \emph{no} file compatibility guaranteed with future versions of this |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 349 | profiler, and there is no compatibility with files produced by other |
| 350 | profilers (e.g., the old system profiler). |
| 351 | |
| 352 | If several files are provided, all the statistics for identical |
| 353 | functions will be coalesced, so that an overall view of several |
| 354 | processes can be considered in a single report. If additional files |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 355 | need to be combined with data in an existing \class{Stats} object, the |
| 356 | \method{add()} method can be used. |
| 357 | \end{classdesc} |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 358 | |
| 359 | |
Guido van Rossum | 470be14 | 1995-03-17 16:07:09 +0000 | [diff] [blame] | 360 | \subsection{The \sectcode{Stats} Class} |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 361 | |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 362 | \setindexsubitem{(Stats method)} |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 363 | |
Fred Drake | 8fe533e | 1998-03-27 05:27:08 +0000 | [diff] [blame^] | 364 | \begin{methoddesc}{strip_dirs}{} |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 365 | This method for the \class{Stats} class removes all leading path |
| 366 | information from file names. It is very useful in reducing the size |
| 367 | of the printout to fit within (close to) 80 columns. This method |
| 368 | modifies the object, and the stripped information is lost. After |
| 369 | performing a strip operation, the object is considered to have its |
| 370 | entries in a ``random'' order, as it was just after object |
| 371 | initialization and loading. If \method{strip_dirs()} causes two |
| 372 | function names to be indistinguishable (i.e., they are on the same |
| 373 | line of the same filename, and have the same function name), then the |
| 374 | statistics for these two entries are accumulated into a single entry. |
Fred Drake | 8fe533e | 1998-03-27 05:27:08 +0000 | [diff] [blame^] | 375 | \end{methoddesc} |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 376 | |
| 377 | |
Fred Drake | 8fe533e | 1998-03-27 05:27:08 +0000 | [diff] [blame^] | 378 | \begin{methoddesc}{add}{filename\optional{, ...}} |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 379 | This method of the \class{Stats} class accumulates additional |
| 380 | profiling information into the current profiling object. Its |
| 381 | arguments should refer to filenames created by the corresponding |
| 382 | version of \function{profile.run()}. Statistics for identically named |
| 383 | (re: file, line, name) functions are automatically accumulated into |
| 384 | single function statistics. |
Fred Drake | 8fe533e | 1998-03-27 05:27:08 +0000 | [diff] [blame^] | 385 | \end{methoddesc} |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 386 | |
Fred Drake | 8fe533e | 1998-03-27 05:27:08 +0000 | [diff] [blame^] | 387 | \begin{methoddesc}{sort_stats}{key\optional{, ...}} |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 388 | This method modifies the \class{Stats} object by sorting it according |
| 389 | to the supplied criteria. The argument is typically a string |
| 390 | identifying the basis of a sort (example: \code{"time"} or |
| 391 | \code{"name"}). |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 392 | |
| 393 | When more than one key is provided, then additional keys are used as |
| 394 | secondary criteria when the there is equality in all keys selected |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 395 | before them. For example, \samp{sort_stats('name', 'file')} will sort |
| 396 | all the entries according to their function name, and resolve all ties |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 397 | (identical function names) by sorting by file name. |
| 398 | |
| 399 | Abbreviations can be used for any key names, as long as the |
| 400 | abbreviation is unambiguous. The following are the keys currently |
| 401 | defined: |
| 402 | |
| 403 | \begin{tableii}{|l|l|}{code}{Valid Arg}{Meaning} |
| 404 | \lineii{"calls"}{call count} |
| 405 | \lineii{"cumulative"}{cumulative time} |
| 406 | \lineii{"file"}{file name} |
| 407 | \lineii{"module"}{file name} |
| 408 | \lineii{"pcalls"}{primitive call count} |
| 409 | \lineii{"line"}{line number} |
| 410 | \lineii{"name"}{function name} |
| 411 | \lineii{"nfl"}{name/file/line} |
| 412 | \lineii{"stdname"}{standard name} |
| 413 | \lineii{"time"}{internal time} |
| 414 | \end{tableii} |
| 415 | |
| 416 | Note that all sorts on statistics are in descending order (placing |
| 417 | most time consuming items first), where as name, file, and line number |
| 418 | searches are in ascending order (i.e., alphabetical). The subtle |
| 419 | distinction between \code{"nfl"} and \code{"stdname"} is that the |
| 420 | standard name is a sort of the name as printed, which means that the |
| 421 | embedded line numbers get compared in an odd way. For example, lines |
| 422 | 3, 20, and 40 would (if the file names were the same) appear in the |
| 423 | string order 20, 3 and 40. In contrast, \code{"nfl"} does a numeric |
| 424 | compare of the line numbers. In fact, \code{sort_stats("nfl")} is the |
| 425 | same as \code{sort_stats("name", "file", "line")}. |
| 426 | |
| 427 | For compatibility with the old profiler, the numeric arguments |
| 428 | \samp{-1}, \samp{0}, \samp{1}, and \samp{2} are permitted. They are |
| 429 | interpreted as \code{"stdname"}, \code{"calls"}, \code{"time"}, and |
| 430 | \code{"cumulative"} respectively. If this old style format (numeric) |
| 431 | is used, only one sort key (the numeric key) will be used, and |
| 432 | additional arguments will be silently ignored. |
Fred Drake | 8fe533e | 1998-03-27 05:27:08 +0000 | [diff] [blame^] | 433 | \end{methoddesc} |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 434 | |
| 435 | |
Fred Drake | 8fe533e | 1998-03-27 05:27:08 +0000 | [diff] [blame^] | 436 | \begin{methoddesc}{reverse_order}{} |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 437 | This method for the \class{Stats} class reverses the ordering of the basic |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 438 | list within the object. This method is provided primarily for |
| 439 | compatibility with the old profiler. Its utility is questionable |
| 440 | now that ascending vs descending order is properly selected based on |
| 441 | the sort key of choice. |
Fred Drake | 8fe533e | 1998-03-27 05:27:08 +0000 | [diff] [blame^] | 442 | \end{methoddesc} |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 443 | |
Fred Drake | 8fe533e | 1998-03-27 05:27:08 +0000 | [diff] [blame^] | 444 | \begin{methoddesc}{print_stats}{restriction\optional{, ...}} |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 445 | This method for the \class{Stats} class prints out a report as described |
| 446 | in the \function{profile.run()} definition. |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 447 | |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 448 | The order of the printing is based on the last \method{sort_stats()} |
| 449 | operation done on the object (subject to caveats in \method{add()} and |
| 450 | \method{strip_dirs()}. |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 451 | |
| 452 | The arguments provided (if any) can be used to limit the list down to |
| 453 | the significant entries. Initially, the list is taken to be the |
| 454 | complete set of profiled functions. Each restriction is either an |
| 455 | integer (to select a count of lines), or a decimal fraction between |
| 456 | 0.0 and 1.0 inclusive (to select a percentage of lines), or a regular |
Guido van Rossum | 364e643 | 1997-11-18 15:28:46 +0000 | [diff] [blame] | 457 | expression (to pattern match the standard name that is printed; as of |
| 458 | Python 1.5b1, this uses the Perl-style regular expression syntax |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 459 | defined by the \module{re} module). If several restrictions are |
Guido van Rossum | 364e643 | 1997-11-18 15:28:46 +0000 | [diff] [blame] | 460 | provided, then they are applied sequentially. For example: |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 461 | |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 462 | \begin{verbatim} |
Guido van Rossum | e47da0a | 1997-07-17 16:34:52 +0000 | [diff] [blame] | 463 | print_stats(.1, "foo:") |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 464 | \end{verbatim} |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 465 | |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 466 | would first limit the printing to first 10\% of list, and then only |
| 467 | print functions that were part of filename \samp{.*foo:}. In |
| 468 | contrast, the command: |
| 469 | |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 470 | \begin{verbatim} |
Guido van Rossum | e47da0a | 1997-07-17 16:34:52 +0000 | [diff] [blame] | 471 | print_stats("foo:", .1) |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 472 | \end{verbatim} |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 473 | |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 474 | would limit the list to all functions having file names \samp{.*foo:}, |
| 475 | and then proceed to only print the first 10\% of them. |
Fred Drake | 8fe533e | 1998-03-27 05:27:08 +0000 | [diff] [blame^] | 476 | \end{methoddesc} |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 477 | |
| 478 | |
Fred Drake | 8fe533e | 1998-03-27 05:27:08 +0000 | [diff] [blame^] | 479 | \begin{methoddesc}{print_callers}{restrictions\optional{, ...}} |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 480 | This method for the \class{Stats} class prints a list of all functions |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 481 | that called each function in the profiled database. The ordering is |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 482 | identical to that provided by \method{print_stats()}, and the definition |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 483 | of the restricting argument is also identical. For convenience, a |
| 484 | number is shown in parentheses after each caller to show how many |
| 485 | times this specific call was made. A second non-parenthesized number |
| 486 | is the cumulative time spent in the function at the right. |
Fred Drake | 8fe533e | 1998-03-27 05:27:08 +0000 | [diff] [blame^] | 487 | \end{methoddesc} |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 488 | |
Fred Drake | 8fe533e | 1998-03-27 05:27:08 +0000 | [diff] [blame^] | 489 | \begin{methoddesc}{print_callees}{restrictions\optional{, ...}} |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 490 | This method for the \class{Stats} class prints a list of all function |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 491 | that were called by the indicated function. Aside from this reversal |
| 492 | of direction of calls (re: called vs was called by), the arguments and |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 493 | ordering are identical to the \method{print_callers()} method. |
Fred Drake | 8fe533e | 1998-03-27 05:27:08 +0000 | [diff] [blame^] | 494 | \end{methoddesc} |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 495 | |
Fred Drake | 8fe533e | 1998-03-27 05:27:08 +0000 | [diff] [blame^] | 496 | \begin{methoddesc}{ignore}{} |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 497 | This method of the \class{Stats} class is used to dispose of the value |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 498 | returned by earlier methods. All standard methods in this class |
| 499 | return the instance that is being processed, so that the commands can |
| 500 | be strung together. For example: |
| 501 | |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 502 | \begin{verbatim} |
Guido van Rossum | 96628a9 | 1995-04-10 11:34:00 +0000 | [diff] [blame] | 503 | pstats.Stats('foofile').strip_dirs().sort_stats('cum') \ |
| 504 | .print_stats().ignore() |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 505 | \end{verbatim} |
Fred Drake | 8fe533e | 1998-03-27 05:27:08 +0000 | [diff] [blame^] | 506 | |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 507 | would perform all the indicated functions, but it would not return |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 508 | the final reference to the \class{Stats} instance.% |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 509 | \footnote{ |
| 510 | This was once necessary, when Python would print any unused expression |
| 511 | result that was not \code{None}. The method is still defined for |
| 512 | backward compatibility. |
| 513 | } |
Fred Drake | 8fe533e | 1998-03-27 05:27:08 +0000 | [diff] [blame^] | 514 | \end{methoddesc} |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 515 | |
| 516 | |
| 517 | \section{Limitations} |
| 518 | |
| 519 | There are two fundamental limitations on this profiler. The first is |
| 520 | that it relies on the Python interpreter to dispatch \dfn{call}, |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 521 | \dfn{return}, and \dfn{exception} events. Compiled \C{} code does not |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 522 | get interpreted, and hence is ``invisible'' to the profiler. All time |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 523 | spent in \C{} code (including builtin functions) will be charged to the |
| 524 | Python function that invoked the \C{} code. If the \C{} code calls out |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 525 | to some native Python code, then those calls will be profiled |
| 526 | properly. |
| 527 | |
| 528 | The second limitation has to do with accuracy of timing information. |
| 529 | There is a fundamental problem with deterministic profilers involving |
| 530 | accuracy. The most obvious restriction is that the underlying ``clock'' |
| 531 | is only ticking at a rate (typically) of about .001 seconds. Hence no |
| 532 | measurements will be more accurate that that underlying clock. If |
| 533 | enough measurements are taken, then the ``error'' will tend to average |
| 534 | out. Unfortunately, removing this first error induces a second source |
| 535 | of error... |
| 536 | |
| 537 | The second problem is that it ``takes a while'' from when an event is |
| 538 | dispatched until the profiler's call to get the time actually |
| 539 | \emph{gets} the state of the clock. Similarly, there is a certain lag |
| 540 | when exiting the profiler event handler from the time that the clock's |
| 541 | value was obtained (and then squirreled away), until the user's code |
| 542 | is once again executing. As a result, functions that are called many |
| 543 | times, or call many functions, will typically accumulate this error. |
| 544 | The error that accumulates in this fashion is typically less than the |
| 545 | accuracy of the clock (i.e., less than one clock tick), but it |
| 546 | \emph{can} accumulate and become very significant. This profiler |
| 547 | provides a means of calibrating itself for a given platform so that |
| 548 | this error can be probabilistically (i.e., on the average) removed. |
| 549 | After the profiler is calibrated, it will be more accurate (in a least |
| 550 | square sense), but it will sometimes produce negative numbers (when |
| 551 | call counts are exceptionally low, and the gods of probability work |
| 552 | against you :-). ) Do \emph{NOT} be alarmed by negative numbers in |
| 553 | the profile. They should \emph{only} appear if you have calibrated |
| 554 | your profiler, and the results are actually better than without |
| 555 | calibration. |
| 556 | |
| 557 | |
| 558 | \section{Calibration} |
| 559 | |
| 560 | The profiler class has a hard coded constant that is added to each |
| 561 | event handling time to compensate for the overhead of calling the time |
| 562 | function, and socking away the results. The following procedure can |
| 563 | be used to obtain this constant for a given platform (see discussion |
| 564 | in section Limitations above). |
| 565 | |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 566 | \begin{verbatim} |
Guido van Rossum | e47da0a | 1997-07-17 16:34:52 +0000 | [diff] [blame] | 567 | import profile |
| 568 | pr = profile.Profile() |
Guido van Rossum | 685ef4e | 1998-03-17 14:37:48 +0000 | [diff] [blame] | 569 | print pr.calibrate(100) |
| 570 | print pr.calibrate(100) |
| 571 | print pr.calibrate(100) |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 572 | \end{verbatim} |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 573 | |
| 574 | The argument to \method{calibrate()} is the number of times to try to |
| 575 | do the sample calls to get the CPU times. If your computer is |
| 576 | \emph{very} fast, you might have to do: |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 577 | |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 578 | \begin{verbatim} |
Guido van Rossum | e47da0a | 1997-07-17 16:34:52 +0000 | [diff] [blame] | 579 | pr.calibrate(1000) |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 580 | \end{verbatim} |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 581 | |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 582 | or even: |
| 583 | |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 584 | \begin{verbatim} |
Guido van Rossum | e47da0a | 1997-07-17 16:34:52 +0000 | [diff] [blame] | 585 | pr.calibrate(10000) |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 586 | \end{verbatim} |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 587 | |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 588 | The object of this exercise is to get a fairly consistent result. |
| 589 | When you have a consistent answer, you are ready to use that number in |
| 590 | the source code. For a Sun Sparcstation 1000 running Solaris 2.3, the |
| 591 | magical number is about .00053. If you have a choice, you are better |
| 592 | off with a smaller constant, and your results will ``less often'' show |
| 593 | up as negative in profile statistics. |
| 594 | |
| 595 | The following shows how the trace_dispatch() method in the Profile |
| 596 | class should be modified to install the calibration constant on a Sun |
| 597 | Sparcstation 1000: |
| 598 | |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 599 | \begin{verbatim} |
Guido van Rossum | e47da0a | 1997-07-17 16:34:52 +0000 | [diff] [blame] | 600 | def trace_dispatch(self, frame, event, arg): |
| 601 | t = self.timer() |
| 602 | t = t[0] + t[1] - self.t - .00053 # Calibration constant |
| 603 | |
| 604 | if self.dispatch[event](frame,t): |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 605 | t = self.timer() |
Guido van Rossum | e47da0a | 1997-07-17 16:34:52 +0000 | [diff] [blame] | 606 | self.t = t[0] + t[1] |
| 607 | else: |
| 608 | r = self.timer() |
| 609 | self.t = r[0] + r[1] - t # put back unrecorded delta |
| 610 | return |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 611 | \end{verbatim} |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 612 | |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 613 | Note that if there is no calibration constant, then the line |
| 614 | containing the callibration constant should simply say: |
| 615 | |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 616 | \begin{verbatim} |
Guido van Rossum | e47da0a | 1997-07-17 16:34:52 +0000 | [diff] [blame] | 617 | t = t[0] + t[1] - self.t # no calibration constant |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 618 | \end{verbatim} |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 619 | |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 620 | You can also achieve the same results using a derived class (and the |
| 621 | profiler will actually run equally fast!!), but the above method is |
| 622 | the simplest to use. I could have made the profiler ``self |
| 623 | calibrating'', but it would have made the initialization of the |
| 624 | profiler class slower, and would have required some \emph{very} fancy |
| 625 | coding, or else the use of a variable where the constant \samp{.00053} |
| 626 | was placed in the code shown. This is a \strong{VERY} critical |
| 627 | performance section, and there is no reason to use a variable lookup |
| 628 | at this point, when a constant can be used. |
| 629 | |
| 630 | |
Guido van Rossum | 86cb092 | 1995-03-20 12:59:56 +0000 | [diff] [blame] | 631 | \section{Extensions --- Deriving Better Profilers} |
| 632 | \nodename{Profiler Extensions} |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 633 | |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 634 | The \class{Profile} class of module \module{profile} was written so that |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 635 | derived classes could be developed to extend the profiler. Rather |
| 636 | than describing all the details of such an effort, I'll just present |
| 637 | the following two examples of derived classes that can be used to do |
| 638 | profiling. If the reader is an avid Python programmer, then it should |
| 639 | be possible to use these as a model and create similar (and perchance |
| 640 | better) profile classes. |
| 641 | |
| 642 | If all you want to do is change how the timer is called, or which |
| 643 | timer function is used, then the basic class has an option for that in |
| 644 | the constructor for the class. Consider passing the name of a |
| 645 | function to call into the constructor: |
| 646 | |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 647 | \begin{verbatim} |
Guido van Rossum | e47da0a | 1997-07-17 16:34:52 +0000 | [diff] [blame] | 648 | pr = profile.Profile(your_time_func) |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 649 | \end{verbatim} |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 650 | |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 651 | The resulting profiler will call \code{your_time_func()} instead of |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 652 | \function{os.times()}. The function should return either a single number |
| 653 | or a list of numbers (like what \function{os.times()} returns). If the |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 654 | function returns a single time number, or the list of returned numbers |
| 655 | has length 2, then you will get an especially fast version of the |
| 656 | dispatch routine. |
| 657 | |
| 658 | Be warned that you \emph{should} calibrate the profiler class for the |
| 659 | timer function that you choose. For most machines, a timer that |
| 660 | returns a lone integer value will provide the best results in terms of |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 661 | low overhead during profiling. (\function{os.times()} is |
| 662 | \emph{pretty} bad, 'cause it returns a tuple of floating point values, |
| 663 | so all arithmetic is floating point in the profiler!). If you want to |
| 664 | substitute a better timer in the cleanest fashion, you should derive a |
| 665 | class, and simply put in the replacement dispatch method that better |
| 666 | handles your timer call, along with the appropriate calibration |
| 667 | constant :-). |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 668 | |
| 669 | |
| 670 | \subsection{OldProfile Class} |
| 671 | |
| 672 | The following derived profiler simulates the old style profiler, |
| 673 | providing errant results on recursive functions. The reason for the |
| 674 | usefulness of this profiler is that it runs faster (i.e., less |
| 675 | overhead) than the old profiler. It still creates all the caller |
| 676 | stats, and is quite useful when there is \emph{no} recursion in the |
| 677 | user's code. It is also a lot more accurate than the old profiler, as |
| 678 | it does not charge all its overhead time to the user's code. |
| 679 | |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 680 | \begin{verbatim} |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 681 | class OldProfile(Profile): |
| 682 | |
| 683 | def trace_dispatch_exception(self, frame, t): |
| 684 | rt, rtt, rct, rfn, rframe, rcur = self.cur |
| 685 | if rcur and not rframe is frame: |
| 686 | return self.trace_dispatch_return(rframe, t) |
| 687 | return 0 |
| 688 | |
| 689 | def trace_dispatch_call(self, frame, t): |
| 690 | fn = `frame.f_code` |
| 691 | |
| 692 | self.cur = (t, 0, 0, fn, frame, self.cur) |
| 693 | if self.timings.has_key(fn): |
| 694 | tt, ct, callers = self.timings[fn] |
| 695 | self.timings[fn] = tt, ct, callers |
| 696 | else: |
| 697 | self.timings[fn] = 0, 0, {} |
| 698 | return 1 |
| 699 | |
| 700 | def trace_dispatch_return(self, frame, t): |
| 701 | rt, rtt, rct, rfn, frame, rcur = self.cur |
| 702 | rtt = rtt + t |
| 703 | sft = rtt + rct |
| 704 | |
| 705 | pt, ptt, pct, pfn, pframe, pcur = rcur |
| 706 | self.cur = pt, ptt+rt, pct+sft, pfn, pframe, pcur |
| 707 | |
| 708 | tt, ct, callers = self.timings[rfn] |
| 709 | if callers.has_key(pfn): |
| 710 | callers[pfn] = callers[pfn] + 1 |
| 711 | else: |
| 712 | callers[pfn] = 1 |
| 713 | self.timings[rfn] = tt+rtt, ct + sft, callers |
| 714 | |
| 715 | return 1 |
| 716 | |
| 717 | |
| 718 | def snapshot_stats(self): |
| 719 | self.stats = {} |
| 720 | for func in self.timings.keys(): |
| 721 | tt, ct, callers = self.timings[func] |
| 722 | nor_func = self.func_normalize(func) |
| 723 | nor_callers = {} |
| 724 | nc = 0 |
| 725 | for func_caller in callers.keys(): |
| 726 | nor_callers[self.func_normalize(func_caller)]=\ |
| 727 | callers[func_caller] |
| 728 | nc = nc + callers[func_caller] |
| 729 | self.stats[nor_func] = nc, nc, tt, ct, nor_callers |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 730 | \end{verbatim} |
Fred Drake | 8fa5eb8 | 1998-02-27 05:23:37 +0000 | [diff] [blame] | 731 | |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 732 | \subsection{HotProfile Class} |
| 733 | |
| 734 | This profiler is the fastest derived profile example. It does not |
| 735 | calculate caller-callee relationships, and does not calculate |
| 736 | cumulative time under a function. It only calculates time spent in a |
| 737 | function, so it runs very quickly (re: very low overhead). In truth, |
| 738 | the basic profiler is so fast, that is probably not worth the savings |
| 739 | to give up the data, but this class still provides a nice example. |
| 740 | |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 741 | \begin{verbatim} |
Guido van Rossum | df804f8 | 1995-03-02 12:38:39 +0000 | [diff] [blame] | 742 | class HotProfile(Profile): |
| 743 | |
| 744 | def trace_dispatch_exception(self, frame, t): |
| 745 | rt, rtt, rfn, rframe, rcur = self.cur |
| 746 | if rcur and not rframe is frame: |
| 747 | return self.trace_dispatch_return(rframe, t) |
| 748 | return 0 |
| 749 | |
| 750 | def trace_dispatch_call(self, frame, t): |
| 751 | self.cur = (t, 0, frame, self.cur) |
| 752 | return 1 |
| 753 | |
| 754 | def trace_dispatch_return(self, frame, t): |
| 755 | rt, rtt, frame, rcur = self.cur |
| 756 | |
| 757 | rfn = `frame.f_code` |
| 758 | |
| 759 | pt, ptt, pframe, pcur = rcur |
| 760 | self.cur = pt, ptt+rt, pframe, pcur |
| 761 | |
| 762 | if self.timings.has_key(rfn): |
| 763 | nc, tt = self.timings[rfn] |
| 764 | self.timings[rfn] = nc + 1, rt + rtt + tt |
| 765 | else: |
| 766 | self.timings[rfn] = 1, rt + rtt |
| 767 | |
| 768 | return 1 |
| 769 | |
| 770 | |
| 771 | def snapshot_stats(self): |
| 772 | self.stats = {} |
| 773 | for func in self.timings.keys(): |
| 774 | nc, tt = self.timings[func] |
| 775 | nor_func = self.func_normalize(func) |
| 776 | self.stats[nor_func] = nc, nc, tt, 0, {} |
Fred Drake | 1947991 | 1998-02-13 06:58:54 +0000 | [diff] [blame] | 777 | \end{verbatim} |