blob: cdc247911bccbc476c08a28ac27db47fbb579142 [file] [log] [blame]
Guido van Rossumf06ee5f1996-11-27 19:52:01 +00001#! /usr/bin/env python
Guido van Rossum81762581992-04-21 15:36:23 +00002#
Guido van Rossumb6775db1994-08-01 11:34:53 +00003# Class for profiling python code. rev 1.0 6/2/94
Guido van Rossum81762581992-04-21 15:36:23 +00004#
Guido van Rossumb6775db1994-08-01 11:34:53 +00005# Based on prior profile module by Sjoerd Mullender...
6# which was hacked somewhat by: Guido van Rossum
Guido van Rossumb6775db1994-08-01 11:34:53 +00007
Guido van Rossum54f22ed2000-02-04 15:10:34 +00008"""Class for profiling Python code."""
Guido van Rossumb6775db1994-08-01 11:34:53 +00009
10# Copyright 1994, by InfoSeek Corporation, all rights reserved.
11# Written by James Roskind
Tim Peters2344fae2001-01-15 00:50:52 +000012#
Guido van Rossumb6775db1994-08-01 11:34:53 +000013# 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.
Tim Peters2344fae2001-01-15 00:50:52 +000025#
Guido van Rossumb6775db1994-08-01 11:34:53 +000026# INFOSEEK CORPORATION DISCLAIMS ALL WARRANTIES WITH REGARD TO THIS
27# SOFTWARE, INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY AND
28# FITNESS. IN NO EVENT SHALL INFOSEEK CORPORATION BE LIABLE FOR ANY
29# SPECIAL, INDIRECT OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER
30# RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF
31# CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN
32# CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.
33
34
Guido van Rossum81762581992-04-21 15:36:23 +000035
36import sys
Guido van Rossum4e160981992-09-02 20:43:20 +000037import os
Guido van Rossumb6775db1994-08-01 11:34:53 +000038import time
Guido van Rossum4e160981992-09-02 20:43:20 +000039import marshal
Nicholas Bastin824b1b22004-03-23 18:44:39 +000040from optparse import OptionParser
Guido van Rossum81762581992-04-21 15:36:23 +000041
Guido van Rossum48713e82004-03-23 19:19:21 +000042__all__ = ["run", "runctx", "help", "Profile"]
Guido van Rossum81762581992-04-21 15:36:23 +000043
Tim Peters2344fae2001-01-15 00:50:52 +000044# Sample timer for use with
Guido van Rossumb6775db1994-08-01 11:34:53 +000045#i_count = 0
46#def integer_timer():
Tim Peters2344fae2001-01-15 00:50:52 +000047# global i_count
48# i_count = i_count + 1
49# return i_count
Guido van Rossumb6775db1994-08-01 11:34:53 +000050#itimes = integer_timer # replace with C coded timer returning integers
Guido van Rossum81762581992-04-21 15:36:23 +000051
Guido van Rossumb6775db1994-08-01 11:34:53 +000052#**************************************************************************
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#**************************************************************************
Guido van Rossum81762581992-04-21 15:36:23 +000056
Nicholas Bastin824b1b22004-03-23 18:44:39 +000057def run(statement, filename=None, sort=-1):
Jeremy Hyltonadcf8a02001-03-14 20:01:19 +000058 """Run statement under profiler optionally saving results in filename
Guido van Rossum4e160981992-09-02 20:43:20 +000059
Jeremy Hyltonadcf8a02001-03-14 20:01:19 +000060 This function takes a single argument that can be passed to the
61 "exec" statement, and an optional file name. In all cases this
62 routine attempts to "exec" its first argument and gather profiling
63 statistics from the execution. If no file name is present, then this
64 function automatically prints a simple profiling report, sorted by the
65 standard name string (file/line/function-name) that is presented in
66 each line.
67 """
Tim Peters2344fae2001-01-15 00:50:52 +000068 prof = Profile()
69 try:
70 prof = prof.run(statement)
71 except SystemExit:
72 pass
Jeremy Hyltonadcf8a02001-03-14 20:01:19 +000073 if filename is not None:
74 prof.dump_stats(filename)
Tim Peters2344fae2001-01-15 00:50:52 +000075 else:
Nicholas Bastin824b1b22004-03-23 18:44:39 +000076 return prof.print_stats(sort)
Guido van Rossume61fa0a1993-10-22 13:56:35 +000077
Nicholas Bastin1eb4bfc2004-03-22 20:12:56 +000078def runctx(statement, globals, locals, filename=None):
79 """Run statement under profiler, supplying your own globals and locals,
80 optionally saving results in filename.
81
82 statement and filename have the same semantics as profile.run
83 """
84 prof = Profile()
85 try:
86 prof = prof.runctx(statement, globals, locals)
87 except SystemExit:
88 pass
89
90 if filename is not None:
91 prof.dump_stats(filename)
92 else:
93 return prof.print_stats()
94
Johannes Gijsbersc0b194a2005-01-10 09:07:22 +000095# Backwards compatibility.
Guido van Rossume61fa0a1993-10-22 13:56:35 +000096def help():
Guido van Rossumbe19ed72007-02-09 05:37:30 +000097 print("Documentation for the profile module can be found ")
98 print("in the Python Library Reference, section 'The Python Profiler'.")
Guido van Rossumb6775db1994-08-01 11:34:53 +000099
Fred Drakeedb5ffb2001-06-08 04:25:24 +0000100if os.name == "mac":
Jack Jansen1bdcadd2001-06-19 20:11:36 +0000101 import MacOS
Fred Drakeedb5ffb2001-06-08 04:25:24 +0000102 def _get_time_mac(timer=MacOS.GetTicks):
103 return timer() / 60.0
104
105if hasattr(os, "times"):
106 def _get_time_times(timer=os.times):
107 t = timer()
108 return t[0] + t[1]
109
Martin v. Löwisa4dac402005-03-03 11:39:45 +0000110# Using getrusage(3) is better than clock(3) if available:
111# on some systems (e.g. FreeBSD), getrusage has a higher resolution
112# Furthermore, on a POSIX system, returns microseconds, which
113# wrap around after 36min.
114_has_res = 0
115try:
116 import resource
117 resgetrusage = lambda: resource.getrusage(resource.RUSAGE_SELF)
118 def _get_time_resource(timer=resgetrusage):
119 t = timer()
120 return t[0] + t[1]
121 _has_res = 1
122except ImportError:
123 pass
Fred Drakeedb5ffb2001-06-08 04:25:24 +0000124
Guido van Rossumb6775db1994-08-01 11:34:53 +0000125class Profile:
Tim Peters2344fae2001-01-15 00:50:52 +0000126 """Profiler class.
Guido van Rossum54f22ed2000-02-04 15:10:34 +0000127
Tim Peters2344fae2001-01-15 00:50:52 +0000128 self.cur is always a tuple. Each such tuple corresponds to a stack
129 frame that is currently active (self.cur[-2]). The following are the
130 definitions of its members. We use this external "parallel stack" to
131 avoid contaminating the program that we are profiling. (old profiler
132 used to write into the frames local dictionary!!) Derived classes
133 can change the definition of some entries, as long as they leave
Tim Petersdf5cfd82001-10-05 23:15:10 +0000134 [-2:] intact (frame and previous tuple). In case an internal error is
135 detected, the -3 element is used as the function name.
Guido van Rossum54f22ed2000-02-04 15:10:34 +0000136
Tim Petersdf5cfd82001-10-05 23:15:10 +0000137 [ 0] = Time that needs to be charged to the parent frame's function.
138 It is used so that a function call will not have to access the
139 timing data for the parent frame.
140 [ 1] = Total time spent in this frame's function, excluding time in
Tim Peters8d061ed2001-10-07 08:35:44 +0000141 subfunctions (this latter is tallied in cur[2]).
Tim Petersfb163782001-10-07 08:49:02 +0000142 [ 2] = Total time spent in subfunctions, excluding time executing the
Tim Peters8d061ed2001-10-07 08:35:44 +0000143 frame's function (this latter is tallied in cur[1]).
Tim Petersdf5cfd82001-10-05 23:15:10 +0000144 [-3] = Name of the function that corresponds to this frame.
Tim Peters8d061ed2001-10-07 08:35:44 +0000145 [-2] = Actual frame that we correspond to (used to sync exception handling).
146 [-1] = Our parent 6-tuple (corresponds to frame.f_back).
Guido van Rossum54f22ed2000-02-04 15:10:34 +0000147
Tim Peters2344fae2001-01-15 00:50:52 +0000148 Timing data for each function is stored as a 5-tuple in the dictionary
Tim Petersdf5cfd82001-10-05 23:15:10 +0000149 self.timings[]. The index is always the name stored in self.cur[-3].
Tim Peters2344fae2001-01-15 00:50:52 +0000150 The following are the definitions of the members:
Guido van Rossumb6775db1994-08-01 11:34:53 +0000151
Tim Peters2344fae2001-01-15 00:50:52 +0000152 [0] = The number of times this function was called, not counting direct
153 or indirect recursion,
154 [1] = Number of times this function appears on the stack, minus one
155 [2] = Total time spent internal to this function
156 [3] = Cumulative time that this function was present on the stack. In
157 non-recursive functions, this is the total execution time from start
158 to finish of each invocation of a function, including time spent in
159 all subfunctions.
Tim Peters6e221492001-10-07 04:02:36 +0000160 [4] = A dictionary indicating for each function name, the number of times
Tim Peters2344fae2001-01-15 00:50:52 +0000161 it was called by us.
162 """
Guido van Rossumb6775db1994-08-01 11:34:53 +0000163
Tim Peters659a6032001-10-09 20:51:19 +0000164 bias = 0 # calibration constant
165
166 def __init__(self, timer=None, bias=None):
Tim Peters2344fae2001-01-15 00:50:52 +0000167 self.timings = {}
168 self.cur = None
169 self.cmd = ""
Nicholas Bastinc69ebe82004-03-24 21:57:10 +0000170 self.c_func_name = ""
Guido van Rossumb6775db1994-08-01 11:34:53 +0000171
Tim Peters659a6032001-10-09 20:51:19 +0000172 if bias is None:
173 bias = self.bias
174 self.bias = bias # Materialize in local dict for lookup speed.
175
Martin v. Löwisa4dac402005-03-03 11:39:45 +0000176 if not timer:
177 if _has_res:
178 self.timer = resgetrusage
179 self.dispatcher = self.trace_dispatch
180 self.get_time = _get_time_resource
181 elif os.name == 'mac':
Tim Peters2344fae2001-01-15 00:50:52 +0000182 self.timer = MacOS.GetTicks
183 self.dispatcher = self.trace_dispatch_mac
Fred Drakeedb5ffb2001-06-08 04:25:24 +0000184 self.get_time = _get_time_mac
Tim Peters2344fae2001-01-15 00:50:52 +0000185 elif hasattr(time, 'clock'):
Fred Drakeedb5ffb2001-06-08 04:25:24 +0000186 self.timer = self.get_time = time.clock
Tim Peters2344fae2001-01-15 00:50:52 +0000187 self.dispatcher = self.trace_dispatch_i
188 elif hasattr(os, 'times'):
189 self.timer = os.times
190 self.dispatcher = self.trace_dispatch
Fred Drakeedb5ffb2001-06-08 04:25:24 +0000191 self.get_time = _get_time_times
Tim Peters2344fae2001-01-15 00:50:52 +0000192 else:
Fred Drakeedb5ffb2001-06-08 04:25:24 +0000193 self.timer = self.get_time = time.time
Tim Peters2344fae2001-01-15 00:50:52 +0000194 self.dispatcher = self.trace_dispatch_i
195 else:
196 self.timer = timer
197 t = self.timer() # test out timer function
198 try:
Fred Drakeedb5ffb2001-06-08 04:25:24 +0000199 length = len(t)
200 except TypeError:
201 self.get_time = timer
202 self.dispatcher = self.trace_dispatch_i
203 else:
204 if length == 2:
Tim Peters2344fae2001-01-15 00:50:52 +0000205 self.dispatcher = self.trace_dispatch
206 else:
207 self.dispatcher = self.trace_dispatch_l
Fred Drakeedb5ffb2001-06-08 04:25:24 +0000208 # This get_time() implementation needs to be defined
209 # here to capture the passed-in timer in the parameter
210 # list (for performance). Note that we can't assume
211 # the timer() result contains two values in all
212 # cases.
Raymond Hettinger97aa32b2003-10-22 16:49:01 +0000213 def get_time_timer(timer=timer, sum=sum):
214 return sum(timer())
Fred Drakeedb5ffb2001-06-08 04:25:24 +0000215 self.get_time = get_time_timer
Tim Peters2344fae2001-01-15 00:50:52 +0000216 self.t = self.get_time()
217 self.simulate_call('profiler')
Guido van Rossumb6775db1994-08-01 11:34:53 +0000218
Tim Peters2344fae2001-01-15 00:50:52 +0000219 # Heavily optimized dispatch routine for os.times() timer
Guido van Rossumb6775db1994-08-01 11:34:53 +0000220
Tim Peters2344fae2001-01-15 00:50:52 +0000221 def trace_dispatch(self, frame, event, arg):
Fred Drakeedb5ffb2001-06-08 04:25:24 +0000222 timer = self.timer
223 t = timer()
Tim Peters659a6032001-10-09 20:51:19 +0000224 t = t[0] + t[1] - self.t - self.bias
Tim Peters2344fae2001-01-15 00:50:52 +0000225
Nicholas Bastinc69ebe82004-03-24 21:57:10 +0000226 if event == "c_call":
Nicholas Bastin12ac3e12004-07-12 23:38:02 +0000227 self.c_func_name = arg.__name__
Nicholas Bastinc69ebe82004-03-24 21:57:10 +0000228
Fred Drakeedb5ffb2001-06-08 04:25:24 +0000229 if self.dispatch[event](self, frame,t):
230 t = timer()
Tim Peters2344fae2001-01-15 00:50:52 +0000231 self.t = t[0] + t[1]
232 else:
Fred Drakeedb5ffb2001-06-08 04:25:24 +0000233 r = timer()
Tim Peters2344fae2001-01-15 00:50:52 +0000234 self.t = r[0] + r[1] - t # put back unrecorded delta
Guido van Rossumb6775db1994-08-01 11:34:53 +0000235
Tim Peters6e221492001-10-07 04:02:36 +0000236 # Dispatch routine for best timer program (return = scalar, fastest if
237 # an integer but float works too -- and time.clock() relies on that).
Guido van Rossumb6775db1994-08-01 11:34:53 +0000238
Tim Peters2344fae2001-01-15 00:50:52 +0000239 def trace_dispatch_i(self, frame, event, arg):
Fred Drakeedb5ffb2001-06-08 04:25:24 +0000240 timer = self.timer
Tim Peters659a6032001-10-09 20:51:19 +0000241 t = timer() - self.t - self.bias
Nicholas Bastinc69ebe82004-03-24 21:57:10 +0000242
243 if event == "c_call":
Nicholas Bastin12ac3e12004-07-12 23:38:02 +0000244 self.c_func_name = arg.__name__
Nicholas Bastinc69ebe82004-03-24 21:57:10 +0000245
246 if self.dispatch[event](self, frame, t):
Fred Drakeedb5ffb2001-06-08 04:25:24 +0000247 self.t = timer()
Tim Peters2344fae2001-01-15 00:50:52 +0000248 else:
Fred Drakeedb5ffb2001-06-08 04:25:24 +0000249 self.t = timer() - t # put back unrecorded delta
Guido van Rossumcbf3dd51997-10-08 15:23:02 +0000250
Fred Drakeedb5ffb2001-06-08 04:25:24 +0000251 # Dispatch routine for macintosh (timer returns time in ticks of
252 # 1/60th second)
Tim Peters2344fae2001-01-15 00:50:52 +0000253
254 def trace_dispatch_mac(self, frame, event, arg):
Fred Drakeedb5ffb2001-06-08 04:25:24 +0000255 timer = self.timer
Tim Peters659a6032001-10-09 20:51:19 +0000256 t = timer()/60.0 - self.t - self.bias
Nicholas Bastinc69ebe82004-03-24 21:57:10 +0000257
258 if event == "c_call":
Nicholas Bastin12ac3e12004-07-12 23:38:02 +0000259 self.c_func_name = arg.__name__
Nicholas Bastinc69ebe82004-03-24 21:57:10 +0000260
Tim Peters659a6032001-10-09 20:51:19 +0000261 if self.dispatch[event](self, frame, t):
Fred Drakeedb5ffb2001-06-08 04:25:24 +0000262 self.t = timer()/60.0
Tim Peters2344fae2001-01-15 00:50:52 +0000263 else:
Fred Drakeedb5ffb2001-06-08 04:25:24 +0000264 self.t = timer()/60.0 - t # put back unrecorded delta
Guido van Rossumb6775db1994-08-01 11:34:53 +0000265
Tim Peters2344fae2001-01-15 00:50:52 +0000266 # SLOW generic dispatch routine for timer returning lists of numbers
Guido van Rossumb6775db1994-08-01 11:34:53 +0000267
Tim Peters2344fae2001-01-15 00:50:52 +0000268 def trace_dispatch_l(self, frame, event, arg):
Fred Drakeedb5ffb2001-06-08 04:25:24 +0000269 get_time = self.get_time
Tim Peters659a6032001-10-09 20:51:19 +0000270 t = get_time() - self.t - self.bias
Guido van Rossumb6775db1994-08-01 11:34:53 +0000271
Nicholas Bastinc69ebe82004-03-24 21:57:10 +0000272 if event == "c_call":
Nicholas Bastin12ac3e12004-07-12 23:38:02 +0000273 self.c_func_name = arg.__name__
Nicholas Bastinc69ebe82004-03-24 21:57:10 +0000274
Tim Peters659a6032001-10-09 20:51:19 +0000275 if self.dispatch[event](self, frame, t):
Fred Drakeedb5ffb2001-06-08 04:25:24 +0000276 self.t = get_time()
Tim Peters2344fae2001-01-15 00:50:52 +0000277 else:
Fred Drakeedb5ffb2001-06-08 04:25:24 +0000278 self.t = get_time() - t # put back unrecorded delta
Guido van Rossumb6775db1994-08-01 11:34:53 +0000279
Tim Peters8d061ed2001-10-07 08:35:44 +0000280 # In the event handlers, the first 3 elements of self.cur are unpacked
281 # into vrbls w/ 3-letter names. The last two characters are meant to be
282 # mnemonic:
283 # _pt self.cur[0] "parent time" time to be charged to parent frame
284 # _it self.cur[1] "internal time" time spent directly in the function
285 # _et self.cur[2] "external time" time spent in subfunctions
Guido van Rossumb6775db1994-08-01 11:34:53 +0000286
Tim Peters2344fae2001-01-15 00:50:52 +0000287 def trace_dispatch_exception(self, frame, t):
Tim Peters8d061ed2001-10-07 08:35:44 +0000288 rpt, rit, ret, rfn, rframe, rcur = self.cur
Fred Drakea0bc9992001-10-03 21:12:32 +0000289 if (rframe is not frame) and rcur:
Tim Peters2344fae2001-01-15 00:50:52 +0000290 return self.trace_dispatch_return(rframe, t)
Tim Peters8d061ed2001-10-07 08:35:44 +0000291 self.cur = rpt, rit+t, ret, rfn, rframe, rcur
Guido van Rossumf137f752001-10-04 00:58:24 +0000292 return 1
Guido van Rossumb6775db1994-08-01 11:34:53 +0000293
294
Tim Peters2344fae2001-01-15 00:50:52 +0000295 def trace_dispatch_call(self, frame, t):
Tim Petersdf5cfd82001-10-05 23:15:10 +0000296 if self.cur and frame.f_back is not self.cur[-2]:
Tim Peters8d061ed2001-10-07 08:35:44 +0000297 rpt, rit, ret, rfn, rframe, rcur = self.cur
Guido van Rossumf137f752001-10-04 00:58:24 +0000298 if not isinstance(rframe, Profile.fake_frame):
Tim Petersdb1ed2a2001-10-07 04:30:53 +0000299 assert rframe.f_back is frame.f_back, ("Bad call", rfn,
300 rframe, rframe.f_back,
301 frame, frame.f_back)
Guido van Rossumf137f752001-10-04 00:58:24 +0000302 self.trace_dispatch_return(rframe, 0)
Tim Petersdb1ed2a2001-10-07 04:30:53 +0000303 assert (self.cur is None or \
304 frame.f_back is self.cur[-2]), ("Bad call",
305 self.cur[-3])
Tim Peters2344fae2001-01-15 00:50:52 +0000306 fcode = frame.f_code
307 fn = (fcode.co_filename, fcode.co_firstlineno, fcode.co_name)
308 self.cur = (t, 0, 0, fn, frame, self.cur)
Fred Drakeedb5ffb2001-06-08 04:25:24 +0000309 timings = self.timings
Raymond Hettinger54f02222002-06-01 14:18:47 +0000310 if fn in timings:
Fred Drakeedb5ffb2001-06-08 04:25:24 +0000311 cc, ns, tt, ct, callers = timings[fn]
312 timings[fn] = cc, ns + 1, tt, ct, callers
Tim Peters2344fae2001-01-15 00:50:52 +0000313 else:
Fred Drakeedb5ffb2001-06-08 04:25:24 +0000314 timings[fn] = 0, 0, 0, 0, {}
Tim Peters2344fae2001-01-15 00:50:52 +0000315 return 1
Guido van Rossumb6775db1994-08-01 11:34:53 +0000316
Nicholas Bastinc69ebe82004-03-24 21:57:10 +0000317 def trace_dispatch_c_call (self, frame, t):
318 fn = ("", 0, self.c_func_name)
319 self.cur = (t, 0, 0, fn, frame, self.cur)
320 timings = self.timings
Guido van Rossume2b70bc2006-08-18 22:13:04 +0000321 if fn in timings:
Nicholas Bastinc69ebe82004-03-24 21:57:10 +0000322 cc, ns, tt, ct, callers = timings[fn]
323 timings[fn] = cc, ns+1, tt, ct, callers
324 else:
325 timings[fn] = 0, 0, 0, 0, {}
326 return 1
327
Tim Peters2344fae2001-01-15 00:50:52 +0000328 def trace_dispatch_return(self, frame, t):
Tim Petersdf5cfd82001-10-05 23:15:10 +0000329 if frame is not self.cur[-2]:
Tim Petersdb1ed2a2001-10-07 04:30:53 +0000330 assert frame is self.cur[-2].f_back, ("Bad return", self.cur[-3])
331 self.trace_dispatch_return(self.cur[-2], 0)
Guido van Rossumb6775db1994-08-01 11:34:53 +0000332
Tim Peters8d061ed2001-10-07 08:35:44 +0000333 # Prefix "r" means part of the Returning or exiting frame.
334 # Prefix "p" means part of the Previous or Parent or older frame.
Guido van Rossumb6775db1994-08-01 11:34:53 +0000335
Tim Peters8d061ed2001-10-07 08:35:44 +0000336 rpt, rit, ret, rfn, frame, rcur = self.cur
337 rit = rit + t
338 frame_total = rit + ret
Guido van Rossumb6775db1994-08-01 11:34:53 +0000339
Tim Peters8d061ed2001-10-07 08:35:44 +0000340 ppt, pit, pet, pfn, pframe, pcur = rcur
341 self.cur = ppt, pit + rpt, pet + frame_total, pfn, pframe, pcur
Guido van Rossumb6775db1994-08-01 11:34:53 +0000342
Fred Drakeedb5ffb2001-06-08 04:25:24 +0000343 timings = self.timings
344 cc, ns, tt, ct, callers = timings[rfn]
Tim Peters2344fae2001-01-15 00:50:52 +0000345 if not ns:
Tim Peters8d061ed2001-10-07 08:35:44 +0000346 # This is the only occurrence of the function on the stack.
347 # Else this is a (directly or indirectly) recursive call, and
348 # its cumulative time will get updated when the topmost call to
349 # it returns.
350 ct = ct + frame_total
Tim Peters2344fae2001-01-15 00:50:52 +0000351 cc = cc + 1
Tim Peters8d061ed2001-10-07 08:35:44 +0000352
Raymond Hettinger54f02222002-06-01 14:18:47 +0000353 if pfn in callers:
Tim Peters2344fae2001-01-15 00:50:52 +0000354 callers[pfn] = callers[pfn] + 1 # hack: gather more
355 # stats such as the amount of time added to ct courtesy
356 # of this specific call, and the contribution to cc
357 # courtesy of this call.
358 else:
359 callers[pfn] = 1
Tim Peters8d061ed2001-10-07 08:35:44 +0000360
361 timings[rfn] = cc, ns - 1, tt + rit, ct, callers
Guido van Rossumb6775db1994-08-01 11:34:53 +0000362
Tim Peters2344fae2001-01-15 00:50:52 +0000363 return 1
Guido van Rossumb6775db1994-08-01 11:34:53 +0000364
Fred Drakeedb5ffb2001-06-08 04:25:24 +0000365
366 dispatch = {
367 "call": trace_dispatch_call,
368 "exception": trace_dispatch_exception,
369 "return": trace_dispatch_return,
Nicholas Bastinc69ebe82004-03-24 21:57:10 +0000370 "c_call": trace_dispatch_c_call,
Armin Rigof8790242005-09-20 18:50:13 +0000371 "c_exception": trace_dispatch_return, # the C function returned
Nicholas Bastinc69ebe82004-03-24 21:57:10 +0000372 "c_return": trace_dispatch_return,
Fred Drakeedb5ffb2001-06-08 04:25:24 +0000373 }
374
375
Tim Petersdb1ed2a2001-10-07 04:30:53 +0000376 # The next few functions play with self.cmd. By carefully preloading
Tim Peters2344fae2001-01-15 00:50:52 +0000377 # our parallel stack, we can force the profiled result to include
378 # an arbitrary string as the name of the calling function.
379 # We use self.cmd as that string, and the resulting stats look
380 # very nice :-).
Guido van Rossumb6775db1994-08-01 11:34:53 +0000381
Tim Peters2344fae2001-01-15 00:50:52 +0000382 def set_cmd(self, cmd):
Tim Petersdf5cfd82001-10-05 23:15:10 +0000383 if self.cur[-1]: return # already set
Tim Peters2344fae2001-01-15 00:50:52 +0000384 self.cmd = cmd
385 self.simulate_call(cmd)
Guido van Rossumb6775db1994-08-01 11:34:53 +0000386
Tim Peters2344fae2001-01-15 00:50:52 +0000387 class fake_code:
388 def __init__(self, filename, line, name):
389 self.co_filename = filename
390 self.co_line = line
391 self.co_name = name
392 self.co_firstlineno = 0
Guido van Rossumb6775db1994-08-01 11:34:53 +0000393
Tim Peters2344fae2001-01-15 00:50:52 +0000394 def __repr__(self):
395 return repr((self.co_filename, self.co_line, self.co_name))
Guido van Rossumb6775db1994-08-01 11:34:53 +0000396
Tim Peters2344fae2001-01-15 00:50:52 +0000397 class fake_frame:
398 def __init__(self, code, prior):
399 self.f_code = code
400 self.f_back = prior
Guido van Rossumb6775db1994-08-01 11:34:53 +0000401
Tim Peters2344fae2001-01-15 00:50:52 +0000402 def simulate_call(self, name):
403 code = self.fake_code('profile', 0, name)
404 if self.cur:
Tim Petersdf5cfd82001-10-05 23:15:10 +0000405 pframe = self.cur[-2]
Tim Peters2344fae2001-01-15 00:50:52 +0000406 else:
407 pframe = None
408 frame = self.fake_frame(code, pframe)
Fred Draked10ed8b2001-10-17 01:49:50 +0000409 self.dispatch['call'](self, frame, 0)
Guido van Rossumb6775db1994-08-01 11:34:53 +0000410
Tim Peters2344fae2001-01-15 00:50:52 +0000411 # collect stats from pending stack, including getting final
412 # timings for self.cmd frame.
Guido van Rossumb6775db1994-08-01 11:34:53 +0000413
Tim Peters2344fae2001-01-15 00:50:52 +0000414 def simulate_cmd_complete(self):
Fred Drakeedb5ffb2001-06-08 04:25:24 +0000415 get_time = self.get_time
416 t = get_time() - self.t
Tim Petersdf5cfd82001-10-05 23:15:10 +0000417 while self.cur[-1]:
Tim Peters2344fae2001-01-15 00:50:52 +0000418 # We *can* cause assertion errors here if
419 # dispatch_trace_return checks for a frame match!
Fred Draked10ed8b2001-10-17 01:49:50 +0000420 self.dispatch['return'](self, self.cur[-2], t)
Tim Peters2344fae2001-01-15 00:50:52 +0000421 t = 0
Fred Drakeedb5ffb2001-06-08 04:25:24 +0000422 self.t = get_time() - t
Guido van Rossumb6775db1994-08-01 11:34:53 +0000423
424
Nicholas Bastin824b1b22004-03-23 18:44:39 +0000425 def print_stats(self, sort=-1):
Tim Peters2344fae2001-01-15 00:50:52 +0000426 import pstats
Nicholas Bastin824b1b22004-03-23 18:44:39 +0000427 pstats.Stats(self).strip_dirs().sort_stats(sort). \
Tim Peters2344fae2001-01-15 00:50:52 +0000428 print_stats()
Guido van Rossumb6775db1994-08-01 11:34:53 +0000429
Tim Peters2344fae2001-01-15 00:50:52 +0000430 def dump_stats(self, file):
431 f = open(file, 'wb')
432 self.create_stats()
433 marshal.dump(self.stats, f)
434 f.close()
435
436 def create_stats(self):
437 self.simulate_cmd_complete()
438 self.snapshot_stats()
439
440 def snapshot_stats(self):
441 self.stats = {}
Guido van Rossumcc2b0162007-02-11 06:12:03 +0000442 for func, (cc, ns, tt, ct, callers) in self.timings.items():
Tim Peters2344fae2001-01-15 00:50:52 +0000443 callers = callers.copy()
444 nc = 0
Guido van Rossumcc2b0162007-02-11 06:12:03 +0000445 for callcnt in callers.values():
Raymond Hettingere0d49722002-06-02 18:55:56 +0000446 nc += callcnt
Tim Peters2344fae2001-01-15 00:50:52 +0000447 self.stats[func] = cc, nc, tt, ct, callers
Guido van Rossumb6775db1994-08-01 11:34:53 +0000448
449
Tim Peters2344fae2001-01-15 00:50:52 +0000450 # The following two methods can be called by clients to use
451 # a profiler to profile a statement, given as a string.
Guido van Rossumb6775db1994-08-01 11:34:53 +0000452
Tim Peters2344fae2001-01-15 00:50:52 +0000453 def run(self, cmd):
454 import __main__
455 dict = __main__.__dict__
456 return self.runctx(cmd, dict, dict)
Guido van Rossumb6775db1994-08-01 11:34:53 +0000457
Tim Peters2344fae2001-01-15 00:50:52 +0000458 def runctx(self, cmd, globals, locals):
459 self.set_cmd(cmd)
460 sys.setprofile(self.dispatcher)
461 try:
Georg Brandl7cae87c2006-09-06 06:51:57 +0000462 exec(cmd, globals, locals)
Tim Peters2344fae2001-01-15 00:50:52 +0000463 finally:
464 sys.setprofile(None)
465 return self
Guido van Rossumb6775db1994-08-01 11:34:53 +0000466
Tim Peters2344fae2001-01-15 00:50:52 +0000467 # This method is more useful to profile a single function call.
Fred Drakeedb5ffb2001-06-08 04:25:24 +0000468 def runcall(self, func, *args, **kw):
Walter Dörwald70a6b492004-02-12 17:35:32 +0000469 self.set_cmd(repr(func))
Tim Peters2344fae2001-01-15 00:50:52 +0000470 sys.setprofile(self.dispatcher)
471 try:
Guido van Rossum68468eb2003-02-27 20:14:51 +0000472 return func(*args, **kw)
Tim Peters2344fae2001-01-15 00:50:52 +0000473 finally:
474 sys.setprofile(None)
Guido van Rossumb6775db1994-08-01 11:34:53 +0000475
Tim Peters2344fae2001-01-15 00:50:52 +0000476
477 #******************************************************************
478 # The following calculates the overhead for using a profiler. The
479 # problem is that it takes a fair amount of time for the profiler
480 # to stop the stopwatch (from the time it receives an event).
481 # Similarly, there is a delay from the time that the profiler
482 # re-starts the stopwatch before the user's code really gets to
483 # continue. The following code tries to measure the difference on
Tim Peters659a6032001-10-09 20:51:19 +0000484 # a per-event basis.
485 #
486 # Note that this difference is only significant if there are a lot of
Tim Peters2344fae2001-01-15 00:50:52 +0000487 # events, and relatively little user code per event. For example,
488 # code with small functions will typically benefit from having the
489 # profiler calibrated for the current platform. This *could* be
490 # done on the fly during init() time, but it is not worth the
491 # effort. Also note that if too large a value specified, then
492 # execution time on some functions will actually appear as a
493 # negative number. It is *normal* for some functions (with very
494 # low call counts) to have such negative stats, even if the
495 # calibration figure is "correct."
496 #
497 # One alternative to profile-time calibration adjustments (i.e.,
498 # adding in the magic little delta during each event) is to track
499 # more carefully the number of events (and cumulatively, the number
500 # of events during sub functions) that are seen. If this were
501 # done, then the arithmetic could be done after the fact (i.e., at
502 # display time). Currently, we track only call/return events.
503 # These values can be deduced by examining the callees and callers
504 # vectors for each functions. Hence we *can* almost correct the
505 # internal time figure at print time (note that we currently don't
506 # track exception event processing counts). Unfortunately, there
507 # is currently no similar information for cumulative sub-function
508 # time. It would not be hard to "get all this info" at profiler
509 # time. Specifically, we would have to extend the tuples to keep
510 # counts of this in each frame, and then extend the defs of timing
511 # tuples to include the significant two figures. I'm a bit fearful
512 # that this additional feature will slow the heavily optimized
513 # event/time ratio (i.e., the profiler would run slower, fur a very
514 # low "value added" feature.)
Tim Peters2344fae2001-01-15 00:50:52 +0000515 #**************************************************************
516
Tim Peterscce092d2001-10-09 05:31:56 +0000517 def calibrate(self, m, verbose=0):
Tim Peters659a6032001-10-09 20:51:19 +0000518 if self.__class__ is not Profile:
519 raise TypeError("Subclasses must override .calibrate().")
520
521 saved_bias = self.bias
522 self.bias = 0
523 try:
Tim Peterse13cc922001-10-09 21:01:31 +0000524 return self._calibrate_inner(m, verbose)
Tim Peters659a6032001-10-09 20:51:19 +0000525 finally:
526 self.bias = saved_bias
527
Tim Peterse13cc922001-10-09 21:01:31 +0000528 def _calibrate_inner(self, m, verbose):
Fred Drakeedb5ffb2001-06-08 04:25:24 +0000529 get_time = self.get_time
Tim Peters2344fae2001-01-15 00:50:52 +0000530
Tim Peterscce092d2001-10-09 05:31:56 +0000531 # Set up a test case to be run with and without profiling. Include
532 # lots of calls, because we're trying to quantify stopwatch overhead.
533 # Do not raise any exceptions, though, because we want to know
534 # exactly how many profile events are generated (one call event, +
535 # one return event, per Python-level call).
Tim Peters2344fae2001-01-15 00:50:52 +0000536
Tim Peterscce092d2001-10-09 05:31:56 +0000537 def f1(n):
538 for i in range(n):
539 x = 1
Tim Peters2344fae2001-01-15 00:50:52 +0000540
Tim Peterscce092d2001-10-09 05:31:56 +0000541 def f(m, f1=f1):
542 for i in range(m):
543 f1(100)
Tim Peters2344fae2001-01-15 00:50:52 +0000544
Tim Peterscce092d2001-10-09 05:31:56 +0000545 f(m) # warm up the cache
546
547 # elapsed_noprofile <- time f(m) takes without profiling.
548 t0 = get_time()
549 f(m)
550 t1 = get_time()
551 elapsed_noprofile = t1 - t0
552 if verbose:
Guido van Rossumbe19ed72007-02-09 05:37:30 +0000553 print("elapsed time without profiling =", elapsed_noprofile)
Tim Peterscce092d2001-10-09 05:31:56 +0000554
555 # elapsed_profile <- time f(m) takes with profiling. The difference
556 # is profiling overhead, only some of which the profiler subtracts
557 # out on its own.
558 p = Profile()
559 t0 = get_time()
560 p.runctx('f(m)', globals(), locals())
561 t1 = get_time()
562 elapsed_profile = t1 - t0
563 if verbose:
Guido van Rossumbe19ed72007-02-09 05:37:30 +0000564 print("elapsed time with profiling =", elapsed_profile)
Tim Peterscce092d2001-10-09 05:31:56 +0000565
566 # reported_time <- "CPU seconds" the profiler charged to f and f1.
567 total_calls = 0.0
568 reported_time = 0.0
569 for (filename, line, funcname), (cc, ns, tt, ct, callers) in \
570 p.timings.items():
571 if funcname in ("f", "f1"):
572 total_calls += cc
573 reported_time += tt
574
575 if verbose:
Guido van Rossumbe19ed72007-02-09 05:37:30 +0000576 print("'CPU seconds' profiler reported =", reported_time)
577 print("total # calls =", total_calls)
Tim Peterscce092d2001-10-09 05:31:56 +0000578 if total_calls != m + 1:
579 raise ValueError("internal error: total calls = %d" % total_calls)
580
581 # reported_time - elapsed_noprofile = overhead the profiler wasn't
582 # able to measure. Divide by twice the number of calls (since there
583 # are two profiler events per call in this test) to get the hidden
584 # overhead per event.
585 mean = (reported_time - elapsed_noprofile) / 2.0 / total_calls
586 if verbose:
Guido van Rossumbe19ed72007-02-09 05:37:30 +0000587 print("mean stopwatch overhead per profile event =", mean)
Tim Peterscce092d2001-10-09 05:31:56 +0000588 return mean
Guido van Rossumb6775db1994-08-01 11:34:53 +0000589
Guido van Rossumb6775db1994-08-01 11:34:53 +0000590#****************************************************************************
591def Stats(*args):
Guido van Rossumbe19ed72007-02-09 05:37:30 +0000592 print('Report generating functions are in the "pstats" module\a')
Guido van Rossumcc778eb1996-10-01 02:55:54 +0000593
Johannes Gijsbers2abe7852005-01-09 01:58:02 +0000594def main():
Nicholas Bastin824b1b22004-03-23 18:44:39 +0000595 usage = "profile.py [-o output_file_path] [-s sort] scriptfile [arg] ..."
Johannes Gijsbers2abe7852005-01-09 01:58:02 +0000596 parser = OptionParser(usage=usage)
Nicholas Bastin824b1b22004-03-23 18:44:39 +0000597 parser.allow_interspersed_args = False
Tim Peters4e0e1b62004-07-07 20:54:48 +0000598 parser.add_option('-o', '--outfile', dest="outfile",
Nicholas Bastin824b1b22004-03-23 18:44:39 +0000599 help="Save stats to <outfile>", default=None)
600 parser.add_option('-s', '--sort', dest="sort",
601 help="Sort order when printing to stdout, based on pstats.Stats class", default=-1)
Tim Petersb497c102005-01-10 16:48:37 +0000602
Johannes Gijsbers2abe7852005-01-09 01:58:02 +0000603 if not sys.argv[1:]:
604 parser.print_usage()
605 sys.exit(2)
Tim Petersb497c102005-01-10 16:48:37 +0000606
Nicholas Bastin824b1b22004-03-23 18:44:39 +0000607 (options, args) = parser.parse_args()
608 sys.argv[:] = args
Tim Petersb497c102005-01-10 16:48:37 +0000609
Nicholas Bastin824b1b22004-03-23 18:44:39 +0000610 if (len(sys.argv) > 0):
611 sys.path.insert(0, os.path.dirname(sys.argv[0]))
Neal Norwitz01688022007-08-12 00:43:29 +0000612 fp = open(sys.argv[0])
613 try:
614 script = fp.read()
615 finally:
616 fp.close()
617 run('exec(%r)' % script, options.outfile, options.sort)
Nicholas Bastin824b1b22004-03-23 18:44:39 +0000618 else:
Johannes Gijsbers2abe7852005-01-09 01:58:02 +0000619 parser.print_usage()
620 return parser
621
622# When invoked as main program, invoke the profiler on a script
623if __name__ == '__main__':
624 main()