codekingpro/portable-devtools
114k
1#2# Class for profiling python code. rev 1.0 6/2/943#4# Written by James Roskind5# Based on prior profile module by Sjoerd Mullender...6# which was hacked somewhat by: Guido van Rossum7 8"""Class for profiling Python code."""9 10# Copyright Disney Enterprises, Inc. All Rights Reserved.11# Licensed to PSF under a Contributor Agreement12#13# Licensed under the Apache License, Version 2.0 (the "License");14# you may not use this file except in compliance with the License.15# You may obtain a copy of the License at16#17# http://www.apache.org/licenses/LICENSE-2.018#19# Unless required by applicable law or agreed to in writing, software20# distributed under the License is distributed on an "AS IS" BASIS,21# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND,22# either express or implied. See the License for the specific language23# governing permissions and limitations under the License.24 25 26import importlib.machinery27import io28import sys29import time30import marshal31 32__all__ = ["run", "runctx", "Profile"]33 34# Sample timer for use with35#i_count = 036#def integer_timer():37# global i_count38# i_count = i_count + 139# return i_count40#itimes = integer_timer # replace with C coded timer returning integers41 42class _Utils:43 """Support class for utility functions which are shared by44 profile.py and cProfile.py modules.45 Not supposed to be used directly.46 """47 48 def __init__(self, profiler):49 self.profiler = profiler50 51 def run(self, statement, filename, sort):52 prof = self.profiler()53 try:54 prof.run(statement)55 except SystemExit:56 pass57 finally:58 self._show(prof, filename, sort)59 60 def runctx(self, statement, globals, locals, filename, sort):61 prof = self.profiler()62 try:63 prof.runctx(statement, globals, locals)64 except SystemExit:65 pass66 finally:67 self._show(prof, filename, sort)68 69 def _show(self, prof, filename, sort):70 if filename is not None:71 prof.dump_stats(filename)72 else:73 prof.print_stats(sort)74 75 76#**************************************************************************77# The following are the static member functions for the profiler class78# Note that an instance of Profile() is *not* needed to call them.79#**************************************************************************80 81def run(statement, filename=None, sort=-1):82 """Run statement under profiler optionally saving results in filename83 84 This function takes a single argument that can be passed to the85 "exec" statement, and an optional file name. In all cases this86 routine attempts to "exec" its first argument and gather profiling87 statistics from the execution. If no file name is present, then this88 function automatically prints a simple profiling report, sorted by the89 standard name string (file/line/function-name) that is presented in90 each line.91 """92 return _Utils(Profile).run(statement, filename, sort)93 94def runctx(statement, globals, locals, filename=None, sort=-1):95 """Run statement under profiler, supplying your own globals and locals,96 optionally saving results in filename.97 98 statement and filename have the same semantics as profile.run99 """100 return _Utils(Profile).runctx(statement, globals, locals, filename, sort)101 102 103class Profile:104 """Profiler class.105 106 self.cur is always a tuple. Each such tuple corresponds to a stack107 frame that is currently active (self.cur[-2]). The following are the108 definitions of its members. We use this external "parallel stack" to109 avoid contaminating the program that we are profiling. (old profiler110 used to write into the frames local dictionary!!) Derived classes111 can change the definition of some entries, as long as they leave112 [-2:] intact (frame and previous tuple). In case an internal error is113 detected, the -3 element is used as the function name.114 115 [ 0] = Time that needs to be charged to the parent frame's function.116 It is used so that a function call will not have to access the117 timing data for the parent frame.118 [ 1] = Total time spent in this frame's function, excluding time in119 subfunctions (this latter is tallied in cur[2]).120 [ 2] = Total time spent in subfunctions, excluding time executing the121 frame's function (this latter is tallied in cur[1]).122 [-3] = Name of the function that corresponds to this frame.123 [-2] = Actual frame that we correspond to (used to sync exception handling).124 [-1] = Our parent 6-tuple (corresponds to frame.f_back).125 126 Timing data for each function is stored as a 5-tuple in the dictionary127 self.timings[]. The index is always the name stored in self.cur[-3].128 The following are the definitions of the members:129 130 [0] = The number of times this function was called, not counting direct131 or indirect recursion,132 [1] = Number of times this function appears on the stack, minus one133 [2] = Total time spent internal to this function134 [3] = Cumulative time that this function was present on the stack. In135 non-recursive functions, this is the total execution time from start136 to finish of each invocation of a function, including time spent in137 all subfunctions.138 [4] = A dictionary indicating for each function name, the number of times139 it was called by us.140 """141 142 bias = 0 # calibration constant143 144 def __init__(self, timer=None, bias=None):145 self.timings = {}146 self.cur = None147 self.cmd = ""148 self.c_func_name = ""149 150 if bias is None:151 bias = self.bias152 self.bias = bias # Materialize in local dict for lookup speed.153 154 if not timer:155 self.timer = self.get_time = time.process_time156 self.dispatcher = self.trace_dispatch_i157 else:158 self.timer = timer159 t = self.timer() # test out timer function160 try:161 length = len(t)162 except TypeError:163 self.get_time = timer164 self.dispatcher = self.trace_dispatch_i165 else:166 if length == 2:167 self.dispatcher = self.trace_dispatch168 else:169 self.dispatcher = self.trace_dispatch_l170 # This get_time() implementation needs to be defined171 # here to capture the passed-in timer in the parameter172 # list (for performance). Note that we can't assume173 # the timer() result contains two values in all174 # cases.175 def get_time_timer(timer=timer, sum=sum):176 return sum(timer())177 self.get_time = get_time_timer178 self.t = self.get_time()179 self.simulate_call('profiler')180 181 # Heavily optimized dispatch routine for time.process_time() timer182 183 def trace_dispatch(self, frame, event, arg):184 timer = self.timer185 t = timer()186 t = t[0] + t[1] - self.t - self.bias187 188 if event == "c_call":189 self.c_func_name = arg.__name__190 191 if self.dispatch[event](self, frame,t):192 t = timer()193 self.t = t[0] + t[1]194 else:195 r = timer()196 self.t = r[0] + r[1] - t # put back unrecorded delta197 198 # Dispatch routine for best timer program (return = scalar, fastest if199 # an integer but float works too -- and time.process_time() relies on that).200 201 def trace_dispatch_i(self, frame, event, arg):202 timer = self.timer203 t = timer() - self.t - self.bias204 205 if event == "c_call":206 self.c_func_name = arg.__name__207 208 if self.dispatch[event](self, frame, t):209 self.t = timer()210 else:211 self.t = timer() - t # put back unrecorded delta212 213 # Dispatch routine for macintosh (timer returns time in ticks of214 # 1/60th second)215 216 def trace_dispatch_mac(self, frame, event, arg):217 timer = self.timer218 t = timer()/60.0 - self.t - self.bias219 220 if event == "c_call":221 self.c_func_name = arg.__name__222 223 if self.dispatch[event](self, frame, t):224 self.t = timer()/60.0225 else:226 self.t = timer()/60.0 - t # put back unrecorded delta227 228 # SLOW generic dispatch routine for timer returning lists of numbers229 230 def trace_dispatch_l(self, frame, event, arg):231 get_time = self.get_time232 t = get_time() - self.t - self.bias233 234 if event == "c_call":235 self.c_func_name = arg.__name__236 237 if self.dispatch[event](self, frame, t):238 self.t = get_time()239 else:240 self.t = get_time() - t # put back unrecorded delta241 242 # In the event handlers, the first 3 elements of self.cur are unpacked243 # into vrbls w/ 3-letter names. The last two characters are meant to be244 # mnemonic:245 # _pt self.cur[0] "parent time" time to be charged to parent frame246 # _it self.cur[1] "internal time" time spent directly in the function247 # _et self.cur[2] "external time" time spent in subfunctions248 249 def trace_dispatch_exception(self, frame, t):250 rpt, rit, ret, rfn, rframe, rcur = self.cur251 if (rframe is not frame) and rcur:252 return self.trace_dispatch_return(rframe, t)253 self.cur = rpt, rit+t, ret, rfn, rframe, rcur254 return 1255 256 257 def trace_dispatch_call(self, frame, t):258 if self.cur and frame.f_back is not self.cur[-2]:259 rpt, rit, ret, rfn, rframe, rcur = self.cur260 if not isinstance(rframe, Profile.fake_frame):261 assert rframe.f_back is frame.f_back, ("Bad call", rfn,262 rframe, rframe.f_back,263 frame, frame.f_back)264 self.trace_dispatch_return(rframe, 0)265 assert (self.cur is None or \266 frame.f_back is self.cur[-2]), ("Bad call",267 self.cur[-3])268 fcode = frame.f_code269 fn = (fcode.co_filename, fcode.co_firstlineno, fcode.co_name)270 self.cur = (t, 0, 0, fn, frame, self.cur)271 timings = self.timings272 if fn in timings:273 cc, ns, tt, ct, callers = timings[fn]274 timings[fn] = cc, ns + 1, tt, ct, callers275 else:276 timings[fn] = 0, 0, 0, 0, {}277 return 1278 279 def trace_dispatch_c_call (self, frame, t):280 fn = ("", 0, self.c_func_name)281 self.cur = (t, 0, 0, fn, frame, self.cur)282 timings = self.timings283 if fn in timings:284 cc, ns, tt, ct, callers = timings[fn]285 timings[fn] = cc, ns+1, tt, ct, callers286 else:287 timings[fn] = 0, 0, 0, 0, {}288 return 1289 290 def trace_dispatch_return(self, frame, t):291 if frame is not self.cur[-2]:292 assert frame is self.cur[-2].f_back, ("Bad return", self.cur[-3])293 self.trace_dispatch_return(self.cur[-2], 0)294 295 # Prefix "r" means part of the Returning or exiting frame.296 # Prefix "p" means part of the Previous or Parent or older frame.297 298 rpt, rit, ret, rfn, frame, rcur = self.cur299 rit = rit + t300 frame_total = rit + ret301 302 ppt, pit, pet, pfn, pframe, pcur = rcur303 self.cur = ppt, pit + rpt, pet + frame_total, pfn, pframe, pcur304 305 timings = self.timings306 cc, ns, tt, ct, callers = timings[rfn]307 if not ns:308 # This is the only occurrence of the function on the stack.309 # Else this is a (directly or indirectly) recursive call, and310 # its cumulative time will get updated when the topmost call to311 # it returns.312 ct = ct + frame_total313 cc = cc + 1314 315 if pfn in callers:316 callers[pfn] = callers[pfn] + 1 # hack: gather more317 # stats such as the amount of time added to ct courtesy318 # of this specific call, and the contribution to cc319 # courtesy of this call.320 else:321 callers[pfn] = 1322 323 timings[rfn] = cc, ns - 1, tt + rit, ct, callers324 325 return 1326 327 328 dispatch = {329 "call": trace_dispatch_call,330 "exception": trace_dispatch_exception,331 "return": trace_dispatch_return,332 "c_call": trace_dispatch_c_call,333 "c_exception": trace_dispatch_return, # the C function returned334 "c_return": trace_dispatch_return,335 }336 337 338 # The next few functions play with self.cmd. By carefully preloading339 # our parallel stack, we can force the profiled result to include340 # an arbitrary string as the name of the calling function.341 # We use self.cmd as that string, and the resulting stats look342 # very nice :-).343 344 def set_cmd(self, cmd):345 if self.cur[-1]: return # already set346 self.cmd = cmd347 self.simulate_call(cmd)348 349 class fake_code:350 def __init__(self, filename, line, name):351 self.co_filename = filename352 self.co_line = line353 self.co_name = name354 self.co_firstlineno = 0355 356 def __repr__(self):357 return repr((self.co_filename, self.co_line, self.co_name))358 359 class fake_frame:360 def __init__(self, code, prior):361 self.f_code = code362 self.f_back = prior363 364 def simulate_call(self, name):365 code = self.fake_code('profile', 0, name)366 if self.cur:367 pframe = self.cur[-2]368 else:369 pframe = None370 frame = self.fake_frame(code, pframe)371 self.dispatch['call'](self, frame, 0)372 373 # collect stats from pending stack, including getting final374 # timings for self.cmd frame.375 376 def simulate_cmd_complete(self):377 get_time = self.get_time378 t = get_time() - self.t379 while self.cur[-1]:380 # We *can* cause assertion errors here if381 # dispatch_trace_return checks for a frame match!382 self.dispatch['return'](self, self.cur[-2], t)383 t = 0384 self.t = get_time() - t385 386 387 def print_stats(self, sort=-1):388 import pstats389 if not isinstance(sort, tuple):390 sort = (sort,)391 pstats.Stats(self).strip_dirs().sort_stats(*sort).print_stats()392 393 def dump_stats(self, file):394 with open(file, 'wb') as f:395 self.create_stats()396 marshal.dump(self.stats, f)397 398 def create_stats(self):399 self.simulate_cmd_complete()400 self.snapshot_stats()401 402 def snapshot_stats(self):403 self.stats = {}404 for func, (cc, ns, tt, ct, callers) in self.timings.items():405 callers = callers.copy()406 nc = 0407 for callcnt in callers.values():408 nc += callcnt409 self.stats[func] = cc, nc, tt, ct, callers410 411 412 # The following two methods can be called by clients to use413 # a profiler to profile a statement, given as a string.414 415 def run(self, cmd):416 import __main__417 dict = __main__.__dict__418 return self.runctx(cmd, dict, dict)419 420 def runctx(self, cmd, globals, locals):421 self.set_cmd(cmd)422 sys.setprofile(self.dispatcher)423 try:424 exec(cmd, globals, locals)425 finally:426 sys.setprofile(None)427 return self428 429 # This method is more useful to profile a single function call.430 def runcall(self, func, /, *args, **kw):431 self.set_cmd(repr(func))432 sys.setprofile(self.dispatcher)433 try:434 return func(*args, **kw)435 finally:436 sys.setprofile(None)437 438 439 #******************************************************************440 # The following calculates the overhead for using a profiler. The441 # problem is that it takes a fair amount of time for the profiler442 # to stop the stopwatch (from the time it receives an event).443 # Similarly, there is a delay from the time that the profiler444 # re-starts the stopwatch before the user's code really gets to445 # continue. The following code tries to measure the difference on446 # a per-event basis.447 #448 # Note that this difference is only significant if there are a lot of449 # events, and relatively little user code per event. For example,450 # code with small functions will typically benefit from having the451 # profiler calibrated for the current platform. This *could* be452 # done on the fly during init() time, but it is not worth the453 # effort. Also note that if too large a value specified, then454 # execution time on some functions will actually appear as a455 # negative number. It is *normal* for some functions (with very456 # low call counts) to have such negative stats, even if the457 # calibration figure is "correct."458 #459 # One alternative to profile-time calibration adjustments (i.e.,460 # adding in the magic little delta during each event) is to track461 # more carefully the number of events (and cumulatively, the number462 # of events during sub functions) that are seen. If this were463 # done, then the arithmetic could be done after the fact (i.e., at464 # display time). Currently, we track only call/return events.465 # These values can be deduced by examining the callees and callers466 # vectors for each functions. Hence we *can* almost correct the467 # internal time figure at print time (note that we currently don't468 # track exception event processing counts). Unfortunately, there469 # is currently no similar information for cumulative sub-function470 # time. It would not be hard to "get all this info" at profiler471 # time. Specifically, we would have to extend the tuples to keep472 # counts of this in each frame, and then extend the defs of timing473 # tuples to include the significant two figures. I'm a bit fearful474 # that this additional feature will slow the heavily optimized475 # event/time ratio (i.e., the profiler would run slower, fur a very476 # low "value added" feature.)477 #**************************************************************478 479 def calibrate(self, m, verbose=0):480 if self.__class__ is not Profile:481 raise TypeError("Subclasses must override .calibrate().")482 483 saved_bias = self.bias484 self.bias = 0485 try:486 return self._calibrate_inner(m, verbose)487 finally:488 self.bias = saved_bias489 490 def _calibrate_inner(self, m, verbose):491 get_time = self.get_time492 493 # Set up a test case to be run with and without profiling. Include494 # lots of calls, because we're trying to quantify stopwatch overhead.495 # Do not raise any exceptions, though, because we want to know496 # exactly how many profile events are generated (one call event, +497 # one return event, per Python-level call).498 499 def f1(n):500 for i in range(n):501 x = 1502 503 def f(m, f1=f1):504 for i in range(m):505 f1(100)506 507 f(m) # warm up the cache508 509 # elapsed_noprofile <- time f(m) takes without profiling.510 t0 = get_time()511 f(m)512 t1 = get_time()513 elapsed_noprofile = t1 - t0514 if verbose:515 print("elapsed time without profiling =", elapsed_noprofile)516 517 # elapsed_profile <- time f(m) takes with profiling. The difference518 # is profiling overhead, only some of which the profiler subtracts519 # out on its own.520 p = Profile()521 t0 = get_time()522 p.runctx('f(m)', globals(), locals())523 t1 = get_time()524 elapsed_profile = t1 - t0525 if verbose:526 print("elapsed time with profiling =", elapsed_profile)527 528 # reported_time <- "CPU seconds" the profiler charged to f and f1.529 total_calls = 0.0530 reported_time = 0.0531 for (filename, line, funcname), (cc, ns, tt, ct, callers) in \532 p.timings.items():533 if funcname in ("f", "f1"):534 total_calls += cc535 reported_time += tt536 537 if verbose:538 print("'CPU seconds' profiler reported =", reported_time)539 print("total # calls =", total_calls)540 if total_calls != m + 1:541 raise ValueError("internal error: total calls = %d" % total_calls)542 543 # reported_time - elapsed_noprofile = overhead the profiler wasn't544 # able to measure. Divide by twice the number of calls (since there545 # are two profiler events per call in this test) to get the hidden546 # overhead per event.547 mean = (reported_time - elapsed_noprofile) / 2.0 / total_calls548 if verbose:549 print("mean stopwatch overhead per profile event =", mean)550 return mean551 552#****************************************************************************553 554def main():555 import os556 from optparse import OptionParser557 558 usage = "profile.py [-o output_file_path] [-s sort] [-m module | scriptfile] [arg] ..."559 parser = OptionParser(usage=usage)560 parser.allow_interspersed_args = False561 parser.add_option('-o', '--outfile', dest="outfile",562 help="Save stats to <outfile>", default=None)563 parser.add_option('-m', dest="module", action="store_true",564 help="Profile a library module.", default=False)565 parser.add_option('-s', '--sort', dest="sort",566 help="Sort order when printing to stdout, based on pstats.Stats class",567 default=-1)568 569 if not sys.argv[1:]:570 parser.print_usage()571 sys.exit(2)572 573 (options, args) = parser.parse_args()574 sys.argv[:] = args575 576 # The script that we're profiling may chdir, so capture the absolute path577 # to the output file at startup.578 if options.outfile is not None:579 options.outfile = os.path.abspath(options.outfile)580 581 if len(args) > 0:582 if options.module:583 import runpy584 code = "run_module(modname, run_name='__main__')"585 globs = {586 'run_module': runpy.run_module,587 'modname': args[0]588 }589 else:590 progname = args[0]591 sys.path.insert(0, os.path.dirname(progname))592 with io.open_code(progname) as fp:593 code = compile(fp.read(), progname, 'exec')594 spec = importlib.machinery.ModuleSpec(name='__main__', loader=None,595 origin=progname)596 globs = {597 '__spec__': spec,598 '__file__': spec.origin,599 '__name__': spec.name,600 '__package__': None,601 '__cached__': None,602 }603 try:604 runctx(code, globs, None, options.outfile, options.sort)605 except BrokenPipeError as exc:606 # Prevent "Exception ignored" during interpreter shutdown.607 sys.stdout = None608 sys.exit(exc.errno)609 else:610 parser.print_usage()611 return parser612 613# When invoked as main program, invoke the profiler on a script614if __name__ == '__main__':615 main()616