Lib/profile.py

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