home *** CD-ROM | disk | FTP | other *** search
/ PC World 2002 May / PCWorld_2002-05_cd.bin / Software / TemaCD / activepython / ActivePython-2.1.1.msi / Python21_Lib_profile.py < prev    next >
Encoding:
Python Source  |  2001-07-26  |  20.8 KB  |  581 lines
  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` + ')')
  581.