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 class Profile:
  93     """Profiler class.
  94
  95     self.cur is always a tuple.  Each such tuple corresponds to a stack
  96     frame that is currently active (self.cur[-2]).  The following are the
  97     definitions of its members.  We use this external "parallel stack" to
  98     avoid contaminating the program that we are profiling. (old profiler
  99     used to write into the frames local dictionary!!) Derived classes
 100     can change the definition of some entries, as long as they leave
 101     [-2:] intact.
 102
 103     [ 0] = Time that needs to be charged to the parent frame's function.
 104            It is used so that a function call will not have to access the
 105            timing data for the parent frame.
 106     [ 1] = Total time spent in this frame's function, excluding time in
 107            subfunctions
 108     [ 2] = Cumulative time spent in this frame's function, including time in
 109            all subfunctions to this frame.
 110     [-3] = Name of the function that corresponds to this frame.
 111     [-2] = Actual frame that we correspond to (used to sync exception handling)
 112     [-1] = Our parent 6-tuple (corresponds to frame.f_back)
 113
 114     Timing data for each function is stored as a 5-tuple in the dictionary
 115     self.timings[].  The index is always the name stored in self.cur[4].
 116     The following are the definitions of the members:
 117
 118     [0] = The number of times this function was called, not counting direct
 119           or indirect recursion,
 120     [1] = Number of times this function appears on the stack, minus one
 121     [2] = Total time spent internal to this function
 122     [3] = Cumulative time that this function was present on the stack.  In
 123           non-recursive functions, this is the total execution time from start
 124           to finish of each invocation of a function, including time spent in
 125           all subfunctions.
 126     [5] = A dictionary indicating for each function name, the number of times
 127           it was called by us.
 128     """
 129
 130     def __init__(self, timer=None):
 131         self.timings = {}
 132         self.cur = None
 133         self.cmd = ""
 134
 135         self.dispatch = {  \
 136                   'call'     : self.trace_dispatch_call, \
 137                   'return'   : self.trace_dispatch_return, \
 138                   'exception': self.trace_dispatch_exception, \
 139                   }
 140
 141         if not timer:
 142             if os.name == 'mac':
 143                 import MacOS
 144                 self.timer = MacOS.GetTicks
 145                 self.dispatcher = self.trace_dispatch_mac
 146                 self.get_time = self.get_time_mac
 147             elif hasattr(time, 'clock'):
 148                 self.timer = time.clock
 149                 self.dispatcher = self.trace_dispatch_i
 150             elif hasattr(os, 'times'):
 151                 self.timer = os.times
 152                 self.dispatcher = self.trace_dispatch
 153             else:
 154                 self.timer = time.time
 155                 self.dispatcher = self.trace_dispatch_i
 156         else:
 157             self.timer = timer
 158             t = self.timer() # test out timer function
 159             try:
 160                 if len(t) == 2:
 161                     self.dispatcher = self.trace_dispatch
 162                 else:
 163                     self.dispatcher = self.trace_dispatch_l
 164             except TypeError:
 165                 self.dispatcher = self.trace_dispatch_i
 166         self.t = self.get_time()
 167         self.simulate_call('profiler')
 168
 169
 170     def get_time(self): # slow simulation of method to acquire time
 171         t = self.timer()
 172         if type(t) == type(()) or type(t) == type([]):
 173             t = reduce(lambda x,y: x+y, t, 0)
 174         return t
 175
 176     def get_time_mac(self):
 177         return self.timer()/60.0
 178
 179     # Heavily optimized dispatch routine for os.times() timer
 180
 181     def trace_dispatch(self, frame, event, arg):
 182         t = self.timer()
 183         t = t[0] + t[1] - self.t        # No Calibration constant
 184         # t = t[0] + t[1] - self.t - .00053 # Calibration constant
 185
 186         if self.dispatch[event](frame,t):
 187             t = self.timer()
 188             self.t = t[0] + t[1]
 189         else:
 190             r = self.timer()
 191             self.t = r[0] + r[1] - t # put back unrecorded delta
 192         return
 193
 194
 195
 196     # Dispatch routine for best timer program (return = scalar integer)
 197
 198     def trace_dispatch_i(self, frame, event, arg):
 199         t = self.timer() - self.t # - 1 # Integer calibration constant
 200         if self.dispatch[event](frame,t):
 201             self.t = self.timer()
 202         else:
 203             self.t = self.timer() - t  # put back unrecorded delta
 204         return
 205
 206     # Dispatch routine for macintosh (timer returns time in ticks of 1/60th second)
 207
 208     def trace_dispatch_mac(self, frame, event, arg):
 209         t = self.timer()/60.0 - self.t # - 1 # Integer calibration constant
 210         if self.dispatch[event](frame,t):
 211             self.t = self.timer()/60.0
 212         else:
 213             self.t = self.timer()/60.0 - t  # put back unrecorded delta
 214         return
 215
 216
 217     # SLOW generic dispatch routine for timer returning lists of numbers
 218
 219     def trace_dispatch_l(self, frame, event, arg):
 220         t = self.get_time() - self.t
 221
 222         if self.dispatch[event](frame,t):
 223             self.t = self.get_time()
 224         else:
 225             self.t = self.get_time()-t # put back unrecorded delta
 226         return
 227
 228
 229     def trace_dispatch_exception(self, frame, t):
 230         rt, rtt, rct, rfn, rframe, rcur = self.cur
 231         if (not rframe is frame) and rcur:
 232             return self.trace_dispatch_return(rframe, t)
 233         return 0
 234
 235
 236     def trace_dispatch_call(self, frame, t):
 237         fcode = frame.f_code
 238         fn = (fcode.co_filename, fcode.co_firstlineno, fcode.co_name)
 239         self.cur = (t, 0, 0, fn, frame, self.cur)
 240         if self.timings.has_key(fn):
 241             cc, ns, tt, ct, callers = self.timings[fn]
 242             self.timings[fn] = cc, ns + 1, tt, ct, callers
 243         else:
 244             self.timings[fn] = 0, 0, 0, 0, {}
 245         return 1
 246
 247     def trace_dispatch_return(self, frame, t):
 248         # if not frame is self.cur[-2]: raise "Bad return", self.cur[3]
 249
 250         # Prefix "r" means part of the Returning or exiting frame
 251         # Prefix "p" means part of the Previous or older frame
 252
 253         rt, rtt, rct, rfn, frame, rcur = self.cur
 254         rtt = rtt + t
 255         sft = rtt + rct
 256
 257         pt, ptt, pct, pfn, pframe, pcur = rcur
 258         self.cur = pt, ptt+rt, pct+sft, pfn, pframe, pcur
 259
 260         cc, ns, tt, ct, callers = self.timings[rfn]
 261         if not ns:
 262             ct = ct + sft
 263             cc = cc + 1
 264         if callers.has_key(pfn):
 265             callers[pfn] = callers[pfn] + 1  # hack: gather more
 266             # stats such as the amount of time added to ct courtesy
 267             # of this specific call, and the contribution to cc
 268             # courtesy of this call.
 269         else:
 270             callers[pfn] = 1
 271         self.timings[rfn] = cc, ns - 1, tt+rtt, ct, callers
 272
 273         return 1
 274
 275     # The next few function play with self.cmd. By carefully preloading
 276     # our parallel stack, we can force the profiled result to include
 277     # an arbitrary string as the name of the calling function.
 278     # We use self.cmd as that string, and the resulting stats look
 279     # very nice :-).
 280
 281     def set_cmd(self, cmd):
 282         if self.cur[-1]: return   # already set
 283         self.cmd = cmd
 284         self.simulate_call(cmd)
 285
 286     class fake_code:
 287         def __init__(self, filename, line, name):
 288             self.co_filename = filename
 289             self.co_line = line
 290             self.co_name = name
 291             self.co_firstlineno = 0
 292
 293         def __repr__(self):
 294             return repr((self.co_filename, self.co_line, self.co_name))
 295
 296     class fake_frame:
 297         def __init__(self, code, prior):
 298             self.f_code = code
 299             self.f_back = prior
 300
 301     def simulate_call(self, name):
 302         code = self.fake_code('profile', 0, name)
 303         if self.cur:
 304             pframe = self.cur[-2]
 305         else:
 306             pframe = None
 307         frame = self.fake_frame(code, pframe)
 308         a = self.dispatch['call'](frame, 0)
 309         return
 310
 311     # collect stats from pending stack, including getting final
 312     # timings for self.cmd frame.
 313
 314     def simulate_cmd_complete(self):
 315         t = self.get_time() - self.t
 316         while self.cur[-1]:
 317             # We *can* cause assertion errors here if
 318             # dispatch_trace_return checks for a frame match!
 319             a = self.dispatch['return'](self.cur[-2], t)
 320             t = 0
 321         self.t = self.get_time() - t
 322
 323
 324     def print_stats(self):
 325         import pstats
 326         pstats.Stats(self).strip_dirs().sort_stats(-1). \
 327                   print_stats()
 328
 329     def dump_stats(self, file):
 330         f = open(file, 'wb')
 331         self.create_stats()
 332         marshal.dump(self.stats, f)
 333         f.close()
 334
 335     def create_stats(self):
 336         self.simulate_cmd_complete()
 337         self.snapshot_stats()
 338
 339     def snapshot_stats(self):
 340         self.stats = {}
 341         for func in self.timings.keys():
 342             cc, ns, tt, ct, callers = self.timings[func]
 343             callers = callers.copy()
 344             nc = 0
 345             for func_caller in callers.keys():
 346                 nc = nc + callers[func_caller]
 347             self.stats[func] = cc, nc, tt, ct, callers
 348
 349
 350     # The following two methods can be called by clients to use
 351     # a profiler to profile a statement, given as a string.
 352
 353     def run(self, cmd):
 354         import __main__
 355         dict = __main__.__dict__
 356         return self.runctx(cmd, dict, dict)
 357
 358     def runctx(self, cmd, globals, locals):
 359         self.set_cmd(cmd)
 360         sys.setprofile(self.dispatcher)
 361         try:
 362             exec cmd in globals, locals
 363         finally:
 364             sys.setprofile(None)
 365         return self
 366
 367     # This method is more useful to profile a single function call.
 368     def runcall(self, func, *args):
 369         self.set_cmd(`func`)
 370         sys.setprofile(self.dispatcher)
 371         try:
 372             return apply(func, args)
 373         finally:
 374             sys.setprofile(None)
 375
 376
 377     #******************************************************************
 378     # The following calculates the overhead for using a profiler.  The
 379     # problem is that it takes a fair amount of time for the profiler
 380     # to stop the stopwatch (from the time it receives an event).
 381     # Similarly, there is a delay from the time that the profiler
 382     # re-starts the stopwatch before the user's code really gets to
 383     # continue.  The following code tries to measure the difference on
 384     # a per-event basis. The result can the be placed in the
 385     # Profile.dispatch_event() routine for the given platform.  Note
 386     # that this difference is only significant if there are a lot of
 387     # events, and relatively little user code per event.  For example,
 388     # code with small functions will typically benefit from having the
 389     # profiler calibrated for the current platform.  This *could* be
 390     # done on the fly during init() time, but it is not worth the
 391     # effort.  Also note that if too large a value specified, then
 392     # execution time on some functions will actually appear as a
 393     # negative number.  It is *normal* for some functions (with very
 394     # low call counts) to have such negative stats, even if the
 395     # calibration figure is "correct."
 396     #
 397     # One alternative to profile-time calibration adjustments (i.e.,
 398     # adding in the magic little delta during each event) is to track
 399     # more carefully the number of events (and cumulatively, the number
 400     # of events during sub functions) that are seen.  If this were
 401     # done, then the arithmetic could be done after the fact (i.e., at
 402     # display time).  Currently, we track only call/return events.
 403     # These values can be deduced by examining the callees and callers
 404     # vectors for each functions.  Hence we *can* almost correct the
 405     # internal time figure at print time (note that we currently don't
 406     # track exception event processing counts).  Unfortunately, there
 407     # is currently no similar information for cumulative sub-function
 408     # time.  It would not be hard to "get all this info" at profiler
 409     # time.  Specifically, we would have to extend the tuples to keep
 410     # counts of this in each frame, and then extend the defs of timing
 411     # tuples to include the significant two figures. I'm a bit fearful
 412     # that this additional feature will slow the heavily optimized
 413     # event/time ratio (i.e., the profiler would run slower, fur a very
 414     # low "value added" feature.)
 415     #
 416     # Plugging in the calibration constant doesn't slow down the
 417     # profiler very much, and the accuracy goes way up.
 418     #**************************************************************
 419
 420     def calibrate(self, m):
 421         # Modified by Tim Peters
 422         n = m
 423         s = self.get_time()
 424         while n:
 425             self.simple()
 426             n = n - 1
 427         f = self.get_time()
 428         my_simple = f - s
 429         #print "Simple =", my_simple,
 430
 431         n = m
 432         s = self.get_time()
 433         while n:
 434             self.instrumented()
 435             n = n - 1
 436         f = self.get_time()
 437         my_inst = f - s
 438         # print "Instrumented =", my_inst
 439         avg_cost = (my_inst - my_simple)/m
 440         #print "Delta/call =", avg_cost, "(profiler fixup constant)"
 441         return avg_cost
 442
 443     # simulate a program with no profiler activity
 444     def simple(self):
 445         a = 1
 446         pass
 447
 448     # simulate a program with call/return event processing
 449     def instrumented(self):
 450         a = 1
 451         self.profiler_simulation(a, a, a)
 452
 453     # simulate an event processing activity (from user's perspective)
 454     def profiler_simulation(self, x, y, z):
 455         t = self.timer()
 456         ## t = t[0] + t[1]
 457         self.ut = t
 458
 459
 460
 461 class OldProfile(Profile):
 462     """A derived profiler that simulates the old style profile, providing
 463     errant results on recursive functions. The reason for the usefulness of
 464     this profiler is that it runs faster (i.e., less overhead).  It still
 465     creates all the caller stats, and is quite useful when there is *no*
 466     recursion in the user's code.
 467
 468     This code also shows how easy it is to create a modified profiler.
 469     """
 470
 471     def trace_dispatch_exception(self, frame, t):
 472         rt, rtt, rct, rfn, rframe, rcur = self.cur
 473         if rcur and not rframe is frame:
 474             return self.trace_dispatch_return(rframe, t)
 475         return 0
 476
 477     def trace_dispatch_call(self, frame, t):
 478         fn = `frame.f_code`
 479
 480         self.cur = (t, 0, 0, fn, frame, self.cur)
 481         if self.timings.has_key(fn):
 482             tt, ct, callers = self.timings[fn]
 483             self.timings[fn] = tt, ct, callers
 484         else:
 485             self.timings[fn] = 0, 0, {}
 486         return 1
 487
 488     def trace_dispatch_return(self, frame, t):
 489         rt, rtt, rct, rfn, frame, rcur = self.cur
 490         rtt = rtt + t
 491         sft = rtt + rct
 492
 493         pt, ptt, pct, pfn, pframe, pcur = rcur
 494         self.cur = pt, ptt+rt, pct+sft, pfn, pframe, pcur
 495
 496         tt, ct, callers = self.timings[rfn]
 497         if callers.has_key(pfn):
 498             callers[pfn] = callers[pfn] + 1
 499         else:
 500             callers[pfn] = 1
 501         self.timings[rfn] = tt+rtt, ct + sft, callers
 502
 503         return 1
 504
 505
 506     def snapshot_stats(self):
 507         self.stats = {}
 508         for func in self.timings.keys():
 509             tt, ct, callers = self.timings[func]
 510             callers = callers.copy()
 511             nc = 0
 512             for func_caller in callers.keys():
 513                 nc = nc + callers[func_caller]
 514             self.stats[func] = nc, nc, tt, ct, callers
 515
 516
 517
 518 class HotProfile(Profile):
 519     """The fastest derived profile example.  It does not calculate
 520     caller-callee relationships, and does not calculate cumulative
 521     time under a function.  It only calculates time spent in a
 522     function, so it runs very quickly due to its very low overhead.
 523     """
 524
 525     def trace_dispatch_exception(self, frame, t):
 526         rt, rtt, rfn, rframe, rcur = self.cur
 527         if rcur and not rframe is frame:
 528             return self.trace_dispatch_return(rframe, t)
 529         return 0
 530
 531     def trace_dispatch_call(self, frame, t):
 532         self.cur = (t, 0, frame, self.cur)
 533         return 1
 534
 535     def trace_dispatch_return(self, frame, t):
 536         rt, rtt, frame, rcur = self.cur
 537
 538         rfn = `frame.f_code`
 539
 540         pt, ptt, pframe, pcur = rcur
 541         self.cur = pt, ptt+rt, pframe, pcur
 542
 543         if self.timings.has_key(rfn):
 544             nc, tt = self.timings[rfn]
 545             self.timings[rfn] = nc + 1, rt + rtt + tt
 546         else:
 547             self.timings[rfn] =      1, rt + rtt
 548
 549         return 1
 550
 551
 552     def snapshot_stats(self):
 553         self.stats = {}
 554         for func in self.timings.keys():
 555             nc, tt = self.timings[func]
 556             self.stats[func] = nc, nc, tt, 0, {}
 557
 558
 559
 560 #****************************************************************************
 561 def Stats(*args):
 562     print 'Report generating functions are in the "pstats" module\a'
 563
 564
 565 # When invoked as main program, invoke the profiler on a script
 566 if __name__ == '__main__':
 567     import sys
 568     import os
 569     if not sys.argv[1:]:
 570         print "usage: profile.py scriptfile [arg] ..."
 571         sys.exit(2)
 572
 573     filename = sys.argv[1]  # Get script filename
 574
 575     del sys.argv[0]         # Hide "profile.py" from argument list
 576
 577     # Insert script directory in front of module search path
 578     sys.path.insert(0, os.path.dirname(filename))
 579
 580     run('execfile(' + `filename` + ')')