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