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 |
| 7 | # |
| 8 | # See profile.doc for more information |
| 9 | |
Guido van Rossum | 54f22ed | 2000-02-04 15:10:34 +0000 | [diff] [blame] | 10 | """Class for profiling Python code.""" |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 11 | |
| 12 | # Copyright 1994, by InfoSeek Corporation, all rights reserved. |
| 13 | # Written by James Roskind |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 14 | # |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 15 | # Permission to use, copy, modify, and distribute this Python software |
| 16 | # and its associated documentation for any purpose (subject to the |
| 17 | # restriction in the following sentence) without fee is hereby granted, |
| 18 | # provided that the above copyright notice appears in all copies, and |
| 19 | # that both that copyright notice and this permission notice appear in |
| 20 | # supporting documentation, and that the name of InfoSeek not be used in |
| 21 | # advertising or publicity pertaining to distribution of the software |
| 22 | # without specific, written prior permission. This permission is |
| 23 | # explicitly restricted to the copying and modification of the software |
| 24 | # to remain in Python, compiled Python, or other languages (such as C) |
| 25 | # wherein the modified or derived code is exclusively imported into a |
| 26 | # Python module. |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 27 | # |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 28 | # INFOSEEK CORPORATION DISCLAIMS ALL WARRANTIES WITH REGARD TO THIS |
| 29 | # SOFTWARE, INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY AND |
| 30 | # FITNESS. IN NO EVENT SHALL INFOSEEK CORPORATION BE LIABLE FOR ANY |
| 31 | # SPECIAL, INDIRECT OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER |
| 32 | # RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF |
| 33 | # CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN |
| 34 | # CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE. |
| 35 | |
| 36 | |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 37 | |
| 38 | import sys |
Guido van Rossum | 4e16098 | 1992-09-02 20:43:20 +0000 | [diff] [blame] | 39 | import os |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 40 | import time |
Guido van Rossum | 4e16098 | 1992-09-02 20:43:20 +0000 | [diff] [blame] | 41 | import marshal |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 42 | |
Skip Montanaro | c62c81e | 2001-02-12 02:00:42 +0000 | [diff] [blame] | 43 | __all__ = ["run","help","Profile"] |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 44 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 45 | # Sample timer for use with |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 46 | #i_count = 0 |
| 47 | #def integer_timer(): |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 48 | # global i_count |
| 49 | # i_count = i_count + 1 |
| 50 | # return i_count |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 51 | #itimes = integer_timer # replace with C coded timer returning integers |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 52 | |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 53 | #************************************************************************** |
| 54 | # The following are the static member functions for the profiler class |
| 55 | # Note that an instance of Profile() is *not* needed to call them. |
| 56 | #************************************************************************** |
Guido van Rossum | 8176258 | 1992-04-21 15:36:23 +0000 | [diff] [blame] | 57 | |
Jeremy Hylton | adcf8a0 | 2001-03-14 20:01:19 +0000 | [diff] [blame] | 58 | def run(statement, filename=None): |
| 59 | """Run statement under profiler optionally saving results in filename |
Guido van Rossum | 4e16098 | 1992-09-02 20:43:20 +0000 | [diff] [blame] | 60 | |
Jeremy Hylton | adcf8a0 | 2001-03-14 20:01:19 +0000 | [diff] [blame] | 61 | This function takes a single argument that can be passed to the |
| 62 | "exec" statement, and an optional file name. In all cases this |
| 63 | routine attempts to "exec" its first argument and gather profiling |
| 64 | statistics from the execution. If no file name is present, then this |
| 65 | function automatically prints a simple profiling report, sorted by the |
| 66 | standard name string (file/line/function-name) that is presented in |
| 67 | each line. |
| 68 | """ |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 69 | prof = Profile() |
| 70 | try: |
| 71 | prof = prof.run(statement) |
| 72 | except SystemExit: |
| 73 | pass |
Jeremy Hylton | adcf8a0 | 2001-03-14 20:01:19 +0000 | [diff] [blame] | 74 | if filename is not None: |
| 75 | prof.dump_stats(filename) |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 76 | else: |
| 77 | return prof.print_stats() |
Guido van Rossum | e61fa0a | 1993-10-22 13:56:35 +0000 | [diff] [blame] | 78 | |
| 79 | # print help |
| 80 | def help(): |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 81 | for dirname in sys.path: |
| 82 | fullname = os.path.join(dirname, 'profile.doc') |
| 83 | if os.path.exists(fullname): |
| 84 | sts = os.system('${PAGER-more} '+fullname) |
| 85 | if sts: print '*** Pager exit status:', sts |
| 86 | break |
| 87 | else: |
| 88 | print 'Sorry, can\'t find the help file "profile.doc"', |
| 89 | print 'along the Python search path' |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 90 | |
| 91 | |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame^] | 92 | if os.name == "mac": |
| 93 | def _get_time_mac(timer=MacOS.GetTicks): |
| 94 | return timer() / 60.0 |
| 95 | |
| 96 | if hasattr(os, "times"): |
| 97 | def _get_time_times(timer=os.times): |
| 98 | t = timer() |
| 99 | return t[0] + t[1] |
| 100 | |
| 101 | |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 102 | class Profile: |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 103 | """Profiler class. |
Guido van Rossum | 54f22ed | 2000-02-04 15:10:34 +0000 | [diff] [blame] | 104 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 105 | self.cur is always a tuple. Each such tuple corresponds to a stack |
| 106 | frame that is currently active (self.cur[-2]). The following are the |
| 107 | definitions of its members. We use this external "parallel stack" to |
| 108 | avoid contaminating the program that we are profiling. (old profiler |
| 109 | used to write into the frames local dictionary!!) Derived classes |
| 110 | can change the definition of some entries, as long as they leave |
| 111 | [-2:] intact. |
Guido van Rossum | 54f22ed | 2000-02-04 15:10:34 +0000 | [diff] [blame] | 112 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 113 | [ 0] = Time that needs to be charged to the parent frame's function. |
| 114 | It is used so that a function call will not have to access the |
| 115 | timing data for the parent frame. |
| 116 | [ 1] = Total time spent in this frame's function, excluding time in |
| 117 | subfunctions |
| 118 | [ 2] = Cumulative time spent in this frame's function, including time in |
| 119 | all subfunctions to this frame. |
| 120 | [-3] = Name of the function that corresponds to this frame. |
| 121 | [-2] = Actual frame that we correspond to (used to sync exception handling) |
| 122 | [-1] = Our parent 6-tuple (corresponds to frame.f_back) |
Guido van Rossum | 54f22ed | 2000-02-04 15:10:34 +0000 | [diff] [blame] | 123 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 124 | Timing data for each function is stored as a 5-tuple in the dictionary |
| 125 | self.timings[]. The index is always the name stored in self.cur[4]. |
| 126 | The following are the definitions of the members: |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 127 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 128 | [0] = The number of times this function was called, not counting direct |
| 129 | or indirect recursion, |
| 130 | [1] = Number of times this function appears on the stack, minus one |
| 131 | [2] = Total time spent internal to this function |
| 132 | [3] = Cumulative time that this function was present on the stack. In |
| 133 | non-recursive functions, this is the total execution time from start |
| 134 | to finish of each invocation of a function, including time spent in |
| 135 | all subfunctions. |
| 136 | [5] = A dictionary indicating for each function name, the number of times |
| 137 | it was called by us. |
| 138 | """ |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 139 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 140 | def __init__(self, timer=None): |
| 141 | self.timings = {} |
| 142 | self.cur = None |
| 143 | self.cmd = "" |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 144 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 145 | if not timer: |
| 146 | if os.name == 'mac': |
| 147 | import MacOS |
| 148 | self.timer = MacOS.GetTicks |
| 149 | self.dispatcher = self.trace_dispatch_mac |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame^] | 150 | self.get_time = _get_time_mac |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 151 | elif hasattr(time, 'clock'): |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame^] | 152 | self.timer = self.get_time = time.clock |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 153 | self.dispatcher = self.trace_dispatch_i |
| 154 | elif hasattr(os, 'times'): |
| 155 | self.timer = os.times |
| 156 | self.dispatcher = self.trace_dispatch |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame^] | 157 | self.get_time = _get_time_times |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 158 | else: |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame^] | 159 | self.timer = self.get_time = time.time |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 160 | self.dispatcher = self.trace_dispatch_i |
| 161 | else: |
| 162 | self.timer = timer |
| 163 | t = self.timer() # test out timer function |
| 164 | try: |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame^] | 165 | length = len(t) |
| 166 | except TypeError: |
| 167 | self.get_time = timer |
| 168 | self.dispatcher = self.trace_dispatch_i |
| 169 | else: |
| 170 | if length == 2: |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 171 | self.dispatcher = self.trace_dispatch |
| 172 | else: |
| 173 | self.dispatcher = self.trace_dispatch_l |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame^] | 174 | # This get_time() implementation needs to be defined |
| 175 | # here to capture the passed-in timer in the parameter |
| 176 | # list (for performance). Note that we can't assume |
| 177 | # the timer() result contains two values in all |
| 178 | # cases. |
| 179 | def get_time_timer(timer=timer, |
| 180 | reduce=reduce, reducer=operator.add): |
| 181 | return reduce(reducer, timer(), 0) |
| 182 | self.get_time = get_time_timer |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 183 | self.t = self.get_time() |
| 184 | self.simulate_call('profiler') |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 185 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 186 | # Heavily optimized dispatch routine for os.times() timer |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 187 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 188 | def trace_dispatch(self, frame, event, arg): |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame^] | 189 | timer = self.timer |
| 190 | t = timer() |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 191 | t = t[0] + t[1] - self.t # No Calibration constant |
| 192 | # t = t[0] + t[1] - self.t - .00053 # Calibration constant |
| 193 | |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame^] | 194 | if self.dispatch[event](self, frame,t): |
| 195 | t = timer() |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 196 | self.t = t[0] + t[1] |
| 197 | else: |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame^] | 198 | r = timer() |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 199 | self.t = r[0] + r[1] - t # put back unrecorded delta |
| 200 | return |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 201 | |
| 202 | |
| 203 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 204 | # Dispatch routine for best timer program (return = scalar integer) |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 205 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 206 | def trace_dispatch_i(self, frame, event, arg): |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame^] | 207 | timer = self.timer |
| 208 | t = timer() - self.t # - 1 # Integer calibration constant |
| 209 | if self.dispatch[event](self, frame,t): |
| 210 | self.t = timer() |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 211 | else: |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame^] | 212 | self.t = timer() - t # put back unrecorded delta |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 213 | return |
Guido van Rossum | cbf3dd5 | 1997-10-08 15:23:02 +0000 | [diff] [blame] | 214 | |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame^] | 215 | # Dispatch routine for macintosh (timer returns time in ticks of |
| 216 | # 1/60th second) |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 217 | |
| 218 | def trace_dispatch_mac(self, frame, event, arg): |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame^] | 219 | timer = self.timer |
| 220 | t = timer()/60.0 - self.t # - 1 # Integer calibration constant |
| 221 | if self.dispatch[event](self, frame,t): |
| 222 | self.t = timer()/60.0 |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 223 | else: |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame^] | 224 | self.t = timer()/60.0 - t # put back unrecorded delta |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 225 | return |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 226 | |
| 227 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 228 | # SLOW generic dispatch routine for timer returning lists of numbers |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 229 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 230 | def trace_dispatch_l(self, frame, event, arg): |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame^] | 231 | get_time = self.get_time |
| 232 | t = get_time() - self.t |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 233 | |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame^] | 234 | if self.dispatch[event](self, frame,t): |
| 235 | self.t = get_time() |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 236 | else: |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame^] | 237 | self.t = get_time() - t # put back unrecorded delta |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 238 | return |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 239 | |
| 240 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 241 | def trace_dispatch_exception(self, frame, t): |
| 242 | rt, rtt, rct, rfn, rframe, rcur = self.cur |
| 243 | if (not rframe is frame) and rcur: |
| 244 | return self.trace_dispatch_return(rframe, t) |
| 245 | return 0 |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 246 | |
| 247 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 248 | def trace_dispatch_call(self, frame, t): |
| 249 | fcode = frame.f_code |
| 250 | fn = (fcode.co_filename, fcode.co_firstlineno, fcode.co_name) |
| 251 | self.cur = (t, 0, 0, fn, frame, self.cur) |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame^] | 252 | timings = self.timings |
| 253 | if timings.has_key(fn): |
| 254 | cc, ns, tt, ct, callers = timings[fn] |
| 255 | timings[fn] = cc, ns + 1, tt, ct, callers |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 256 | else: |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame^] | 257 | timings[fn] = 0, 0, 0, 0, {} |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 258 | return 1 |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 259 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 260 | def trace_dispatch_return(self, frame, t): |
| 261 | # if not frame is self.cur[-2]: raise "Bad return", self.cur[3] |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 262 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 263 | # Prefix "r" means part of the Returning or exiting frame |
| 264 | # Prefix "p" means part of the Previous or older frame |
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 | rt, rtt, rct, rfn, frame, rcur = self.cur |
| 267 | rtt = rtt + t |
| 268 | sft = rtt + rct |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 269 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 270 | pt, ptt, pct, pfn, pframe, pcur = rcur |
| 271 | self.cur = pt, ptt+rt, pct+sft, pfn, pframe, pcur |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 272 | |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame^] | 273 | timings = self.timings |
| 274 | cc, ns, tt, ct, callers = timings[rfn] |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 275 | if not ns: |
| 276 | ct = ct + sft |
| 277 | cc = cc + 1 |
| 278 | if callers.has_key(pfn): |
| 279 | callers[pfn] = callers[pfn] + 1 # hack: gather more |
| 280 | # stats such as the amount of time added to ct courtesy |
| 281 | # of this specific call, and the contribution to cc |
| 282 | # courtesy of this call. |
| 283 | else: |
| 284 | callers[pfn] = 1 |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame^] | 285 | timings[rfn] = cc, ns - 1, tt+rtt, ct, callers |
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 | return 1 |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 288 | |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame^] | 289 | |
| 290 | dispatch = { |
| 291 | "call": trace_dispatch_call, |
| 292 | "exception": trace_dispatch_exception, |
| 293 | "return": trace_dispatch_return, |
| 294 | } |
| 295 | |
| 296 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 297 | # The next few function play with self.cmd. By carefully preloading |
| 298 | # our parallel stack, we can force the profiled result to include |
| 299 | # an arbitrary string as the name of the calling function. |
| 300 | # We use self.cmd as that string, and the resulting stats look |
| 301 | # very nice :-). |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 302 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 303 | def set_cmd(self, cmd): |
| 304 | if self.cur[-1]: return # already set |
| 305 | self.cmd = cmd |
| 306 | self.simulate_call(cmd) |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 307 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 308 | class fake_code: |
| 309 | def __init__(self, filename, line, name): |
| 310 | self.co_filename = filename |
| 311 | self.co_line = line |
| 312 | self.co_name = name |
| 313 | self.co_firstlineno = 0 |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 314 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 315 | def __repr__(self): |
| 316 | return repr((self.co_filename, self.co_line, self.co_name)) |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 317 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 318 | class fake_frame: |
| 319 | def __init__(self, code, prior): |
| 320 | self.f_code = code |
| 321 | self.f_back = prior |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 322 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 323 | def simulate_call(self, name): |
| 324 | code = self.fake_code('profile', 0, name) |
| 325 | if self.cur: |
| 326 | pframe = self.cur[-2] |
| 327 | else: |
| 328 | pframe = None |
| 329 | frame = self.fake_frame(code, pframe) |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame^] | 330 | a = self.dispatch['call'](self, frame, 0) |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 331 | return |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 332 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 333 | # collect stats from pending stack, including getting final |
| 334 | # timings for self.cmd frame. |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 335 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 336 | def simulate_cmd_complete(self): |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame^] | 337 | get_time = self.get_time |
| 338 | t = get_time() - self.t |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 339 | while self.cur[-1]: |
| 340 | # We *can* cause assertion errors here if |
| 341 | # dispatch_trace_return checks for a frame match! |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame^] | 342 | a = self.dispatch['return'](self, self.cur[-2], t) |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 343 | t = 0 |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame^] | 344 | self.t = get_time() - t |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 345 | |
| 346 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 347 | def print_stats(self): |
| 348 | import pstats |
| 349 | pstats.Stats(self).strip_dirs().sort_stats(-1). \ |
| 350 | print_stats() |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 351 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 352 | def dump_stats(self, file): |
| 353 | f = open(file, 'wb') |
| 354 | self.create_stats() |
| 355 | marshal.dump(self.stats, f) |
| 356 | f.close() |
| 357 | |
| 358 | def create_stats(self): |
| 359 | self.simulate_cmd_complete() |
| 360 | self.snapshot_stats() |
| 361 | |
| 362 | def snapshot_stats(self): |
| 363 | self.stats = {} |
| 364 | for func in self.timings.keys(): |
| 365 | cc, ns, tt, ct, callers = self.timings[func] |
| 366 | callers = callers.copy() |
| 367 | nc = 0 |
| 368 | for func_caller in callers.keys(): |
| 369 | nc = nc + callers[func_caller] |
| 370 | self.stats[func] = cc, nc, tt, ct, callers |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 371 | |
| 372 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 373 | # The following two methods can be called by clients to use |
| 374 | # a profiler to profile a statement, given as a string. |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 375 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 376 | def run(self, cmd): |
| 377 | import __main__ |
| 378 | dict = __main__.__dict__ |
| 379 | return self.runctx(cmd, dict, dict) |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 380 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 381 | def runctx(self, cmd, globals, locals): |
| 382 | self.set_cmd(cmd) |
| 383 | sys.setprofile(self.dispatcher) |
| 384 | try: |
| 385 | exec cmd in globals, locals |
| 386 | finally: |
| 387 | sys.setprofile(None) |
| 388 | return self |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 389 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 390 | # This method is more useful to profile a single function call. |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame^] | 391 | def runcall(self, func, *args, **kw): |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 392 | self.set_cmd(`func`) |
| 393 | sys.setprofile(self.dispatcher) |
| 394 | try: |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame^] | 395 | return apply(func, args, kw) |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 396 | finally: |
| 397 | sys.setprofile(None) |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 398 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 399 | |
| 400 | #****************************************************************** |
| 401 | # The following calculates the overhead for using a profiler. The |
| 402 | # problem is that it takes a fair amount of time for the profiler |
| 403 | # to stop the stopwatch (from the time it receives an event). |
| 404 | # Similarly, there is a delay from the time that the profiler |
| 405 | # re-starts the stopwatch before the user's code really gets to |
| 406 | # continue. The following code tries to measure the difference on |
| 407 | # a per-event basis. The result can the be placed in the |
| 408 | # Profile.dispatch_event() routine for the given platform. Note |
| 409 | # that this difference is only significant if there are a lot of |
| 410 | # events, and relatively little user code per event. For example, |
| 411 | # code with small functions will typically benefit from having the |
| 412 | # profiler calibrated for the current platform. This *could* be |
| 413 | # done on the fly during init() time, but it is not worth the |
| 414 | # effort. Also note that if too large a value specified, then |
| 415 | # execution time on some functions will actually appear as a |
| 416 | # negative number. It is *normal* for some functions (with very |
| 417 | # low call counts) to have such negative stats, even if the |
| 418 | # calibration figure is "correct." |
| 419 | # |
| 420 | # One alternative to profile-time calibration adjustments (i.e., |
| 421 | # adding in the magic little delta during each event) is to track |
| 422 | # more carefully the number of events (and cumulatively, the number |
| 423 | # of events during sub functions) that are seen. If this were |
| 424 | # done, then the arithmetic could be done after the fact (i.e., at |
| 425 | # display time). Currently, we track only call/return events. |
| 426 | # These values can be deduced by examining the callees and callers |
| 427 | # vectors for each functions. Hence we *can* almost correct the |
| 428 | # internal time figure at print time (note that we currently don't |
| 429 | # track exception event processing counts). Unfortunately, there |
| 430 | # is currently no similar information for cumulative sub-function |
| 431 | # time. It would not be hard to "get all this info" at profiler |
| 432 | # time. Specifically, we would have to extend the tuples to keep |
| 433 | # counts of this in each frame, and then extend the defs of timing |
| 434 | # tuples to include the significant two figures. I'm a bit fearful |
| 435 | # that this additional feature will slow the heavily optimized |
| 436 | # event/time ratio (i.e., the profiler would run slower, fur a very |
| 437 | # low "value added" feature.) |
| 438 | # |
| 439 | # Plugging in the calibration constant doesn't slow down the |
| 440 | # profiler very much, and the accuracy goes way up. |
| 441 | #************************************************************** |
| 442 | |
| 443 | def calibrate(self, m): |
| 444 | # Modified by Tim Peters |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame^] | 445 | get_time = self.get_time |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 446 | n = m |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame^] | 447 | s = get_time() |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 448 | while n: |
| 449 | self.simple() |
| 450 | n = n - 1 |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame^] | 451 | f = get_time() |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 452 | my_simple = f - s |
| 453 | #print "Simple =", my_simple, |
| 454 | |
| 455 | n = m |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame^] | 456 | s = get_time() |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 457 | while n: |
| 458 | self.instrumented() |
| 459 | n = n - 1 |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame^] | 460 | f = get_time() |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 461 | my_inst = f - s |
| 462 | # print "Instrumented =", my_inst |
| 463 | avg_cost = (my_inst - my_simple)/m |
| 464 | #print "Delta/call =", avg_cost, "(profiler fixup constant)" |
| 465 | return avg_cost |
| 466 | |
| 467 | # simulate a program with no profiler activity |
| 468 | def simple(self): |
| 469 | a = 1 |
| 470 | pass |
| 471 | |
| 472 | # simulate a program with call/return event processing |
| 473 | def instrumented(self): |
| 474 | a = 1 |
| 475 | self.profiler_simulation(a, a, a) |
| 476 | |
| 477 | # simulate an event processing activity (from user's perspective) |
| 478 | def profiler_simulation(self, x, y, z): |
| 479 | t = self.timer() |
| 480 | ## t = t[0] + t[1] |
| 481 | self.ut = t |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 482 | |
| 483 | |
| 484 | |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 485 | class OldProfile(Profile): |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 486 | """A derived profiler that simulates the old style profile, providing |
| 487 | errant results on recursive functions. The reason for the usefulness of |
| 488 | this profiler is that it runs faster (i.e., less overhead). It still |
| 489 | creates all the caller stats, and is quite useful when there is *no* |
| 490 | recursion in the user's code. |
Guido van Rossum | 54f22ed | 2000-02-04 15:10:34 +0000 | [diff] [blame] | 491 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 492 | This code also shows how easy it is to create a modified profiler. |
| 493 | """ |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 494 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 495 | def trace_dispatch_exception(self, frame, t): |
| 496 | rt, rtt, rct, rfn, rframe, rcur = self.cur |
| 497 | if rcur and not rframe is frame: |
| 498 | return self.trace_dispatch_return(rframe, t) |
| 499 | return 0 |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 500 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 501 | def trace_dispatch_call(self, frame, t): |
| 502 | fn = `frame.f_code` |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 503 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 504 | self.cur = (t, 0, 0, fn, frame, self.cur) |
| 505 | if self.timings.has_key(fn): |
| 506 | tt, ct, callers = self.timings[fn] |
| 507 | self.timings[fn] = tt, ct, callers |
| 508 | else: |
| 509 | self.timings[fn] = 0, 0, {} |
| 510 | return 1 |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 511 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 512 | def trace_dispatch_return(self, frame, t): |
| 513 | rt, rtt, rct, rfn, frame, rcur = self.cur |
| 514 | rtt = rtt + t |
| 515 | sft = rtt + rct |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 516 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 517 | pt, ptt, pct, pfn, pframe, pcur = rcur |
| 518 | self.cur = pt, ptt+rt, pct+sft, pfn, pframe, pcur |
| 519 | |
| 520 | tt, ct, callers = self.timings[rfn] |
| 521 | if callers.has_key(pfn): |
| 522 | callers[pfn] = callers[pfn] + 1 |
| 523 | else: |
| 524 | callers[pfn] = 1 |
| 525 | self.timings[rfn] = tt+rtt, ct + sft, callers |
| 526 | |
| 527 | return 1 |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 528 | |
| 529 | |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame^] | 530 | dispatch = { |
| 531 | "call": trace_dispatch_call, |
| 532 | "exception": trace_dispatch_exception, |
| 533 | "return": trace_dispatch_return, |
| 534 | } |
| 535 | |
| 536 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 537 | def snapshot_stats(self): |
| 538 | self.stats = {} |
| 539 | for func in self.timings.keys(): |
| 540 | tt, ct, callers = self.timings[func] |
| 541 | callers = callers.copy() |
| 542 | nc = 0 |
| 543 | for func_caller in callers.keys(): |
| 544 | nc = nc + callers[func_caller] |
| 545 | self.stats[func] = nc, nc, tt, ct, callers |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 546 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 547 | |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 548 | |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 549 | class HotProfile(Profile): |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 550 | """The fastest derived profile example. It does not calculate |
| 551 | caller-callee relationships, and does not calculate cumulative |
| 552 | time under a function. It only calculates time spent in a |
| 553 | function, so it runs very quickly due to its very low overhead. |
| 554 | """ |
Guido van Rossum | 54f22ed | 2000-02-04 15:10:34 +0000 | [diff] [blame] | 555 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 556 | def trace_dispatch_exception(self, frame, t): |
| 557 | rt, rtt, rfn, rframe, rcur = self.cur |
| 558 | if rcur and not rframe is frame: |
| 559 | return self.trace_dispatch_return(rframe, t) |
| 560 | return 0 |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 561 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 562 | def trace_dispatch_call(self, frame, t): |
| 563 | self.cur = (t, 0, frame, self.cur) |
| 564 | return 1 |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 565 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 566 | def trace_dispatch_return(self, frame, t): |
| 567 | rt, rtt, frame, rcur = self.cur |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 568 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 569 | rfn = `frame.f_code` |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 570 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 571 | pt, ptt, pframe, pcur = rcur |
| 572 | self.cur = pt, ptt+rt, pframe, pcur |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 573 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 574 | if self.timings.has_key(rfn): |
| 575 | nc, tt = self.timings[rfn] |
| 576 | self.timings[rfn] = nc + 1, rt + rtt + tt |
| 577 | else: |
| 578 | self.timings[rfn] = 1, rt + rtt |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 579 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 580 | return 1 |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 581 | |
| 582 | |
Fred Drake | edb5ffb | 2001-06-08 04:25:24 +0000 | [diff] [blame^] | 583 | dispatch = { |
| 584 | "call": trace_dispatch_call, |
| 585 | "exception": trace_dispatch_exception, |
| 586 | "return": trace_dispatch_return, |
| 587 | } |
| 588 | |
| 589 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 590 | def snapshot_stats(self): |
| 591 | self.stats = {} |
| 592 | for func in self.timings.keys(): |
| 593 | nc, tt = self.timings[func] |
| 594 | self.stats[func] = nc, nc, tt, 0, {} |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 595 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 596 | |
Guido van Rossum | b6775db | 1994-08-01 11:34:53 +0000 | [diff] [blame] | 597 | |
| 598 | #**************************************************************************** |
| 599 | def Stats(*args): |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 600 | print 'Report generating functions are in the "pstats" module\a' |
Guido van Rossum | cc778eb | 1996-10-01 02:55:54 +0000 | [diff] [blame] | 601 | |
| 602 | |
| 603 | # When invoked as main program, invoke the profiler on a script |
| 604 | if __name__ == '__main__': |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 605 | if not sys.argv[1:]: |
| 606 | print "usage: profile.py scriptfile [arg] ..." |
| 607 | sys.exit(2) |
Guido van Rossum | cc778eb | 1996-10-01 02:55:54 +0000 | [diff] [blame] | 608 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 609 | filename = sys.argv[1] # Get script filename |
Guido van Rossum | cc778eb | 1996-10-01 02:55:54 +0000 | [diff] [blame] | 610 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 611 | del sys.argv[0] # Hide "profile.py" from argument list |
Guido van Rossum | cc778eb | 1996-10-01 02:55:54 +0000 | [diff] [blame] | 612 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 613 | # Insert script directory in front of module search path |
| 614 | sys.path.insert(0, os.path.dirname(filename)) |
Guido van Rossum | cc778eb | 1996-10-01 02:55:54 +0000 | [diff] [blame] | 615 | |
Tim Peters | 2344fae | 2001-01-15 00:50:52 +0000 | [diff] [blame] | 616 | run('execfile(' + `filename` + ')') |