##// END OF EJS Templates
py3: handle keyword arguments correctly in statprof.py...
Pulkit Goyal -
r35371:c5853c9a default
parent child Browse files
Show More
@@ -1,930 +1,930 b''
1 #!/usr/bin/env python
1 #!/usr/bin/env python
2 ## statprof.py
2 ## statprof.py
3 ## Copyright (C) 2012 Bryan O'Sullivan <bos@serpentine.com>
3 ## Copyright (C) 2012 Bryan O'Sullivan <bos@serpentine.com>
4 ## Copyright (C) 2011 Alex Fraser <alex at phatcore dot com>
4 ## Copyright (C) 2011 Alex Fraser <alex at phatcore dot com>
5 ## Copyright (C) 2004,2005 Andy Wingo <wingo at pobox dot com>
5 ## Copyright (C) 2004,2005 Andy Wingo <wingo at pobox dot com>
6 ## Copyright (C) 2001 Rob Browning <rlb at defaultvalue dot org>
6 ## Copyright (C) 2001 Rob Browning <rlb at defaultvalue dot org>
7
7
8 ## This library is free software; you can redistribute it and/or
8 ## This library is free software; you can redistribute it and/or
9 ## modify it under the terms of the GNU Lesser General Public
9 ## modify it under the terms of the GNU Lesser General Public
10 ## License as published by the Free Software Foundation; either
10 ## License as published by the Free Software Foundation; either
11 ## version 2.1 of the License, or (at your option) any later version.
11 ## version 2.1 of the License, or (at your option) any later version.
12 ##
12 ##
13 ## This library is distributed in the hope that it will be useful,
13 ## This library is distributed in the hope that it will be useful,
14 ## but WITHOUT ANY WARRANTY; without even the implied warranty of
14 ## but WITHOUT ANY WARRANTY; without even the implied warranty of
15 ## MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
15 ## MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
16 ## Lesser General Public License for more details.
16 ## Lesser General Public License for more details.
17 ##
17 ##
18 ## You should have received a copy of the GNU Lesser General Public
18 ## You should have received a copy of the GNU Lesser General Public
19 ## License along with this program; if not, contact:
19 ## License along with this program; if not, contact:
20 ##
20 ##
21 ## Free Software Foundation Voice: +1-617-542-5942
21 ## Free Software Foundation Voice: +1-617-542-5942
22 ## 59 Temple Place - Suite 330 Fax: +1-617-542-2652
22 ## 59 Temple Place - Suite 330 Fax: +1-617-542-2652
23 ## Boston, MA 02111-1307, USA gnu@gnu.org
23 ## Boston, MA 02111-1307, USA gnu@gnu.org
24
24
25 """
25 """
26 statprof is intended to be a fairly simple statistical profiler for
26 statprof is intended to be a fairly simple statistical profiler for
27 python. It was ported directly from a statistical profiler for guile,
27 python. It was ported directly from a statistical profiler for guile,
28 also named statprof, available from guile-lib [0].
28 also named statprof, available from guile-lib [0].
29
29
30 [0] http://wingolog.org/software/guile-lib/statprof/
30 [0] http://wingolog.org/software/guile-lib/statprof/
31
31
32 To start profiling, call statprof.start():
32 To start profiling, call statprof.start():
33 >>> start()
33 >>> start()
34
34
35 Then run whatever it is that you want to profile, for example:
35 Then run whatever it is that you want to profile, for example:
36 >>> import test.pystone; test.pystone.pystones()
36 >>> import test.pystone; test.pystone.pystones()
37
37
38 Then stop the profiling and print out the results:
38 Then stop the profiling and print out the results:
39 >>> stop()
39 >>> stop()
40 >>> display()
40 >>> display()
41 % cumulative self
41 % cumulative self
42 time seconds seconds name
42 time seconds seconds name
43 26.72 1.40 0.37 pystone.py:79:Proc0
43 26.72 1.40 0.37 pystone.py:79:Proc0
44 13.79 0.56 0.19 pystone.py:133:Proc1
44 13.79 0.56 0.19 pystone.py:133:Proc1
45 13.79 0.19 0.19 pystone.py:208:Proc8
45 13.79 0.19 0.19 pystone.py:208:Proc8
46 10.34 0.16 0.14 pystone.py:229:Func2
46 10.34 0.16 0.14 pystone.py:229:Func2
47 6.90 0.10 0.10 pystone.py:45:__init__
47 6.90 0.10 0.10 pystone.py:45:__init__
48 4.31 0.16 0.06 pystone.py:53:copy
48 4.31 0.16 0.06 pystone.py:53:copy
49 ...
49 ...
50
50
51 All of the numerical data is statistically approximate. In the
51 All of the numerical data is statistically approximate. In the
52 following column descriptions, and in all of statprof, "time" refers
52 following column descriptions, and in all of statprof, "time" refers
53 to execution time (both user and system), not wall clock time.
53 to execution time (both user and system), not wall clock time.
54
54
55 % time
55 % time
56 The percent of the time spent inside the procedure itself (not
56 The percent of the time spent inside the procedure itself (not
57 counting children).
57 counting children).
58
58
59 cumulative seconds
59 cumulative seconds
60 The total number of seconds spent in the procedure, including
60 The total number of seconds spent in the procedure, including
61 children.
61 children.
62
62
63 self seconds
63 self seconds
64 The total number of seconds spent in the procedure itself (not
64 The total number of seconds spent in the procedure itself (not
65 counting children).
65 counting children).
66
66
67 name
67 name
68 The name of the procedure.
68 The name of the procedure.
69
69
70 By default statprof keeps the data collected from previous runs. If you
70 By default statprof keeps the data collected from previous runs. If you
71 want to clear the collected data, call reset():
71 want to clear the collected data, call reset():
72 >>> reset()
72 >>> reset()
73
73
74 reset() can also be used to change the sampling frequency from the
74 reset() can also be used to change the sampling frequency from the
75 default of 1000 Hz. For example, to tell statprof to sample 50 times a
75 default of 1000 Hz. For example, to tell statprof to sample 50 times a
76 second:
76 second:
77 >>> reset(50)
77 >>> reset(50)
78
78
79 This means that statprof will sample the call stack after every 1/50 of
79 This means that statprof will sample the call stack after every 1/50 of
80 a second of user + system time spent running on behalf of the python
80 a second of user + system time spent running on behalf of the python
81 process. When your process is idle (for example, blocking in a read(),
81 process. When your process is idle (for example, blocking in a read(),
82 as is the case at the listener), the clock does not advance. For this
82 as is the case at the listener), the clock does not advance. For this
83 reason statprof is not currently not suitable for profiling io-bound
83 reason statprof is not currently not suitable for profiling io-bound
84 operations.
84 operations.
85
85
86 The profiler uses the hash of the code object itself to identify the
86 The profiler uses the hash of the code object itself to identify the
87 procedures, so it won't confuse different procedures with the same name.
87 procedures, so it won't confuse different procedures with the same name.
88 They will show up as two different rows in the output.
88 They will show up as two different rows in the output.
89
89
90 Right now the profiler is quite simplistic. I cannot provide
90 Right now the profiler is quite simplistic. I cannot provide
91 call-graphs or other higher level information. What you see in the
91 call-graphs or other higher level information. What you see in the
92 table is pretty much all there is. Patches are welcome :-)
92 table is pretty much all there is. Patches are welcome :-)
93
93
94
94
95 Threading
95 Threading
96 ---------
96 ---------
97
97
98 Because signals only get delivered to the main thread in Python,
98 Because signals only get delivered to the main thread in Python,
99 statprof only profiles the main thread. However because the time
99 statprof only profiles the main thread. However because the time
100 reporting function uses per-process timers, the results can be
100 reporting function uses per-process timers, the results can be
101 significantly off if other threads' work patterns are not similar to the
101 significantly off if other threads' work patterns are not similar to the
102 main thread's work patterns.
102 main thread's work patterns.
103 """
103 """
104 # no-check-code
104 # no-check-code
105 from __future__ import absolute_import, division, print_function
105 from __future__ import absolute_import, division, print_function
106
106
107 import collections
107 import collections
108 import contextlib
108 import contextlib
109 import getopt
109 import getopt
110 import inspect
110 import inspect
111 import json
111 import json
112 import os
112 import os
113 import signal
113 import signal
114 import sys
114 import sys
115 import tempfile
115 import tempfile
116 import threading
116 import threading
117 import time
117 import time
118
118
119 from . import (
119 from . import (
120 encoding,
120 encoding,
121 pycompat,
121 pycompat,
122 )
122 )
123
123
124 defaultdict = collections.defaultdict
124 defaultdict = collections.defaultdict
125 contextmanager = contextlib.contextmanager
125 contextmanager = contextlib.contextmanager
126
126
127 __all__ = ['start', 'stop', 'reset', 'display', 'profile']
127 __all__ = ['start', 'stop', 'reset', 'display', 'profile']
128
128
129 skips = {"util.py:check", "extensions.py:closure",
129 skips = {"util.py:check", "extensions.py:closure",
130 "color.py:colorcmd", "dispatch.py:checkargs",
130 "color.py:colorcmd", "dispatch.py:checkargs",
131 "dispatch.py:<lambda>", "dispatch.py:_runcatch",
131 "dispatch.py:<lambda>", "dispatch.py:_runcatch",
132 "dispatch.py:_dispatch", "dispatch.py:_runcommand",
132 "dispatch.py:_dispatch", "dispatch.py:_runcommand",
133 "pager.py:pagecmd", "dispatch.py:run",
133 "pager.py:pagecmd", "dispatch.py:run",
134 "dispatch.py:dispatch", "dispatch.py:runcommand",
134 "dispatch.py:dispatch", "dispatch.py:runcommand",
135 "hg.py:<module>", "evolve.py:warnobserrors",
135 "hg.py:<module>", "evolve.py:warnobserrors",
136 }
136 }
137
137
138 ###########################################################################
138 ###########################################################################
139 ## Utils
139 ## Utils
140
140
141 def clock():
141 def clock():
142 times = os.times()
142 times = os.times()
143 return times[0] + times[1]
143 return times[0] + times[1]
144
144
145
145
146 ###########################################################################
146 ###########################################################################
147 ## Collection data structures
147 ## Collection data structures
148
148
149 class ProfileState(object):
149 class ProfileState(object):
150 def __init__(self, frequency=None):
150 def __init__(self, frequency=None):
151 self.reset(frequency)
151 self.reset(frequency)
152
152
153 def reset(self, frequency=None):
153 def reset(self, frequency=None):
154 # total so far
154 # total so far
155 self.accumulated_time = 0.0
155 self.accumulated_time = 0.0
156 # start_time when timer is active
156 # start_time when timer is active
157 self.last_start_time = None
157 self.last_start_time = None
158 # a float
158 # a float
159 if frequency:
159 if frequency:
160 self.sample_interval = 1.0 / frequency
160 self.sample_interval = 1.0 / frequency
161 elif not hasattr(self, 'sample_interval'):
161 elif not hasattr(self, 'sample_interval'):
162 # default to 1000 Hz
162 # default to 1000 Hz
163 self.sample_interval = 1.0 / 1000.0
163 self.sample_interval = 1.0 / 1000.0
164 else:
164 else:
165 # leave the frequency as it was
165 # leave the frequency as it was
166 pass
166 pass
167 self.remaining_prof_time = None
167 self.remaining_prof_time = None
168 # for user start/stop nesting
168 # for user start/stop nesting
169 self.profile_level = 0
169 self.profile_level = 0
170
170
171 self.samples = []
171 self.samples = []
172
172
173 def accumulate_time(self, stop_time):
173 def accumulate_time(self, stop_time):
174 self.accumulated_time += stop_time - self.last_start_time
174 self.accumulated_time += stop_time - self.last_start_time
175
175
176 def seconds_per_sample(self):
176 def seconds_per_sample(self):
177 return self.accumulated_time / len(self.samples)
177 return self.accumulated_time / len(self.samples)
178
178
179 state = ProfileState()
179 state = ProfileState()
180
180
181
181
182 class CodeSite(object):
182 class CodeSite(object):
183 cache = {}
183 cache = {}
184
184
185 __slots__ = (u'path', u'lineno', u'function', u'source')
185 __slots__ = (u'path', u'lineno', u'function', u'source')
186
186
187 def __init__(self, path, lineno, function):
187 def __init__(self, path, lineno, function):
188 self.path = path
188 self.path = path
189 self.lineno = lineno
189 self.lineno = lineno
190 self.function = function
190 self.function = function
191 self.source = None
191 self.source = None
192
192
193 def __eq__(self, other):
193 def __eq__(self, other):
194 try:
194 try:
195 return (self.lineno == other.lineno and
195 return (self.lineno == other.lineno and
196 self.path == other.path)
196 self.path == other.path)
197 except:
197 except:
198 return False
198 return False
199
199
200 def __hash__(self):
200 def __hash__(self):
201 return hash((self.lineno, self.path))
201 return hash((self.lineno, self.path))
202
202
203 @classmethod
203 @classmethod
204 def get(cls, path, lineno, function):
204 def get(cls, path, lineno, function):
205 k = (path, lineno)
205 k = (path, lineno)
206 try:
206 try:
207 return cls.cache[k]
207 return cls.cache[k]
208 except KeyError:
208 except KeyError:
209 v = cls(path, lineno, function)
209 v = cls(path, lineno, function)
210 cls.cache[k] = v
210 cls.cache[k] = v
211 return v
211 return v
212
212
213 def getsource(self, length):
213 def getsource(self, length):
214 if self.source is None:
214 if self.source is None:
215 lineno = self.lineno - 1
215 lineno = self.lineno - 1
216 fp = None
216 fp = None
217 try:
217 try:
218 fp = open(self.path)
218 fp = open(self.path)
219 for i, line in enumerate(fp):
219 for i, line in enumerate(fp):
220 if i == lineno:
220 if i == lineno:
221 self.source = line.strip()
221 self.source = line.strip()
222 break
222 break
223 except:
223 except:
224 pass
224 pass
225 finally:
225 finally:
226 if fp:
226 if fp:
227 fp.close()
227 fp.close()
228 if self.source is None:
228 if self.source is None:
229 self.source = ''
229 self.source = ''
230
230
231 source = self.source
231 source = self.source
232 if len(source) > length:
232 if len(source) > length:
233 source = source[:(length - 3)] + "..."
233 source = source[:(length - 3)] + "..."
234 return source
234 return source
235
235
236 def filename(self):
236 def filename(self):
237 return os.path.basename(self.path)
237 return os.path.basename(self.path)
238
238
239 class Sample(object):
239 class Sample(object):
240 __slots__ = (u'stack', u'time')
240 __slots__ = (u'stack', u'time')
241
241
242 def __init__(self, stack, time):
242 def __init__(self, stack, time):
243 self.stack = stack
243 self.stack = stack
244 self.time = time
244 self.time = time
245
245
246 @classmethod
246 @classmethod
247 def from_frame(cls, frame, time):
247 def from_frame(cls, frame, time):
248 stack = []
248 stack = []
249
249
250 while frame:
250 while frame:
251 stack.append(CodeSite.get(frame.f_code.co_filename, frame.f_lineno,
251 stack.append(CodeSite.get(frame.f_code.co_filename, frame.f_lineno,
252 frame.f_code.co_name))
252 frame.f_code.co_name))
253 frame = frame.f_back
253 frame = frame.f_back
254
254
255 return Sample(stack, time)
255 return Sample(stack, time)
256
256
257 ###########################################################################
257 ###########################################################################
258 ## SIGPROF handler
258 ## SIGPROF handler
259
259
260 def profile_signal_handler(signum, frame):
260 def profile_signal_handler(signum, frame):
261 if state.profile_level > 0:
261 if state.profile_level > 0:
262 now = clock()
262 now = clock()
263 state.accumulate_time(now)
263 state.accumulate_time(now)
264
264
265 state.samples.append(Sample.from_frame(frame, state.accumulated_time))
265 state.samples.append(Sample.from_frame(frame, state.accumulated_time))
266
266
267 signal.setitimer(signal.ITIMER_PROF,
267 signal.setitimer(signal.ITIMER_PROF,
268 state.sample_interval, 0.0)
268 state.sample_interval, 0.0)
269 state.last_start_time = now
269 state.last_start_time = now
270
270
271 stopthread = threading.Event()
271 stopthread = threading.Event()
272 def samplerthread(tid):
272 def samplerthread(tid):
273 while not stopthread.is_set():
273 while not stopthread.is_set():
274 now = clock()
274 now = clock()
275 state.accumulate_time(now)
275 state.accumulate_time(now)
276
276
277 frame = sys._current_frames()[tid]
277 frame = sys._current_frames()[tid]
278 state.samples.append(Sample.from_frame(frame, state.accumulated_time))
278 state.samples.append(Sample.from_frame(frame, state.accumulated_time))
279
279
280 state.last_start_time = now
280 state.last_start_time = now
281 time.sleep(state.sample_interval)
281 time.sleep(state.sample_interval)
282
282
283 stopthread.clear()
283 stopthread.clear()
284
284
285 ###########################################################################
285 ###########################################################################
286 ## Profiling API
286 ## Profiling API
287
287
288 def is_active():
288 def is_active():
289 return state.profile_level > 0
289 return state.profile_level > 0
290
290
291 lastmechanism = None
291 lastmechanism = None
292 def start(mechanism='thread'):
292 def start(mechanism='thread'):
293 '''Install the profiling signal handler, and start profiling.'''
293 '''Install the profiling signal handler, and start profiling.'''
294 state.profile_level += 1
294 state.profile_level += 1
295 if state.profile_level == 1:
295 if state.profile_level == 1:
296 state.last_start_time = clock()
296 state.last_start_time = clock()
297 rpt = state.remaining_prof_time
297 rpt = state.remaining_prof_time
298 state.remaining_prof_time = None
298 state.remaining_prof_time = None
299
299
300 global lastmechanism
300 global lastmechanism
301 lastmechanism = mechanism
301 lastmechanism = mechanism
302
302
303 if mechanism == 'signal':
303 if mechanism == 'signal':
304 signal.signal(signal.SIGPROF, profile_signal_handler)
304 signal.signal(signal.SIGPROF, profile_signal_handler)
305 signal.setitimer(signal.ITIMER_PROF,
305 signal.setitimer(signal.ITIMER_PROF,
306 rpt or state.sample_interval, 0.0)
306 rpt or state.sample_interval, 0.0)
307 elif mechanism == 'thread':
307 elif mechanism == 'thread':
308 frame = inspect.currentframe()
308 frame = inspect.currentframe()
309 tid = [k for k, f in sys._current_frames().items() if f == frame][0]
309 tid = [k for k, f in sys._current_frames().items() if f == frame][0]
310 state.thread = threading.Thread(target=samplerthread,
310 state.thread = threading.Thread(target=samplerthread,
311 args=(tid,), name="samplerthread")
311 args=(tid,), name="samplerthread")
312 state.thread.start()
312 state.thread.start()
313
313
314 def stop():
314 def stop():
315 '''Stop profiling, and uninstall the profiling signal handler.'''
315 '''Stop profiling, and uninstall the profiling signal handler.'''
316 state.profile_level -= 1
316 state.profile_level -= 1
317 if state.profile_level == 0:
317 if state.profile_level == 0:
318 if lastmechanism == 'signal':
318 if lastmechanism == 'signal':
319 rpt = signal.setitimer(signal.ITIMER_PROF, 0.0, 0.0)
319 rpt = signal.setitimer(signal.ITIMER_PROF, 0.0, 0.0)
320 signal.signal(signal.SIGPROF, signal.SIG_IGN)
320 signal.signal(signal.SIGPROF, signal.SIG_IGN)
321 state.remaining_prof_time = rpt[0]
321 state.remaining_prof_time = rpt[0]
322 elif lastmechanism == 'thread':
322 elif lastmechanism == 'thread':
323 stopthread.set()
323 stopthread.set()
324 state.thread.join()
324 state.thread.join()
325
325
326 state.accumulate_time(clock())
326 state.accumulate_time(clock())
327 state.last_start_time = None
327 state.last_start_time = None
328 statprofpath = encoding.environ.get('STATPROF_DEST')
328 statprofpath = encoding.environ.get('STATPROF_DEST')
329 if statprofpath:
329 if statprofpath:
330 save_data(statprofpath)
330 save_data(statprofpath)
331
331
332 return state
332 return state
333
333
334 def save_data(path):
334 def save_data(path):
335 with open(path, 'w+') as file:
335 with open(path, 'w+') as file:
336 file.write(str(state.accumulated_time) + '\n')
336 file.write(str(state.accumulated_time) + '\n')
337 for sample in state.samples:
337 for sample in state.samples:
338 time = str(sample.time)
338 time = str(sample.time)
339 stack = sample.stack
339 stack = sample.stack
340 sites = ['\1'.join([s.path, str(s.lineno), s.function])
340 sites = ['\1'.join([s.path, str(s.lineno), s.function])
341 for s in stack]
341 for s in stack]
342 file.write(time + '\0' + '\0'.join(sites) + '\n')
342 file.write(time + '\0' + '\0'.join(sites) + '\n')
343
343
344 def load_data(path):
344 def load_data(path):
345 lines = open(path, 'r').read().splitlines()
345 lines = open(path, 'r').read().splitlines()
346
346
347 state.accumulated_time = float(lines[0])
347 state.accumulated_time = float(lines[0])
348 state.samples = []
348 state.samples = []
349 for line in lines[1:]:
349 for line in lines[1:]:
350 parts = line.split('\0')
350 parts = line.split('\0')
351 time = float(parts[0])
351 time = float(parts[0])
352 rawsites = parts[1:]
352 rawsites = parts[1:]
353 sites = []
353 sites = []
354 for rawsite in rawsites:
354 for rawsite in rawsites:
355 siteparts = rawsite.split('\1')
355 siteparts = rawsite.split('\1')
356 sites.append(CodeSite.get(siteparts[0], int(siteparts[1]),
356 sites.append(CodeSite.get(siteparts[0], int(siteparts[1]),
357 siteparts[2]))
357 siteparts[2]))
358
358
359 state.samples.append(Sample(sites, time))
359 state.samples.append(Sample(sites, time))
360
360
361
361
362
362
363 def reset(frequency=None):
363 def reset(frequency=None):
364 '''Clear out the state of the profiler. Do not call while the
364 '''Clear out the state of the profiler. Do not call while the
365 profiler is running.
365 profiler is running.
366
366
367 The optional frequency argument specifies the number of samples to
367 The optional frequency argument specifies the number of samples to
368 collect per second.'''
368 collect per second.'''
369 assert state.profile_level == 0, "Can't reset() while statprof is running"
369 assert state.profile_level == 0, "Can't reset() while statprof is running"
370 CodeSite.cache.clear()
370 CodeSite.cache.clear()
371 state.reset(frequency)
371 state.reset(frequency)
372
372
373
373
374 @contextmanager
374 @contextmanager
375 def profile():
375 def profile():
376 start()
376 start()
377 try:
377 try:
378 yield
378 yield
379 finally:
379 finally:
380 stop()
380 stop()
381 display()
381 display()
382
382
383
383
384 ###########################################################################
384 ###########################################################################
385 ## Reporting API
385 ## Reporting API
386
386
387 class SiteStats(object):
387 class SiteStats(object):
388 def __init__(self, site):
388 def __init__(self, site):
389 self.site = site
389 self.site = site
390 self.selfcount = 0
390 self.selfcount = 0
391 self.totalcount = 0
391 self.totalcount = 0
392
392
393 def addself(self):
393 def addself(self):
394 self.selfcount += 1
394 self.selfcount += 1
395
395
396 def addtotal(self):
396 def addtotal(self):
397 self.totalcount += 1
397 self.totalcount += 1
398
398
399 def selfpercent(self):
399 def selfpercent(self):
400 return self.selfcount / len(state.samples) * 100
400 return self.selfcount / len(state.samples) * 100
401
401
402 def totalpercent(self):
402 def totalpercent(self):
403 return self.totalcount / len(state.samples) * 100
403 return self.totalcount / len(state.samples) * 100
404
404
405 def selfseconds(self):
405 def selfseconds(self):
406 return self.selfcount * state.seconds_per_sample()
406 return self.selfcount * state.seconds_per_sample()
407
407
408 def totalseconds(self):
408 def totalseconds(self):
409 return self.totalcount * state.seconds_per_sample()
409 return self.totalcount * state.seconds_per_sample()
410
410
411 @classmethod
411 @classmethod
412 def buildstats(cls, samples):
412 def buildstats(cls, samples):
413 stats = {}
413 stats = {}
414
414
415 for sample in samples:
415 for sample in samples:
416 for i, site in enumerate(sample.stack):
416 for i, site in enumerate(sample.stack):
417 sitestat = stats.get(site)
417 sitestat = stats.get(site)
418 if not sitestat:
418 if not sitestat:
419 sitestat = SiteStats(site)
419 sitestat = SiteStats(site)
420 stats[site] = sitestat
420 stats[site] = sitestat
421
421
422 sitestat.addtotal()
422 sitestat.addtotal()
423
423
424 if i == 0:
424 if i == 0:
425 sitestat.addself()
425 sitestat.addself()
426
426
427 return [s for s in stats.itervalues()]
427 return [s for s in stats.itervalues()]
428
428
429 class DisplayFormats:
429 class DisplayFormats:
430 ByLine = 0
430 ByLine = 0
431 ByMethod = 1
431 ByMethod = 1
432 AboutMethod = 2
432 AboutMethod = 2
433 Hotpath = 3
433 Hotpath = 3
434 FlameGraph = 4
434 FlameGraph = 4
435 Json = 5
435 Json = 5
436 Chrome = 6
436 Chrome = 6
437
437
438 def display(fp=None, format=3, data=None, **kwargs):
438 def display(fp=None, format=3, data=None, **kwargs):
439 '''Print statistics, either to stdout or the given file object.'''
439 '''Print statistics, either to stdout or the given file object.'''
440 data = data or state
440 data = data or state
441
441
442 if fp is None:
442 if fp is None:
443 import sys
443 import sys
444 fp = sys.stdout
444 fp = sys.stdout
445 if len(data.samples) == 0:
445 if len(data.samples) == 0:
446 print('No samples recorded.', file=fp)
446 print('No samples recorded.', file=fp)
447 return
447 return
448
448
449 if format == DisplayFormats.ByLine:
449 if format == DisplayFormats.ByLine:
450 display_by_line(data, fp)
450 display_by_line(data, fp)
451 elif format == DisplayFormats.ByMethod:
451 elif format == DisplayFormats.ByMethod:
452 display_by_method(data, fp)
452 display_by_method(data, fp)
453 elif format == DisplayFormats.AboutMethod:
453 elif format == DisplayFormats.AboutMethod:
454 display_about_method(data, fp, **kwargs)
454 display_about_method(data, fp, **kwargs)
455 elif format == DisplayFormats.Hotpath:
455 elif format == DisplayFormats.Hotpath:
456 display_hotpath(data, fp, **kwargs)
456 display_hotpath(data, fp, **kwargs)
457 elif format == DisplayFormats.FlameGraph:
457 elif format == DisplayFormats.FlameGraph:
458 write_to_flame(data, fp, **kwargs)
458 write_to_flame(data, fp, **kwargs)
459 elif format == DisplayFormats.Json:
459 elif format == DisplayFormats.Json:
460 write_to_json(data, fp)
460 write_to_json(data, fp)
461 elif format == DisplayFormats.Chrome:
461 elif format == DisplayFormats.Chrome:
462 write_to_chrome(data, fp, **kwargs)
462 write_to_chrome(data, fp, **kwargs)
463 else:
463 else:
464 raise Exception("Invalid display format")
464 raise Exception("Invalid display format")
465
465
466 if format not in (DisplayFormats.Json, DisplayFormats.Chrome):
466 if format not in (DisplayFormats.Json, DisplayFormats.Chrome):
467 print('---', file=fp)
467 print('---', file=fp)
468 print('Sample count: %d' % len(data.samples), file=fp)
468 print('Sample count: %d' % len(data.samples), file=fp)
469 print('Total time: %f seconds' % data.accumulated_time, file=fp)
469 print('Total time: %f seconds' % data.accumulated_time, file=fp)
470
470
471 def display_by_line(data, fp):
471 def display_by_line(data, fp):
472 '''Print the profiler data with each sample line represented
472 '''Print the profiler data with each sample line represented
473 as one row in a table. Sorted by self-time per line.'''
473 as one row in a table. Sorted by self-time per line.'''
474 stats = SiteStats.buildstats(data.samples)
474 stats = SiteStats.buildstats(data.samples)
475 stats.sort(reverse=True, key=lambda x: x.selfseconds())
475 stats.sort(reverse=True, key=lambda x: x.selfseconds())
476
476
477 print('%5.5s %10.10s %7.7s %-8.8s' %
477 print('%5.5s %10.10s %7.7s %-8.8s' %
478 ('% ', 'cumulative', 'self', ''), file=fp)
478 ('% ', 'cumulative', 'self', ''), file=fp)
479 print('%5.5s %9.9s %8.8s %-8.8s' %
479 print('%5.5s %9.9s %8.8s %-8.8s' %
480 ("time", "seconds", "seconds", "name"), file=fp)
480 ("time", "seconds", "seconds", "name"), file=fp)
481
481
482 for stat in stats:
482 for stat in stats:
483 site = stat.site
483 site = stat.site
484 sitelabel = '%s:%d:%s' % (site.filename(), site.lineno, site.function)
484 sitelabel = '%s:%d:%s' % (site.filename(), site.lineno, site.function)
485 print('%6.2f %9.2f %9.2f %s' % (stat.selfpercent(),
485 print('%6.2f %9.2f %9.2f %s' % (stat.selfpercent(),
486 stat.totalseconds(),
486 stat.totalseconds(),
487 stat.selfseconds(),
487 stat.selfseconds(),
488 sitelabel),
488 sitelabel),
489 file=fp)
489 file=fp)
490
490
491 def display_by_method(data, fp):
491 def display_by_method(data, fp):
492 '''Print the profiler data with each sample function represented
492 '''Print the profiler data with each sample function represented
493 as one row in a table. Important lines within that function are
493 as one row in a table. Important lines within that function are
494 output as nested rows. Sorted by self-time per line.'''
494 output as nested rows. Sorted by self-time per line.'''
495 print('%5.5s %10.10s %7.7s %-8.8s' %
495 print('%5.5s %10.10s %7.7s %-8.8s' %
496 ('% ', 'cumulative', 'self', ''), file=fp)
496 ('% ', 'cumulative', 'self', ''), file=fp)
497 print('%5.5s %9.9s %8.8s %-8.8s' %
497 print('%5.5s %9.9s %8.8s %-8.8s' %
498 ("time", "seconds", "seconds", "name"), file=fp)
498 ("time", "seconds", "seconds", "name"), file=fp)
499
499
500 stats = SiteStats.buildstats(data.samples)
500 stats = SiteStats.buildstats(data.samples)
501
501
502 grouped = defaultdict(list)
502 grouped = defaultdict(list)
503 for stat in stats:
503 for stat in stats:
504 grouped[stat.site.filename() + ":" + stat.site.function].append(stat)
504 grouped[stat.site.filename() + ":" + stat.site.function].append(stat)
505
505
506 # compute sums for each function
506 # compute sums for each function
507 functiondata = []
507 functiondata = []
508 for fname, sitestats in grouped.iteritems():
508 for fname, sitestats in grouped.iteritems():
509 total_cum_sec = 0
509 total_cum_sec = 0
510 total_self_sec = 0
510 total_self_sec = 0
511 total_percent = 0
511 total_percent = 0
512 for stat in sitestats:
512 for stat in sitestats:
513 total_cum_sec += stat.totalseconds()
513 total_cum_sec += stat.totalseconds()
514 total_self_sec += stat.selfseconds()
514 total_self_sec += stat.selfseconds()
515 total_percent += stat.selfpercent()
515 total_percent += stat.selfpercent()
516
516
517 functiondata.append((fname,
517 functiondata.append((fname,
518 total_cum_sec,
518 total_cum_sec,
519 total_self_sec,
519 total_self_sec,
520 total_percent,
520 total_percent,
521 sitestats))
521 sitestats))
522
522
523 # sort by total self sec
523 # sort by total self sec
524 functiondata.sort(reverse=True, key=lambda x: x[2])
524 functiondata.sort(reverse=True, key=lambda x: x[2])
525
525
526 for function in functiondata:
526 for function in functiondata:
527 if function[3] < 0.05:
527 if function[3] < 0.05:
528 continue
528 continue
529 print('%6.2f %9.2f %9.2f %s' % (function[3], # total percent
529 print('%6.2f %9.2f %9.2f %s' % (function[3], # total percent
530 function[1], # total cum sec
530 function[1], # total cum sec
531 function[2], # total self sec
531 function[2], # total self sec
532 function[0]), # file:function
532 function[0]), # file:function
533 file=fp)
533 file=fp)
534 function[4].sort(reverse=True, key=lambda i: i.selfseconds())
534 function[4].sort(reverse=True, key=lambda i: i.selfseconds())
535 for stat in function[4]:
535 for stat in function[4]:
536 # only show line numbers for significant locations (>1% time spent)
536 # only show line numbers for significant locations (>1% time spent)
537 if stat.selfpercent() > 1:
537 if stat.selfpercent() > 1:
538 source = stat.site.getsource(25)
538 source = stat.site.getsource(25)
539 stattuple = (stat.selfpercent(), stat.selfseconds(),
539 stattuple = (stat.selfpercent(), stat.selfseconds(),
540 stat.site.lineno, source)
540 stat.site.lineno, source)
541
541
542 print('%33.0f%% %6.2f line %s: %s' % (stattuple), file=fp)
542 print('%33.0f%% %6.2f line %s: %s' % (stattuple), file=fp)
543
543
544 def display_about_method(data, fp, function=None, **kwargs):
544 def display_about_method(data, fp, function=None, **kwargs):
545 if function is None:
545 if function is None:
546 raise Exception("Invalid function")
546 raise Exception("Invalid function")
547
547
548 filename = None
548 filename = None
549 if ':' in function:
549 if ':' in function:
550 filename, function = function.split(':')
550 filename, function = function.split(':')
551
551
552 relevant_samples = 0
552 relevant_samples = 0
553 parents = {}
553 parents = {}
554 children = {}
554 children = {}
555
555
556 for sample in data.samples:
556 for sample in data.samples:
557 for i, site in enumerate(sample.stack):
557 for i, site in enumerate(sample.stack):
558 if site.function == function and (not filename
558 if site.function == function and (not filename
559 or site.filename() == filename):
559 or site.filename() == filename):
560 relevant_samples += 1
560 relevant_samples += 1
561 if i != len(sample.stack) - 1:
561 if i != len(sample.stack) - 1:
562 parent = sample.stack[i + 1]
562 parent = sample.stack[i + 1]
563 if parent in parents:
563 if parent in parents:
564 parents[parent] = parents[parent] + 1
564 parents[parent] = parents[parent] + 1
565 else:
565 else:
566 parents[parent] = 1
566 parents[parent] = 1
567
567
568 if site in children:
568 if site in children:
569 children[site] = children[site] + 1
569 children[site] = children[site] + 1
570 else:
570 else:
571 children[site] = 1
571 children[site] = 1
572
572
573 parents = [(parent, count) for parent, count in parents.iteritems()]
573 parents = [(parent, count) for parent, count in parents.iteritems()]
574 parents.sort(reverse=True, key=lambda x: x[1])
574 parents.sort(reverse=True, key=lambda x: x[1])
575 for parent, count in parents:
575 for parent, count in parents:
576 print('%6.2f%% %s:%s line %s: %s' %
576 print('%6.2f%% %s:%s line %s: %s' %
577 (count / relevant_samples * 100, parent.filename(),
577 (count / relevant_samples * 100, parent.filename(),
578 parent.function, parent.lineno, parent.getsource(50)), file=fp)
578 parent.function, parent.lineno, parent.getsource(50)), file=fp)
579
579
580 stats = SiteStats.buildstats(data.samples)
580 stats = SiteStats.buildstats(data.samples)
581 stats = [s for s in stats
581 stats = [s for s in stats
582 if s.site.function == function and
582 if s.site.function == function and
583 (not filename or s.site.filename() == filename)]
583 (not filename or s.site.filename() == filename)]
584
584
585 total_cum_sec = 0
585 total_cum_sec = 0
586 total_self_sec = 0
586 total_self_sec = 0
587 total_self_percent = 0
587 total_self_percent = 0
588 total_cum_percent = 0
588 total_cum_percent = 0
589 for stat in stats:
589 for stat in stats:
590 total_cum_sec += stat.totalseconds()
590 total_cum_sec += stat.totalseconds()
591 total_self_sec += stat.selfseconds()
591 total_self_sec += stat.selfseconds()
592 total_self_percent += stat.selfpercent()
592 total_self_percent += stat.selfpercent()
593 total_cum_percent += stat.totalpercent()
593 total_cum_percent += stat.totalpercent()
594
594
595 print(
595 print(
596 '\n %s:%s Total: %0.2fs (%0.2f%%) Self: %0.2fs (%0.2f%%)\n' %
596 '\n %s:%s Total: %0.2fs (%0.2f%%) Self: %0.2fs (%0.2f%%)\n' %
597 (
597 (
598 filename or '___',
598 filename or '___',
599 function,
599 function,
600 total_cum_sec,
600 total_cum_sec,
601 total_cum_percent,
601 total_cum_percent,
602 total_self_sec,
602 total_self_sec,
603 total_self_percent
603 total_self_percent
604 ), file=fp)
604 ), file=fp)
605
605
606 children = [(child, count) for child, count in children.iteritems()]
606 children = [(child, count) for child, count in children.iteritems()]
607 children.sort(reverse=True, key=lambda x: x[1])
607 children.sort(reverse=True, key=lambda x: x[1])
608 for child, count in children:
608 for child, count in children:
609 print(' %6.2f%% line %s: %s' %
609 print(' %6.2f%% line %s: %s' %
610 (count / relevant_samples * 100, child.lineno,
610 (count / relevant_samples * 100, child.lineno,
611 child.getsource(50)), file=fp)
611 child.getsource(50)), file=fp)
612
612
613 def display_hotpath(data, fp, limit=0.05, **kwargs):
613 def display_hotpath(data, fp, limit=0.05, **kwargs):
614 class HotNode(object):
614 class HotNode(object):
615 def __init__(self, site):
615 def __init__(self, site):
616 self.site = site
616 self.site = site
617 self.count = 0
617 self.count = 0
618 self.children = {}
618 self.children = {}
619
619
620 def add(self, stack, time):
620 def add(self, stack, time):
621 self.count += time
621 self.count += time
622 site = stack[0]
622 site = stack[0]
623 child = self.children.get(site)
623 child = self.children.get(site)
624 if not child:
624 if not child:
625 child = HotNode(site)
625 child = HotNode(site)
626 self.children[site] = child
626 self.children[site] = child
627
627
628 if len(stack) > 1:
628 if len(stack) > 1:
629 i = 1
629 i = 1
630 # Skip boiler plate parts of the stack
630 # Skip boiler plate parts of the stack
631 while i < len(stack) and '%s:%s' % (stack[i].filename(), stack[i].function) in skips:
631 while i < len(stack) and '%s:%s' % (stack[i].filename(), stack[i].function) in skips:
632 i += 1
632 i += 1
633 if i < len(stack):
633 if i < len(stack):
634 child.add(stack[i:], time)
634 child.add(stack[i:], time)
635
635
636 root = HotNode(None)
636 root = HotNode(None)
637 lasttime = data.samples[0].time
637 lasttime = data.samples[0].time
638 for sample in data.samples:
638 for sample in data.samples:
639 root.add(sample.stack[::-1], sample.time - lasttime)
639 root.add(sample.stack[::-1], sample.time - lasttime)
640 lasttime = sample.time
640 lasttime = sample.time
641
641
642 def _write(node, depth, multiple_siblings):
642 def _write(node, depth, multiple_siblings):
643 site = node.site
643 site = node.site
644 visiblechildren = [c for c in node.children.itervalues()
644 visiblechildren = [c for c in node.children.itervalues()
645 if c.count >= (limit * root.count)]
645 if c.count >= (limit * root.count)]
646 if site:
646 if site:
647 indent = depth * 2 - 1
647 indent = depth * 2 - 1
648 filename = ''
648 filename = ''
649 function = ''
649 function = ''
650 if len(node.children) > 0:
650 if len(node.children) > 0:
651 childsite = list(node.children.itervalues())[0].site
651 childsite = list(node.children.itervalues())[0].site
652 filename = (childsite.filename() + ':').ljust(15)
652 filename = (childsite.filename() + ':').ljust(15)
653 function = childsite.function
653 function = childsite.function
654
654
655 # lots of string formatting
655 # lots of string formatting
656 listpattern = ''.ljust(indent) +\
656 listpattern = ''.ljust(indent) +\
657 ('\\' if multiple_siblings else '|') +\
657 ('\\' if multiple_siblings else '|') +\
658 ' %4.1f%% %s %s'
658 ' %4.1f%% %s %s'
659 liststring = listpattern % (node.count / root.count * 100,
659 liststring = listpattern % (node.count / root.count * 100,
660 filename, function)
660 filename, function)
661 codepattern = '%' + str(55 - len(liststring)) + 's %s: %s'
661 codepattern = '%' + str(55 - len(liststring)) + 's %s: %s'
662 codestring = codepattern % ('line', site.lineno, site.getsource(30))
662 codestring = codepattern % ('line', site.lineno, site.getsource(30))
663
663
664 finalstring = liststring + codestring
664 finalstring = liststring + codestring
665 childrensamples = sum([c.count for c in node.children.itervalues()])
665 childrensamples = sum([c.count for c in node.children.itervalues()])
666 # Make frames that performed more than 10% of the operation red
666 # Make frames that performed more than 10% of the operation red
667 if node.count - childrensamples > (0.1 * root.count):
667 if node.count - childrensamples > (0.1 * root.count):
668 finalstring = '\033[91m' + finalstring + '\033[0m'
668 finalstring = '\033[91m' + finalstring + '\033[0m'
669 # Make frames that didn't actually perform work dark grey
669 # Make frames that didn't actually perform work dark grey
670 elif node.count - childrensamples == 0:
670 elif node.count - childrensamples == 0:
671 finalstring = '\033[90m' + finalstring + '\033[0m'
671 finalstring = '\033[90m' + finalstring + '\033[0m'
672 print(finalstring, file=fp)
672 print(finalstring, file=fp)
673
673
674 newdepth = depth
674 newdepth = depth
675 if len(visiblechildren) > 1 or multiple_siblings:
675 if len(visiblechildren) > 1 or multiple_siblings:
676 newdepth += 1
676 newdepth += 1
677
677
678 visiblechildren.sort(reverse=True, key=lambda x: x.count)
678 visiblechildren.sort(reverse=True, key=lambda x: x.count)
679 for child in visiblechildren:
679 for child in visiblechildren:
680 _write(child, newdepth, len(visiblechildren) > 1)
680 _write(child, newdepth, len(visiblechildren) > 1)
681
681
682 if root.count > 0:
682 if root.count > 0:
683 _write(root, 0, False)
683 _write(root, 0, False)
684
684
685 def write_to_flame(data, fp, scriptpath=None, outputfile=None, **kwargs):
685 def write_to_flame(data, fp, scriptpath=None, outputfile=None, **kwargs):
686 if scriptpath is None:
686 if scriptpath is None:
687 scriptpath = encoding.environ['HOME'] + '/flamegraph.pl'
687 scriptpath = encoding.environ['HOME'] + '/flamegraph.pl'
688 if not os.path.exists(scriptpath):
688 if not os.path.exists(scriptpath):
689 print("error: missing %s" % scriptpath, file=fp)
689 print("error: missing %s" % scriptpath, file=fp)
690 print("get it here: https://github.com/brendangregg/FlameGraph",
690 print("get it here: https://github.com/brendangregg/FlameGraph",
691 file=fp)
691 file=fp)
692 return
692 return
693
693
694 fd, path = tempfile.mkstemp()
694 fd, path = tempfile.mkstemp()
695
695
696 file = open(path, "w+")
696 file = open(path, "w+")
697
697
698 lines = {}
698 lines = {}
699 for sample in data.samples:
699 for sample in data.samples:
700 sites = [s.function for s in sample.stack]
700 sites = [s.function for s in sample.stack]
701 sites.reverse()
701 sites.reverse()
702 line = ';'.join(sites)
702 line = ';'.join(sites)
703 if line in lines:
703 if line in lines:
704 lines[line] = lines[line] + 1
704 lines[line] = lines[line] + 1
705 else:
705 else:
706 lines[line] = 1
706 lines[line] = 1
707
707
708 for line, count in lines.iteritems():
708 for line, count in lines.iteritems():
709 file.write("%s %s\n" % (line, count))
709 file.write("%s %s\n" % (line, count))
710
710
711 file.close()
711 file.close()
712
712
713 if outputfile is None:
713 if outputfile is None:
714 outputfile = '~/flamegraph.svg'
714 outputfile = '~/flamegraph.svg'
715
715
716 os.system("perl ~/flamegraph.pl %s > %s" % (path, outputfile))
716 os.system("perl ~/flamegraph.pl %s > %s" % (path, outputfile))
717 print("Written to %s" % outputfile, file=fp)
717 print("Written to %s" % outputfile, file=fp)
718
718
719 _pathcache = {}
719 _pathcache = {}
720 def simplifypath(path):
720 def simplifypath(path):
721 '''Attempt to make the path to a Python module easier to read by
721 '''Attempt to make the path to a Python module easier to read by
722 removing whatever part of the Python search path it was found
722 removing whatever part of the Python search path it was found
723 on.'''
723 on.'''
724
724
725 if path in _pathcache:
725 if path in _pathcache:
726 return _pathcache[path]
726 return _pathcache[path]
727 hgpath = pycompat.fsencode(encoding.__file__).rsplit(os.sep, 2)[0]
727 hgpath = pycompat.fsencode(encoding.__file__).rsplit(os.sep, 2)[0]
728 for p in [hgpath] + sys.path:
728 for p in [hgpath] + sys.path:
729 prefix = p + os.sep
729 prefix = p + os.sep
730 if path.startswith(prefix):
730 if path.startswith(prefix):
731 path = path[len(prefix):]
731 path = path[len(prefix):]
732 break
732 break
733 _pathcache[path] = path
733 _pathcache[path] = path
734 return path
734 return path
735
735
736 def write_to_json(data, fp):
736 def write_to_json(data, fp):
737 samples = []
737 samples = []
738
738
739 for sample in data.samples:
739 for sample in data.samples:
740 stack = []
740 stack = []
741
741
742 for frame in sample.stack:
742 for frame in sample.stack:
743 stack.append((frame.path, frame.lineno, frame.function))
743 stack.append((frame.path, frame.lineno, frame.function))
744
744
745 samples.append((sample.time, stack))
745 samples.append((sample.time, stack))
746
746
747 print(json.dumps(samples), file=fp)
747 print(json.dumps(samples), file=fp)
748
748
749 def write_to_chrome(data, fp, minthreshold=0.005, maxthreshold=0.999):
749 def write_to_chrome(data, fp, minthreshold=0.005, maxthreshold=0.999):
750 samples = []
750 samples = []
751 laststack = collections.deque()
751 laststack = collections.deque()
752 lastseen = collections.deque()
752 lastseen = collections.deque()
753
753
754 # The Chrome tracing format allows us to use a compact stack
754 # The Chrome tracing format allows us to use a compact stack
755 # representation to save space. It's fiddly but worth it.
755 # representation to save space. It's fiddly but worth it.
756 # We maintain a bijection between stack and ID.
756 # We maintain a bijection between stack and ID.
757 stack2id = {}
757 stack2id = {}
758 id2stack = [] # will eventually be rendered
758 id2stack = [] # will eventually be rendered
759
759
760 def stackid(stack):
760 def stackid(stack):
761 if not stack:
761 if not stack:
762 return
762 return
763 if stack in stack2id:
763 if stack in stack2id:
764 return stack2id[stack]
764 return stack2id[stack]
765 parent = stackid(stack[1:])
765 parent = stackid(stack[1:])
766 myid = len(stack2id)
766 myid = len(stack2id)
767 stack2id[stack] = myid
767 stack2id[stack] = myid
768 id2stack.append(dict(category=stack[0][0], name='%s %s' % stack[0]))
768 id2stack.append(dict(category=stack[0][0], name='%s %s' % stack[0]))
769 if parent is not None:
769 if parent is not None:
770 id2stack[-1].update(parent=parent)
770 id2stack[-1].update(parent=parent)
771 return myid
771 return myid
772
772
773 def endswith(a, b):
773 def endswith(a, b):
774 return list(a)[-len(b):] == list(b)
774 return list(a)[-len(b):] == list(b)
775
775
776 # The sampling profiler can sample multiple times without
776 # The sampling profiler can sample multiple times without
777 # advancing the clock, potentially causing the Chrome trace viewer
777 # advancing the clock, potentially causing the Chrome trace viewer
778 # to render single-pixel columns that we cannot zoom in on. We
778 # to render single-pixel columns that we cannot zoom in on. We
779 # work around this by pretending that zero-duration samples are a
779 # work around this by pretending that zero-duration samples are a
780 # millisecond in length.
780 # millisecond in length.
781
781
782 clamp = 0.001
782 clamp = 0.001
783
783
784 # We provide knobs that by default attempt to filter out stack
784 # We provide knobs that by default attempt to filter out stack
785 # frames that are too noisy:
785 # frames that are too noisy:
786 #
786 #
787 # * A few take almost all execution time. These are usually boring
787 # * A few take almost all execution time. These are usually boring
788 # setup functions, giving a stack that is deep but uninformative.
788 # setup functions, giving a stack that is deep but uninformative.
789 #
789 #
790 # * Numerous samples take almost no time, but introduce lots of
790 # * Numerous samples take almost no time, but introduce lots of
791 # noisy, oft-deep "spines" into a rendered profile.
791 # noisy, oft-deep "spines" into a rendered profile.
792
792
793 blacklist = set()
793 blacklist = set()
794 totaltime = data.samples[-1].time - data.samples[0].time
794 totaltime = data.samples[-1].time - data.samples[0].time
795 minthreshold = totaltime * minthreshold
795 minthreshold = totaltime * minthreshold
796 maxthreshold = max(totaltime * maxthreshold, clamp)
796 maxthreshold = max(totaltime * maxthreshold, clamp)
797
797
798 def poplast():
798 def poplast():
799 oldsid = stackid(tuple(laststack))
799 oldsid = stackid(tuple(laststack))
800 oldcat, oldfunc = laststack.popleft()
800 oldcat, oldfunc = laststack.popleft()
801 oldtime, oldidx = lastseen.popleft()
801 oldtime, oldidx = lastseen.popleft()
802 duration = sample.time - oldtime
802 duration = sample.time - oldtime
803 if minthreshold <= duration <= maxthreshold:
803 if minthreshold <= duration <= maxthreshold:
804 # ensure no zero-duration events
804 # ensure no zero-duration events
805 sampletime = max(oldtime + clamp, sample.time)
805 sampletime = max(oldtime + clamp, sample.time)
806 samples.append(dict(ph='E', name=oldfunc, cat=oldcat, sf=oldsid,
806 samples.append(dict(ph='E', name=oldfunc, cat=oldcat, sf=oldsid,
807 ts=sampletime*1e6, pid=0))
807 ts=sampletime*1e6, pid=0))
808 else:
808 else:
809 blacklist.add(oldidx)
809 blacklist.add(oldidx)
810
810
811 # Much fiddling to synthesize correctly(ish) nested begin/end
811 # Much fiddling to synthesize correctly(ish) nested begin/end
812 # events given only stack snapshots.
812 # events given only stack snapshots.
813
813
814 for sample in data.samples:
814 for sample in data.samples:
815 tos = sample.stack[0]
815 tos = sample.stack[0]
816 name = tos.function
816 name = tos.function
817 path = simplifypath(tos.path)
817 path = simplifypath(tos.path)
818 category = '%s:%d' % (path, tos.lineno)
818 category = '%s:%d' % (path, tos.lineno)
819 stack = tuple((('%s:%d' % (simplifypath(frame.path), frame.lineno),
819 stack = tuple((('%s:%d' % (simplifypath(frame.path), frame.lineno),
820 frame.function) for frame in sample.stack))
820 frame.function) for frame in sample.stack))
821 qstack = collections.deque(stack)
821 qstack = collections.deque(stack)
822 if laststack == qstack:
822 if laststack == qstack:
823 continue
823 continue
824 while laststack and qstack and laststack[-1] == qstack[-1]:
824 while laststack and qstack and laststack[-1] == qstack[-1]:
825 laststack.pop()
825 laststack.pop()
826 qstack.pop()
826 qstack.pop()
827 while laststack:
827 while laststack:
828 poplast()
828 poplast()
829 for f in reversed(qstack):
829 for f in reversed(qstack):
830 lastseen.appendleft((sample.time, len(samples)))
830 lastseen.appendleft((sample.time, len(samples)))
831 laststack.appendleft(f)
831 laststack.appendleft(f)
832 path, name = f
832 path, name = f
833 sid = stackid(tuple(laststack))
833 sid = stackid(tuple(laststack))
834 samples.append(dict(ph='B', name=name, cat=path, ts=sample.time*1e6,
834 samples.append(dict(ph='B', name=name, cat=path, ts=sample.time*1e6,
835 sf=sid, pid=0))
835 sf=sid, pid=0))
836 laststack = collections.deque(stack)
836 laststack = collections.deque(stack)
837 while laststack:
837 while laststack:
838 poplast()
838 poplast()
839 events = [s[1] for s in enumerate(samples) if s[0] not in blacklist]
839 events = [s[1] for s in enumerate(samples) if s[0] not in blacklist]
840 frames = collections.OrderedDict((str(k), v)
840 frames = collections.OrderedDict((str(k), v)
841 for (k,v) in enumerate(id2stack))
841 for (k,v) in enumerate(id2stack))
842 json.dump(dict(traceEvents=events, stackFrames=frames), fp, indent=1)
842 json.dump(dict(traceEvents=events, stackFrames=frames), fp, indent=1)
843 fp.write('\n')
843 fp.write('\n')
844
844
845 def printusage():
845 def printusage():
846 print("""
846 print("""
847 The statprof command line allows you to inspect the last profile's results in
847 The statprof command line allows you to inspect the last profile's results in
848 the following forms:
848 the following forms:
849
849
850 usage:
850 usage:
851 hotpath [-l --limit percent]
851 hotpath [-l --limit percent]
852 Shows a graph of calls with the percent of time each takes.
852 Shows a graph of calls with the percent of time each takes.
853 Red calls take over 10%% of the total time themselves.
853 Red calls take over 10%% of the total time themselves.
854 lines
854 lines
855 Shows the actual sampled lines.
855 Shows the actual sampled lines.
856 functions
856 functions
857 Shows the samples grouped by function.
857 Shows the samples grouped by function.
858 function [filename:]functionname
858 function [filename:]functionname
859 Shows the callers and callees of a particular function.
859 Shows the callers and callees of a particular function.
860 flame [-s --script-path] [-o --output-file path]
860 flame [-s --script-path] [-o --output-file path]
861 Writes out a flamegraph to output-file (defaults to ~/flamegraph.svg)
861 Writes out a flamegraph to output-file (defaults to ~/flamegraph.svg)
862 Requires that ~/flamegraph.pl exist.
862 Requires that ~/flamegraph.pl exist.
863 (Specify alternate script path with --script-path.)""")
863 (Specify alternate script path with --script-path.)""")
864
864
865 def main(argv=None):
865 def main(argv=None):
866 if argv is None:
866 if argv is None:
867 argv = sys.argv
867 argv = sys.argv
868
868
869 if len(argv) == 1:
869 if len(argv) == 1:
870 printusage()
870 printusage()
871 return 0
871 return 0
872
872
873 displayargs = {}
873 displayargs = {}
874
874
875 optstart = 2
875 optstart = 2
876 displayargs['function'] = None
876 displayargs['function'] = None
877 if argv[1] == 'hotpath':
877 if argv[1] == 'hotpath':
878 displayargs['format'] = DisplayFormats.Hotpath
878 displayargs['format'] = DisplayFormats.Hotpath
879 elif argv[1] == 'lines':
879 elif argv[1] == 'lines':
880 displayargs['format'] = DisplayFormats.ByLine
880 displayargs['format'] = DisplayFormats.ByLine
881 elif argv[1] == 'functions':
881 elif argv[1] == 'functions':
882 displayargs['format'] = DisplayFormats.ByMethod
882 displayargs['format'] = DisplayFormats.ByMethod
883 elif argv[1] == 'function':
883 elif argv[1] == 'function':
884 displayargs['format'] = DisplayFormats.AboutMethod
884 displayargs['format'] = DisplayFormats.AboutMethod
885 displayargs['function'] = argv[2]
885 displayargs['function'] = argv[2]
886 optstart = 3
886 optstart = 3
887 elif argv[1] == 'flame':
887 elif argv[1] == 'flame':
888 displayargs['format'] = DisplayFormats.FlameGraph
888 displayargs['format'] = DisplayFormats.FlameGraph
889 else:
889 else:
890 printusage()
890 printusage()
891 return 0
891 return 0
892
892
893 # process options
893 # process options
894 try:
894 try:
895 opts, args = pycompat.getoptb(sys.argv[optstart:], "hl:f:o:p:",
895 opts, args = pycompat.getoptb(sys.argv[optstart:], "hl:f:o:p:",
896 ["help", "limit=", "file=", "output-file=", "script-path="])
896 ["help", "limit=", "file=", "output-file=", "script-path="])
897 except getopt.error as msg:
897 except getopt.error as msg:
898 print(msg)
898 print(msg)
899 printusage()
899 printusage()
900 return 2
900 return 2
901
901
902 displayargs['limit'] = 0.05
902 displayargs['limit'] = 0.05
903 path = None
903 path = None
904 for o, value in opts:
904 for o, value in opts:
905 if o in ("-l", "--limit"):
905 if o in ("-l", "--limit"):
906 displayargs['limit'] = float(value)
906 displayargs['limit'] = float(value)
907 elif o in ("-f", "--file"):
907 elif o in ("-f", "--file"):
908 path = value
908 path = value
909 elif o in ("-o", "--output-file"):
909 elif o in ("-o", "--output-file"):
910 displayargs['outputfile'] = value
910 displayargs['outputfile'] = value
911 elif o in ("-p", "--script-path"):
911 elif o in ("-p", "--script-path"):
912 displayargs['scriptpath'] = value
912 displayargs['scriptpath'] = value
913 elif o in ("-h", "help"):
913 elif o in ("-h", "help"):
914 printusage()
914 printusage()
915 return 0
915 return 0
916 else:
916 else:
917 assert False, "unhandled option %s" % o
917 assert False, "unhandled option %s" % o
918
918
919 if not path:
919 if not path:
920 print('must specify --file to load')
920 print('must specify --file to load')
921 return 1
921 return 1
922
922
923 load_data(path=path)
923 load_data(path=path)
924
924
925 display(**displayargs)
925 display(**pycompat.strkwargs(displayargs))
926
926
927 return 0
927 return 0
928
928
929 if __name__ == "__main__":
929 if __name__ == "__main__":
930 sys.exit(main())
930 sys.exit(main())
General Comments 0
You need to be logged in to leave comments. Login now