##// END OF EJS Templates
statprof: clarify by naming tuple members while enumerate()'ing...
Martin von Zweigbergk -
r43101:3f81d58a default
parent child Browse files
Show More
@@ -1,972 +1,973 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 threading
115 import threading
116 import time
116 import time
117
117
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__ = ['start', 'stop', 'reset', 'display', 'profile']
126 __all__ = ['start', 'stop', 'reset', 'display', 'profile']
127
127
128 skips = {
128 skips = {
129 r"util.py:check",
129 r"util.py:check",
130 r"extensions.py:closure",
130 r"extensions.py:closure",
131 r"color.py:colorcmd",
131 r"color.py:colorcmd",
132 r"dispatch.py:checkargs",
132 r"dispatch.py:checkargs",
133 r"dispatch.py:<lambda>",
133 r"dispatch.py:<lambda>",
134 r"dispatch.py:_runcatch",
134 r"dispatch.py:_runcatch",
135 r"dispatch.py:_dispatch",
135 r"dispatch.py:_dispatch",
136 r"dispatch.py:_runcommand",
136 r"dispatch.py:_runcommand",
137 r"pager.py:pagecmd",
137 r"pager.py:pagecmd",
138 r"dispatch.py:run",
138 r"dispatch.py:run",
139 r"dispatch.py:dispatch",
139 r"dispatch.py:dispatch",
140 r"dispatch.py:runcommand",
140 r"dispatch.py:runcommand",
141 r"hg.py:<module>",
141 r"hg.py:<module>",
142 r"evolve.py:warnobserrors",
142 r"evolve.py:warnobserrors",
143 }
143 }
144
144
145 ###########################################################################
145 ###########################################################################
146 ## Utils
146 ## Utils
147
147
148 def clock():
148 def clock():
149 times = os.times()
149 times = os.times()
150 return (times[0] + times[1], times[4])
150 return (times[0] + times[1], times[4])
151
151
152
152
153 ###########################################################################
153 ###########################################################################
154 ## Collection data structures
154 ## Collection data structures
155
155
156 class ProfileState(object):
156 class ProfileState(object):
157 def __init__(self, frequency=None):
157 def __init__(self, frequency=None):
158 self.reset(frequency)
158 self.reset(frequency)
159 self.track = 'cpu'
159 self.track = 'cpu'
160
160
161 def reset(self, frequency=None):
161 def reset(self, frequency=None):
162 # total so far
162 # total so far
163 self.accumulated_time = (0.0, 0.0)
163 self.accumulated_time = (0.0, 0.0)
164 # start_time when timer is active
164 # start_time when timer is active
165 self.last_start_time = None
165 self.last_start_time = None
166 # a float
166 # a float
167 if frequency:
167 if frequency:
168 self.sample_interval = 1.0 / frequency
168 self.sample_interval = 1.0 / frequency
169 elif not hasattr(self, 'sample_interval'):
169 elif not hasattr(self, 'sample_interval'):
170 # default to 1000 Hz
170 # default to 1000 Hz
171 self.sample_interval = 1.0 / 1000.0
171 self.sample_interval = 1.0 / 1000.0
172 else:
172 else:
173 # leave the frequency as it was
173 # leave the frequency as it was
174 pass
174 pass
175 self.remaining_prof_time = None
175 self.remaining_prof_time = None
176 # for user start/stop nesting
176 # for user start/stop nesting
177 self.profile_level = 0
177 self.profile_level = 0
178
178
179 self.samples = []
179 self.samples = []
180
180
181 def accumulate_time(self, stop_time):
181 def accumulate_time(self, stop_time):
182 increment = (
182 increment = (
183 stop_time[0] - self.last_start_time[0],
183 stop_time[0] - self.last_start_time[0],
184 stop_time[1] - self.last_start_time[1],
184 stop_time[1] - self.last_start_time[1],
185 )
185 )
186 self.accumulated_time = (
186 self.accumulated_time = (
187 self.accumulated_time[0] + increment[0],
187 self.accumulated_time[0] + increment[0],
188 self.accumulated_time[1] + increment[1],
188 self.accumulated_time[1] + increment[1],
189 )
189 )
190
190
191 def seconds_per_sample(self):
191 def seconds_per_sample(self):
192 return self.accumulated_time[self.timeidx] / len(self.samples)
192 return self.accumulated_time[self.timeidx] / len(self.samples)
193
193
194 @property
194 @property
195 def timeidx(self):
195 def timeidx(self):
196 if self.track == 'real':
196 if self.track == 'real':
197 return 1
197 return 1
198 return 0
198 return 0
199
199
200 state = ProfileState()
200 state = ProfileState()
201
201
202
202
203 class CodeSite(object):
203 class CodeSite(object):
204 cache = {}
204 cache = {}
205
205
206 __slots__ = (r'path', r'lineno', r'function', r'source')
206 __slots__ = (r'path', r'lineno', r'function', r'source')
207
207
208 def __init__(self, path, lineno, function):
208 def __init__(self, path, lineno, function):
209 assert isinstance(path, bytes)
209 assert isinstance(path, bytes)
210 self.path = path
210 self.path = path
211 self.lineno = lineno
211 self.lineno = lineno
212 assert isinstance(function, bytes)
212 assert isinstance(function, bytes)
213 self.function = function
213 self.function = function
214 self.source = None
214 self.source = None
215
215
216 def __eq__(self, other):
216 def __eq__(self, other):
217 try:
217 try:
218 return (self.lineno == other.lineno and
218 return (self.lineno == other.lineno and
219 self.path == other.path)
219 self.path == other.path)
220 except:
220 except:
221 return False
221 return False
222
222
223 def __hash__(self):
223 def __hash__(self):
224 return hash((self.lineno, self.path))
224 return hash((self.lineno, self.path))
225
225
226 @classmethod
226 @classmethod
227 def get(cls, path, lineno, function):
227 def get(cls, path, lineno, function):
228 k = (path, lineno)
228 k = (path, lineno)
229 try:
229 try:
230 return cls.cache[k]
230 return cls.cache[k]
231 except KeyError:
231 except KeyError:
232 v = cls(path, lineno, function)
232 v = cls(path, lineno, function)
233 cls.cache[k] = v
233 cls.cache[k] = v
234 return v
234 return v
235
235
236 def getsource(self, length):
236 def getsource(self, length):
237 if self.source is None:
237 if self.source is None:
238 lineno = self.lineno - 1
238 lineno = self.lineno - 1
239 fp = None
239 fp = None
240 try:
240 try:
241 fp = open(self.path, 'rb')
241 fp = open(self.path, 'rb')
242 for i, line in enumerate(fp):
242 for i, line in enumerate(fp):
243 if i == lineno:
243 if i == lineno:
244 self.source = line.strip()
244 self.source = line.strip()
245 break
245 break
246 except:
246 except:
247 pass
247 pass
248 finally:
248 finally:
249 if fp:
249 if fp:
250 fp.close()
250 fp.close()
251 if self.source is None:
251 if self.source is None:
252 self.source = ''
252 self.source = ''
253
253
254 source = self.source
254 source = self.source
255 if len(source) > length:
255 if len(source) > length:
256 source = source[:(length - 3)] + "..."
256 source = source[:(length - 3)] + "..."
257 return source
257 return source
258
258
259 def filename(self):
259 def filename(self):
260 return os.path.basename(self.path)
260 return os.path.basename(self.path)
261
261
262 def skipname(self):
262 def skipname(self):
263 return r'%s:%s' % (self.filename(), self.function)
263 return r'%s:%s' % (self.filename(), self.function)
264
264
265 class Sample(object):
265 class Sample(object):
266 __slots__ = (r'stack', r'time')
266 __slots__ = (r'stack', r'time')
267
267
268 def __init__(self, stack, time):
268 def __init__(self, stack, time):
269 self.stack = stack
269 self.stack = stack
270 self.time = time
270 self.time = time
271
271
272 @classmethod
272 @classmethod
273 def from_frame(cls, frame, time):
273 def from_frame(cls, frame, time):
274 stack = []
274 stack = []
275
275
276 while frame:
276 while frame:
277 stack.append(CodeSite.get(
277 stack.append(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 frame = frame.f_back
281 frame = frame.f_back
282
282
283 return Sample(stack, time)
283 return Sample(stack, time)
284
284
285 ###########################################################################
285 ###########################################################################
286 ## SIGPROF handler
286 ## SIGPROF handler
287
287
288 def profile_signal_handler(signum, frame):
288 def profile_signal_handler(signum, frame):
289 if state.profile_level > 0:
289 if state.profile_level > 0:
290 now = clock()
290 now = clock()
291 state.accumulate_time(now)
291 state.accumulate_time(now)
292
292
293 timestamp = state.accumulated_time[state.timeidx]
293 timestamp = state.accumulated_time[state.timeidx]
294 state.samples.append(Sample.from_frame(frame, timestamp))
294 state.samples.append(Sample.from_frame(frame, timestamp))
295
295
296 signal.setitimer(signal.ITIMER_PROF,
296 signal.setitimer(signal.ITIMER_PROF,
297 state.sample_interval, 0.0)
297 state.sample_interval, 0.0)
298 state.last_start_time = now
298 state.last_start_time = now
299
299
300 stopthread = threading.Event()
300 stopthread = threading.Event()
301 def samplerthread(tid):
301 def samplerthread(tid):
302 while not stopthread.is_set():
302 while not stopthread.is_set():
303 now = clock()
303 now = clock()
304 state.accumulate_time(now)
304 state.accumulate_time(now)
305
305
306 frame = sys._current_frames()[tid]
306 frame = sys._current_frames()[tid]
307
307
308 timestamp = state.accumulated_time[state.timeidx]
308 timestamp = state.accumulated_time[state.timeidx]
309 state.samples.append(Sample.from_frame(frame, timestamp))
309 state.samples.append(Sample.from_frame(frame, timestamp))
310
310
311 state.last_start_time = now
311 state.last_start_time = now
312 time.sleep(state.sample_interval)
312 time.sleep(state.sample_interval)
313
313
314 stopthread.clear()
314 stopthread.clear()
315
315
316 ###########################################################################
316 ###########################################################################
317 ## Profiling API
317 ## Profiling API
318
318
319 def is_active():
319 def is_active():
320 return state.profile_level > 0
320 return state.profile_level > 0
321
321
322 lastmechanism = None
322 lastmechanism = None
323 def start(mechanism='thread', track='cpu'):
323 def start(mechanism='thread', track='cpu'):
324 '''Install the profiling signal handler, and start profiling.'''
324 '''Install the profiling signal handler, and start profiling.'''
325 state.track = track # note: nesting different mode won't work
325 state.track = track # note: nesting different mode won't work
326 state.profile_level += 1
326 state.profile_level += 1
327 if state.profile_level == 1:
327 if state.profile_level == 1:
328 state.last_start_time = clock()
328 state.last_start_time = clock()
329 rpt = state.remaining_prof_time
329 rpt = state.remaining_prof_time
330 state.remaining_prof_time = None
330 state.remaining_prof_time = None
331
331
332 global lastmechanism
332 global lastmechanism
333 lastmechanism = mechanism
333 lastmechanism = mechanism
334
334
335 if mechanism == 'signal':
335 if mechanism == 'signal':
336 signal.signal(signal.SIGPROF, profile_signal_handler)
336 signal.signal(signal.SIGPROF, profile_signal_handler)
337 signal.setitimer(signal.ITIMER_PROF,
337 signal.setitimer(signal.ITIMER_PROF,
338 rpt or state.sample_interval, 0.0)
338 rpt or state.sample_interval, 0.0)
339 elif mechanism == 'thread':
339 elif mechanism == 'thread':
340 frame = inspect.currentframe()
340 frame = inspect.currentframe()
341 tid = [k for k, f in sys._current_frames().items() if f == frame][0]
341 tid = [k for k, f in sys._current_frames().items() if f == frame][0]
342 state.thread = threading.Thread(target=samplerthread,
342 state.thread = threading.Thread(target=samplerthread,
343 args=(tid,), name="samplerthread")
343 args=(tid,), name="samplerthread")
344 state.thread.start()
344 state.thread.start()
345
345
346 def stop():
346 def stop():
347 '''Stop profiling, and uninstall the profiling signal handler.'''
347 '''Stop profiling, and uninstall the profiling signal handler.'''
348 state.profile_level -= 1
348 state.profile_level -= 1
349 if state.profile_level == 0:
349 if state.profile_level == 0:
350 if lastmechanism == 'signal':
350 if lastmechanism == 'signal':
351 rpt = signal.setitimer(signal.ITIMER_PROF, 0.0, 0.0)
351 rpt = signal.setitimer(signal.ITIMER_PROF, 0.0, 0.0)
352 signal.signal(signal.SIGPROF, signal.SIG_IGN)
352 signal.signal(signal.SIGPROF, signal.SIG_IGN)
353 state.remaining_prof_time = rpt[0]
353 state.remaining_prof_time = rpt[0]
354 elif lastmechanism == 'thread':
354 elif lastmechanism == 'thread':
355 stopthread.set()
355 stopthread.set()
356 state.thread.join()
356 state.thread.join()
357
357
358 state.accumulate_time(clock())
358 state.accumulate_time(clock())
359 state.last_start_time = None
359 state.last_start_time = None
360 statprofpath = encoding.environ.get('STATPROF_DEST')
360 statprofpath = encoding.environ.get('STATPROF_DEST')
361 if statprofpath:
361 if statprofpath:
362 save_data(statprofpath)
362 save_data(statprofpath)
363
363
364 return state
364 return state
365
365
366 def save_data(path):
366 def save_data(path):
367 with open(path, 'w+') as file:
367 with open(path, 'w+') as file:
368 file.write("%f %f\n" % state.accumulated_time)
368 file.write("%f %f\n" % state.accumulated_time)
369 for sample in state.samples:
369 for sample in state.samples:
370 time = sample.time
370 time = sample.time
371 stack = sample.stack
371 stack = sample.stack
372 sites = ['\1'.join([s.path, b'%d' % s.lineno, s.function])
372 sites = ['\1'.join([s.path, b'%d' % s.lineno, s.function])
373 for s in stack]
373 for s in stack]
374 file.write("%d\0%s\n" % (time, '\0'.join(sites)))
374 file.write("%d\0%s\n" % (time, '\0'.join(sites)))
375
375
376 def load_data(path):
376 def load_data(path):
377 lines = open(path, 'rb').read().splitlines()
377 lines = open(path, 'rb').read().splitlines()
378
378
379 state.accumulated_time = [float(value) for value in lines[0].split()]
379 state.accumulated_time = [float(value) for value in lines[0].split()]
380 state.samples = []
380 state.samples = []
381 for line in lines[1:]:
381 for line in lines[1:]:
382 parts = line.split('\0')
382 parts = line.split('\0')
383 time = float(parts[0])
383 time = float(parts[0])
384 rawsites = parts[1:]
384 rawsites = parts[1:]
385 sites = []
385 sites = []
386 for rawsite in rawsites:
386 for rawsite in rawsites:
387 siteparts = rawsite.split('\1')
387 siteparts = rawsite.split('\1')
388 sites.append(CodeSite.get(siteparts[0], int(siteparts[1]),
388 sites.append(CodeSite.get(siteparts[0], int(siteparts[1]),
389 siteparts[2]))
389 siteparts[2]))
390
390
391 state.samples.append(Sample(sites, time))
391 state.samples.append(Sample(sites, time))
392
392
393
393
394
394
395 def reset(frequency=None):
395 def reset(frequency=None):
396 '''Clear out the state of the profiler. Do not call while the
396 '''Clear out the state of the profiler. Do not call while the
397 profiler is running.
397 profiler is running.
398
398
399 The optional frequency argument specifies the number of samples to
399 The optional frequency argument specifies the number of samples to
400 collect per second.'''
400 collect per second.'''
401 assert state.profile_level == 0, "Can't reset() while statprof is running"
401 assert state.profile_level == 0, "Can't reset() while statprof is running"
402 CodeSite.cache.clear()
402 CodeSite.cache.clear()
403 state.reset(frequency)
403 state.reset(frequency)
404
404
405
405
406 @contextmanager
406 @contextmanager
407 def profile():
407 def profile():
408 start()
408 start()
409 try:
409 try:
410 yield
410 yield
411 finally:
411 finally:
412 stop()
412 stop()
413 display()
413 display()
414
414
415
415
416 ###########################################################################
416 ###########################################################################
417 ## Reporting API
417 ## Reporting API
418
418
419 class SiteStats(object):
419 class SiteStats(object):
420 def __init__(self, site):
420 def __init__(self, site):
421 self.site = site
421 self.site = site
422 self.selfcount = 0
422 self.selfcount = 0
423 self.totalcount = 0
423 self.totalcount = 0
424
424
425 def addself(self):
425 def addself(self):
426 self.selfcount += 1
426 self.selfcount += 1
427
427
428 def addtotal(self):
428 def addtotal(self):
429 self.totalcount += 1
429 self.totalcount += 1
430
430
431 def selfpercent(self):
431 def selfpercent(self):
432 return self.selfcount / len(state.samples) * 100
432 return self.selfcount / len(state.samples) * 100
433
433
434 def totalpercent(self):
434 def totalpercent(self):
435 return self.totalcount / len(state.samples) * 100
435 return self.totalcount / len(state.samples) * 100
436
436
437 def selfseconds(self):
437 def selfseconds(self):
438 return self.selfcount * state.seconds_per_sample()
438 return self.selfcount * state.seconds_per_sample()
439
439
440 def totalseconds(self):
440 def totalseconds(self):
441 return self.totalcount * state.seconds_per_sample()
441 return self.totalcount * state.seconds_per_sample()
442
442
443 @classmethod
443 @classmethod
444 def buildstats(cls, samples):
444 def buildstats(cls, samples):
445 stats = {}
445 stats = {}
446
446
447 for sample in samples:
447 for sample in samples:
448 for i, site in enumerate(sample.stack):
448 for i, site in enumerate(sample.stack):
449 sitestat = stats.get(site)
449 sitestat = stats.get(site)
450 if not sitestat:
450 if not sitestat:
451 sitestat = SiteStats(site)
451 sitestat = SiteStats(site)
452 stats[site] = sitestat
452 stats[site] = sitestat
453
453
454 sitestat.addtotal()
454 sitestat.addtotal()
455
455
456 if i == 0:
456 if i == 0:
457 sitestat.addself()
457 sitestat.addself()
458
458
459 return [s for s in stats.itervalues()]
459 return [s for s in stats.itervalues()]
460
460
461 class DisplayFormats:
461 class DisplayFormats:
462 ByLine = 0
462 ByLine = 0
463 ByMethod = 1
463 ByMethod = 1
464 AboutMethod = 2
464 AboutMethod = 2
465 Hotpath = 3
465 Hotpath = 3
466 FlameGraph = 4
466 FlameGraph = 4
467 Json = 5
467 Json = 5
468 Chrome = 6
468 Chrome = 6
469
469
470 def display(fp=None, format=3, data=None, **kwargs):
470 def display(fp=None, format=3, data=None, **kwargs):
471 '''Print statistics, either to stdout or the given file object.'''
471 '''Print statistics, either to stdout or the given file object.'''
472 if data is None:
472 if data is None:
473 data = state
473 data = state
474
474
475 if fp is None:
475 if fp is None:
476 import sys
476 import sys
477 fp = sys.stdout
477 fp = sys.stdout
478 if len(data.samples) == 0:
478 if len(data.samples) == 0:
479 fp.write(b'No samples recorded.\n')
479 fp.write(b'No samples recorded.\n')
480 return
480 return
481
481
482 if format == DisplayFormats.ByLine:
482 if format == DisplayFormats.ByLine:
483 display_by_line(data, fp)
483 display_by_line(data, fp)
484 elif format == DisplayFormats.ByMethod:
484 elif format == DisplayFormats.ByMethod:
485 display_by_method(data, fp)
485 display_by_method(data, fp)
486 elif format == DisplayFormats.AboutMethod:
486 elif format == DisplayFormats.AboutMethod:
487 display_about_method(data, fp, **kwargs)
487 display_about_method(data, fp, **kwargs)
488 elif format == DisplayFormats.Hotpath:
488 elif format == DisplayFormats.Hotpath:
489 display_hotpath(data, fp, **kwargs)
489 display_hotpath(data, fp, **kwargs)
490 elif format == DisplayFormats.FlameGraph:
490 elif format == DisplayFormats.FlameGraph:
491 write_to_flame(data, fp, **kwargs)
491 write_to_flame(data, fp, **kwargs)
492 elif format == DisplayFormats.Json:
492 elif format == DisplayFormats.Json:
493 write_to_json(data, fp)
493 write_to_json(data, fp)
494 elif format == DisplayFormats.Chrome:
494 elif format == DisplayFormats.Chrome:
495 write_to_chrome(data, fp, **kwargs)
495 write_to_chrome(data, fp, **kwargs)
496 else:
496 else:
497 raise Exception("Invalid display format")
497 raise Exception("Invalid display format")
498
498
499 if format not in (DisplayFormats.Json, DisplayFormats.Chrome):
499 if format not in (DisplayFormats.Json, DisplayFormats.Chrome):
500 fp.write(b'---\n')
500 fp.write(b'---\n')
501 fp.write(b'Sample count: %d\n' % len(data.samples))
501 fp.write(b'Sample count: %d\n' % len(data.samples))
502 fp.write(b'Total time: %f seconds (%f wall)\n' % data.accumulated_time)
502 fp.write(b'Total time: %f seconds (%f wall)\n' % data.accumulated_time)
503
503
504 def display_by_line(data, fp):
504 def display_by_line(data, fp):
505 '''Print the profiler data with each sample line represented
505 '''Print the profiler data with each sample line represented
506 as one row in a table. Sorted by self-time per line.'''
506 as one row in a table. Sorted by self-time per line.'''
507 stats = SiteStats.buildstats(data.samples)
507 stats = SiteStats.buildstats(data.samples)
508 stats.sort(reverse=True, key=lambda x: x.selfseconds())
508 stats.sort(reverse=True, key=lambda x: x.selfseconds())
509
509
510 fp.write(b'%5.5s %10.10s %7.7s %-8.8s\n' % (
510 fp.write(b'%5.5s %10.10s %7.7s %-8.8s\n' % (
511 b'% ', b'cumulative', b'self', b''))
511 b'% ', b'cumulative', b'self', b''))
512 fp.write(b'%5.5s %9.9s %8.8s %-8.8s\n' % (
512 fp.write(b'%5.5s %9.9s %8.8s %-8.8s\n' % (
513 b"time", b"seconds", b"seconds", b"name"))
513 b"time", b"seconds", b"seconds", b"name"))
514
514
515 for stat in stats:
515 for stat in stats:
516 site = stat.site
516 site = stat.site
517 sitelabel = '%s:%d:%s' % (site.filename(),
517 sitelabel = '%s:%d:%s' % (site.filename(),
518 site.lineno,
518 site.lineno,
519 site.function)
519 site.function)
520 fp.write(b'%6.2f %9.2f %9.2f %s\n' % (
520 fp.write(b'%6.2f %9.2f %9.2f %s\n' % (
521 stat.selfpercent(), stat.totalseconds(),
521 stat.selfpercent(), stat.totalseconds(),
522 stat.selfseconds(), sitelabel))
522 stat.selfseconds(), sitelabel))
523
523
524 def display_by_method(data, fp):
524 def display_by_method(data, fp):
525 '''Print the profiler data with each sample function represented
525 '''Print the profiler data with each sample function represented
526 as one row in a table. Important lines within that function are
526 as one row in a table. Important lines within that function are
527 output as nested rows. Sorted by self-time per line.'''
527 output as nested rows. Sorted by self-time per line.'''
528 fp.write(b'%5.5s %10.10s %7.7s %-8.8s\n' %
528 fp.write(b'%5.5s %10.10s %7.7s %-8.8s\n' %
529 ('% ', 'cumulative', 'self', ''))
529 ('% ', 'cumulative', 'self', ''))
530 fp.write(b'%5.5s %9.9s %8.8s %-8.8s\n' %
530 fp.write(b'%5.5s %9.9s %8.8s %-8.8s\n' %
531 ("time", "seconds", "seconds", "name"))
531 ("time", "seconds", "seconds", "name"))
532
532
533 stats = SiteStats.buildstats(data.samples)
533 stats = SiteStats.buildstats(data.samples)
534
534
535 grouped = defaultdict(list)
535 grouped = defaultdict(list)
536 for stat in stats:
536 for stat in stats:
537 grouped[stat.site.filename() + b":" + stat.site.function].append(stat)
537 grouped[stat.site.filename() + b":" + stat.site.function].append(stat)
538
538
539 # compute sums for each function
539 # compute sums for each function
540 functiondata = []
540 functiondata = []
541 for fname, sitestats in grouped.iteritems():
541 for fname, sitestats in grouped.iteritems():
542 total_cum_sec = 0
542 total_cum_sec = 0
543 total_self_sec = 0
543 total_self_sec = 0
544 total_percent = 0
544 total_percent = 0
545 for stat in sitestats:
545 for stat in sitestats:
546 total_cum_sec += stat.totalseconds()
546 total_cum_sec += stat.totalseconds()
547 total_self_sec += stat.selfseconds()
547 total_self_sec += stat.selfseconds()
548 total_percent += stat.selfpercent()
548 total_percent += stat.selfpercent()
549
549
550 functiondata.append((fname,
550 functiondata.append((fname,
551 total_cum_sec,
551 total_cum_sec,
552 total_self_sec,
552 total_self_sec,
553 total_percent,
553 total_percent,
554 sitestats))
554 sitestats))
555
555
556 # sort by total self sec
556 # sort by total self sec
557 functiondata.sort(reverse=True, key=lambda x: x[2])
557 functiondata.sort(reverse=True, key=lambda x: x[2])
558
558
559 for function in functiondata:
559 for function in functiondata:
560 if function[3] < 0.05:
560 if function[3] < 0.05:
561 continue
561 continue
562 fp.write(b'%6.2f %9.2f %9.2f %s\n' % (
562 fp.write(b'%6.2f %9.2f %9.2f %s\n' % (
563 function[3], # total percent
563 function[3], # total percent
564 function[1], # total cum sec
564 function[1], # total cum sec
565 function[2], # total self sec
565 function[2], # total self sec
566 function[0])) # file:function
566 function[0])) # file:function
567
567
568 function[4].sort(reverse=True, key=lambda i: i.selfseconds())
568 function[4].sort(reverse=True, key=lambda i: i.selfseconds())
569 for stat in function[4]:
569 for stat in function[4]:
570 # only show line numbers for significant locations (>1% time spent)
570 # only show line numbers for significant locations (>1% time spent)
571 if stat.selfpercent() > 1:
571 if stat.selfpercent() > 1:
572 source = stat.site.getsource(25)
572 source = stat.site.getsource(25)
573 if sys.version_info.major >= 3 and not isinstance(source, bytes):
573 if sys.version_info.major >= 3 and not isinstance(source, bytes):
574 source = pycompat.bytestr(source)
574 source = pycompat.bytestr(source)
575
575
576 stattuple = (stat.selfpercent(), stat.selfseconds(),
576 stattuple = (stat.selfpercent(), stat.selfseconds(),
577 stat.site.lineno, source)
577 stat.site.lineno, source)
578
578
579 fp.write(b'%33.0f%% %6.2f line %d: %s\n' % stattuple)
579 fp.write(b'%33.0f%% %6.2f line %d: %s\n' % stattuple)
580
580
581 def display_about_method(data, fp, function=None, **kwargs):
581 def display_about_method(data, fp, function=None, **kwargs):
582 if function is None:
582 if function is None:
583 raise Exception("Invalid function")
583 raise Exception("Invalid function")
584
584
585 filename = None
585 filename = None
586 if ':' in function:
586 if ':' in function:
587 filename, function = function.split(':')
587 filename, function = function.split(':')
588
588
589 relevant_samples = 0
589 relevant_samples = 0
590 parents = {}
590 parents = {}
591 children = {}
591 children = {}
592
592
593 for sample in data.samples:
593 for sample in data.samples:
594 for i, site in enumerate(sample.stack):
594 for i, site in enumerate(sample.stack):
595 if site.function == function and (not filename
595 if site.function == function and (not filename
596 or site.filename() == filename):
596 or site.filename() == filename):
597 relevant_samples += 1
597 relevant_samples += 1
598 if i != len(sample.stack) - 1:
598 if i != len(sample.stack) - 1:
599 parent = sample.stack[i + 1]
599 parent = sample.stack[i + 1]
600 if parent in parents:
600 if parent in parents:
601 parents[parent] = parents[parent] + 1
601 parents[parent] = parents[parent] + 1
602 else:
602 else:
603 parents[parent] = 1
603 parents[parent] = 1
604
604
605 if site in children:
605 if site in children:
606 children[site] = children[site] + 1
606 children[site] = children[site] + 1
607 else:
607 else:
608 children[site] = 1
608 children[site] = 1
609
609
610 parents = [(parent, count) for parent, count in parents.iteritems()]
610 parents = [(parent, count) for parent, count in parents.iteritems()]
611 parents.sort(reverse=True, key=lambda x: x[1])
611 parents.sort(reverse=True, key=lambda x: x[1])
612 for parent, count in parents:
612 for parent, count in parents:
613 fp.write(b'%6.2f%% %s:%s line %s: %s\n' %
613 fp.write(b'%6.2f%% %s:%s line %s: %s\n' %
614 (count / relevant_samples * 100,
614 (count / relevant_samples * 100,
615 pycompat.fsencode(parent.filename()),
615 pycompat.fsencode(parent.filename()),
616 pycompat.sysbytes(parent.function),
616 pycompat.sysbytes(parent.function),
617 parent.lineno,
617 parent.lineno,
618 pycompat.sysbytes(parent.getsource(50))))
618 pycompat.sysbytes(parent.getsource(50))))
619
619
620 stats = SiteStats.buildstats(data.samples)
620 stats = SiteStats.buildstats(data.samples)
621 stats = [s for s in stats
621 stats = [s for s in stats
622 if s.site.function == function and
622 if s.site.function == function and
623 (not filename or s.site.filename() == filename)]
623 (not filename or s.site.filename() == filename)]
624
624
625 total_cum_sec = 0
625 total_cum_sec = 0
626 total_self_sec = 0
626 total_self_sec = 0
627 total_self_percent = 0
627 total_self_percent = 0
628 total_cum_percent = 0
628 total_cum_percent = 0
629 for stat in stats:
629 for stat in stats:
630 total_cum_sec += stat.totalseconds()
630 total_cum_sec += stat.totalseconds()
631 total_self_sec += stat.selfseconds()
631 total_self_sec += stat.selfseconds()
632 total_self_percent += stat.selfpercent()
632 total_self_percent += stat.selfpercent()
633 total_cum_percent += stat.totalpercent()
633 total_cum_percent += stat.totalpercent()
634
634
635 fp.write(
635 fp.write(
636 b'\n %s:%s Total: %0.2fs (%0.2f%%) Self: %0.2fs (%0.2f%%)\n\n'
636 b'\n %s:%s Total: %0.2fs (%0.2f%%) Self: %0.2fs (%0.2f%%)\n\n'
637 % (
637 % (
638 pycompat.sysbytes(filename or '___'),
638 pycompat.sysbytes(filename or '___'),
639 pycompat.sysbytes(function),
639 pycompat.sysbytes(function),
640 total_cum_sec,
640 total_cum_sec,
641 total_cum_percent,
641 total_cum_percent,
642 total_self_sec,
642 total_self_sec,
643 total_self_percent
643 total_self_percent
644 ))
644 ))
645
645
646 children = [(child, count) for child, count in children.iteritems()]
646 children = [(child, count) for child, count in children.iteritems()]
647 children.sort(reverse=True, key=lambda x: x[1])
647 children.sort(reverse=True, key=lambda x: x[1])
648 for child, count in children:
648 for child, count in children:
649 fp.write(b' %6.2f%% line %s: %s\n' %
649 fp.write(b' %6.2f%% line %s: %s\n' %
650 (count / relevant_samples * 100, child.lineno,
650 (count / relevant_samples * 100, child.lineno,
651 pycompat.sysbytes(child.getsource(50))))
651 pycompat.sysbytes(child.getsource(50))))
652
652
653 def display_hotpath(data, fp, limit=0.05, **kwargs):
653 def display_hotpath(data, fp, limit=0.05, **kwargs):
654 class HotNode(object):
654 class HotNode(object):
655 def __init__(self, site):
655 def __init__(self, site):
656 self.site = site
656 self.site = site
657 self.count = 0
657 self.count = 0
658 self.children = {}
658 self.children = {}
659
659
660 def add(self, stack, time):
660 def add(self, stack, time):
661 self.count += time
661 self.count += time
662 site = stack[0]
662 site = stack[0]
663 child = self.children.get(site)
663 child = self.children.get(site)
664 if not child:
664 if not child:
665 child = HotNode(site)
665 child = HotNode(site)
666 self.children[site] = child
666 self.children[site] = child
667
667
668 if len(stack) > 1:
668 if len(stack) > 1:
669 i = 1
669 i = 1
670 # Skip boiler plate parts of the stack
670 # Skip boiler plate parts of the stack
671 while i < len(stack) and stack[i].skipname() in skips:
671 while i < len(stack) and stack[i].skipname() in skips:
672 i += 1
672 i += 1
673 if i < len(stack):
673 if i < len(stack):
674 child.add(stack[i:], time)
674 child.add(stack[i:], time)
675
675
676 root = HotNode(None)
676 root = HotNode(None)
677 lasttime = data.samples[0].time
677 lasttime = data.samples[0].time
678 for sample in data.samples:
678 for sample in data.samples:
679 root.add(sample.stack[::-1], sample.time - lasttime)
679 root.add(sample.stack[::-1], sample.time - lasttime)
680 lasttime = sample.time
680 lasttime = sample.time
681 showtime = kwargs.get(r'showtime', True)
681 showtime = kwargs.get(r'showtime', True)
682
682
683 def _write(node, depth, multiple_siblings):
683 def _write(node, depth, multiple_siblings):
684 site = node.site
684 site = node.site
685 visiblechildren = [c for c in node.children.itervalues()
685 visiblechildren = [c for c in node.children.itervalues()
686 if c.count >= (limit * root.count)]
686 if c.count >= (limit * root.count)]
687 if site:
687 if site:
688 indent = depth * 2 - 1
688 indent = depth * 2 - 1
689 filename = ''
689 filename = ''
690 function = ''
690 function = ''
691 if len(node.children) > 0:
691 if len(node.children) > 0:
692 childsite = list(node.children.itervalues())[0].site
692 childsite = list(node.children.itervalues())[0].site
693 filename = (childsite.filename() + ':').ljust(15)
693 filename = (childsite.filename() + ':').ljust(15)
694 function = childsite.function
694 function = childsite.function
695
695
696 # lots of string formatting
696 # lots of string formatting
697 listpattern = ''.ljust(indent) +\
697 listpattern = ''.ljust(indent) +\
698 ('\\' if multiple_siblings else '|') +\
698 ('\\' if multiple_siblings else '|') +\
699 ' %4.1f%%' +\
699 ' %4.1f%%' +\
700 (' %5.2fs' % node.count if showtime else '') +\
700 (' %5.2fs' % node.count if showtime else '') +\
701 ' %s %s'
701 ' %s %s'
702 liststring = listpattern % (node.count / root.count * 100,
702 liststring = listpattern % (node.count / root.count * 100,
703 filename, function)
703 filename, function)
704 codepattern = '%' + ('%d' % (55 - len(liststring))) + 's %d: %s'
704 codepattern = '%' + ('%d' % (55 - len(liststring))) + 's %d: %s'
705 codestring = codepattern % ('line', site.lineno, site.getsource(30))
705 codestring = codepattern % ('line', site.lineno, site.getsource(30))
706
706
707 finalstring = liststring + codestring
707 finalstring = liststring + codestring
708 childrensamples = sum([c.count for c in node.children.itervalues()])
708 childrensamples = sum([c.count for c in node.children.itervalues()])
709 # Make frames that performed more than 10% of the operation red
709 # Make frames that performed more than 10% of the operation red
710 if node.count - childrensamples > (0.1 * root.count):
710 if node.count - childrensamples > (0.1 * root.count):
711 finalstring = '\033[91m' + finalstring + '\033[0m'
711 finalstring = '\033[91m' + finalstring + '\033[0m'
712 # Make frames that didn't actually perform work dark grey
712 # Make frames that didn't actually perform work dark grey
713 elif node.count - childrensamples == 0:
713 elif node.count - childrensamples == 0:
714 finalstring = '\033[90m' + finalstring + '\033[0m'
714 finalstring = '\033[90m' + finalstring + '\033[0m'
715 fp.write(finalstring + b'\n')
715 fp.write(finalstring + b'\n')
716
716
717 newdepth = depth
717 newdepth = depth
718 if len(visiblechildren) > 1 or multiple_siblings:
718 if len(visiblechildren) > 1 or multiple_siblings:
719 newdepth += 1
719 newdepth += 1
720
720
721 visiblechildren.sort(reverse=True, key=lambda x: x.count)
721 visiblechildren.sort(reverse=True, key=lambda x: x.count)
722 for child in visiblechildren:
722 for child in visiblechildren:
723 _write(child, newdepth, len(visiblechildren) > 1)
723 _write(child, newdepth, len(visiblechildren) > 1)
724
724
725 if root.count > 0:
725 if root.count > 0:
726 _write(root, 0, False)
726 _write(root, 0, False)
727
727
728 def write_to_flame(data, fp, scriptpath=None, outputfile=None, **kwargs):
728 def write_to_flame(data, fp, scriptpath=None, outputfile=None, **kwargs):
729 if scriptpath is None:
729 if scriptpath is None:
730 scriptpath = encoding.environ['HOME'] + '/flamegraph.pl'
730 scriptpath = encoding.environ['HOME'] + '/flamegraph.pl'
731 if not os.path.exists(scriptpath):
731 if not os.path.exists(scriptpath):
732 fp.write(b'error: missing %s\n' % scriptpath)
732 fp.write(b'error: missing %s\n' % scriptpath)
733 fp.write(b'get it here: https://github.com/brendangregg/FlameGraph\n')
733 fp.write(b'get it here: https://github.com/brendangregg/FlameGraph\n')
734 return
734 return
735
735
736 fd, path = pycompat.mkstemp()
736 fd, path = pycompat.mkstemp()
737
737
738 file = open(path, "w+")
738 file = open(path, "w+")
739
739
740 lines = {}
740 lines = {}
741 for sample in data.samples:
741 for sample in data.samples:
742 sites = [s.function for s in sample.stack]
742 sites = [s.function for s in sample.stack]
743 sites.reverse()
743 sites.reverse()
744 line = ';'.join(sites)
744 line = ';'.join(sites)
745 if line in lines:
745 if line in lines:
746 lines[line] = lines[line] + 1
746 lines[line] = lines[line] + 1
747 else:
747 else:
748 lines[line] = 1
748 lines[line] = 1
749
749
750 for line, count in lines.iteritems():
750 for line, count in lines.iteritems():
751 file.write("%s %d\n" % (line, count))
751 file.write("%s %d\n" % (line, count))
752
752
753 file.close()
753 file.close()
754
754
755 if outputfile is None:
755 if outputfile is None:
756 outputfile = '~/flamegraph.svg'
756 outputfile = '~/flamegraph.svg'
757
757
758 os.system("perl ~/flamegraph.pl %s > %s" % (path, outputfile))
758 os.system("perl ~/flamegraph.pl %s > %s" % (path, outputfile))
759 fp.write(b'Written to %s\n' % outputfile)
759 fp.write(b'Written to %s\n' % outputfile)
760
760
761 _pathcache = {}
761 _pathcache = {}
762 def simplifypath(path):
762 def simplifypath(path):
763 '''Attempt to make the path to a Python module easier to read by
763 '''Attempt to make the path to a Python module easier to read by
764 removing whatever part of the Python search path it was found
764 removing whatever part of the Python search path it was found
765 on.'''
765 on.'''
766
766
767 if path in _pathcache:
767 if path in _pathcache:
768 return _pathcache[path]
768 return _pathcache[path]
769 hgpath = pycompat.fsencode(encoding.__file__).rsplit(os.sep, 2)[0]
769 hgpath = pycompat.fsencode(encoding.__file__).rsplit(os.sep, 2)[0]
770 for p in [hgpath] + sys.path:
770 for p in [hgpath] + sys.path:
771 prefix = p + os.sep
771 prefix = p + os.sep
772 if path.startswith(prefix):
772 if path.startswith(prefix):
773 path = path[len(prefix):]
773 path = path[len(prefix):]
774 break
774 break
775 _pathcache[path] = path
775 _pathcache[path] = path
776 return path
776 return path
777
777
778 def write_to_json(data, fp):
778 def write_to_json(data, fp):
779 samples = []
779 samples = []
780
780
781 for sample in data.samples:
781 for sample in data.samples:
782 stack = []
782 stack = []
783
783
784 for frame in sample.stack:
784 for frame in sample.stack:
785 stack.append(
785 stack.append(
786 (pycompat.sysstr(frame.path),
786 (pycompat.sysstr(frame.path),
787 frame.lineno,
787 frame.lineno,
788 pycompat.sysstr(frame.function)))
788 pycompat.sysstr(frame.function)))
789
789
790 samples.append((sample.time, stack))
790 samples.append((sample.time, stack))
791
791
792 data = json.dumps(samples)
792 data = json.dumps(samples)
793 if not isinstance(data, bytes):
793 if not isinstance(data, bytes):
794 data = data.encode('utf-8')
794 data = data.encode('utf-8')
795
795
796 fp.write(data)
796 fp.write(data)
797
797
798 def write_to_chrome(data, fp, minthreshold=0.005, maxthreshold=0.999):
798 def write_to_chrome(data, fp, minthreshold=0.005, maxthreshold=0.999):
799 samples = []
799 samples = []
800 laststack = collections.deque()
800 laststack = collections.deque()
801 lastseen = collections.deque()
801 lastseen = collections.deque()
802
802
803 # The Chrome tracing format allows us to use a compact stack
803 # The Chrome tracing format allows us to use a compact stack
804 # representation to save space. It's fiddly but worth it.
804 # representation to save space. It's fiddly but worth it.
805 # We maintain a bijection between stack and ID.
805 # We maintain a bijection between stack and ID.
806 stack2id = {}
806 stack2id = {}
807 id2stack = [] # will eventually be rendered
807 id2stack = [] # will eventually be rendered
808
808
809 def stackid(stack):
809 def stackid(stack):
810 if not stack:
810 if not stack:
811 return
811 return
812 if stack in stack2id:
812 if stack in stack2id:
813 return stack2id[stack]
813 return stack2id[stack]
814 parent = stackid(stack[1:])
814 parent = stackid(stack[1:])
815 myid = len(stack2id)
815 myid = len(stack2id)
816 stack2id[stack] = myid
816 stack2id[stack] = myid
817 id2stack.append(dict(category=stack[0][0], name='%s %s' % stack[0]))
817 id2stack.append(dict(category=stack[0][0], name='%s %s' % stack[0]))
818 if parent is not None:
818 if parent is not None:
819 id2stack[-1].update(parent=parent)
819 id2stack[-1].update(parent=parent)
820 return myid
820 return myid
821
821
822 # The sampling profiler can sample multiple times without
822 # The sampling profiler can sample multiple times without
823 # advancing the clock, potentially causing the Chrome trace viewer
823 # advancing the clock, potentially causing the Chrome trace viewer
824 # to render single-pixel columns that we cannot zoom in on. We
824 # to render single-pixel columns that we cannot zoom in on. We
825 # work around this by pretending that zero-duration samples are a
825 # work around this by pretending that zero-duration samples are a
826 # millisecond in length.
826 # millisecond in length.
827
827
828 clamp = 0.001
828 clamp = 0.001
829
829
830 # We provide knobs that by default attempt to filter out stack
830 # We provide knobs that by default attempt to filter out stack
831 # frames that are too noisy:
831 # frames that are too noisy:
832 #
832 #
833 # * A few take almost all execution time. These are usually boring
833 # * A few take almost all execution time. These are usually boring
834 # setup functions, giving a stack that is deep but uninformative.
834 # setup functions, giving a stack that is deep but uninformative.
835 #
835 #
836 # * Numerous samples take almost no time, but introduce lots of
836 # * Numerous samples take almost no time, but introduce lots of
837 # noisy, oft-deep "spines" into a rendered profile.
837 # noisy, oft-deep "spines" into a rendered profile.
838
838
839 blacklist = set()
839 blacklist = set()
840 totaltime = data.samples[-1].time - data.samples[0].time
840 totaltime = data.samples[-1].time - data.samples[0].time
841 minthreshold = totaltime * minthreshold
841 minthreshold = totaltime * minthreshold
842 maxthreshold = max(totaltime * maxthreshold, clamp)
842 maxthreshold = max(totaltime * maxthreshold, clamp)
843
843
844 def poplast():
844 def poplast():
845 oldsid = stackid(tuple(laststack))
845 oldsid = stackid(tuple(laststack))
846 oldcat, oldfunc = laststack.popleft()
846 oldcat, oldfunc = laststack.popleft()
847 oldtime, oldidx = lastseen.popleft()
847 oldtime, oldidx = lastseen.popleft()
848 duration = sample.time - oldtime
848 duration = sample.time - oldtime
849 if minthreshold <= duration <= maxthreshold:
849 if minthreshold <= duration <= maxthreshold:
850 # ensure no zero-duration events
850 # ensure no zero-duration events
851 sampletime = max(oldtime + clamp, sample.time)
851 sampletime = max(oldtime + clamp, sample.time)
852 samples.append(dict(ph='E', name=oldfunc, cat=oldcat, sf=oldsid,
852 samples.append(dict(ph='E', name=oldfunc, cat=oldcat, sf=oldsid,
853 ts=sampletime*1e6, pid=0))
853 ts=sampletime*1e6, pid=0))
854 else:
854 else:
855 blacklist.add(oldidx)
855 blacklist.add(oldidx)
856
856
857 # Much fiddling to synthesize correctly(ish) nested begin/end
857 # Much fiddling to synthesize correctly(ish) nested begin/end
858 # events given only stack snapshots.
858 # events given only stack snapshots.
859
859
860 for sample in data.samples:
860 for sample in data.samples:
861 stack = tuple((('%s:%d' % (simplifypath(frame.path), frame.lineno),
861 stack = tuple((('%s:%d' % (simplifypath(frame.path), frame.lineno),
862 frame.function) for frame in sample.stack))
862 frame.function) for frame in sample.stack))
863 qstack = collections.deque(stack)
863 qstack = collections.deque(stack)
864 if laststack == qstack:
864 if laststack == qstack:
865 continue
865 continue
866 while laststack and qstack and laststack[-1] == qstack[-1]:
866 while laststack and qstack and laststack[-1] == qstack[-1]:
867 laststack.pop()
867 laststack.pop()
868 qstack.pop()
868 qstack.pop()
869 while laststack:
869 while laststack:
870 poplast()
870 poplast()
871 for f in reversed(qstack):
871 for f in reversed(qstack):
872 lastseen.appendleft((sample.time, len(samples)))
872 lastseen.appendleft((sample.time, len(samples)))
873 laststack.appendleft(f)
873 laststack.appendleft(f)
874 path, name = f
874 path, name = f
875 sid = stackid(tuple(laststack))
875 sid = stackid(tuple(laststack))
876 samples.append(dict(ph='B', name=name, cat=path, ts=sample.time*1e6,
876 samples.append(dict(ph='B', name=name, cat=path, ts=sample.time*1e6,
877 sf=sid, pid=0))
877 sf=sid, pid=0))
878 laststack = collections.deque(stack)
878 laststack = collections.deque(stack)
879 while laststack:
879 while laststack:
880 poplast()
880 poplast()
881 events = [s[1] for s in enumerate(samples) if s[0] not in blacklist]
881 events = [sample for idx, sample in enumerate(samples)
882 if idx not in blacklist]
882 frames = collections.OrderedDict((str(k), v)
883 frames = collections.OrderedDict((str(k), v)
883 for (k,v) in enumerate(id2stack))
884 for (k,v) in enumerate(id2stack))
884 json.dump(dict(traceEvents=events, stackFrames=frames), fp, indent=1)
885 json.dump(dict(traceEvents=events, stackFrames=frames), fp, indent=1)
885 fp.write('\n')
886 fp.write('\n')
886
887
887 def printusage():
888 def printusage():
888 print(r"""
889 print(r"""
889 The statprof command line allows you to inspect the last profile's results in
890 The statprof command line allows you to inspect the last profile's results in
890 the following forms:
891 the following forms:
891
892
892 usage:
893 usage:
893 hotpath [-l --limit percent]
894 hotpath [-l --limit percent]
894 Shows a graph of calls with the percent of time each takes.
895 Shows a graph of calls with the percent of time each takes.
895 Red calls take over 10%% of the total time themselves.
896 Red calls take over 10%% of the total time themselves.
896 lines
897 lines
897 Shows the actual sampled lines.
898 Shows the actual sampled lines.
898 functions
899 functions
899 Shows the samples grouped by function.
900 Shows the samples grouped by function.
900 function [filename:]functionname
901 function [filename:]functionname
901 Shows the callers and callees of a particular function.
902 Shows the callers and callees of a particular function.
902 flame [-s --script-path] [-o --output-file path]
903 flame [-s --script-path] [-o --output-file path]
903 Writes out a flamegraph to output-file (defaults to ~/flamegraph.svg)
904 Writes out a flamegraph to output-file (defaults to ~/flamegraph.svg)
904 Requires that ~/flamegraph.pl exist.
905 Requires that ~/flamegraph.pl exist.
905 (Specify alternate script path with --script-path.)""")
906 (Specify alternate script path with --script-path.)""")
906
907
907 def main(argv=None):
908 def main(argv=None):
908 if argv is None:
909 if argv is None:
909 argv = sys.argv
910 argv = sys.argv
910
911
911 if len(argv) == 1:
912 if len(argv) == 1:
912 printusage()
913 printusage()
913 return 0
914 return 0
914
915
915 displayargs = {}
916 displayargs = {}
916
917
917 optstart = 2
918 optstart = 2
918 displayargs['function'] = None
919 displayargs['function'] = None
919 if argv[1] == r'hotpath':
920 if argv[1] == r'hotpath':
920 displayargs['format'] = DisplayFormats.Hotpath
921 displayargs['format'] = DisplayFormats.Hotpath
921 elif argv[1] == r'lines':
922 elif argv[1] == r'lines':
922 displayargs['format'] = DisplayFormats.ByLine
923 displayargs['format'] = DisplayFormats.ByLine
923 elif argv[1] == r'functions':
924 elif argv[1] == r'functions':
924 displayargs['format'] = DisplayFormats.ByMethod
925 displayargs['format'] = DisplayFormats.ByMethod
925 elif argv[1] == r'function':
926 elif argv[1] == r'function':
926 displayargs['format'] = DisplayFormats.AboutMethod
927 displayargs['format'] = DisplayFormats.AboutMethod
927 displayargs['function'] = argv[2]
928 displayargs['function'] = argv[2]
928 optstart = 3
929 optstart = 3
929 elif argv[1] == r'flame':
930 elif argv[1] == r'flame':
930 displayargs['format'] = DisplayFormats.FlameGraph
931 displayargs['format'] = DisplayFormats.FlameGraph
931 else:
932 else:
932 printusage()
933 printusage()
933 return 0
934 return 0
934
935
935 # process options
936 # process options
936 try:
937 try:
937 opts, args = pycompat.getoptb(sys.argv[optstart:], "hl:f:o:p:",
938 opts, args = pycompat.getoptb(sys.argv[optstart:], "hl:f:o:p:",
938 ["help", "limit=", "file=", "output-file=", "script-path="])
939 ["help", "limit=", "file=", "output-file=", "script-path="])
939 except getopt.error as msg:
940 except getopt.error as msg:
940 print(msg)
941 print(msg)
941 printusage()
942 printusage()
942 return 2
943 return 2
943
944
944 displayargs['limit'] = 0.05
945 displayargs['limit'] = 0.05
945 path = None
946 path = None
946 for o, value in opts:
947 for o, value in opts:
947 if o in (r"-l", r"--limit"):
948 if o in (r"-l", r"--limit"):
948 displayargs['limit'] = float(value)
949 displayargs['limit'] = float(value)
949 elif o in (r"-f", r"--file"):
950 elif o in (r"-f", r"--file"):
950 path = value
951 path = value
951 elif o in (r"-o", r"--output-file"):
952 elif o in (r"-o", r"--output-file"):
952 displayargs['outputfile'] = value
953 displayargs['outputfile'] = value
953 elif o in (r"-p", r"--script-path"):
954 elif o in (r"-p", r"--script-path"):
954 displayargs['scriptpath'] = value
955 displayargs['scriptpath'] = value
955 elif o in (r"-h", r"help"):
956 elif o in (r"-h", r"help"):
956 printusage()
957 printusage()
957 return 0
958 return 0
958 else:
959 else:
959 assert False, "unhandled option %s" % o
960 assert False, "unhandled option %s" % o
960
961
961 if not path:
962 if not path:
962 print(r'must specify --file to load')
963 print(r'must specify --file to load')
963 return 1
964 return 1
964
965
965 load_data(path=path)
966 load_data(path=path)
966
967
967 display(**pycompat.strkwargs(displayargs))
968 display(**pycompat.strkwargs(displayargs))
968
969
969 return 0
970 return 0
970
971
971 if __name__ == r"__main__":
972 if __name__ == r"__main__":
972 sys.exit(main())
973 sys.exit(main())
General Comments 0
You need to be logged in to leave comments. Login now