##// END OF EJS Templates
py3: make statprof's chrome output work...
Martin von Zweigbergk -
r43105:cde1c101 default
parent child Browse files
Show More
@@ -1,969 +1,971 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 lines = {}
732 lines = {}
733 for sample in data.samples:
733 for sample in data.samples:
734 sites = [s.function for s in sample.stack]
734 sites = [s.function for s in sample.stack]
735 sites.reverse()
735 sites.reverse()
736 line = ';'.join(sites)
736 line = ';'.join(sites)
737 if line in lines:
737 if line in lines:
738 lines[line] = lines[line] + 1
738 lines[line] = lines[line] + 1
739 else:
739 else:
740 lines[line] = 1
740 lines[line] = 1
741
741
742 fd, path = pycompat.mkstemp()
742 fd, path = pycompat.mkstemp()
743
743
744 with open(path, "w+") as file:
744 with open(path, "w+") as file:
745 for line, count in lines.iteritems():
745 for line, count in lines.iteritems():
746 file.write("%s %d\n" % (line, count))
746 file.write("%s %d\n" % (line, count))
747
747
748 if outputfile is None:
748 if outputfile is None:
749 outputfile = '~/flamegraph.svg'
749 outputfile = '~/flamegraph.svg'
750
750
751 os.system("perl ~/flamegraph.pl %s > %s" % (path, outputfile))
751 os.system("perl ~/flamegraph.pl %s > %s" % (path, outputfile))
752 fp.write(b'Written to %s\n' % outputfile)
752 fp.write(b'Written to %s\n' % outputfile)
753
753
754 _pathcache = {}
754 _pathcache = {}
755 def simplifypath(path):
755 def simplifypath(path):
756 '''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
757 removing whatever part of the Python search path it was found
757 removing whatever part of the Python search path it was found
758 on.'''
758 on.'''
759
759
760 if path in _pathcache:
760 if path in _pathcache:
761 return _pathcache[path]
761 return _pathcache[path]
762 hgpath = pycompat.fsencode(encoding.__file__).rsplit(os.sep, 2)[0]
762 hgpath = encoding.__file__.rsplit(os.sep, 2)[0]
763 for p in [hgpath] + sys.path:
763 for p in [hgpath] + sys.path:
764 prefix = p + os.sep
764 prefix = p + os.sep
765 if path.startswith(prefix):
765 if path.startswith(prefix):
766 path = path[len(prefix):]
766 path = path[len(prefix):]
767 break
767 break
768 _pathcache[path] = path
768 _pathcache[path] = path
769 return path
769 return path
770
770
771 def write_to_json(data, fp):
771 def write_to_json(data, fp):
772 samples = []
772 samples = []
773
773
774 for sample in data.samples:
774 for sample in data.samples:
775 stack = []
775 stack = []
776
776
777 for frame in sample.stack:
777 for frame in sample.stack:
778 stack.append(
778 stack.append(
779 (pycompat.sysstr(frame.path),
779 (pycompat.sysstr(frame.path),
780 frame.lineno,
780 frame.lineno,
781 pycompat.sysstr(frame.function)))
781 pycompat.sysstr(frame.function)))
782
782
783 samples.append((sample.time, stack))
783 samples.append((sample.time, stack))
784
784
785 data = json.dumps(samples)
785 data = json.dumps(samples)
786 if not isinstance(data, bytes):
786 if not isinstance(data, bytes):
787 data = data.encode('utf-8')
787 data = data.encode('utf-8')
788
788
789 fp.write(data)
789 fp.write(data)
790
790
791 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):
792 samples = []
792 samples = []
793 laststack = collections.deque()
793 laststack = collections.deque()
794 lastseen = collections.deque()
794 lastseen = collections.deque()
795
795
796 # The Chrome tracing format allows us to use a compact stack
796 # The Chrome tracing format allows us to use a compact stack
797 # representation to save space. It's fiddly but worth it.
797 # representation to save space. It's fiddly but worth it.
798 # We maintain a bijection between stack and ID.
798 # We maintain a bijection between stack and ID.
799 stack2id = {}
799 stack2id = {}
800 id2stack = [] # will eventually be rendered
800 id2stack = [] # will eventually be rendered
801
801
802 def stackid(stack):
802 def stackid(stack):
803 if not stack:
803 if not stack:
804 return
804 return
805 if stack in stack2id:
805 if stack in stack2id:
806 return stack2id[stack]
806 return stack2id[stack]
807 parent = stackid(stack[1:])
807 parent = stackid(stack[1:])
808 myid = len(stack2id)
808 myid = len(stack2id)
809 stack2id[stack] = myid
809 stack2id[stack] = myid
810 id2stack.append(dict(category=stack[0][0], name='%s %s' % stack[0]))
810 id2stack.append(dict(category=stack[0][0], name=r'%s %s' % stack[0]))
811 if parent is not None:
811 if parent is not None:
812 id2stack[-1].update(parent=parent)
812 id2stack[-1].update(parent=parent)
813 return myid
813 return myid
814
814
815 # The sampling profiler can sample multiple times without
815 # The sampling profiler can sample multiple times without
816 # advancing the clock, potentially causing the Chrome trace viewer
816 # advancing the clock, potentially causing the Chrome trace viewer
817 # 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
818 # work around this by pretending that zero-duration samples are a
818 # work around this by pretending that zero-duration samples are a
819 # millisecond in length.
819 # millisecond in length.
820
820
821 clamp = 0.001
821 clamp = 0.001
822
822
823 # We provide knobs that by default attempt to filter out stack
823 # We provide knobs that by default attempt to filter out stack
824 # frames that are too noisy:
824 # frames that are too noisy:
825 #
825 #
826 # * A few take almost all execution time. These are usually boring
826 # * A few take almost all execution time. These are usually boring
827 # setup functions, giving a stack that is deep but uninformative.
827 # setup functions, giving a stack that is deep but uninformative.
828 #
828 #
829 # * Numerous samples take almost no time, but introduce lots of
829 # * Numerous samples take almost no time, but introduce lots of
830 # noisy, oft-deep "spines" into a rendered profile.
830 # noisy, oft-deep "spines" into a rendered profile.
831
831
832 blacklist = set()
832 blacklist = set()
833 totaltime = data.samples[-1].time - data.samples[0].time
833 totaltime = data.samples[-1].time - data.samples[0].time
834 minthreshold = totaltime * minthreshold
834 minthreshold = totaltime * minthreshold
835 maxthreshold = max(totaltime * maxthreshold, clamp)
835 maxthreshold = max(totaltime * maxthreshold, clamp)
836
836
837 def poplast():
837 def poplast():
838 oldsid = stackid(tuple(laststack))
838 oldsid = stackid(tuple(laststack))
839 oldcat, oldfunc = laststack.popleft()
839 oldcat, oldfunc = laststack.popleft()
840 oldtime, oldidx = lastseen.popleft()
840 oldtime, oldidx = lastseen.popleft()
841 duration = sample.time - oldtime
841 duration = sample.time - oldtime
842 if minthreshold <= duration <= maxthreshold:
842 if minthreshold <= duration <= maxthreshold:
843 # ensure no zero-duration events
843 # ensure no zero-duration events
844 sampletime = max(oldtime + clamp, sample.time)
844 sampletime = max(oldtime + clamp, sample.time)
845 samples.append(dict(ph='E', name=oldfunc, cat=oldcat, sf=oldsid,
845 samples.append(dict(ph=r'E', name=oldfunc, cat=oldcat, sf=oldsid,
846 ts=sampletime*1e6, pid=0))
846 ts=sampletime*1e6, pid=0))
847 else:
847 else:
848 blacklist.add(oldidx)
848 blacklist.add(oldidx)
849
849
850 # Much fiddling to synthesize correctly(ish) nested begin/end
850 # Much fiddling to synthesize correctly(ish) nested begin/end
851 # events given only stack snapshots.
851 # events given only stack snapshots.
852
852
853 for sample in data.samples:
853 for sample in data.samples:
854 stack = tuple((('%s:%d' % (simplifypath(frame.path), frame.lineno),
854 stack = tuple(((r'%s:%d' % (simplifypath(pycompat.sysstr(frame.path)),
855 frame.function) for frame in sample.stack))
855 frame.lineno),
856 pycompat.sysstr(frame.function))
857 for frame in sample.stack))
856 qstack = collections.deque(stack)
858 qstack = collections.deque(stack)
857 if laststack == qstack:
859 if laststack == qstack:
858 continue
860 continue
859 while laststack and qstack and laststack[-1] == qstack[-1]:
861 while laststack and qstack and laststack[-1] == qstack[-1]:
860 laststack.pop()
862 laststack.pop()
861 qstack.pop()
863 qstack.pop()
862 while laststack:
864 while laststack:
863 poplast()
865 poplast()
864 for f in reversed(qstack):
866 for f in reversed(qstack):
865 lastseen.appendleft((sample.time, len(samples)))
867 lastseen.appendleft((sample.time, len(samples)))
866 laststack.appendleft(f)
868 laststack.appendleft(f)
867 path, name = f
869 path, name = f
868 sid = stackid(tuple(laststack))
870 sid = stackid(tuple(laststack))
869 samples.append(dict(ph='B', name=name, cat=path, ts=sample.time*1e6,
871 samples.append(dict(ph=r'B', name=name, cat=path,
870 sf=sid, pid=0))
872 ts=sample.time*1e6, sf=sid, pid=0))
871 laststack = collections.deque(stack)
873 laststack = collections.deque(stack)
872 while laststack:
874 while laststack:
873 poplast()
875 poplast()
874 events = [sample for idx, sample in enumerate(samples)
876 events = [sample for idx, sample in enumerate(samples)
875 if idx not in blacklist]
877 if idx not in blacklist]
876 frames = collections.OrderedDict((str(k), v)
878 frames = collections.OrderedDict((str(k), v)
877 for (k,v) in enumerate(id2stack))
879 for (k,v) in enumerate(id2stack))
878 data = json.dumps(dict(traceEvents=events, stackFrames=frames), indent=1)
880 data = json.dumps(dict(traceEvents=events, stackFrames=frames), indent=1)
879 if not isinstance(data, bytes):
881 if not isinstance(data, bytes):
880 data = data.encode('utf-8')
882 data = data.encode('utf-8')
881 fp.write(data)
883 fp.write(data)
882 fp.write('\n')
884 fp.write('\n')
883
885
884 def printusage():
886 def printusage():
885 print(r"""
887 print(r"""
886 The statprof command line allows you to inspect the last profile's results in
888 The statprof command line allows you to inspect the last profile's results in
887 the following forms:
889 the following forms:
888
890
889 usage:
891 usage:
890 hotpath [-l --limit percent]
892 hotpath [-l --limit percent]
891 Shows a graph of calls with the percent of time each takes.
893 Shows a graph of calls with the percent of time each takes.
892 Red calls take over 10%% of the total time themselves.
894 Red calls take over 10%% of the total time themselves.
893 lines
895 lines
894 Shows the actual sampled lines.
896 Shows the actual sampled lines.
895 functions
897 functions
896 Shows the samples grouped by function.
898 Shows the samples grouped by function.
897 function [filename:]functionname
899 function [filename:]functionname
898 Shows the callers and callees of a particular function.
900 Shows the callers and callees of a particular function.
899 flame [-s --script-path] [-o --output-file path]
901 flame [-s --script-path] [-o --output-file path]
900 Writes out a flamegraph to output-file (defaults to ~/flamegraph.svg)
902 Writes out a flamegraph to output-file (defaults to ~/flamegraph.svg)
901 Requires that ~/flamegraph.pl exist.
903 Requires that ~/flamegraph.pl exist.
902 (Specify alternate script path with --script-path.)""")
904 (Specify alternate script path with --script-path.)""")
903
905
904 def main(argv=None):
906 def main(argv=None):
905 if argv is None:
907 if argv is None:
906 argv = sys.argv
908 argv = sys.argv
907
909
908 if len(argv) == 1:
910 if len(argv) == 1:
909 printusage()
911 printusage()
910 return 0
912 return 0
911
913
912 displayargs = {}
914 displayargs = {}
913
915
914 optstart = 2
916 optstart = 2
915 displayargs['function'] = None
917 displayargs['function'] = None
916 if argv[1] == r'hotpath':
918 if argv[1] == r'hotpath':
917 displayargs['format'] = DisplayFormats.Hotpath
919 displayargs['format'] = DisplayFormats.Hotpath
918 elif argv[1] == r'lines':
920 elif argv[1] == r'lines':
919 displayargs['format'] = DisplayFormats.ByLine
921 displayargs['format'] = DisplayFormats.ByLine
920 elif argv[1] == r'functions':
922 elif argv[1] == r'functions':
921 displayargs['format'] = DisplayFormats.ByMethod
923 displayargs['format'] = DisplayFormats.ByMethod
922 elif argv[1] == r'function':
924 elif argv[1] == r'function':
923 displayargs['format'] = DisplayFormats.AboutMethod
925 displayargs['format'] = DisplayFormats.AboutMethod
924 displayargs['function'] = argv[2]
926 displayargs['function'] = argv[2]
925 optstart = 3
927 optstart = 3
926 elif argv[1] == r'flame':
928 elif argv[1] == r'flame':
927 displayargs['format'] = DisplayFormats.FlameGraph
929 displayargs['format'] = DisplayFormats.FlameGraph
928 else:
930 else:
929 printusage()
931 printusage()
930 return 0
932 return 0
931
933
932 # process options
934 # process options
933 try:
935 try:
934 opts, args = pycompat.getoptb(sys.argv[optstart:], "hl:f:o:p:",
936 opts, args = pycompat.getoptb(sys.argv[optstart:], "hl:f:o:p:",
935 ["help", "limit=", "file=", "output-file=", "script-path="])
937 ["help", "limit=", "file=", "output-file=", "script-path="])
936 except getopt.error as msg:
938 except getopt.error as msg:
937 print(msg)
939 print(msg)
938 printusage()
940 printusage()
939 return 2
941 return 2
940
942
941 displayargs['limit'] = 0.05
943 displayargs['limit'] = 0.05
942 path = None
944 path = None
943 for o, value in opts:
945 for o, value in opts:
944 if o in (r"-l", r"--limit"):
946 if o in (r"-l", r"--limit"):
945 displayargs['limit'] = float(value)
947 displayargs['limit'] = float(value)
946 elif o in (r"-f", r"--file"):
948 elif o in (r"-f", r"--file"):
947 path = value
949 path = value
948 elif o in (r"-o", r"--output-file"):
950 elif o in (r"-o", r"--output-file"):
949 displayargs['outputfile'] = value
951 displayargs['outputfile'] = value
950 elif o in (r"-p", r"--script-path"):
952 elif o in (r"-p", r"--script-path"):
951 displayargs['scriptpath'] = value
953 displayargs['scriptpath'] = value
952 elif o in (r"-h", r"help"):
954 elif o in (r"-h", r"help"):
953 printusage()
955 printusage()
954 return 0
956 return 0
955 else:
957 else:
956 assert False, "unhandled option %s" % o
958 assert False, "unhandled option %s" % o
957
959
958 if not path:
960 if not path:
959 print(r'must specify --file to load')
961 print(r'must specify --file to load')
960 return 1
962 return 1
961
963
962 load_data(path=path)
964 load_data(path=path)
963
965
964 display(**pycompat.strkwargs(displayargs))
966 display(**pycompat.strkwargs(displayargs))
965
967
966 return 0
968 return 0
967
969
968 if __name__ == r"__main__":
970 if __name__ == r"__main__":
969 sys.exit(main())
971 sys.exit(main())
General Comments 0
You need to be logged in to leave comments. Login now