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