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