root/software/statprof/trunk/statprof.py

Revision 4, 10.5 kB (checked in by t, 12 years ago)

added example & changelog; integrated my patches.

Line 
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, OUT=None, percent_threshold=None):
280         """
281         Display the profiling results for this function.
282
283         If OUT is given, print results to that fp.  Default to stdout.
284        
285         If percent_threshold is given, only print results where
286         the percentage of the time spent in the function is greater
287         than the threshold.
288         """
289         if percent_threshold is not None:
290             if self.pcnt_time_in_proc <= percent_threshold:
291                 return
292                
293         print>>OUT, '%6.2f %9.2f %9.2f  %s' % (self.pcnt_time_in_proc,
294                                          self.cum_secs_in_proc,
295                                          self.self_secs_in_proc,
296                                          self.name)
297
298 def display(OUT=None, percent_threshold=None):
299     if state.sample_count == 0:
300         print>>OUT, 'No samples recorded.'
301         return
302
303     l = [CallStats(x) for x in call_data.itervalues()]
304     l = [(x.self_secs_in_proc, x.cum_secs_in_proc, x) for x in l]
305     l.sort()
306     l.reverse()
307     l = [x[2] for x in l]
308
309     print>>OUT, '%5.5s %10.10s   %7.7s  %-8.8s' % ('%  ', 'cumulative', 'self', '')
310     print>>OUT, '%5.5s  %9.9s  %8.8s  %-8.8s' % ("time", "seconds", "seconds", "name")
311
312     for x in l:
313         x.display(OUT, percent_threshold=percent_threshold)
314
315     print>>OUT, '---'
316     print>>OUT, 'Sample count: %d' % state.sample_count
317     print>>OUT, 'Total time: %f seconds' % state.accumulated_time
Note: See TracBrowser for help on using the browser.