home *** CD-ROM | disk | FTP | other *** search
/ Chip 2003 January / Chip_2003-01_cd2.bin / convert / eJayMp3Pro / mp3pro_demo.exe / PROFILE.PY < prev    next >
Encoding:
Python Source  |  1998-09-21  |  18.8 KB  |  579 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.  
  11. # Copyright 1994, by InfoSeek Corporation, all rights reserved.
  12. # Written by James Roskind
  13. # 
  14. # Permission to use, copy, modify, and distribute this Python software
  15. # and its associated documentation for any purpose (subject to the
  16. # restriction in the following sentence) without fee is hereby granted,
  17. # provided that the above copyright notice appears in all copies, and
  18. # that both that copyright notice and this permission notice appear in
  19. # supporting documentation, and that the name of InfoSeek not be used in
  20. # advertising or publicity pertaining to distribution of the software
  21. # without specific, written prior permission.  This permission is
  22. # explicitly restricted to the copying and modification of the software
  23. # to remain in Python, compiled Python, or other languages (such as C)
  24. # wherein the modified or derived code is exclusively imported into a
  25. # Python module.
  26. # 
  27. # INFOSEEK CORPORATION DISCLAIMS ALL WARRANTIES WITH REGARD TO THIS
  28. # SOFTWARE, INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY AND
  29. # FITNESS. IN NO EVENT SHALL INFOSEEK CORPORATION BE LIABLE FOR ANY
  30. # SPECIAL, INDIRECT OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER
  31. # RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF
  32. # CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN
  33. # CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.
  34.  
  35.  
  36.  
  37. import sys
  38. import os
  39. import time
  40. import string
  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. #**************************************************************************
  84. # class Profile documentation:
  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.  It is
  95. #        used so that a function call will not have to access the timing data
  96. #        for the parents 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. class Profile:
  121.  
  122.     def __init__(self, timer=None):
  123.         self.timings = {}
  124.         self.cur = None
  125.         self.cmd = ""
  126.  
  127.         self.dispatch = {  \
  128.               'call'     : self.trace_dispatch_call, \
  129.               'return'   : self.trace_dispatch_return, \
  130.               'exception': self.trace_dispatch_exception, \
  131.               }
  132.  
  133.         if not timer:
  134.             if os.name == 'mac':
  135.                 import MacOS
  136.                 self.timer = MacOS.GetTicks
  137.                 self.dispatcher = self.trace_dispatch_mac
  138.                 self.get_time = self.get_time_mac
  139.             elif hasattr(time, 'clock'):
  140.                 self.timer = time.clock
  141.                 self.dispatcher = self.trace_dispatch_i
  142.             elif hasattr(os, 'times'):
  143.                 self.timer = os.times
  144.                 self.dispatcher = self.trace_dispatch
  145.             else:
  146.                 self.timer = time.time
  147.                 self.dispatcher = self.trace_dispatch_i
  148.         else:
  149.             self.timer = timer
  150.             t = self.timer() # test out timer function
  151.             try:
  152.                 if len(t) == 2:
  153.                     self.dispatcher = self.trace_dispatch
  154.                 else:
  155.                     self.dispatcher = self.trace_dispatch_l
  156.             except TypeError:
  157.                 self.dispatcher = self.trace_dispatch_i
  158.         self.t = self.get_time()
  159.         self.simulate_call('profiler')
  160.  
  161.  
  162.     def get_time(self): # slow simulation of method to acquire time
  163.         t = self.timer()
  164.         if type(t) == type(()) or type(t) == type([]):
  165.             t = reduce(lambda x,y: x+y, t, 0)
  166.         return t
  167.         
  168.     def get_time_mac(self):
  169.         return self.timer()/60.0
  170.  
  171.     # Heavily optimized dispatch routine for os.times() timer
  172.  
  173.     def trace_dispatch(self, frame, event, arg):
  174.         t = self.timer()
  175.         t = t[0] + t[1] - self.t        # No Calibration constant
  176.         # t = t[0] + t[1] - self.t - .00053 # Calibration constant
  177.  
  178.         if self.dispatch[event](frame,t):
  179.             t = self.timer()
  180.             self.t = t[0] + t[1]
  181.         else:
  182.             r = self.timer()
  183.             self.t = r[0] + r[1] - t # put back unrecorded delta
  184.         return
  185.  
  186.  
  187.  
  188.     # Dispatch routine for best timer program (return = scalar integer)
  189.  
  190.     def trace_dispatch_i(self, frame, event, arg):
  191.         t = self.timer() - self.t # - 1 # Integer calibration constant
  192.         if self.dispatch[event](frame,t):
  193.             self.t = self.timer()
  194.         else:
  195.             self.t = self.timer() - t  # put back unrecorded delta
  196.         return
  197.     
  198.     # Dispatch routine for macintosh (timer returns time in ticks of 1/60th second)
  199.  
  200.     def trace_dispatch_mac(self, frame, event, arg):
  201.         t = self.timer()/60.0 - self.t # - 1 # Integer calibration constant
  202.         if self.dispatch[event](frame,t):
  203.             self.t = self.timer()/60.0
  204.         else:
  205.             self.t = self.timer()/60.0 - t  # put back unrecorded delta
  206.         return
  207.  
  208.  
  209.     # SLOW generic dispatch rountine for timer returning lists of numbers
  210.  
  211.     def trace_dispatch_l(self, frame, event, arg):
  212.         t = self.get_time() - self.t
  213.  
  214.         if self.dispatch[event](frame,t):
  215.             self.t = self.get_time()
  216.         else:
  217.             self.t = self.get_time()-t # put back unrecorded delta
  218.         return
  219.  
  220.  
  221.     def trace_dispatch_exception(self, frame, t):
  222.         rt, rtt, rct, rfn, rframe, rcur = self.cur
  223.         if (not rframe is frame) and rcur:
  224.             return self.trace_dispatch_return(rframe, t)
  225.         return 0
  226.  
  227.  
  228.     def trace_dispatch_call(self, frame, t):
  229.         fcode = frame.f_code
  230.         fn = (fcode.co_filename, fcode.co_firstlineno, fcode.co_name)
  231.         self.cur = (t, 0, 0, fn, frame, self.cur)
  232.         if self.timings.has_key(fn):
  233.             cc, ns, tt, ct, callers = self.timings[fn]
  234.             self.timings[fn] = cc, ns + 1, tt, ct, callers
  235.         else:
  236.             self.timings[fn] = 0, 0, 0, 0, {}
  237.         return 1
  238.  
  239.     def trace_dispatch_return(self, frame, t):
  240.         # if not frame is self.cur[-2]: raise "Bad return", self.cur[3]
  241.  
  242.         # Prefix "r" means part of the Returning or exiting frame
  243.         # Prefix "p" means part of the Previous or older frame
  244.  
  245.         rt, rtt, rct, rfn, frame, rcur = self.cur
  246.         rtt = rtt + t
  247.         sft = rtt + rct
  248.  
  249.         pt, ptt, pct, pfn, pframe, pcur = rcur
  250.         self.cur = pt, ptt+rt, pct+sft, pfn, pframe, pcur
  251.  
  252.         cc, ns, tt, ct, callers = self.timings[rfn]
  253.         if not ns:
  254.             ct = ct + sft
  255.             cc = cc + 1
  256.         if callers.has_key(pfn):
  257.             callers[pfn] = callers[pfn] + 1  # hack: gather more
  258.             # stats such as the amount of time added to ct courtesy
  259.             # of this specific call, and the contribution to cc
  260.             # courtesy of this call.
  261.         else:
  262.             callers[pfn] = 1
  263.         self.timings[rfn] = cc, ns - 1, tt+rtt, ct, callers
  264.  
  265.         return 1
  266.  
  267.     # The next few function play with self.cmd. By carefully preloading
  268.     # our paralell stack, we can force the profiled result to include
  269.     # an arbitrary string as the name of the calling function.
  270.     # We use self.cmd as that string, and the resulting stats look
  271.     # very nice :-).
  272.  
  273.     def set_cmd(self, cmd):
  274.         if self.cur[-1]: return   # already set
  275.         self.cmd = cmd
  276.         self.simulate_call(cmd)
  277.  
  278.     class fake_code:
  279.         def __init__(self, filename, line, name):
  280.             self.co_filename = filename
  281.             self.co_line = line
  282.             self.co_name = name
  283.             self.co_firstlineno = 0
  284.  
  285.         def __repr__(self):
  286.             return repr((self.co_filename, self.co_line, self.co_name))
  287.  
  288.     class fake_frame:
  289.         def __init__(self, code, prior):
  290.             self.f_code = code
  291.             self.f_back = prior
  292.             
  293.     def simulate_call(self, name):
  294.         code = self.fake_code('profile', 0, name)
  295.         if self.cur:
  296.             pframe = self.cur[-2]
  297.         else:
  298.             pframe = None
  299.         frame = self.fake_frame(code, pframe)
  300.         a = self.dispatch['call'](frame, 0)
  301.         return
  302.  
  303.     # collect stats from pending stack, including getting final
  304.     # timings for self.cmd frame.
  305.     
  306.     def simulate_cmd_complete(self):   
  307.         t = self.get_time() - self.t
  308.         while self.cur[-1]:
  309.             # We *can* cause assertion errors here if
  310.             # dispatch_trace_return checks for a frame match!
  311.             a = self.dispatch['return'](self.cur[-2], t)
  312.             t = 0
  313.         self.t = self.get_time() - t
  314.  
  315.     
  316.     def print_stats(self):
  317.         import pstats
  318.         pstats.Stats(self).strip_dirs().sort_stats(-1). \
  319.               print_stats()
  320.  
  321.     def dump_stats(self, file):
  322.         f = open(file, 'wb')
  323.         self.create_stats()
  324.         marshal.dump(self.stats, f)
  325.         f.close()
  326.  
  327.     def create_stats(self):
  328.         self.simulate_cmd_complete()
  329.         self.snapshot_stats()
  330.  
  331.     def snapshot_stats(self):
  332.         self.stats = {}
  333.         for func in self.timings.keys():
  334.             cc, ns, tt, ct, callers = self.timings[func]
  335.             callers = callers.copy()
  336.             nc = 0
  337.             for func_caller in callers.keys():
  338.                 nc = nc + callers[func_caller]
  339.             self.stats[func] = cc, nc, tt, ct, callers
  340.  
  341.  
  342.     # The following two methods can be called by clients to use
  343.     # a profiler to profile a statement, given as a string.
  344.     
  345.     def run(self, cmd):
  346.         import __main__
  347.         dict = __main__.__dict__
  348.         return self.runctx(cmd, dict, dict)
  349.     
  350.     def runctx(self, cmd, globals, locals):
  351.         self.set_cmd(cmd)
  352.         sys.setprofile(self.dispatcher)
  353.         try:
  354.             exec cmd in globals, locals
  355.         finally:
  356.             sys.setprofile(None)
  357.         return self
  358.  
  359.     # This method is more useful to profile a single function call.
  360.     def runcall(self, func, *args):
  361.         self.set_cmd(`func`)
  362.         sys.setprofile(self.dispatcher)
  363.         try:
  364.             return apply(func, args)
  365.         finally:
  366.             sys.setprofile(None)
  367.  
  368.  
  369.     #******************************************************************
  370.     # The following calculates the overhead for using a profiler.  The
  371.     # problem is that it takes a fair amount of time for the profiler
  372.     # to stop the stopwatch (from the time it recieves an event).
  373.     # Similarly, there is a delay from the time that the profiler
  374.     # re-starts the stopwatch before the user's code really gets to
  375.     # continue.  The following code tries to measure the difference on
  376.     # a per-event basis. The result can the be placed in the
  377.     # Profile.dispatch_event() routine for the given platform.  Note
  378.     # that this difference is only significant if there are a lot of
  379.     # events, and relatively little user code per event.  For example,
  380.     # code with small functions will typically benefit from having the
  381.     # profiler calibrated for the current platform.  This *could* be
  382.     # done on the fly during init() time, but it is not worth the
  383.     # effort.  Also note that if too large a value specified, then
  384.     # execution time on some functions will actually appear as a
  385.     # negative number.  It is *normal* for some functions (with very
  386.     # low call counts) to have such negative stats, even if the
  387.     # calibration figure is "correct." 
  388.     #
  389.     # One alternative to profile-time calibration adjustments (i.e.,
  390.     # adding in the magic little delta during each event) is to track
  391.     # more carefully the number of events (and cumulatively, the number
  392.     # of events during sub functions) that are seen.  If this were
  393.     # done, then the arithmetic could be done after the fact (i.e., at
  394.     # display time).  Currintly, we track only call/return events.
  395.     # These values can be deduced by examining the callees and callers
  396.     # vectors for each functions.  Hence we *can* almost correct the
  397.     # internal time figure at print time (note that we currently don't
  398.     # track exception event processing counts).  Unfortunately, there
  399.     # is currently no similar information for cumulative sub-function
  400.     # time.  It would not be hard to "get all this info" at profiler
  401.     # time.  Specifically, we would have to extend the tuples to keep
  402.     # counts of this in each frame, and then extend the defs of timing
  403.     # tuples to include the significant two figures. I'm a bit fearful
  404.     # that this additional feature will slow the heavily optimized
  405.     # event/time ratio (i.e., the profiler would run slower, fur a very
  406.     # low "value added" feature.) 
  407.     #
  408.     # Plugging in the calibration constant doesn't slow down the
  409.     # profiler very much, and the accuracy goes way up.
  410.     #**************************************************************
  411.     
  412.     def calibrate(self, m):
  413.         # Modified by Tim Peters
  414.         n = m
  415.         s = self.get_time()
  416.         while n:
  417.             self.simple()
  418.             n = n - 1
  419.         f = self.get_time()
  420.         my_simple = f - s
  421.         #print "Simple =", my_simple,
  422.  
  423.         n = m
  424.         s = self.get_time()
  425.         while n:
  426.             self.instrumented()
  427.             n = n - 1
  428.         f = self.get_time()
  429.         my_inst = f - s
  430.         # print "Instrumented =", my_inst
  431.         avg_cost = (my_inst - my_simple)/m
  432.         #print "Delta/call =", avg_cost, "(profiler fixup constant)"
  433.         return avg_cost
  434.  
  435.     # simulate a program with no profiler activity
  436.     def simple(self):
  437.         a = 1
  438.         pass
  439.  
  440.     # simulate a program with call/return event processing
  441.     def instrumented(self):
  442.         a = 1
  443.         self.profiler_simulation(a, a, a)
  444.  
  445.     # simulate an event processing activity (from user's perspective)
  446.     def profiler_simulation(self, x, y, z):  
  447.         t = self.timer()
  448.         ## t = t[0] + t[1]
  449.         self.ut = t
  450.  
  451.  
  452.  
  453. #****************************************************************************
  454. # OldProfile class documentation
  455. #****************************************************************************
  456. #
  457. # The following derived profiler simulates the old style profile, providing
  458. # errant results on recursive functions. The reason for the usefulnes of this
  459. # profiler is that it runs faster (i.e., less overhead).  It still creates
  460. # all the caller stats, and is quite useful when there is *no* recursion
  461. # in the user's code.
  462. #
  463. # This code also shows how easy it is to create a modified profiler.
  464. #****************************************************************************
  465. class OldProfile(Profile):
  466.     def trace_dispatch_exception(self, frame, t):
  467.         rt, rtt, rct, rfn, rframe, rcur = self.cur
  468.         if rcur and not rframe is frame:
  469.             return self.trace_dispatch_return(rframe, t)
  470.         return 0
  471.  
  472.     def trace_dispatch_call(self, frame, t):
  473.         fn = `frame.f_code`
  474.         
  475.         self.cur = (t, 0, 0, fn, frame, self.cur)
  476.         if self.timings.has_key(fn):
  477.             tt, ct, callers = self.timings[fn]
  478.             self.timings[fn] = tt, ct, callers
  479.         else:
  480.             self.timings[fn] = 0, 0, {}
  481.         return 1
  482.  
  483.     def trace_dispatch_return(self, frame, t):
  484.         rt, rtt, rct, rfn, frame, rcur = self.cur
  485.         rtt = rtt + t
  486.         sft = rtt + rct
  487.  
  488.         pt, ptt, pct, pfn, pframe, pcur = rcur
  489.         self.cur = pt, ptt+rt, pct+sft, pfn, pframe, pcur
  490.  
  491.         tt, ct, callers = self.timings[rfn]
  492.         if callers.has_key(pfn):
  493.             callers[pfn] = callers[pfn] + 1
  494.         else:
  495.             callers[pfn] = 1
  496.         self.timings[rfn] = tt+rtt, ct + sft, callers
  497.  
  498.         return 1
  499.  
  500.  
  501.     def snapshot_stats(self):
  502.         self.stats = {}
  503.         for func in self.timings.keys():
  504.             tt, ct, callers = self.timings[func]
  505.             callers = callers.copy()
  506.             nc = 0
  507.             for func_caller in callers.keys():
  508.                 nc = nc + callers[func_caller]
  509.             self.stats[func] = nc, nc, tt, ct, callers
  510.  
  511.         
  512.  
  513. #****************************************************************************
  514. # HotProfile class documentation
  515. #****************************************************************************
  516. #
  517. # This profiler is the fastest derived profile example.  It does not
  518. # calculate caller-callee relationships, and does not calculate cumulative
  519. # time under a function.  It only calculates time spent in a function, so
  520. # it runs very quickly (re: very low overhead)
  521. #****************************************************************************
  522. class HotProfile(Profile):
  523.     def trace_dispatch_exception(self, frame, t):
  524.         rt, rtt, rfn, rframe, rcur = self.cur
  525.         if rcur and not rframe is frame:
  526.             return self.trace_dispatch_return(rframe, t)
  527.         return 0
  528.  
  529.     def trace_dispatch_call(self, frame, t):
  530.         self.cur = (t, 0, frame, self.cur)
  531.         return 1
  532.  
  533.     def trace_dispatch_return(self, frame, t):
  534.         rt, rtt, frame, rcur = self.cur
  535.  
  536.         rfn = `frame.f_code`
  537.  
  538.         pt, ptt, pframe, pcur = rcur
  539.         self.cur = pt, ptt+rt, pframe, pcur
  540.  
  541.         if self.timings.has_key(rfn):
  542.             nc, tt = self.timings[rfn]
  543.             self.timings[rfn] = nc + 1, rt + rtt + tt
  544.         else:
  545.             self.timings[rfn] =      1, rt + rtt
  546.  
  547.         return 1
  548.  
  549.  
  550.     def snapshot_stats(self):
  551.         self.stats = {}
  552.         for func in self.timings.keys():
  553.             nc, tt = self.timings[func]
  554.             self.stats[func] = nc, nc, tt, 0, {}
  555.  
  556.         
  557.  
  558. #****************************************************************************
  559. def Stats(*args):
  560.     print 'Report generating functions are in the "pstats" module\a'
  561.  
  562.  
  563. # When invoked as main program, invoke the profiler on a script
  564. if __name__ == '__main__':
  565.     import sys
  566.     import os
  567.     if not sys.argv[1:]:
  568.         print "usage: profile.py scriptfile [arg] ..."
  569.         sys.exit(2)
  570.  
  571.     filename = sys.argv[1]    # Get script filename
  572.  
  573.     del sys.argv[0]        # Hide "profile.py" from argument list
  574.  
  575.     # Insert script directory in front of module search path
  576.     sys.path.insert(0, os.path.dirname(filename))
  577.  
  578.     run('execfile(' + `filename` + ')')
  579.