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