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