| 1 | n/a | #! /usr/bin/env python3 |
|---|
| 2 | n/a | # |
|---|
| 3 | n/a | # Class for profiling python code. rev 1.0 6/2/94 |
|---|
| 4 | n/a | # |
|---|
| 5 | n/a | # Written by James Roskind |
|---|
| 6 | n/a | # Based on prior profile module by Sjoerd Mullender... |
|---|
| 7 | n/a | # which was hacked somewhat by: Guido van Rossum |
|---|
| 8 | n/a | |
|---|
| 9 | n/a | """Class for profiling Python code.""" |
|---|
| 10 | n/a | |
|---|
| 11 | n/a | # Copyright Disney Enterprises, Inc. All Rights Reserved. |
|---|
| 12 | n/a | # Licensed to PSF under a Contributor Agreement |
|---|
| 13 | n/a | # |
|---|
| 14 | n/a | # Licensed under the Apache License, Version 2.0 (the "License"); |
|---|
| 15 | n/a | # you may not use this file except in compliance with the License. |
|---|
| 16 | n/a | # You may obtain a copy of the License at |
|---|
| 17 | n/a | # |
|---|
| 18 | n/a | # http://www.apache.org/licenses/LICENSE-2.0 |
|---|
| 19 | n/a | # |
|---|
| 20 | n/a | # Unless required by applicable law or agreed to in writing, software |
|---|
| 21 | n/a | # distributed under the License is distributed on an "AS IS" BASIS, |
|---|
| 22 | n/a | # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, |
|---|
| 23 | n/a | # either express or implied. See the License for the specific language |
|---|
| 24 | n/a | # governing permissions and limitations under the License. |
|---|
| 25 | n/a | |
|---|
| 26 | n/a | |
|---|
| 27 | n/a | import sys |
|---|
| 28 | n/a | import os |
|---|
| 29 | n/a | import time |
|---|
| 30 | n/a | import marshal |
|---|
| 31 | n/a | from optparse import OptionParser |
|---|
| 32 | n/a | |
|---|
| 33 | n/a | __all__ = ["run", "runctx", "Profile"] |
|---|
| 34 | n/a | |
|---|
| 35 | n/a | # Sample timer for use with |
|---|
| 36 | n/a | #i_count = 0 |
|---|
| 37 | n/a | #def integer_timer(): |
|---|
| 38 | n/a | # global i_count |
|---|
| 39 | n/a | # i_count = i_count + 1 |
|---|
| 40 | n/a | # return i_count |
|---|
| 41 | n/a | #itimes = integer_timer # replace with C coded timer returning integers |
|---|
| 42 | n/a | |
|---|
| 43 | n/a | class _Utils: |
|---|
| 44 | n/a | """Support class for utility functions which are shared by |
|---|
| 45 | n/a | profile.py and cProfile.py modules. |
|---|
| 46 | n/a | Not supposed to be used directly. |
|---|
| 47 | n/a | """ |
|---|
| 48 | n/a | |
|---|
| 49 | n/a | def __init__(self, profiler): |
|---|
| 50 | n/a | self.profiler = profiler |
|---|
| 51 | n/a | |
|---|
| 52 | n/a | def run(self, statement, filename, sort): |
|---|
| 53 | n/a | prof = self.profiler() |
|---|
| 54 | n/a | try: |
|---|
| 55 | n/a | prof.run(statement) |
|---|
| 56 | n/a | except SystemExit: |
|---|
| 57 | n/a | pass |
|---|
| 58 | n/a | finally: |
|---|
| 59 | n/a | self._show(prof, filename, sort) |
|---|
| 60 | n/a | |
|---|
| 61 | n/a | def runctx(self, statement, globals, locals, filename, sort): |
|---|
| 62 | n/a | prof = self.profiler() |
|---|
| 63 | n/a | try: |
|---|
| 64 | n/a | prof.runctx(statement, globals, locals) |
|---|
| 65 | n/a | except SystemExit: |
|---|
| 66 | n/a | pass |
|---|
| 67 | n/a | finally: |
|---|
| 68 | n/a | self._show(prof, filename, sort) |
|---|
| 69 | n/a | |
|---|
| 70 | n/a | def _show(self, prof, filename, sort): |
|---|
| 71 | n/a | if filename is not None: |
|---|
| 72 | n/a | prof.dump_stats(filename) |
|---|
| 73 | n/a | else: |
|---|
| 74 | n/a | prof.print_stats(sort) |
|---|
| 75 | n/a | |
|---|
| 76 | n/a | |
|---|
| 77 | n/a | #************************************************************************** |
|---|
| 78 | n/a | # The following are the static member functions for the profiler class |
|---|
| 79 | n/a | # Note that an instance of Profile() is *not* needed to call them. |
|---|
| 80 | n/a | #************************************************************************** |
|---|
| 81 | n/a | |
|---|
| 82 | n/a | def run(statement, filename=None, sort=-1): |
|---|
| 83 | n/a | """Run statement under profiler optionally saving results in filename |
|---|
| 84 | n/a | |
|---|
| 85 | n/a | This function takes a single argument that can be passed to the |
|---|
| 86 | n/a | "exec" statement, and an optional file name. In all cases this |
|---|
| 87 | n/a | routine attempts to "exec" its first argument and gather profiling |
|---|
| 88 | n/a | statistics from the execution. If no file name is present, then this |
|---|
| 89 | n/a | function automatically prints a simple profiling report, sorted by the |
|---|
| 90 | n/a | standard name string (file/line/function-name) that is presented in |
|---|
| 91 | n/a | each line. |
|---|
| 92 | n/a | """ |
|---|
| 93 | n/a | return _Utils(Profile).run(statement, filename, sort) |
|---|
| 94 | n/a | |
|---|
| 95 | n/a | def runctx(statement, globals, locals, filename=None, sort=-1): |
|---|
| 96 | n/a | """Run statement under profiler, supplying your own globals and locals, |
|---|
| 97 | n/a | optionally saving results in filename. |
|---|
| 98 | n/a | |
|---|
| 99 | n/a | statement and filename have the same semantics as profile.run |
|---|
| 100 | n/a | """ |
|---|
| 101 | n/a | return _Utils(Profile).runctx(statement, globals, locals, filename, sort) |
|---|
| 102 | n/a | |
|---|
| 103 | n/a | |
|---|
| 104 | n/a | class Profile: |
|---|
| 105 | n/a | """Profiler class. |
|---|
| 106 | n/a | |
|---|
| 107 | n/a | self.cur is always a tuple. Each such tuple corresponds to a stack |
|---|
| 108 | n/a | frame that is currently active (self.cur[-2]). The following are the |
|---|
| 109 | n/a | definitions of its members. We use this external "parallel stack" to |
|---|
| 110 | n/a | avoid contaminating the program that we are profiling. (old profiler |
|---|
| 111 | n/a | used to write into the frames local dictionary!!) Derived classes |
|---|
| 112 | n/a | can change the definition of some entries, as long as they leave |
|---|
| 113 | n/a | [-2:] intact (frame and previous tuple). In case an internal error is |
|---|
| 114 | n/a | detected, the -3 element is used as the function name. |
|---|
| 115 | n/a | |
|---|
| 116 | n/a | [ 0] = Time that needs to be charged to the parent frame's function. |
|---|
| 117 | n/a | It is used so that a function call will not have to access the |
|---|
| 118 | n/a | timing data for the parent frame. |
|---|
| 119 | n/a | [ 1] = Total time spent in this frame's function, excluding time in |
|---|
| 120 | n/a | subfunctions (this latter is tallied in cur[2]). |
|---|
| 121 | n/a | [ 2] = Total time spent in subfunctions, excluding time executing the |
|---|
| 122 | n/a | frame's function (this latter is tallied in cur[1]). |
|---|
| 123 | n/a | [-3] = Name of the function that corresponds to this frame. |
|---|
| 124 | n/a | [-2] = Actual frame that we correspond to (used to sync exception handling). |
|---|
| 125 | n/a | [-1] = Our parent 6-tuple (corresponds to frame.f_back). |
|---|
| 126 | n/a | |
|---|
| 127 | n/a | Timing data for each function is stored as a 5-tuple in the dictionary |
|---|
| 128 | n/a | self.timings[]. The index is always the name stored in self.cur[-3]. |
|---|
| 129 | n/a | The following are the definitions of the members: |
|---|
| 130 | n/a | |
|---|
| 131 | n/a | [0] = The number of times this function was called, not counting direct |
|---|
| 132 | n/a | or indirect recursion, |
|---|
| 133 | n/a | [1] = Number of times this function appears on the stack, minus one |
|---|
| 134 | n/a | [2] = Total time spent internal to this function |
|---|
| 135 | n/a | [3] = Cumulative time that this function was present on the stack. In |
|---|
| 136 | n/a | non-recursive functions, this is the total execution time from start |
|---|
| 137 | n/a | to finish of each invocation of a function, including time spent in |
|---|
| 138 | n/a | all subfunctions. |
|---|
| 139 | n/a | [4] = A dictionary indicating for each function name, the number of times |
|---|
| 140 | n/a | it was called by us. |
|---|
| 141 | n/a | """ |
|---|
| 142 | n/a | |
|---|
| 143 | n/a | bias = 0 # calibration constant |
|---|
| 144 | n/a | |
|---|
| 145 | n/a | def __init__(self, timer=None, bias=None): |
|---|
| 146 | n/a | self.timings = {} |
|---|
| 147 | n/a | self.cur = None |
|---|
| 148 | n/a | self.cmd = "" |
|---|
| 149 | n/a | self.c_func_name = "" |
|---|
| 150 | n/a | |
|---|
| 151 | n/a | if bias is None: |
|---|
| 152 | n/a | bias = self.bias |
|---|
| 153 | n/a | self.bias = bias # Materialize in local dict for lookup speed. |
|---|
| 154 | n/a | |
|---|
| 155 | n/a | if not timer: |
|---|
| 156 | n/a | self.timer = self.get_time = time.process_time |
|---|
| 157 | n/a | self.dispatcher = self.trace_dispatch_i |
|---|
| 158 | n/a | else: |
|---|
| 159 | n/a | self.timer = timer |
|---|
| 160 | n/a | t = self.timer() # test out timer function |
|---|
| 161 | n/a | try: |
|---|
| 162 | n/a | length = len(t) |
|---|
| 163 | n/a | except TypeError: |
|---|
| 164 | n/a | self.get_time = timer |
|---|
| 165 | n/a | self.dispatcher = self.trace_dispatch_i |
|---|
| 166 | n/a | else: |
|---|
| 167 | n/a | if length == 2: |
|---|
| 168 | n/a | self.dispatcher = self.trace_dispatch |
|---|
| 169 | n/a | else: |
|---|
| 170 | n/a | self.dispatcher = self.trace_dispatch_l |
|---|
| 171 | n/a | # This get_time() implementation needs to be defined |
|---|
| 172 | n/a | # here to capture the passed-in timer in the parameter |
|---|
| 173 | n/a | # list (for performance). Note that we can't assume |
|---|
| 174 | n/a | # the timer() result contains two values in all |
|---|
| 175 | n/a | # cases. |
|---|
| 176 | n/a | def get_time_timer(timer=timer, sum=sum): |
|---|
| 177 | n/a | return sum(timer()) |
|---|
| 178 | n/a | self.get_time = get_time_timer |
|---|
| 179 | n/a | self.t = self.get_time() |
|---|
| 180 | n/a | self.simulate_call('profiler') |
|---|
| 181 | n/a | |
|---|
| 182 | n/a | # Heavily optimized dispatch routine for os.times() timer |
|---|
| 183 | n/a | |
|---|
| 184 | n/a | def trace_dispatch(self, frame, event, arg): |
|---|
| 185 | n/a | timer = self.timer |
|---|
| 186 | n/a | t = timer() |
|---|
| 187 | n/a | t = t[0] + t[1] - self.t - self.bias |
|---|
| 188 | n/a | |
|---|
| 189 | n/a | if event == "c_call": |
|---|
| 190 | n/a | self.c_func_name = arg.__name__ |
|---|
| 191 | n/a | |
|---|
| 192 | n/a | if self.dispatch[event](self, frame,t): |
|---|
| 193 | n/a | t = timer() |
|---|
| 194 | n/a | self.t = t[0] + t[1] |
|---|
| 195 | n/a | else: |
|---|
| 196 | n/a | r = timer() |
|---|
| 197 | n/a | self.t = r[0] + r[1] - t # put back unrecorded delta |
|---|
| 198 | n/a | |
|---|
| 199 | n/a | # Dispatch routine for best timer program (return = scalar, fastest if |
|---|
| 200 | n/a | # an integer but float works too -- and time.clock() relies on that). |
|---|
| 201 | n/a | |
|---|
| 202 | n/a | def trace_dispatch_i(self, frame, event, arg): |
|---|
| 203 | n/a | timer = self.timer |
|---|
| 204 | n/a | t = timer() - self.t - self.bias |
|---|
| 205 | n/a | |
|---|
| 206 | n/a | if event == "c_call": |
|---|
| 207 | n/a | self.c_func_name = arg.__name__ |
|---|
| 208 | n/a | |
|---|
| 209 | n/a | if self.dispatch[event](self, frame, t): |
|---|
| 210 | n/a | self.t = timer() |
|---|
| 211 | n/a | else: |
|---|
| 212 | n/a | self.t = timer() - t # put back unrecorded delta |
|---|
| 213 | n/a | |
|---|
| 214 | n/a | # Dispatch routine for macintosh (timer returns time in ticks of |
|---|
| 215 | n/a | # 1/60th second) |
|---|
| 216 | n/a | |
|---|
| 217 | n/a | def trace_dispatch_mac(self, frame, event, arg): |
|---|
| 218 | n/a | timer = self.timer |
|---|
| 219 | n/a | t = timer()/60.0 - self.t - self.bias |
|---|
| 220 | n/a | |
|---|
| 221 | n/a | if event == "c_call": |
|---|
| 222 | n/a | self.c_func_name = arg.__name__ |
|---|
| 223 | n/a | |
|---|
| 224 | n/a | if self.dispatch[event](self, frame, t): |
|---|
| 225 | n/a | self.t = timer()/60.0 |
|---|
| 226 | n/a | else: |
|---|
| 227 | n/a | self.t = timer()/60.0 - t # put back unrecorded delta |
|---|
| 228 | n/a | |
|---|
| 229 | n/a | # SLOW generic dispatch routine for timer returning lists of numbers |
|---|
| 230 | n/a | |
|---|
| 231 | n/a | def trace_dispatch_l(self, frame, event, arg): |
|---|
| 232 | n/a | get_time = self.get_time |
|---|
| 233 | n/a | t = get_time() - self.t - self.bias |
|---|
| 234 | n/a | |
|---|
| 235 | n/a | if event == "c_call": |
|---|
| 236 | n/a | self.c_func_name = arg.__name__ |
|---|
| 237 | n/a | |
|---|
| 238 | n/a | if self.dispatch[event](self, frame, t): |
|---|
| 239 | n/a | self.t = get_time() |
|---|
| 240 | n/a | else: |
|---|
| 241 | n/a | self.t = get_time() - t # put back unrecorded delta |
|---|
| 242 | n/a | |
|---|
| 243 | n/a | # In the event handlers, the first 3 elements of self.cur are unpacked |
|---|
| 244 | n/a | # into vrbls w/ 3-letter names. The last two characters are meant to be |
|---|
| 245 | n/a | # mnemonic: |
|---|
| 246 | n/a | # _pt self.cur[0] "parent time" time to be charged to parent frame |
|---|
| 247 | n/a | # _it self.cur[1] "internal time" time spent directly in the function |
|---|
| 248 | n/a | # _et self.cur[2] "external time" time spent in subfunctions |
|---|
| 249 | n/a | |
|---|
| 250 | n/a | def trace_dispatch_exception(self, frame, t): |
|---|
| 251 | n/a | rpt, rit, ret, rfn, rframe, rcur = self.cur |
|---|
| 252 | n/a | if (rframe is not frame) and rcur: |
|---|
| 253 | n/a | return self.trace_dispatch_return(rframe, t) |
|---|
| 254 | n/a | self.cur = rpt, rit+t, ret, rfn, rframe, rcur |
|---|
| 255 | n/a | return 1 |
|---|
| 256 | n/a | |
|---|
| 257 | n/a | |
|---|
| 258 | n/a | def trace_dispatch_call(self, frame, t): |
|---|
| 259 | n/a | if self.cur and frame.f_back is not self.cur[-2]: |
|---|
| 260 | n/a | rpt, rit, ret, rfn, rframe, rcur = self.cur |
|---|
| 261 | n/a | if not isinstance(rframe, Profile.fake_frame): |
|---|
| 262 | n/a | assert rframe.f_back is frame.f_back, ("Bad call", rfn, |
|---|
| 263 | n/a | rframe, rframe.f_back, |
|---|
| 264 | n/a | frame, frame.f_back) |
|---|
| 265 | n/a | self.trace_dispatch_return(rframe, 0) |
|---|
| 266 | n/a | assert (self.cur is None or \ |
|---|
| 267 | n/a | frame.f_back is self.cur[-2]), ("Bad call", |
|---|
| 268 | n/a | self.cur[-3]) |
|---|
| 269 | n/a | fcode = frame.f_code |
|---|
| 270 | n/a | fn = (fcode.co_filename, fcode.co_firstlineno, fcode.co_name) |
|---|
| 271 | n/a | self.cur = (t, 0, 0, fn, frame, self.cur) |
|---|
| 272 | n/a | timings = self.timings |
|---|
| 273 | n/a | if fn in timings: |
|---|
| 274 | n/a | cc, ns, tt, ct, callers = timings[fn] |
|---|
| 275 | n/a | timings[fn] = cc, ns + 1, tt, ct, callers |
|---|
| 276 | n/a | else: |
|---|
| 277 | n/a | timings[fn] = 0, 0, 0, 0, {} |
|---|
| 278 | n/a | return 1 |
|---|
| 279 | n/a | |
|---|
| 280 | n/a | def trace_dispatch_c_call (self, frame, t): |
|---|
| 281 | n/a | fn = ("", 0, self.c_func_name) |
|---|
| 282 | n/a | self.cur = (t, 0, 0, fn, frame, self.cur) |
|---|
| 283 | n/a | timings = self.timings |
|---|
| 284 | n/a | if fn in timings: |
|---|
| 285 | n/a | cc, ns, tt, ct, callers = timings[fn] |
|---|
| 286 | n/a | timings[fn] = cc, ns+1, tt, ct, callers |
|---|
| 287 | n/a | else: |
|---|
| 288 | n/a | timings[fn] = 0, 0, 0, 0, {} |
|---|
| 289 | n/a | return 1 |
|---|
| 290 | n/a | |
|---|
| 291 | n/a | def trace_dispatch_return(self, frame, t): |
|---|
| 292 | n/a | if frame is not self.cur[-2]: |
|---|
| 293 | n/a | assert frame is self.cur[-2].f_back, ("Bad return", self.cur[-3]) |
|---|
| 294 | n/a | self.trace_dispatch_return(self.cur[-2], 0) |
|---|
| 295 | n/a | |
|---|
| 296 | n/a | # Prefix "r" means part of the Returning or exiting frame. |
|---|
| 297 | n/a | # Prefix "p" means part of the Previous or Parent or older frame. |
|---|
| 298 | n/a | |
|---|
| 299 | n/a | rpt, rit, ret, rfn, frame, rcur = self.cur |
|---|
| 300 | n/a | rit = rit + t |
|---|
| 301 | n/a | frame_total = rit + ret |
|---|
| 302 | n/a | |
|---|
| 303 | n/a | ppt, pit, pet, pfn, pframe, pcur = rcur |
|---|
| 304 | n/a | self.cur = ppt, pit + rpt, pet + frame_total, pfn, pframe, pcur |
|---|
| 305 | n/a | |
|---|
| 306 | n/a | timings = self.timings |
|---|
| 307 | n/a | cc, ns, tt, ct, callers = timings[rfn] |
|---|
| 308 | n/a | if not ns: |
|---|
| 309 | n/a | # This is the only occurrence of the function on the stack. |
|---|
| 310 | n/a | # Else this is a (directly or indirectly) recursive call, and |
|---|
| 311 | n/a | # its cumulative time will get updated when the topmost call to |
|---|
| 312 | n/a | # it returns. |
|---|
| 313 | n/a | ct = ct + frame_total |
|---|
| 314 | n/a | cc = cc + 1 |
|---|
| 315 | n/a | |
|---|
| 316 | n/a | if pfn in callers: |
|---|
| 317 | n/a | callers[pfn] = callers[pfn] + 1 # hack: gather more |
|---|
| 318 | n/a | # stats such as the amount of time added to ct courtesy |
|---|
| 319 | n/a | # of this specific call, and the contribution to cc |
|---|
| 320 | n/a | # courtesy of this call. |
|---|
| 321 | n/a | else: |
|---|
| 322 | n/a | callers[pfn] = 1 |
|---|
| 323 | n/a | |
|---|
| 324 | n/a | timings[rfn] = cc, ns - 1, tt + rit, ct, callers |
|---|
| 325 | n/a | |
|---|
| 326 | n/a | return 1 |
|---|
| 327 | n/a | |
|---|
| 328 | n/a | |
|---|
| 329 | n/a | dispatch = { |
|---|
| 330 | n/a | "call": trace_dispatch_call, |
|---|
| 331 | n/a | "exception": trace_dispatch_exception, |
|---|
| 332 | n/a | "return": trace_dispatch_return, |
|---|
| 333 | n/a | "c_call": trace_dispatch_c_call, |
|---|
| 334 | n/a | "c_exception": trace_dispatch_return, # the C function returned |
|---|
| 335 | n/a | "c_return": trace_dispatch_return, |
|---|
| 336 | n/a | } |
|---|
| 337 | n/a | |
|---|
| 338 | n/a | |
|---|
| 339 | n/a | # The next few functions play with self.cmd. By carefully preloading |
|---|
| 340 | n/a | # our parallel stack, we can force the profiled result to include |
|---|
| 341 | n/a | # an arbitrary string as the name of the calling function. |
|---|
| 342 | n/a | # We use self.cmd as that string, and the resulting stats look |
|---|
| 343 | n/a | # very nice :-). |
|---|
| 344 | n/a | |
|---|
| 345 | n/a | def set_cmd(self, cmd): |
|---|
| 346 | n/a | if self.cur[-1]: return # already set |
|---|
| 347 | n/a | self.cmd = cmd |
|---|
| 348 | n/a | self.simulate_call(cmd) |
|---|
| 349 | n/a | |
|---|
| 350 | n/a | class fake_code: |
|---|
| 351 | n/a | def __init__(self, filename, line, name): |
|---|
| 352 | n/a | self.co_filename = filename |
|---|
| 353 | n/a | self.co_line = line |
|---|
| 354 | n/a | self.co_name = name |
|---|
| 355 | n/a | self.co_firstlineno = 0 |
|---|
| 356 | n/a | |
|---|
| 357 | n/a | def __repr__(self): |
|---|
| 358 | n/a | return repr((self.co_filename, self.co_line, self.co_name)) |
|---|
| 359 | n/a | |
|---|
| 360 | n/a | class fake_frame: |
|---|
| 361 | n/a | def __init__(self, code, prior): |
|---|
| 362 | n/a | self.f_code = code |
|---|
| 363 | n/a | self.f_back = prior |
|---|
| 364 | n/a | |
|---|
| 365 | n/a | def simulate_call(self, name): |
|---|
| 366 | n/a | code = self.fake_code('profile', 0, name) |
|---|
| 367 | n/a | if self.cur: |
|---|
| 368 | n/a | pframe = self.cur[-2] |
|---|
| 369 | n/a | else: |
|---|
| 370 | n/a | pframe = None |
|---|
| 371 | n/a | frame = self.fake_frame(code, pframe) |
|---|
| 372 | n/a | self.dispatch['call'](self, frame, 0) |
|---|
| 373 | n/a | |
|---|
| 374 | n/a | # collect stats from pending stack, including getting final |
|---|
| 375 | n/a | # timings for self.cmd frame. |
|---|
| 376 | n/a | |
|---|
| 377 | n/a | def simulate_cmd_complete(self): |
|---|
| 378 | n/a | get_time = self.get_time |
|---|
| 379 | n/a | t = get_time() - self.t |
|---|
| 380 | n/a | while self.cur[-1]: |
|---|
| 381 | n/a | # We *can* cause assertion errors here if |
|---|
| 382 | n/a | # dispatch_trace_return checks for a frame match! |
|---|
| 383 | n/a | self.dispatch['return'](self, self.cur[-2], t) |
|---|
| 384 | n/a | t = 0 |
|---|
| 385 | n/a | self.t = get_time() - t |
|---|
| 386 | n/a | |
|---|
| 387 | n/a | |
|---|
| 388 | n/a | def print_stats(self, sort=-1): |
|---|
| 389 | n/a | import pstats |
|---|
| 390 | n/a | pstats.Stats(self).strip_dirs().sort_stats(sort). \ |
|---|
| 391 | n/a | print_stats() |
|---|
| 392 | n/a | |
|---|
| 393 | n/a | def dump_stats(self, file): |
|---|
| 394 | n/a | with open(file, 'wb') as f: |
|---|
| 395 | n/a | self.create_stats() |
|---|
| 396 | n/a | marshal.dump(self.stats, f) |
|---|
| 397 | n/a | |
|---|
| 398 | n/a | def create_stats(self): |
|---|
| 399 | n/a | self.simulate_cmd_complete() |
|---|
| 400 | n/a | self.snapshot_stats() |
|---|
| 401 | n/a | |
|---|
| 402 | n/a | def snapshot_stats(self): |
|---|
| 403 | n/a | self.stats = {} |
|---|
| 404 | n/a | for func, (cc, ns, tt, ct, callers) in self.timings.items(): |
|---|
| 405 | n/a | callers = callers.copy() |
|---|
| 406 | n/a | nc = 0 |
|---|
| 407 | n/a | for callcnt in callers.values(): |
|---|
| 408 | n/a | nc += callcnt |
|---|
| 409 | n/a | self.stats[func] = cc, nc, tt, ct, callers |
|---|
| 410 | n/a | |
|---|
| 411 | n/a | |
|---|
| 412 | n/a | # The following two methods can be called by clients to use |
|---|
| 413 | n/a | # a profiler to profile a statement, given as a string. |
|---|
| 414 | n/a | |
|---|
| 415 | n/a | def run(self, cmd): |
|---|
| 416 | n/a | import __main__ |
|---|
| 417 | n/a | dict = __main__.__dict__ |
|---|
| 418 | n/a | return self.runctx(cmd, dict, dict) |
|---|
| 419 | n/a | |
|---|
| 420 | n/a | def runctx(self, cmd, globals, locals): |
|---|
| 421 | n/a | self.set_cmd(cmd) |
|---|
| 422 | n/a | sys.setprofile(self.dispatcher) |
|---|
| 423 | n/a | try: |
|---|
| 424 | n/a | exec(cmd, globals, locals) |
|---|
| 425 | n/a | finally: |
|---|
| 426 | n/a | sys.setprofile(None) |
|---|
| 427 | n/a | return self |
|---|
| 428 | n/a | |
|---|
| 429 | n/a | # This method is more useful to profile a single function call. |
|---|
| 430 | n/a | def runcall(self, func, *args, **kw): |
|---|
| 431 | n/a | self.set_cmd(repr(func)) |
|---|
| 432 | n/a | sys.setprofile(self.dispatcher) |
|---|
| 433 | n/a | try: |
|---|
| 434 | n/a | return func(*args, **kw) |
|---|
| 435 | n/a | finally: |
|---|
| 436 | n/a | sys.setprofile(None) |
|---|
| 437 | n/a | |
|---|
| 438 | n/a | |
|---|
| 439 | n/a | #****************************************************************** |
|---|
| 440 | n/a | # The following calculates the overhead for using a profiler. The |
|---|
| 441 | n/a | # problem is that it takes a fair amount of time for the profiler |
|---|
| 442 | n/a | # to stop the stopwatch (from the time it receives an event). |
|---|
| 443 | n/a | # Similarly, there is a delay from the time that the profiler |
|---|
| 444 | n/a | # re-starts the stopwatch before the user's code really gets to |
|---|
| 445 | n/a | # continue. The following code tries to measure the difference on |
|---|
| 446 | n/a | # a per-event basis. |
|---|
| 447 | n/a | # |
|---|
| 448 | n/a | # Note that this difference is only significant if there are a lot of |
|---|
| 449 | n/a | # events, and relatively little user code per event. For example, |
|---|
| 450 | n/a | # code with small functions will typically benefit from having the |
|---|
| 451 | n/a | # profiler calibrated for the current platform. This *could* be |
|---|
| 452 | n/a | # done on the fly during init() time, but it is not worth the |
|---|
| 453 | n/a | # effort. Also note that if too large a value specified, then |
|---|
| 454 | n/a | # execution time on some functions will actually appear as a |
|---|
| 455 | n/a | # negative number. It is *normal* for some functions (with very |
|---|
| 456 | n/a | # low call counts) to have such negative stats, even if the |
|---|
| 457 | n/a | # calibration figure is "correct." |
|---|
| 458 | n/a | # |
|---|
| 459 | n/a | # One alternative to profile-time calibration adjustments (i.e., |
|---|
| 460 | n/a | # adding in the magic little delta during each event) is to track |
|---|
| 461 | n/a | # more carefully the number of events (and cumulatively, the number |
|---|
| 462 | n/a | # of events during sub functions) that are seen. If this were |
|---|
| 463 | n/a | # done, then the arithmetic could be done after the fact (i.e., at |
|---|
| 464 | n/a | # display time). Currently, we track only call/return events. |
|---|
| 465 | n/a | # These values can be deduced by examining the callees and callers |
|---|
| 466 | n/a | # vectors for each functions. Hence we *can* almost correct the |
|---|
| 467 | n/a | # internal time figure at print time (note that we currently don't |
|---|
| 468 | n/a | # track exception event processing counts). Unfortunately, there |
|---|
| 469 | n/a | # is currently no similar information for cumulative sub-function |
|---|
| 470 | n/a | # time. It would not be hard to "get all this info" at profiler |
|---|
| 471 | n/a | # time. Specifically, we would have to extend the tuples to keep |
|---|
| 472 | n/a | # counts of this in each frame, and then extend the defs of timing |
|---|
| 473 | n/a | # tuples to include the significant two figures. I'm a bit fearful |
|---|
| 474 | n/a | # that this additional feature will slow the heavily optimized |
|---|
| 475 | n/a | # event/time ratio (i.e., the profiler would run slower, fur a very |
|---|
| 476 | n/a | # low "value added" feature.) |
|---|
| 477 | n/a | #************************************************************** |
|---|
| 478 | n/a | |
|---|
| 479 | n/a | def calibrate(self, m, verbose=0): |
|---|
| 480 | n/a | if self.__class__ is not Profile: |
|---|
| 481 | n/a | raise TypeError("Subclasses must override .calibrate().") |
|---|
| 482 | n/a | |
|---|
| 483 | n/a | saved_bias = self.bias |
|---|
| 484 | n/a | self.bias = 0 |
|---|
| 485 | n/a | try: |
|---|
| 486 | n/a | return self._calibrate_inner(m, verbose) |
|---|
| 487 | n/a | finally: |
|---|
| 488 | n/a | self.bias = saved_bias |
|---|
| 489 | n/a | |
|---|
| 490 | n/a | def _calibrate_inner(self, m, verbose): |
|---|
| 491 | n/a | get_time = self.get_time |
|---|
| 492 | n/a | |
|---|
| 493 | n/a | # Set up a test case to be run with and without profiling. Include |
|---|
| 494 | n/a | # lots of calls, because we're trying to quantify stopwatch overhead. |
|---|
| 495 | n/a | # Do not raise any exceptions, though, because we want to know |
|---|
| 496 | n/a | # exactly how many profile events are generated (one call event, + |
|---|
| 497 | n/a | # one return event, per Python-level call). |
|---|
| 498 | n/a | |
|---|
| 499 | n/a | def f1(n): |
|---|
| 500 | n/a | for i in range(n): |
|---|
| 501 | n/a | x = 1 |
|---|
| 502 | n/a | |
|---|
| 503 | n/a | def f(m, f1=f1): |
|---|
| 504 | n/a | for i in range(m): |
|---|
| 505 | n/a | f1(100) |
|---|
| 506 | n/a | |
|---|
| 507 | n/a | f(m) # warm up the cache |
|---|
| 508 | n/a | |
|---|
| 509 | n/a | # elapsed_noprofile <- time f(m) takes without profiling. |
|---|
| 510 | n/a | t0 = get_time() |
|---|
| 511 | n/a | f(m) |
|---|
| 512 | n/a | t1 = get_time() |
|---|
| 513 | n/a | elapsed_noprofile = t1 - t0 |
|---|
| 514 | n/a | if verbose: |
|---|
| 515 | n/a | print("elapsed time without profiling =", elapsed_noprofile) |
|---|
| 516 | n/a | |
|---|
| 517 | n/a | # elapsed_profile <- time f(m) takes with profiling. The difference |
|---|
| 518 | n/a | # is profiling overhead, only some of which the profiler subtracts |
|---|
| 519 | n/a | # out on its own. |
|---|
| 520 | n/a | p = Profile() |
|---|
| 521 | n/a | t0 = get_time() |
|---|
| 522 | n/a | p.runctx('f(m)', globals(), locals()) |
|---|
| 523 | n/a | t1 = get_time() |
|---|
| 524 | n/a | elapsed_profile = t1 - t0 |
|---|
| 525 | n/a | if verbose: |
|---|
| 526 | n/a | print("elapsed time with profiling =", elapsed_profile) |
|---|
| 527 | n/a | |
|---|
| 528 | n/a | # reported_time <- "CPU seconds" the profiler charged to f and f1. |
|---|
| 529 | n/a | total_calls = 0.0 |
|---|
| 530 | n/a | reported_time = 0.0 |
|---|
| 531 | n/a | for (filename, line, funcname), (cc, ns, tt, ct, callers) in \ |
|---|
| 532 | n/a | p.timings.items(): |
|---|
| 533 | n/a | if funcname in ("f", "f1"): |
|---|
| 534 | n/a | total_calls += cc |
|---|
| 535 | n/a | reported_time += tt |
|---|
| 536 | n/a | |
|---|
| 537 | n/a | if verbose: |
|---|
| 538 | n/a | print("'CPU seconds' profiler reported =", reported_time) |
|---|
| 539 | n/a | print("total # calls =", total_calls) |
|---|
| 540 | n/a | if total_calls != m + 1: |
|---|
| 541 | n/a | raise ValueError("internal error: total calls = %d" % total_calls) |
|---|
| 542 | n/a | |
|---|
| 543 | n/a | # reported_time - elapsed_noprofile = overhead the profiler wasn't |
|---|
| 544 | n/a | # able to measure. Divide by twice the number of calls (since there |
|---|
| 545 | n/a | # are two profiler events per call in this test) to get the hidden |
|---|
| 546 | n/a | # overhead per event. |
|---|
| 547 | n/a | mean = (reported_time - elapsed_noprofile) / 2.0 / total_calls |
|---|
| 548 | n/a | if verbose: |
|---|
| 549 | n/a | print("mean stopwatch overhead per profile event =", mean) |
|---|
| 550 | n/a | return mean |
|---|
| 551 | n/a | |
|---|
| 552 | n/a | #**************************************************************************** |
|---|
| 553 | n/a | |
|---|
| 554 | n/a | def main(): |
|---|
| 555 | n/a | usage = "profile.py [-o output_file_path] [-s sort] scriptfile [arg] ..." |
|---|
| 556 | n/a | parser = OptionParser(usage=usage) |
|---|
| 557 | n/a | parser.allow_interspersed_args = False |
|---|
| 558 | n/a | parser.add_option('-o', '--outfile', dest="outfile", |
|---|
| 559 | n/a | help="Save stats to <outfile>", default=None) |
|---|
| 560 | n/a | parser.add_option('-s', '--sort', dest="sort", |
|---|
| 561 | n/a | help="Sort order when printing to stdout, based on pstats.Stats class", |
|---|
| 562 | n/a | default=-1) |
|---|
| 563 | n/a | |
|---|
| 564 | n/a | if not sys.argv[1:]: |
|---|
| 565 | n/a | parser.print_usage() |
|---|
| 566 | n/a | sys.exit(2) |
|---|
| 567 | n/a | |
|---|
| 568 | n/a | (options, args) = parser.parse_args() |
|---|
| 569 | n/a | sys.argv[:] = args |
|---|
| 570 | n/a | |
|---|
| 571 | n/a | if len(args) > 0: |
|---|
| 572 | n/a | progname = args[0] |
|---|
| 573 | n/a | sys.path.insert(0, os.path.dirname(progname)) |
|---|
| 574 | n/a | with open(progname, 'rb') as fp: |
|---|
| 575 | n/a | code = compile(fp.read(), progname, 'exec') |
|---|
| 576 | n/a | globs = { |
|---|
| 577 | n/a | '__file__': progname, |
|---|
| 578 | n/a | '__name__': '__main__', |
|---|
| 579 | n/a | '__package__': None, |
|---|
| 580 | n/a | '__cached__': None, |
|---|
| 581 | n/a | } |
|---|
| 582 | n/a | runctx(code, globs, None, options.outfile, options.sort) |
|---|
| 583 | n/a | else: |
|---|
| 584 | n/a | parser.print_usage() |
|---|
| 585 | n/a | return parser |
|---|
| 586 | n/a | |
|---|
| 587 | n/a | # When invoked as main program, invoke the profiler on a script |
|---|
| 588 | n/a | if __name__ == '__main__': |
|---|
| 589 | n/a | main() |
|---|