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