Guido van Rossum | f06ee5f | 1996-11-27 19:52:01 +0000 | [diff] [blame] | 1 | #! /usr/bin/env python |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 2 | # |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 3 | # Class for profiling python code. rev 1.0 6/2/94 |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 4 | # |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 5 | # Based on prior profile module by Sjoerd Mullender... |
| 6 | # which was hacked somewhat by: Guido van Rossum |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 7 | |
Guido van Rossum | 54f22ed | 2000-02-04 15:10:34 +0000 | [diff] [blame] | 8 | """Class for profiling Python code.""" |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 9 | |
| 10 | # Copyright 1994, by InfoSeek Corporation, all rights reserved. |
| 11 | # Written by James Roskind |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 12 | # |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 13 | # Permission to use, copy, modify, and distribute this Python software |
| 14 | # and its associated documentation for any purpose (subject to the |
| 15 | # restriction in the following sentence) without fee is hereby granted, |
| 16 | # provided that the above copyright notice appears in all copies, and |
| 17 | # that both that copyright notice and this permission notice appear in |
| 18 | # supporting documentation, and that the name of InfoSeek not be used in |
| 19 | # advertising or publicity pertaining to distribution of the software |
| 20 | # without specific, written prior permission. This permission is |
| 21 | # explicitly restricted to the copying and modification of the software |
| 22 | # to remain in Python, compiled Python, or other languages (such as C) |
| 23 | # wherein the modified or derived code is exclusively imported into a |
| 24 | # Python module. |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 25 | # |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 26 | # INFOSEEK CORPORATION DISCLAIMS ALL WARRANTIES WITH REGARD TO THIS |
| 27 | # SOFTWARE, INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY AND |
| 28 | # FITNESS. IN NO EVENT SHALL INFOSEEK CORPORATION BE LIABLE FOR ANY |
| 29 | # SPECIAL, INDIRECT OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER |
| 30 | # RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF |
| 31 | # CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN |
| 32 | # CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE. |
| 33 | |
| 34 | |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 35 | |
| 36 | import sys |
Guido van Rossum | 4e16098 | 1992-09-02 20:43:20 +0000 | [diff] [blame] | 37 | import os |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 38 | import time |
Guido van Rossum | 4e16098 | 1992-09-02 20:43:20 +0000 | [diff] [blame] | 39 | import marshal |
Nicholas Bastin | 824b1b2 | 2004-03-23 18:44:39 +0000 | [diff] [blame] | 40 | from optparse import OptionParser |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 41 | |
Guido van Rossum | 48713e8 | 2004-03-23 19:19:21 +0000 | [diff] [blame] | 42 | __all__ = ["run", "runctx", "help", "Profile"] |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 43 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 44 | # Sample timer for use with |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 45 | #i_count = 0 |
| 46 | #def integer_timer(): |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 47 | # global i_count |
| 48 | # i_count = i_count + 1 |
| 49 | # return i_count |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 50 | #itimes = integer_timer # replace with C coded timer returning integers |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 51 | |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 52 | #************************************************************************** |
| 53 | # The following are the static member functions for the profiler class |
| 54 | # Note that an instance of Profile() is *not* needed to call them. |
| 55 | #************************************************************************** |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 56 | |
Nicholas Bastin | 824b1b2 | 2004-03-23 18:44:39 +0000 | [diff] [blame] | 57 | def run(statement, filename=None, sort=-1): |
Jeremy Hylton | adcf8a0 | 2001-03-14 20:01:19 +0000 | [diff] [blame] | 58 | """Run statement under profiler optionally saving results in filename |
Guido van Rossum | 4e16098 | 1992-09-02 20:43:20 +0000 | [diff] [blame] | 59 | |
Jeremy Hylton | adcf8a0 | 2001-03-14 20:01:19 +0000 | [diff] [blame] | 60 | This function takes a single argument that can be passed to the |
| 61 | "exec" statement, and an optional file name. In all cases this |
| 62 | routine attempts to "exec" its first argument and gather profiling |
| 63 | statistics from the execution. If no file name is present, then this |
| 64 | function automatically prints a simple profiling report, sorted by the |
| 65 | standard name string (file/line/function-name) that is presented in |
| 66 | each line. |
| 67 | """ |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 68 | prof = Profile() |
| 69 | try: |
| 70 | prof = prof.run(statement) |
| 71 | except SystemExit: |
| 72 | pass |
Jeremy Hylton | adcf8a0 | 2001-03-14 20:01:19 +0000 | [diff] [blame] | 73 | if filename is not None: |
| 74 | prof.dump_stats(filename) |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 75 | else: |
Nicholas Bastin | 824b1b2 | 2004-03-23 18:44:39 +0000 | [diff] [blame] | 76 | return prof.print_stats(sort) |
Guido van Rossum | e61fa0a | 1993-10-22 13:56:35 +0000 | [diff] [blame] | 77 | |
Nicholas Bastin | 1eb4bfc | 2004-03-22 20:12:56 +0000 | [diff] [blame] | 78 | def runctx(statement, globals, locals, filename=None): |
| 79 | """Run statement under profiler, supplying your own globals and locals, |
| 80 | optionally saving results in filename. |
| 81 | |
| 82 | statement and filename have the same semantics as profile.run |
| 83 | """ |
| 84 | prof = Profile() |
| 85 | try: |
| 86 | prof = prof.runctx(statement, globals, locals) |
| 87 | except SystemExit: |
| 88 | pass |
| 89 | |
| 90 | if filename is not None: |
| 91 | prof.dump_stats(filename) |
| 92 | else: |
| 93 | return prof.print_stats() |
| 94 | |
Johannes Gijsbers | c0b194a | 2005-01-10 09:07:22 +0000 | [diff] [blame] | 95 | # Backwards compatibility. |
Guido van Rossum | e61fa0a | 1993-10-22 13:56:35 +0000 | [diff] [blame] | 96 | def help(): |
Guido van Rossum | be19ed7 | 2007-02-09 05:37:30 +0000 | [diff] [blame] | 97 | print("Documentation for the profile module can be found ") |
| 98 | print("in the Python Library Reference, section 'The Python Profiler'.") |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 99 | |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame] | 100 | if os.name == "mac": |
Jack Jansen | 1bdcadd | 2001-06-19 20:11:36 +0000 | [diff] [blame] | 101 | import MacOS |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame] | 102 | def _get_time_mac(timer=MacOS.GetTicks): |
| 103 | return timer() / 60.0 |
| 104 | |
| 105 | if hasattr(os, "times"): |
| 106 | def _get_time_times(timer=os.times): |
| 107 | t = timer() |
| 108 | return t[0] + t[1] |
| 109 | |
Martin v. Löwis | a4dac40 | 2005-03-03 11:39:45 +0000 | [diff] [blame] | 110 | # Using getrusage(3) is better than clock(3) if available: |
| 111 | # on some systems (e.g. FreeBSD), getrusage has a higher resolution |
| 112 | # Furthermore, on a POSIX system, returns microseconds, which |
| 113 | # wrap around after 36min. |
| 114 | _has_res = 0 |
| 115 | try: |
| 116 | import resource |
| 117 | resgetrusage = lambda: resource.getrusage(resource.RUSAGE_SELF) |
| 118 | def _get_time_resource(timer=resgetrusage): |
| 119 | t = timer() |
| 120 | return t[0] + t[1] |
| 121 | _has_res = 1 |
| 122 | except ImportError: |
| 123 | pass |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame] | 124 | |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 125 | class Profile: |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 126 | """Profiler class. |
Guido van Rossum | 54f22ed | 2000-02-04 15:10:34 +0000 | [diff] [blame] | 127 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 128 | self.cur is always a tuple. Each such tuple corresponds to a stack |
| 129 | frame that is currently active (self.cur[-2]). The following are the |
| 130 | definitions of its members. We use this external "parallel stack" to |
| 131 | avoid contaminating the program that we are profiling. (old profiler |
| 132 | used to write into the frames local dictionary!!) Derived classes |
| 133 | can change the definition of some entries, as long as they leave |
Tim Peters | df5cfd8 | 2001-10-05 23:15:10 +0000 | [diff] [blame] | 134 | [-2:] intact (frame and previous tuple). In case an internal error is |
| 135 | detected, the -3 element is used as the function name. |
Guido van Rossum | 54f22ed | 2000-02-04 15:10:34 +0000 | [diff] [blame] | 136 | |
Tim Peters | df5cfd8 | 2001-10-05 23:15:10 +0000 | [diff] [blame] | 137 | [ 0] = Time that needs to be charged to the parent frame's function. |
| 138 | It is used so that a function call will not have to access the |
| 139 | timing data for the parent frame. |
| 140 | [ 1] = Total time spent in this frame's function, excluding time in |
Tim Peters | 8d061ed | 2001-10-07 08:35:44 +0000 | [diff] [blame] | 141 | subfunctions (this latter is tallied in cur[2]). |
Tim Peters | fb16378 | 2001-10-07 08:49:02 +0000 | [diff] [blame] | 142 | [ 2] = Total time spent in subfunctions, excluding time executing the |
Tim Peters | 8d061ed | 2001-10-07 08:35:44 +0000 | [diff] [blame] | 143 | frame's function (this latter is tallied in cur[1]). |
Tim Peters | df5cfd8 | 2001-10-05 23:15:10 +0000 | [diff] [blame] | 144 | [-3] = Name of the function that corresponds to this frame. |
Tim Peters | 8d061ed | 2001-10-07 08:35:44 +0000 | [diff] [blame] | 145 | [-2] = Actual frame that we correspond to (used to sync exception handling). |
| 146 | [-1] = Our parent 6-tuple (corresponds to frame.f_back). |
Guido van Rossum | 54f22ed | 2000-02-04 15:10:34 +0000 | [diff] [blame] | 147 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 148 | Timing data for each function is stored as a 5-tuple in the dictionary |
Tim Peters | df5cfd8 | 2001-10-05 23:15:10 +0000 | [diff] [blame] | 149 | self.timings[]. The index is always the name stored in self.cur[-3]. |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 150 | The following are the definitions of the members: |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 151 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 152 | [0] = The number of times this function was called, not counting direct |
| 153 | or indirect recursion, |
| 154 | [1] = Number of times this function appears on the stack, minus one |
| 155 | [2] = Total time spent internal to this function |
| 156 | [3] = Cumulative time that this function was present on the stack. In |
| 157 | non-recursive functions, this is the total execution time from start |
| 158 | to finish of each invocation of a function, including time spent in |
| 159 | all subfunctions. |
Tim Peters | 6e22149 | 2001-10-07 04:02:36 +0000 | [diff] [blame] | 160 | [4] = A dictionary indicating for each function name, the number of times |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 161 | it was called by us. |
| 162 | """ |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 163 | |
Tim Peters | 659a603 | 2001-10-09 20:51:19 +0000 | [diff] [blame] | 164 | bias = 0 # calibration constant |
| 165 | |
| 166 | def __init__(self, timer=None, bias=None): |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 167 | self.timings = {} |
| 168 | self.cur = None |
| 169 | self.cmd = "" |
Nicholas Bastin | c69ebe8 | 2004-03-24 21:57:10 +0000 | [diff] [blame] | 170 | self.c_func_name = "" |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 171 | |
Tim Peters | 659a603 | 2001-10-09 20:51:19 +0000 | [diff] [blame] | 172 | if bias is None: |
| 173 | bias = self.bias |
| 174 | self.bias = bias # Materialize in local dict for lookup speed. |
| 175 | |
Martin v. Löwis | a4dac40 | 2005-03-03 11:39:45 +0000 | [diff] [blame] | 176 | if not timer: |
| 177 | if _has_res: |
| 178 | self.timer = resgetrusage |
| 179 | self.dispatcher = self.trace_dispatch |
| 180 | self.get_time = _get_time_resource |
| 181 | elif os.name == 'mac': |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 182 | self.timer = MacOS.GetTicks |
| 183 | self.dispatcher = self.trace_dispatch_mac |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame] | 184 | self.get_time = _get_time_mac |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 185 | elif hasattr(time, 'clock'): |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame] | 186 | self.timer = self.get_time = time.clock |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 187 | self.dispatcher = self.trace_dispatch_i |
| 188 | elif hasattr(os, 'times'): |
| 189 | self.timer = os.times |
| 190 | self.dispatcher = self.trace_dispatch |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame] | 191 | self.get_time = _get_time_times |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 192 | else: |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame] | 193 | self.timer = self.get_time = time.time |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 194 | self.dispatcher = self.trace_dispatch_i |
| 195 | else: |
| 196 | self.timer = timer |
| 197 | t = self.timer() # test out timer function |
| 198 | try: |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame] | 199 | length = len(t) |
| 200 | except TypeError: |
| 201 | self.get_time = timer |
| 202 | self.dispatcher = self.trace_dispatch_i |
| 203 | else: |
| 204 | if length == 2: |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 205 | self.dispatcher = self.trace_dispatch |
| 206 | else: |
| 207 | self.dispatcher = self.trace_dispatch_l |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame] | 208 | # This get_time() implementation needs to be defined |
| 209 | # here to capture the passed-in timer in the parameter |
| 210 | # list (for performance). Note that we can't assume |
| 211 | # the timer() result contains two values in all |
| 212 | # cases. |
Raymond Hettinger | 97aa32b | 2003-10-22 16:49:01 +0000 | [diff] [blame] | 213 | def get_time_timer(timer=timer, sum=sum): |
| 214 | return sum(timer()) |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame] | 215 | self.get_time = get_time_timer |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 216 | self.t = self.get_time() |
| 217 | self.simulate_call('profiler') |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 218 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 219 | # Heavily optimized dispatch routine for os.times() timer |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 220 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 221 | def trace_dispatch(self, frame, event, arg): |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame] | 222 | timer = self.timer |
| 223 | t = timer() |
Tim Peters | 659a603 | 2001-10-09 20:51:19 +0000 | [diff] [blame] | 224 | t = t[0] + t[1] - self.t - self.bias |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 225 | |
Nicholas Bastin | c69ebe8 | 2004-03-24 21:57:10 +0000 | [diff] [blame] | 226 | if event == "c_call": |
Nicholas Bastin | 12ac3e1 | 2004-07-12 23:38:02 +0000 | [diff] [blame] | 227 | self.c_func_name = arg.__name__ |
Nicholas Bastin | c69ebe8 | 2004-03-24 21:57:10 +0000 | [diff] [blame] | 228 | |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame] | 229 | if self.dispatch[event](self, frame,t): |
| 230 | t = timer() |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 231 | self.t = t[0] + t[1] |
| 232 | else: |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame] | 233 | r = timer() |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 234 | self.t = r[0] + r[1] - t # put back unrecorded delta |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 235 | |
Tim Peters | 6e22149 | 2001-10-07 04:02:36 +0000 | [diff] [blame] | 236 | # Dispatch routine for best timer program (return = scalar, fastest if |
| 237 | # an integer but float works too -- and time.clock() relies on that). |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 238 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 239 | def trace_dispatch_i(self, frame, event, arg): |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame] | 240 | timer = self.timer |
Tim Peters | 659a603 | 2001-10-09 20:51:19 +0000 | [diff] [blame] | 241 | t = timer() - self.t - self.bias |
Nicholas Bastin | c69ebe8 | 2004-03-24 21:57:10 +0000 | [diff] [blame] | 242 | |
| 243 | if event == "c_call": |
Nicholas Bastin | 12ac3e1 | 2004-07-12 23:38:02 +0000 | [diff] [blame] | 244 | self.c_func_name = arg.__name__ |
Nicholas Bastin | c69ebe8 | 2004-03-24 21:57:10 +0000 | [diff] [blame] | 245 | |
| 246 | if self.dispatch[event](self, frame, t): |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame] | 247 | self.t = timer() |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 248 | else: |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame] | 249 | self.t = timer() - t # put back unrecorded delta |
Guido van Rossum | cbf3dd5 | 1997-10-08 15:23:02 +0000 | [diff] [blame] | 250 | |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame] | 251 | # Dispatch routine for macintosh (timer returns time in ticks of |
| 252 | # 1/60th second) |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 253 | |
| 254 | def trace_dispatch_mac(self, frame, event, arg): |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame] | 255 | timer = self.timer |
Tim Peters | 659a603 | 2001-10-09 20:51:19 +0000 | [diff] [blame] | 256 | t = timer()/60.0 - self.t - self.bias |
Nicholas Bastin | c69ebe8 | 2004-03-24 21:57:10 +0000 | [diff] [blame] | 257 | |
| 258 | if event == "c_call": |
Nicholas Bastin | 12ac3e1 | 2004-07-12 23:38:02 +0000 | [diff] [blame] | 259 | self.c_func_name = arg.__name__ |
Nicholas Bastin | c69ebe8 | 2004-03-24 21:57:10 +0000 | [diff] [blame] | 260 | |
Tim Peters | 659a603 | 2001-10-09 20:51:19 +0000 | [diff] [blame] | 261 | if self.dispatch[event](self, frame, t): |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame] | 262 | self.t = timer()/60.0 |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 263 | else: |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame] | 264 | self.t = timer()/60.0 - t # put back unrecorded delta |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 265 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 266 | # SLOW generic dispatch routine for timer returning lists of numbers |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 267 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 268 | def trace_dispatch_l(self, frame, event, arg): |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame] | 269 | get_time = self.get_time |
Tim Peters | 659a603 | 2001-10-09 20:51:19 +0000 | [diff] [blame] | 270 | t = get_time() - self.t - self.bias |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 271 | |
Nicholas Bastin | c69ebe8 | 2004-03-24 21:57:10 +0000 | [diff] [blame] | 272 | if event == "c_call": |
Nicholas Bastin | 12ac3e1 | 2004-07-12 23:38:02 +0000 | [diff] [blame] | 273 | self.c_func_name = arg.__name__ |
Nicholas Bastin | c69ebe8 | 2004-03-24 21:57:10 +0000 | [diff] [blame] | 274 | |
Tim Peters | 659a603 | 2001-10-09 20:51:19 +0000 | [diff] [blame] | 275 | if self.dispatch[event](self, frame, t): |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame] | 276 | self.t = get_time() |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 277 | else: |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame] | 278 | self.t = get_time() - t # put back unrecorded delta |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 279 | |
Tim Peters | 8d061ed | 2001-10-07 08:35:44 +0000 | [diff] [blame] | 280 | # In the event handlers, the first 3 elements of self.cur are unpacked |
| 281 | # into vrbls w/ 3-letter names. The last two characters are meant to be |
| 282 | # mnemonic: |
| 283 | # _pt self.cur[0] "parent time" time to be charged to parent frame |
| 284 | # _it self.cur[1] "internal time" time spent directly in the function |
| 285 | # _et self.cur[2] "external time" time spent in subfunctions |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 286 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 287 | def trace_dispatch_exception(self, frame, t): |
Tim Peters | 8d061ed | 2001-10-07 08:35:44 +0000 | [diff] [blame] | 288 | rpt, rit, ret, rfn, rframe, rcur = self.cur |
Fred Drake | a0bc999 | 2001-10-03 21:12:32 +0000 | [diff] [blame] | 289 | if (rframe is not frame) and rcur: |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 290 | return self.trace_dispatch_return(rframe, t) |
Tim Peters | 8d061ed | 2001-10-07 08:35:44 +0000 | [diff] [blame] | 291 | self.cur = rpt, rit+t, ret, rfn, rframe, rcur |
Guido van Rossum | f137f75 | 2001-10-04 00:58:24 +0000 | [diff] [blame] | 292 | return 1 |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 293 | |
| 294 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 295 | def trace_dispatch_call(self, frame, t): |
Tim Peters | df5cfd8 | 2001-10-05 23:15:10 +0000 | [diff] [blame] | 296 | if self.cur and frame.f_back is not self.cur[-2]: |
Tim Peters | 8d061ed | 2001-10-07 08:35:44 +0000 | [diff] [blame] | 297 | rpt, rit, ret, rfn, rframe, rcur = self.cur |
Guido van Rossum | f137f75 | 2001-10-04 00:58:24 +0000 | [diff] [blame] | 298 | if not isinstance(rframe, Profile.fake_frame): |
Tim Peters | db1ed2a | 2001-10-07 04:30:53 +0000 | [diff] [blame] | 299 | assert rframe.f_back is frame.f_back, ("Bad call", rfn, |
| 300 | rframe, rframe.f_back, |
| 301 | frame, frame.f_back) |
Guido van Rossum | f137f75 | 2001-10-04 00:58:24 +0000 | [diff] [blame] | 302 | self.trace_dispatch_return(rframe, 0) |
Tim Peters | db1ed2a | 2001-10-07 04:30:53 +0000 | [diff] [blame] | 303 | assert (self.cur is None or \ |
| 304 | frame.f_back is self.cur[-2]), ("Bad call", |
| 305 | self.cur[-3]) |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 306 | fcode = frame.f_code |
| 307 | fn = (fcode.co_filename, fcode.co_firstlineno, fcode.co_name) |
| 308 | self.cur = (t, 0, 0, fn, frame, self.cur) |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame] | 309 | timings = self.timings |
Raymond Hettinger | 54f0222 | 2002-06-01 14:18:47 +0000 | [diff] [blame] | 310 | if fn in timings: |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame] | 311 | cc, ns, tt, ct, callers = timings[fn] |
| 312 | timings[fn] = cc, ns + 1, tt, ct, callers |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 313 | else: |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame] | 314 | timings[fn] = 0, 0, 0, 0, {} |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 315 | return 1 |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 316 | |
Nicholas Bastin | c69ebe8 | 2004-03-24 21:57:10 +0000 | [diff] [blame] | 317 | def trace_dispatch_c_call (self, frame, t): |
| 318 | fn = ("", 0, self.c_func_name) |
| 319 | self.cur = (t, 0, 0, fn, frame, self.cur) |
| 320 | timings = self.timings |
Guido van Rossum | e2b70bc | 2006-08-18 22:13:04 +0000 | [diff] [blame] | 321 | if fn in timings: |
Nicholas Bastin | c69ebe8 | 2004-03-24 21:57:10 +0000 | [diff] [blame] | 322 | cc, ns, tt, ct, callers = timings[fn] |
| 323 | timings[fn] = cc, ns+1, tt, ct, callers |
| 324 | else: |
| 325 | timings[fn] = 0, 0, 0, 0, {} |
| 326 | return 1 |
| 327 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 328 | def trace_dispatch_return(self, frame, t): |
Tim Peters | df5cfd8 | 2001-10-05 23:15:10 +0000 | [diff] [blame] | 329 | if frame is not self.cur[-2]: |
Tim Peters | db1ed2a | 2001-10-07 04:30:53 +0000 | [diff] [blame] | 330 | assert frame is self.cur[-2].f_back, ("Bad return", self.cur[-3]) |
| 331 | self.trace_dispatch_return(self.cur[-2], 0) |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 332 | |
Tim Peters | 8d061ed | 2001-10-07 08:35:44 +0000 | [diff] [blame] | 333 | # Prefix "r" means part of the Returning or exiting frame. |
| 334 | # Prefix "p" means part of the Previous or Parent or older frame. |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 335 | |
Tim Peters | 8d061ed | 2001-10-07 08:35:44 +0000 | [diff] [blame] | 336 | rpt, rit, ret, rfn, frame, rcur = self.cur |
| 337 | rit = rit + t |
| 338 | frame_total = rit + ret |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 339 | |
Tim Peters | 8d061ed | 2001-10-07 08:35:44 +0000 | [diff] [blame] | 340 | ppt, pit, pet, pfn, pframe, pcur = rcur |
| 341 | self.cur = ppt, pit + rpt, pet + frame_total, pfn, pframe, pcur |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 342 | |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame] | 343 | timings = self.timings |
| 344 | cc, ns, tt, ct, callers = timings[rfn] |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 345 | if not ns: |
Tim Peters | 8d061ed | 2001-10-07 08:35:44 +0000 | [diff] [blame] | 346 | # This is the only occurrence of the function on the stack. |
| 347 | # Else this is a (directly or indirectly) recursive call, and |
| 348 | # its cumulative time will get updated when the topmost call to |
| 349 | # it returns. |
| 350 | ct = ct + frame_total |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 351 | cc = cc + 1 |
Tim Peters | 8d061ed | 2001-10-07 08:35:44 +0000 | [diff] [blame] | 352 | |
Raymond Hettinger | 54f0222 | 2002-06-01 14:18:47 +0000 | [diff] [blame] | 353 | if pfn in callers: |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 354 | callers[pfn] = callers[pfn] + 1 # hack: gather more |
| 355 | # stats such as the amount of time added to ct courtesy |
| 356 | # of this specific call, and the contribution to cc |
| 357 | # courtesy of this call. |
| 358 | else: |
| 359 | callers[pfn] = 1 |
Tim Peters | 8d061ed | 2001-10-07 08:35:44 +0000 | [diff] [blame] | 360 | |
| 361 | timings[rfn] = cc, ns - 1, tt + rit, ct, callers |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 362 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 363 | return 1 |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 364 | |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame] | 365 | |
| 366 | dispatch = { |
| 367 | "call": trace_dispatch_call, |
| 368 | "exception": trace_dispatch_exception, |
| 369 | "return": trace_dispatch_return, |
Nicholas Bastin | c69ebe8 | 2004-03-24 21:57:10 +0000 | [diff] [blame] | 370 | "c_call": trace_dispatch_c_call, |
Armin Rigo | f879024 | 2005-09-20 18:50:13 +0000 | [diff] [blame] | 371 | "c_exception": trace_dispatch_return, # the C function returned |
Nicholas Bastin | c69ebe8 | 2004-03-24 21:57:10 +0000 | [diff] [blame] | 372 | "c_return": trace_dispatch_return, |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame] | 373 | } |
| 374 | |
| 375 | |
Tim Peters | db1ed2a | 2001-10-07 04:30:53 +0000 | [diff] [blame] | 376 | # The next few functions play with self.cmd. By carefully preloading |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 377 | # our parallel stack, we can force the profiled result to include |
| 378 | # an arbitrary string as the name of the calling function. |
| 379 | # We use self.cmd as that string, and the resulting stats look |
| 380 | # very nice :-). |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 381 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 382 | def set_cmd(self, cmd): |
Tim Peters | df5cfd8 | 2001-10-05 23:15:10 +0000 | [diff] [blame] | 383 | if self.cur[-1]: return # already set |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 384 | self.cmd = cmd |
| 385 | self.simulate_call(cmd) |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 386 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 387 | class fake_code: |
| 388 | def __init__(self, filename, line, name): |
| 389 | self.co_filename = filename |
| 390 | self.co_line = line |
| 391 | self.co_name = name |
| 392 | self.co_firstlineno = 0 |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 393 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 394 | def __repr__(self): |
| 395 | return repr((self.co_filename, self.co_line, self.co_name)) |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 396 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 397 | class fake_frame: |
| 398 | def __init__(self, code, prior): |
| 399 | self.f_code = code |
| 400 | self.f_back = prior |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 401 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 402 | def simulate_call(self, name): |
| 403 | code = self.fake_code('profile', 0, name) |
| 404 | if self.cur: |
Tim Peters | df5cfd8 | 2001-10-05 23:15:10 +0000 | [diff] [blame] | 405 | pframe = self.cur[-2] |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 406 | else: |
| 407 | pframe = None |
| 408 | frame = self.fake_frame(code, pframe) |
Fred Drake | d10ed8b | 2001-10-17 01:49:50 +0000 | [diff] [blame] | 409 | self.dispatch['call'](self, frame, 0) |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 410 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 411 | # collect stats from pending stack, including getting final |
| 412 | # timings for self.cmd frame. |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 413 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 414 | def simulate_cmd_complete(self): |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame] | 415 | get_time = self.get_time |
| 416 | t = get_time() - self.t |
Tim Peters | df5cfd8 | 2001-10-05 23:15:10 +0000 | [diff] [blame] | 417 | while self.cur[-1]: |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 418 | # We *can* cause assertion errors here if |
| 419 | # dispatch_trace_return checks for a frame match! |
Fred Drake | d10ed8b | 2001-10-17 01:49:50 +0000 | [diff] [blame] | 420 | self.dispatch['return'](self, self.cur[-2], t) |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 421 | t = 0 |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame] | 422 | self.t = get_time() - t |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 423 | |
| 424 | |
Nicholas Bastin | 824b1b2 | 2004-03-23 18:44:39 +0000 | [diff] [blame] | 425 | def print_stats(self, sort=-1): |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 426 | import pstats |
Nicholas Bastin | 824b1b2 | 2004-03-23 18:44:39 +0000 | [diff] [blame] | 427 | pstats.Stats(self).strip_dirs().sort_stats(sort). \ |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 428 | print_stats() |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 429 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 430 | def dump_stats(self, file): |
| 431 | f = open(file, 'wb') |
| 432 | self.create_stats() |
| 433 | marshal.dump(self.stats, f) |
| 434 | f.close() |
| 435 | |
| 436 | def create_stats(self): |
| 437 | self.simulate_cmd_complete() |
| 438 | self.snapshot_stats() |
| 439 | |
| 440 | def snapshot_stats(self): |
| 441 | self.stats = {} |
Guido van Rossum | cc2b016 | 2007-02-11 06:12:03 +0000 | [diff] [blame] | 442 | for func, (cc, ns, tt, ct, callers) in self.timings.items(): |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 443 | callers = callers.copy() |
| 444 | nc = 0 |
Guido van Rossum | cc2b016 | 2007-02-11 06:12:03 +0000 | [diff] [blame] | 445 | for callcnt in callers.values(): |
Raymond Hettinger | e0d4972 | 2002-06-02 18:55:56 +0000 | [diff] [blame] | 446 | nc += callcnt |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 447 | self.stats[func] = cc, nc, tt, ct, callers |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 448 | |
| 449 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 450 | # The following two methods can be called by clients to use |
| 451 | # a profiler to profile a statement, given as a string. |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 452 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 453 | def run(self, cmd): |
| 454 | import __main__ |
| 455 | dict = __main__.__dict__ |
| 456 | return self.runctx(cmd, dict, dict) |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 457 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 458 | def runctx(self, cmd, globals, locals): |
| 459 | self.set_cmd(cmd) |
| 460 | sys.setprofile(self.dispatcher) |
| 461 | try: |
Georg Brandl | 7cae87c | 2006-09-06 06:51:57 +0000 | [diff] [blame] | 462 | exec(cmd, globals, locals) |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 463 | finally: |
| 464 | sys.setprofile(None) |
| 465 | return self |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 466 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 467 | # This method is more useful to profile a single function call. |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame] | 468 | def runcall(self, func, *args, **kw): |
Walter Dörwald | 70a6b49 | 2004-02-12 17:35:32 +0000 | [diff] [blame] | 469 | self.set_cmd(repr(func)) |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 470 | sys.setprofile(self.dispatcher) |
| 471 | try: |
Guido van Rossum | 68468eb | 2003-02-27 20:14:51 +0000 | [diff] [blame] | 472 | return func(*args, **kw) |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 473 | finally: |
| 474 | sys.setprofile(None) |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 475 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 476 | |
| 477 | #****************************************************************** |
| 478 | # The following calculates the overhead for using a profiler. The |
| 479 | # problem is that it takes a fair amount of time for the profiler |
| 480 | # to stop the stopwatch (from the time it receives an event). |
| 481 | # Similarly, there is a delay from the time that the profiler |
| 482 | # re-starts the stopwatch before the user's code really gets to |
| 483 | # continue. The following code tries to measure the difference on |
Tim Peters | 659a603 | 2001-10-09 20:51:19 +0000 | [diff] [blame] | 484 | # a per-event basis. |
| 485 | # |
| 486 | # Note that this difference is only significant if there are a lot of |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 487 | # events, and relatively little user code per event. For example, |
| 488 | # code with small functions will typically benefit from having the |
| 489 | # profiler calibrated for the current platform. This *could* be |
| 490 | # done on the fly during init() time, but it is not worth the |
| 491 | # effort. Also note that if too large a value specified, then |
| 492 | # execution time on some functions will actually appear as a |
| 493 | # negative number. It is *normal* for some functions (with very |
| 494 | # low call counts) to have such negative stats, even if the |
| 495 | # calibration figure is "correct." |
| 496 | # |
| 497 | # One alternative to profile-time calibration adjustments (i.e., |
| 498 | # adding in the magic little delta during each event) is to track |
| 499 | # more carefully the number of events (and cumulatively, the number |
| 500 | # of events during sub functions) that are seen. If this were |
| 501 | # done, then the arithmetic could be done after the fact (i.e., at |
| 502 | # display time). Currently, we track only call/return events. |
| 503 | # These values can be deduced by examining the callees and callers |
| 504 | # vectors for each functions. Hence we *can* almost correct the |
| 505 | # internal time figure at print time (note that we currently don't |
| 506 | # track exception event processing counts). Unfortunately, there |
| 507 | # is currently no similar information for cumulative sub-function |
| 508 | # time. It would not be hard to "get all this info" at profiler |
| 509 | # time. Specifically, we would have to extend the tuples to keep |
| 510 | # counts of this in each frame, and then extend the defs of timing |
| 511 | # tuples to include the significant two figures. I'm a bit fearful |
| 512 | # that this additional feature will slow the heavily optimized |
| 513 | # event/time ratio (i.e., the profiler would run slower, fur a very |
| 514 | # low "value added" feature.) |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 515 | #************************************************************** |
| 516 | |
Tim Peters | cce092d | 2001-10-09 05:31:56 +0000 | [diff] [blame] | 517 | def calibrate(self, m, verbose=0): |
Tim Peters | 659a603 | 2001-10-09 20:51:19 +0000 | [diff] [blame] | 518 | if self.__class__ is not Profile: |
| 519 | raise TypeError("Subclasses must override .calibrate().") |
| 520 | |
| 521 | saved_bias = self.bias |
| 522 | self.bias = 0 |
| 523 | try: |
Tim Peters | e13cc92 | 2001-10-09 21:01:31 +0000 | [diff] [blame] | 524 | return self._calibrate_inner(m, verbose) |
Tim Peters | 659a603 | 2001-10-09 20:51:19 +0000 | [diff] [blame] | 525 | finally: |
| 526 | self.bias = saved_bias |
| 527 | |
Tim Peters | e13cc92 | 2001-10-09 21:01:31 +0000 | [diff] [blame] | 528 | def _calibrate_inner(self, m, verbose): |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame] | 529 | get_time = self.get_time |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 530 | |
Tim Peters | cce092d | 2001-10-09 05:31:56 +0000 | [diff] [blame] | 531 | # Set up a test case to be run with and without profiling. Include |
| 532 | # lots of calls, because we're trying to quantify stopwatch overhead. |
| 533 | # Do not raise any exceptions, though, because we want to know |
| 534 | # exactly how many profile events are generated (one call event, + |
| 535 | # one return event, per Python-level call). |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 536 | |
Tim Peters | cce092d | 2001-10-09 05:31:56 +0000 | [diff] [blame] | 537 | def f1(n): |
| 538 | for i in range(n): |
| 539 | x = 1 |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 540 | |
Tim Peters | cce092d | 2001-10-09 05:31:56 +0000 | [diff] [blame] | 541 | def f(m, f1=f1): |
| 542 | for i in range(m): |
| 543 | f1(100) |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 544 | |
Tim Peters | cce092d | 2001-10-09 05:31:56 +0000 | [diff] [blame] | 545 | f(m) # warm up the cache |
| 546 | |
| 547 | # elapsed_noprofile <- time f(m) takes without profiling. |
| 548 | t0 = get_time() |
| 549 | f(m) |
| 550 | t1 = get_time() |
| 551 | elapsed_noprofile = t1 - t0 |
| 552 | if verbose: |
Guido van Rossum | be19ed7 | 2007-02-09 05:37:30 +0000 | [diff] [blame] | 553 | print("elapsed time without profiling =", elapsed_noprofile) |
Tim Peters | cce092d | 2001-10-09 05:31:56 +0000 | [diff] [blame] | 554 | |
| 555 | # elapsed_profile <- time f(m) takes with profiling. The difference |
| 556 | # is profiling overhead, only some of which the profiler subtracts |
| 557 | # out on its own. |
| 558 | p = Profile() |
| 559 | t0 = get_time() |
| 560 | p.runctx('f(m)', globals(), locals()) |
| 561 | t1 = get_time() |
| 562 | elapsed_profile = t1 - t0 |
| 563 | if verbose: |
Guido van Rossum | be19ed7 | 2007-02-09 05:37:30 +0000 | [diff] [blame] | 564 | print("elapsed time with profiling =", elapsed_profile) |
Tim Peters | cce092d | 2001-10-09 05:31:56 +0000 | [diff] [blame] | 565 | |
| 566 | # reported_time <- "CPU seconds" the profiler charged to f and f1. |
| 567 | total_calls = 0.0 |
| 568 | reported_time = 0.0 |
| 569 | for (filename, line, funcname), (cc, ns, tt, ct, callers) in \ |
| 570 | p.timings.items(): |
| 571 | if funcname in ("f", "f1"): |
| 572 | total_calls += cc |
| 573 | reported_time += tt |
| 574 | |
| 575 | if verbose: |
Guido van Rossum | be19ed7 | 2007-02-09 05:37:30 +0000 | [diff] [blame] | 576 | print("'CPU seconds' profiler reported =", reported_time) |
| 577 | print("total # calls =", total_calls) |
Tim Peters | cce092d | 2001-10-09 05:31:56 +0000 | [diff] [blame] | 578 | if total_calls != m + 1: |
| 579 | raise ValueError("internal error: total calls = %d" % total_calls) |
| 580 | |
| 581 | # reported_time - elapsed_noprofile = overhead the profiler wasn't |
| 582 | # able to measure. Divide by twice the number of calls (since there |
| 583 | # are two profiler events per call in this test) to get the hidden |
| 584 | # overhead per event. |
| 585 | mean = (reported_time - elapsed_noprofile) / 2.0 / total_calls |
| 586 | if verbose: |
Guido van Rossum | be19ed7 | 2007-02-09 05:37:30 +0000 | [diff] [blame] | 587 | print("mean stopwatch overhead per profile event =", mean) |
Tim Peters | cce092d | 2001-10-09 05:31:56 +0000 | [diff] [blame] | 588 | return mean |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 589 | |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 590 | #**************************************************************************** |
| 591 | def Stats(*args): |
Guido van Rossum | be19ed7 | 2007-02-09 05:37:30 +0000 | [diff] [blame] | 592 | print('Report generating functions are in the "pstats" module\a') |
Guido van Rossum | cc778eb | 1996-10-01 02:55:54 +0000 | [diff] [blame] | 593 | |
Johannes Gijsbers | 2abe785 | 2005-01-09 01:58:02 +0000 | [diff] [blame] | 594 | def main(): |
Nicholas Bastin | 824b1b2 | 2004-03-23 18:44:39 +0000 | [diff] [blame] | 595 | usage = "profile.py [-o output_file_path] [-s sort] scriptfile [arg] ..." |
Johannes Gijsbers | 2abe785 | 2005-01-09 01:58:02 +0000 | [diff] [blame] | 596 | parser = OptionParser(usage=usage) |
Nicholas Bastin | 824b1b2 | 2004-03-23 18:44:39 +0000 | [diff] [blame] | 597 | parser.allow_interspersed_args = False |
Tim Peters | 4e0e1b6 | 2004-07-07 20:54:48 +0000 | [diff] [blame] | 598 | parser.add_option('-o', '--outfile', dest="outfile", |
Nicholas Bastin | 824b1b2 | 2004-03-23 18:44:39 +0000 | [diff] [blame] | 599 | help="Save stats to <outfile>", default=None) |
| 600 | parser.add_option('-s', '--sort', dest="sort", |
| 601 | help="Sort order when printing to stdout, based on pstats.Stats class", default=-1) |
Tim Peters | b497c10 | 2005-01-10 16:48:37 +0000 | [diff] [blame] | 602 | |
Johannes Gijsbers | 2abe785 | 2005-01-09 01:58:02 +0000 | [diff] [blame] | 603 | if not sys.argv[1:]: |
| 604 | parser.print_usage() |
| 605 | sys.exit(2) |
Tim Peters | b497c10 | 2005-01-10 16:48:37 +0000 | [diff] [blame] | 606 | |
Nicholas Bastin | 824b1b2 | 2004-03-23 18:44:39 +0000 | [diff] [blame] | 607 | (options, args) = parser.parse_args() |
Tim Peters | b497c10 | 2005-01-10 16:48:37 +0000 | [diff] [blame] | 608 | |
Matthias Klose | b111743 | 2009-09-13 15:31:14 +0000 | [diff] [blame] | 609 | if (len(args) > 0): |
| 610 | sys.argv[:] = args |
Nicholas Bastin | 824b1b2 | 2004-03-23 18:44:39 +0000 | [diff] [blame] | 611 | sys.path.insert(0, os.path.dirname(sys.argv[0])) |
Neal Norwitz | 0168802 | 2007-08-12 00:43:29 +0000 | [diff] [blame] | 612 | fp = open(sys.argv[0]) |
| 613 | try: |
| 614 | script = fp.read() |
| 615 | finally: |
| 616 | fp.close() |
| 617 | run('exec(%r)' % script, options.outfile, options.sort) |
Nicholas Bastin | 824b1b2 | 2004-03-23 18:44:39 +0000 | [diff] [blame] | 618 | else: |
Johannes Gijsbers | 2abe785 | 2005-01-09 01:58:02 +0000 | [diff] [blame] | 619 | parser.print_usage() |
| 620 | return parser |
| 621 | |
| 622 | # When invoked as main program, invoke the profiler on a script |
| 623 | if __name__ == '__main__': |
| 624 | main() |