tools/statprof.py

   1 ## statprof.py
   2 ## Copyright (C) 2004,2005 Andy Wingo <wingo at pobox dot com>
   3 ## Copyright (C) 2001 Rob Browning <rlb at defaultvalue dot org>
   4
   5 ## This library is free software; you can redistribute it and/or
   6 ## modify it under the terms of the GNU Lesser General Public
   7 ## License as published by the Free Software Foundation; either
   8 ## version 2.1 of the License, or (at your option) any later version.
   9 ##
  10 ## This library is distributed in the hope that it will be useful,
  11 ## but WITHOUT ANY WARRANTY; without even the implied warranty of
  12 ## MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
  13 ## Lesser General Public License for more details.
  14 ##
  15 ## You should have received a copy of the GNU Lesser General Public
  16 ## License along with this program; if not, contact:
  17 ##
  18 ## Free Software Foundation           Voice:  +1-617-542-5942
  19 ## 59 Temple Place - Suite 330        Fax:    +1-617-542-2652
  20 ## Boston, MA  02111-1307,  USA       gnu@gnu.org
  21
  22 """
  23 statprof is intended to be a fairly simple statistical profiler for
  24 python. It was ported directly from a statistical profiler for guile,
  25 also named statprof, available from guile-lib [0].
  26
  27 [0] http://wingolog.org/software/guile-lib/statprof/
  28
  29 To start profiling, call statprof.start():
  30 >>> start()
  31
  32 Then run whatever it is that you want to profile, for example:
  33 >>> import test.pystone; test.pystone.pystones()
  34
  35 Then stop the profiling and print out the results:
  36 >>> stop()
  37 >>> display()
  38   %   cumulative      self
  39  time    seconds   seconds  name
  40  26.72      1.40      0.37  pystone.py:79:Proc0
  41  13.79      0.56      0.19  pystone.py:133:Proc1
  42  13.79      0.19      0.19  pystone.py:208:Proc8
  43  10.34      0.16      0.14  pystone.py:229:Func2
  44   6.90      0.10      0.10  pystone.py:45:__init__
  45   4.31      0.16      0.06  pystone.py:53:copy
  46     ...
  47
  48 All of the numerical data with the exception of the calls column is
  49 statistically approximate. In the following column descriptions, and
  50 in all of statprof, "time" refers to execution time (both user and
  51 system), not wall clock time.
  52
  53 % time
  54     The percent of the time spent inside the procedure itself (not
  55     counting children).
  56
  57 cumulative seconds
  58     The total number of seconds spent in the procedure, including
  59     children.
  60
  61 self seconds
  62     The total number of seconds spent in the procedure itself (not
  63     counting children).
  64
  65 name
  66     The name of the procedure.
  67
  68 By default statprof keeps the data collected from previous runs. If you
  69 want to clear the collected data, call reset():
  70 >>> reset()
  71
  72 reset() can also be used to change the sampling frequency. For example,
  73 to tell statprof to sample 50 times a second:
  74 >>> reset(50)
  75
  76 This means that statprof will sample the call stack after every 1/50 of
  77 a second of user + system time spent running on behalf of the python
  78 process. When your process is idle (for example, blocking in a read(),
  79 as is the case at the listener), the clock does not advance. For this
  80 reason statprof is not currently not suitable for profiling io-bound
  81 operations.
  82
  83 The profiler uses the hash of the code object itself to identify the
  84 procedures, so it won't confuse different procedures with the same name.
  85 They will show up as two different rows in the output.
  86
  87 Right now the profiler is quite simplistic.  I cannot provide
  88 call-graphs or other higher level information.  What you see in the
  89 table is pretty much all there is. Patches are welcome :-)
  90
  91
  92 Threading
  93 ---------
  94
  95 Because signals only get delivered to the main thread in Python,
  96 statprof only profiles the main thread. However because the time
  97 reporting function uses per-process timers, the results can be
  98 significantly off if other threads' work patterns are not similar to the
  99 main thread's work patterns.
 100
 101
 102 Implementation notes
 103 --------------------
 104
 105 The profiler works by setting the unix profiling signal ITIMER_PROF to
 106 go off after the interval you define in the call to reset(). When the
 107 signal fires, a sampling routine is run which looks at the current
 108 procedure that's executing, and then crawls up the stack, and for each
 109 frame encountered, increments that frame's code object's sample count.
 110 Note that if a procedure is encountered multiple times on a given stack,
 111 it is only counted once. After the sampling is complete, the profiler
 112 resets profiling timer to fire again after the appropriate interval.
 113
 114 Meanwhile, the profiler keeps track, via os.times(), how much CPU time
 115 (system and user -- which is also what ITIMER_PROF tracks), has elapsed
 116 while code has been executing within a start()/stop() block.
 117
 118 The profiler also tries to avoid counting or timing its own code as
 119 much as possible.
 120 """
 121
 122
 123 from __future__ import division
 124
 125 try:
 126     import itimer
 127 except ImportError:
 128     raise ImportError('''statprof requires the itimer python extension.
 129 To install it, enter the following commands from a terminal:
 130
 131 wget http://www.cute.fi/~torppa/py-itimer/py-itimer.tar.gz
 132 tar zxvf py-itimer.tar.gz
 133 cd py-itimer
 134 sudo python setup.py install
 135 ''')
 136
 137 import signal
 138 import os
 139
 140
 141 __all__ = ['start', 'stop', 'reset', 'display']
 142
 143
 144 ###########################################################################
 145 ## Utils
 146
 147 def clock():
 148     times = os.times()
 149     return times[0] + times[1]
 150
 151
 152 ###########################################################################
 153 ## Collection data structures
 154
 155 class ProfileState(object):
 156     def __init__(self, frequency=None):
 157         self.reset(frequency)
 158
 159     def reset(self, frequency=None):
 160         # total so far
 161         self.accumulated_time = 0.0
 162         # start_time when timer is active
 163         self.last_start_time = None
 164         # total count of sampler calls
 165         self.sample_count = 0
 166         # a float
 167         if frequency:
 168             self.sample_interval = 1.0/frequency
 169         elif not hasattr(self, 'sample_interval'):
 170             # default to 100 Hz
 171             self.sample_interval = 1.0/100.0
 172         else:
 173             # leave the frequency as it was
 174             pass
 175         self.remaining_prof_time = None
 176         # for user start/stop nesting
 177         self.profile_level = 0
 178         # whether to catch apply-frame
 179         self.count_calls = False
 180         # gc time between start() and stop()
 181         self.gc_time_taken = 0
 182
 183     def accumulate_time(self, stop_time):
 184         self.accumulated_time += stop_time - self.last_start_time
 185
 186 state = ProfileState()
 187
 188 ## call_data := { code object: CallData }
 189 call_data = {}
 190 class CallData(object):
 191     def __init__(self, code):
 192         self.name = code.co_name
 193         self.filename = code.co_filename
 194         self.lineno = code.co_firstlineno
 195         self.call_count = 0
 196         self.cum_sample_count = 0
 197         self.self_sample_count = 0
 198         call_data[code] = self
 199
 200 def get_call_data(code):
 201     return call_data.get(code, None) or CallData(code)
 202
 203
 204 ###########################################################################
 205 ## SIGPROF handler
 206
 207 def sample_stack_procs(frame):
 208     state.sample_count += 1
 209     get_call_data(frame.f_code).self_sample_count += 1
 210
 211     code_seen = {}
 212     while frame:
 213         code_seen[frame.f_code] = True
 214         frame = frame.f_back
 215     for code in code_seen.iterkeys():
 216         get_call_data(code).cum_sample_count += 1
 217
 218 def profile_signal_handler(signum, frame):
 219     if state.profile_level > 0:
 220         state.accumulate_time(clock())
 221         sample_stack_procs(frame)
 222         itimer.setitimer(itimer.ITIMER_PROF,
 223             state.sample_interval, 0.0)
 224         state.last_start_time = clock()
 225
 226
 227 ###########################################################################
 228 ## Profiling API
 229
 230 def is_active():
 231     return state.profile_level > 0
 232
 233 def start():
 234     state.profile_level += 1
 235     if state.profile_level == 1:
 236         state.last_start_time = clock()
 237         rpt = state.remaining_prof_time
 238         state.remaining_prof_time = None
 239         signal.signal(signal.SIGPROF, profile_signal_handler)
 240         itimer.setitimer(itimer.ITIMER_PROF,
 241             rpt or state.sample_interval, 0.0)
 242         state.gc_time_taken = 0 # dunno
 243
 244 def stop():
 245     state.profile_level -= 1
 246     if state.profile_level == 0:
 247         state.accumulate_time(clock())
 248         state.last_start_time = None
 249         rpt = itimer.setitimer(itimer.ITIMER_PROF, 0.0, 0.0)
 250         signal.signal(signal.SIGPROF, signal.SIG_IGN)
 251         state.remaining_prof_time = rpt[0]
 252         state.gc_time_taken = 0 # dunno
 253
 254 def reset(frequency=None):
 255     assert state.profile_level == 0, "Can't reset() while statprof is running"
 256     call_data.clear()
 257     state.reset(frequency)
 258
 259
 260 ###########################################################################
 261 ## Reporting API
 262
 263 class CallStats(object):
 264     def __init__(self, call_data):
 265         self_samples = call_data.self_sample_count
 266         cum_samples = call_data.cum_sample_count
 267         nsamples = state.sample_count
 268         secs_per_sample = state.accumulated_time / nsamples
 269         basename = os.path.basename(call_data.filename)
 270
 271         self.name = '%s:%d:%s' % (basename, call_data.lineno, call_data.name)
 272         self.pcnt_time_in_proc = self_samples / nsamples * 100
 273         self.cum_secs_in_proc = cum_samples * secs_per_sample
 274         self.self_secs_in_proc = self_samples * secs_per_sample
 275         self.num_calls = None
 276         self.self_secs_per_call = None
 277         self.cum_secs_per_call = None
 278
 279     def display(self):
 280         print '%6.2f %9.2f %9.2f  %s' % (self.pcnt_time_in_proc,
 281                                          self.cum_secs_in_proc,
 282                                          self.self_secs_in_proc,
 283                                          self.name)
 284
 285
 286 def display():
 287     if state.sample_count == 0:
 288         print 'No samples recorded.'
 289         return
 290
 291     l = [CallStats(x) for x in call_data.itervalues()]
 292     l = [(x.self_secs_in_proc, x.cum_secs_in_proc, x) for x in l]
 293     l.sort(reverse=True)
 294     l = [x[2] for x in l]
 295
 296     print '%5.5s %10.10s   %7.7s  %-8.8s' % ('%  ', 'cumulative', 'self', '')
 297     print '%5.5s  %9.9s  %8.8s  %-8.8s' % ("time", "seconds", "seconds", "name")
 298
 299     for x in l:
 300         x.display()
 301
 302     print '---'
 303     print 'Sample count: %d' % state.sample_count
 304     print 'Total time: %f seconds' % state.accumulated_time