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