[3] | 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 |
---|