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