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