##// END OF EJS Templates
statprof: small if cleanup...
Boris Feld -
r38719:3c569172 @83 default
parent child Browse files
Show More
@@ -1,947 +1,948 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(time + '\0' + '\0'.join(sites) + '\n')
359 file.write(time + '\0' + '\0'.join(sites) + '\n')
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 data = data or state
457 if data is None:
458 data = state
458
459
459 if fp is None:
460 if fp is None:
460 import sys
461 import sys
461 fp = sys.stdout
462 fp = sys.stdout
462 if len(data.samples) == 0:
463 if len(data.samples) == 0:
463 print('No samples recorded.', file=fp)
464 print('No samples recorded.', file=fp)
464 return
465 return
465
466
466 if format == DisplayFormats.ByLine:
467 if format == DisplayFormats.ByLine:
467 display_by_line(data, fp)
468 display_by_line(data, fp)
468 elif format == DisplayFormats.ByMethod:
469 elif format == DisplayFormats.ByMethod:
469 display_by_method(data, fp)
470 display_by_method(data, fp)
470 elif format == DisplayFormats.AboutMethod:
471 elif format == DisplayFormats.AboutMethod:
471 display_about_method(data, fp, **kwargs)
472 display_about_method(data, fp, **kwargs)
472 elif format == DisplayFormats.Hotpath:
473 elif format == DisplayFormats.Hotpath:
473 display_hotpath(data, fp, **kwargs)
474 display_hotpath(data, fp, **kwargs)
474 elif format == DisplayFormats.FlameGraph:
475 elif format == DisplayFormats.FlameGraph:
475 write_to_flame(data, fp, **kwargs)
476 write_to_flame(data, fp, **kwargs)
476 elif format == DisplayFormats.Json:
477 elif format == DisplayFormats.Json:
477 write_to_json(data, fp)
478 write_to_json(data, fp)
478 elif format == DisplayFormats.Chrome:
479 elif format == DisplayFormats.Chrome:
479 write_to_chrome(data, fp, **kwargs)
480 write_to_chrome(data, fp, **kwargs)
480 else:
481 else:
481 raise Exception("Invalid display format")
482 raise Exception("Invalid display format")
482
483
483 if format not in (DisplayFormats.Json, DisplayFormats.Chrome):
484 if format not in (DisplayFormats.Json, DisplayFormats.Chrome):
484 print('---', file=fp)
485 print('---', file=fp)
485 print('Sample count: %d' % len(data.samples), file=fp)
486 print('Sample count: %d' % len(data.samples), file=fp)
486 print('Total time: %f seconds (%f wall)' % data.accumulated_time,
487 print('Total time: %f seconds (%f wall)' % data.accumulated_time,
487 file=fp)
488 file=fp)
488
489
489 def display_by_line(data, fp):
490 def display_by_line(data, fp):
490 '''Print the profiler data with each sample line represented
491 '''Print the profiler data with each sample line represented
491 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.'''
492 stats = SiteStats.buildstats(data.samples)
493 stats = SiteStats.buildstats(data.samples)
493 stats.sort(reverse=True, key=lambda x: x.selfseconds())
494 stats.sort(reverse=True, key=lambda x: x.selfseconds())
494
495
495 print('%5.5s %10.10s %7.7s %-8.8s' %
496 print('%5.5s %10.10s %7.7s %-8.8s' %
496 ('% ', 'cumulative', 'self', ''), file=fp)
497 ('% ', 'cumulative', 'self', ''), file=fp)
497 print('%5.5s %9.9s %8.8s %-8.8s' %
498 print('%5.5s %9.9s %8.8s %-8.8s' %
498 ("time", "seconds", "seconds", "name"), file=fp)
499 ("time", "seconds", "seconds", "name"), file=fp)
499
500
500 for stat in stats:
501 for stat in stats:
501 site = stat.site
502 site = stat.site
502 sitelabel = '%s:%d:%s' % (site.filename(), site.lineno, site.function)
503 sitelabel = '%s:%d:%s' % (site.filename(), site.lineno, site.function)
503 print('%6.2f %9.2f %9.2f %s' % (stat.selfpercent(),
504 print('%6.2f %9.2f %9.2f %s' % (stat.selfpercent(),
504 stat.totalseconds(),
505 stat.totalseconds(),
505 stat.selfseconds(),
506 stat.selfseconds(),
506 sitelabel),
507 sitelabel),
507 file=fp)
508 file=fp)
508
509
509 def display_by_method(data, fp):
510 def display_by_method(data, fp):
510 '''Print the profiler data with each sample function represented
511 '''Print the profiler data with each sample function represented
511 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
512 output as nested rows. Sorted by self-time per line.'''
513 output as nested rows. Sorted by self-time per line.'''
513 print('%5.5s %10.10s %7.7s %-8.8s' %
514 print('%5.5s %10.10s %7.7s %-8.8s' %
514 ('% ', 'cumulative', 'self', ''), file=fp)
515 ('% ', 'cumulative', 'self', ''), file=fp)
515 print('%5.5s %9.9s %8.8s %-8.8s' %
516 print('%5.5s %9.9s %8.8s %-8.8s' %
516 ("time", "seconds", "seconds", "name"), file=fp)
517 ("time", "seconds", "seconds", "name"), file=fp)
517
518
518 stats = SiteStats.buildstats(data.samples)
519 stats = SiteStats.buildstats(data.samples)
519
520
520 grouped = defaultdict(list)
521 grouped = defaultdict(list)
521 for stat in stats:
522 for stat in stats:
522 grouped[stat.site.filename() + ":" + stat.site.function].append(stat)
523 grouped[stat.site.filename() + ":" + stat.site.function].append(stat)
523
524
524 # compute sums for each function
525 # compute sums for each function
525 functiondata = []
526 functiondata = []
526 for fname, sitestats in grouped.iteritems():
527 for fname, sitestats in grouped.iteritems():
527 total_cum_sec = 0
528 total_cum_sec = 0
528 total_self_sec = 0
529 total_self_sec = 0
529 total_percent = 0
530 total_percent = 0
530 for stat in sitestats:
531 for stat in sitestats:
531 total_cum_sec += stat.totalseconds()
532 total_cum_sec += stat.totalseconds()
532 total_self_sec += stat.selfseconds()
533 total_self_sec += stat.selfseconds()
533 total_percent += stat.selfpercent()
534 total_percent += stat.selfpercent()
534
535
535 functiondata.append((fname,
536 functiondata.append((fname,
536 total_cum_sec,
537 total_cum_sec,
537 total_self_sec,
538 total_self_sec,
538 total_percent,
539 total_percent,
539 sitestats))
540 sitestats))
540
541
541 # sort by total self sec
542 # sort by total self sec
542 functiondata.sort(reverse=True, key=lambda x: x[2])
543 functiondata.sort(reverse=True, key=lambda x: x[2])
543
544
544 for function in functiondata:
545 for function in functiondata:
545 if function[3] < 0.05:
546 if function[3] < 0.05:
546 continue
547 continue
547 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
548 function[1], # total cum sec
549 function[1], # total cum sec
549 function[2], # total self sec
550 function[2], # total self sec
550 function[0]), # file:function
551 function[0]), # file:function
551 file=fp)
552 file=fp)
552 function[4].sort(reverse=True, key=lambda i: i.selfseconds())
553 function[4].sort(reverse=True, key=lambda i: i.selfseconds())
553 for stat in function[4]:
554 for stat in function[4]:
554 # only show line numbers for significant locations (>1% time spent)
555 # only show line numbers for significant locations (>1% time spent)
555 if stat.selfpercent() > 1:
556 if stat.selfpercent() > 1:
556 source = stat.site.getsource(25)
557 source = stat.site.getsource(25)
557 stattuple = (stat.selfpercent(), stat.selfseconds(),
558 stattuple = (stat.selfpercent(), stat.selfseconds(),
558 stat.site.lineno, source)
559 stat.site.lineno, source)
559
560
560 print('%33.0f%% %6.2f line %s: %s' % (stattuple), file=fp)
561 print('%33.0f%% %6.2f line %s: %s' % (stattuple), file=fp)
561
562
562 def display_about_method(data, fp, function=None, **kwargs):
563 def display_about_method(data, fp, function=None, **kwargs):
563 if function is None:
564 if function is None:
564 raise Exception("Invalid function")
565 raise Exception("Invalid function")
565
566
566 filename = None
567 filename = None
567 if ':' in function:
568 if ':' in function:
568 filename, function = function.split(':')
569 filename, function = function.split(':')
569
570
570 relevant_samples = 0
571 relevant_samples = 0
571 parents = {}
572 parents = {}
572 children = {}
573 children = {}
573
574
574 for sample in data.samples:
575 for sample in data.samples:
575 for i, site in enumerate(sample.stack):
576 for i, site in enumerate(sample.stack):
576 if site.function == function and (not filename
577 if site.function == function and (not filename
577 or site.filename() == filename):
578 or site.filename() == filename):
578 relevant_samples += 1
579 relevant_samples += 1
579 if i != len(sample.stack) - 1:
580 if i != len(sample.stack) - 1:
580 parent = sample.stack[i + 1]
581 parent = sample.stack[i + 1]
581 if parent in parents:
582 if parent in parents:
582 parents[parent] = parents[parent] + 1
583 parents[parent] = parents[parent] + 1
583 else:
584 else:
584 parents[parent] = 1
585 parents[parent] = 1
585
586
586 if site in children:
587 if site in children:
587 children[site] = children[site] + 1
588 children[site] = children[site] + 1
588 else:
589 else:
589 children[site] = 1
590 children[site] = 1
590
591
591 parents = [(parent, count) for parent, count in parents.iteritems()]
592 parents = [(parent, count) for parent, count in parents.iteritems()]
592 parents.sort(reverse=True, key=lambda x: x[1])
593 parents.sort(reverse=True, key=lambda x: x[1])
593 for parent, count in parents:
594 for parent, count in parents:
594 print('%6.2f%% %s:%s line %s: %s' %
595 print('%6.2f%% %s:%s line %s: %s' %
595 (count / relevant_samples * 100, parent.filename(),
596 (count / relevant_samples * 100, parent.filename(),
596 parent.function, parent.lineno, parent.getsource(50)), file=fp)
597 parent.function, parent.lineno, parent.getsource(50)), file=fp)
597
598
598 stats = SiteStats.buildstats(data.samples)
599 stats = SiteStats.buildstats(data.samples)
599 stats = [s for s in stats
600 stats = [s for s in stats
600 if s.site.function == function and
601 if s.site.function == function and
601 (not filename or s.site.filename() == filename)]
602 (not filename or s.site.filename() == filename)]
602
603
603 total_cum_sec = 0
604 total_cum_sec = 0
604 total_self_sec = 0
605 total_self_sec = 0
605 total_self_percent = 0
606 total_self_percent = 0
606 total_cum_percent = 0
607 total_cum_percent = 0
607 for stat in stats:
608 for stat in stats:
608 total_cum_sec += stat.totalseconds()
609 total_cum_sec += stat.totalseconds()
609 total_self_sec += stat.selfseconds()
610 total_self_sec += stat.selfseconds()
610 total_self_percent += stat.selfpercent()
611 total_self_percent += stat.selfpercent()
611 total_cum_percent += stat.totalpercent()
612 total_cum_percent += stat.totalpercent()
612
613
613 print(
614 print(
614 '\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' %
615 (
616 (
616 filename or '___',
617 filename or '___',
617 function,
618 function,
618 total_cum_sec,
619 total_cum_sec,
619 total_cum_percent,
620 total_cum_percent,
620 total_self_sec,
621 total_self_sec,
621 total_self_percent
622 total_self_percent
622 ), file=fp)
623 ), file=fp)
623
624
624 children = [(child, count) for child, count in children.iteritems()]
625 children = [(child, count) for child, count in children.iteritems()]
625 children.sort(reverse=True, key=lambda x: x[1])
626 children.sort(reverse=True, key=lambda x: x[1])
626 for child, count in children:
627 for child, count in children:
627 print(' %6.2f%% line %s: %s' %
628 print(' %6.2f%% line %s: %s' %
628 (count / relevant_samples * 100, child.lineno,
629 (count / relevant_samples * 100, child.lineno,
629 child.getsource(50)), file=fp)
630 child.getsource(50)), file=fp)
630
631
631 def display_hotpath(data, fp, limit=0.05, **kwargs):
632 def display_hotpath(data, fp, limit=0.05, **kwargs):
632 class HotNode(object):
633 class HotNode(object):
633 def __init__(self, site):
634 def __init__(self, site):
634 self.site = site
635 self.site = site
635 self.count = 0
636 self.count = 0
636 self.children = {}
637 self.children = {}
637
638
638 def add(self, stack, time):
639 def add(self, stack, time):
639 self.count += time
640 self.count += time
640 site = stack[0]
641 site = stack[0]
641 child = self.children.get(site)
642 child = self.children.get(site)
642 if not child:
643 if not child:
643 child = HotNode(site)
644 child = HotNode(site)
644 self.children[site] = child
645 self.children[site] = child
645
646
646 if len(stack) > 1:
647 if len(stack) > 1:
647 i = 1
648 i = 1
648 # Skip boiler plate parts of the stack
649 # Skip boiler plate parts of the stack
649 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:
650 i += 1
651 i += 1
651 if i < len(stack):
652 if i < len(stack):
652 child.add(stack[i:], time)
653 child.add(stack[i:], time)
653
654
654 root = HotNode(None)
655 root = HotNode(None)
655 lasttime = data.samples[0].time
656 lasttime = data.samples[0].time
656 for sample in data.samples:
657 for sample in data.samples:
657 root.add(sample.stack[::-1], sample.time - lasttime)
658 root.add(sample.stack[::-1], sample.time - lasttime)
658 lasttime = sample.time
659 lasttime = sample.time
659
660
660 def _write(node, depth, multiple_siblings):
661 def _write(node, depth, multiple_siblings):
661 site = node.site
662 site = node.site
662 visiblechildren = [c for c in node.children.itervalues()
663 visiblechildren = [c for c in node.children.itervalues()
663 if c.count >= (limit * root.count)]
664 if c.count >= (limit * root.count)]
664 if site:
665 if site:
665 indent = depth * 2 - 1
666 indent = depth * 2 - 1
666 filename = ''
667 filename = ''
667 function = ''
668 function = ''
668 if len(node.children) > 0:
669 if len(node.children) > 0:
669 childsite = list(node.children.itervalues())[0].site
670 childsite = list(node.children.itervalues())[0].site
670 filename = (childsite.filename() + ':').ljust(15)
671 filename = (childsite.filename() + ':').ljust(15)
671 function = childsite.function
672 function = childsite.function
672
673
673 # lots of string formatting
674 # lots of string formatting
674 listpattern = ''.ljust(indent) +\
675 listpattern = ''.ljust(indent) +\
675 ('\\' if multiple_siblings else '|') +\
676 ('\\' if multiple_siblings else '|') +\
676 ' %4.1f%% %s %s'
677 ' %4.1f%% %s %s'
677 liststring = listpattern % (node.count / root.count * 100,
678 liststring = listpattern % (node.count / root.count * 100,
678 filename, function)
679 filename, function)
679 codepattern = '%' + str(55 - len(liststring)) + 's %s: %s'
680 codepattern = '%' + str(55 - len(liststring)) + 's %s: %s'
680 codestring = codepattern % ('line', site.lineno, site.getsource(30))
681 codestring = codepattern % ('line', site.lineno, site.getsource(30))
681
682
682 finalstring = liststring + codestring
683 finalstring = liststring + codestring
683 childrensamples = sum([c.count for c in node.children.itervalues()])
684 childrensamples = sum([c.count for c in node.children.itervalues()])
684 # Make frames that performed more than 10% of the operation red
685 # Make frames that performed more than 10% of the operation red
685 if node.count - childrensamples > (0.1 * root.count):
686 if node.count - childrensamples > (0.1 * root.count):
686 finalstring = '\033[91m' + finalstring + '\033[0m'
687 finalstring = '\033[91m' + finalstring + '\033[0m'
687 # Make frames that didn't actually perform work dark grey
688 # Make frames that didn't actually perform work dark grey
688 elif node.count - childrensamples == 0:
689 elif node.count - childrensamples == 0:
689 finalstring = '\033[90m' + finalstring + '\033[0m'
690 finalstring = '\033[90m' + finalstring + '\033[0m'
690 print(finalstring, file=fp)
691 print(finalstring, file=fp)
691
692
692 newdepth = depth
693 newdepth = depth
693 if len(visiblechildren) > 1 or multiple_siblings:
694 if len(visiblechildren) > 1 or multiple_siblings:
694 newdepth += 1
695 newdepth += 1
695
696
696 visiblechildren.sort(reverse=True, key=lambda x: x.count)
697 visiblechildren.sort(reverse=True, key=lambda x: x.count)
697 for child in visiblechildren:
698 for child in visiblechildren:
698 _write(child, newdepth, len(visiblechildren) > 1)
699 _write(child, newdepth, len(visiblechildren) > 1)
699
700
700 if root.count > 0:
701 if root.count > 0:
701 _write(root, 0, False)
702 _write(root, 0, False)
702
703
703 def write_to_flame(data, fp, scriptpath=None, outputfile=None, **kwargs):
704 def write_to_flame(data, fp, scriptpath=None, outputfile=None, **kwargs):
704 if scriptpath is None:
705 if scriptpath is None:
705 scriptpath = encoding.environ['HOME'] + '/flamegraph.pl'
706 scriptpath = encoding.environ['HOME'] + '/flamegraph.pl'
706 if not os.path.exists(scriptpath):
707 if not os.path.exists(scriptpath):
707 print("error: missing %s" % scriptpath, file=fp)
708 print("error: missing %s" % scriptpath, file=fp)
708 print("get it here: https://github.com/brendangregg/FlameGraph",
709 print("get it here: https://github.com/brendangregg/FlameGraph",
709 file=fp)
710 file=fp)
710 return
711 return
711
712
712 fd, path = pycompat.mkstemp()
713 fd, path = pycompat.mkstemp()
713
714
714 file = open(path, "w+")
715 file = open(path, "w+")
715
716
716 lines = {}
717 lines = {}
717 for sample in data.samples:
718 for sample in data.samples:
718 sites = [s.function for s in sample.stack]
719 sites = [s.function for s in sample.stack]
719 sites.reverse()
720 sites.reverse()
720 line = ';'.join(sites)
721 line = ';'.join(sites)
721 if line in lines:
722 if line in lines:
722 lines[line] = lines[line] + 1
723 lines[line] = lines[line] + 1
723 else:
724 else:
724 lines[line] = 1
725 lines[line] = 1
725
726
726 for line, count in lines.iteritems():
727 for line, count in lines.iteritems():
727 file.write("%s %s\n" % (line, count))
728 file.write("%s %s\n" % (line, count))
728
729
729 file.close()
730 file.close()
730
731
731 if outputfile is None:
732 if outputfile is None:
732 outputfile = '~/flamegraph.svg'
733 outputfile = '~/flamegraph.svg'
733
734
734 os.system("perl ~/flamegraph.pl %s > %s" % (path, outputfile))
735 os.system("perl ~/flamegraph.pl %s > %s" % (path, outputfile))
735 print("Written to %s" % outputfile, file=fp)
736 print("Written to %s" % outputfile, file=fp)
736
737
737 _pathcache = {}
738 _pathcache = {}
738 def simplifypath(path):
739 def simplifypath(path):
739 '''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
740 removing whatever part of the Python search path it was found
741 removing whatever part of the Python search path it was found
741 on.'''
742 on.'''
742
743
743 if path in _pathcache:
744 if path in _pathcache:
744 return _pathcache[path]
745 return _pathcache[path]
745 hgpath = pycompat.fsencode(encoding.__file__).rsplit(os.sep, 2)[0]
746 hgpath = pycompat.fsencode(encoding.__file__).rsplit(os.sep, 2)[0]
746 for p in [hgpath] + sys.path:
747 for p in [hgpath] + sys.path:
747 prefix = p + os.sep
748 prefix = p + os.sep
748 if path.startswith(prefix):
749 if path.startswith(prefix):
749 path = path[len(prefix):]
750 path = path[len(prefix):]
750 break
751 break
751 _pathcache[path] = path
752 _pathcache[path] = path
752 return path
753 return path
753
754
754 def write_to_json(data, fp):
755 def write_to_json(data, fp):
755 samples = []
756 samples = []
756
757
757 for sample in data.samples:
758 for sample in data.samples:
758 stack = []
759 stack = []
759
760
760 for frame in sample.stack:
761 for frame in sample.stack:
761 stack.append((frame.path, frame.lineno, frame.function))
762 stack.append((frame.path, frame.lineno, frame.function))
762
763
763 samples.append((sample.time, stack))
764 samples.append((sample.time, stack))
764
765
765 print(json.dumps(samples), file=fp)
766 print(json.dumps(samples), file=fp)
766
767
767 def write_to_chrome(data, fp, minthreshold=0.005, maxthreshold=0.999):
768 def write_to_chrome(data, fp, minthreshold=0.005, maxthreshold=0.999):
768 samples = []
769 samples = []
769 laststack = collections.deque()
770 laststack = collections.deque()
770 lastseen = collections.deque()
771 lastseen = collections.deque()
771
772
772 # The Chrome tracing format allows us to use a compact stack
773 # The Chrome tracing format allows us to use a compact stack
773 # representation to save space. It's fiddly but worth it.
774 # representation to save space. It's fiddly but worth it.
774 # We maintain a bijection between stack and ID.
775 # We maintain a bijection between stack and ID.
775 stack2id = {}
776 stack2id = {}
776 id2stack = [] # will eventually be rendered
777 id2stack = [] # will eventually be rendered
777
778
778 def stackid(stack):
779 def stackid(stack):
779 if not stack:
780 if not stack:
780 return
781 return
781 if stack in stack2id:
782 if stack in stack2id:
782 return stack2id[stack]
783 return stack2id[stack]
783 parent = stackid(stack[1:])
784 parent = stackid(stack[1:])
784 myid = len(stack2id)
785 myid = len(stack2id)
785 stack2id[stack] = myid
786 stack2id[stack] = myid
786 id2stack.append(dict(category=stack[0][0], name='%s %s' % stack[0]))
787 id2stack.append(dict(category=stack[0][0], name='%s %s' % stack[0]))
787 if parent is not None:
788 if parent is not None:
788 id2stack[-1].update(parent=parent)
789 id2stack[-1].update(parent=parent)
789 return myid
790 return myid
790
791
791 def endswith(a, b):
792 def endswith(a, b):
792 return list(a)[-len(b):] == list(b)
793 return list(a)[-len(b):] == list(b)
793
794
794 # The sampling profiler can sample multiple times without
795 # The sampling profiler can sample multiple times without
795 # advancing the clock, potentially causing the Chrome trace viewer
796 # advancing the clock, potentially causing the Chrome trace viewer
796 # to render single-pixel columns that we cannot zoom in on. We
797 # to render single-pixel columns that we cannot zoom in on. We
797 # work around this by pretending that zero-duration samples are a
798 # work around this by pretending that zero-duration samples are a
798 # millisecond in length.
799 # millisecond in length.
799
800
800 clamp = 0.001
801 clamp = 0.001
801
802
802 # We provide knobs that by default attempt to filter out stack
803 # We provide knobs that by default attempt to filter out stack
803 # frames that are too noisy:
804 # frames that are too noisy:
804 #
805 #
805 # * A few take almost all execution time. These are usually boring
806 # * A few take almost all execution time. These are usually boring
806 # setup functions, giving a stack that is deep but uninformative.
807 # setup functions, giving a stack that is deep but uninformative.
807 #
808 #
808 # * Numerous samples take almost no time, but introduce lots of
809 # * Numerous samples take almost no time, but introduce lots of
809 # noisy, oft-deep "spines" into a rendered profile.
810 # noisy, oft-deep "spines" into a rendered profile.
810
811
811 blacklist = set()
812 blacklist = set()
812 totaltime = data.samples[-1].time - data.samples[0].time
813 totaltime = data.samples[-1].time - data.samples[0].time
813 minthreshold = totaltime * minthreshold
814 minthreshold = totaltime * minthreshold
814 maxthreshold = max(totaltime * maxthreshold, clamp)
815 maxthreshold = max(totaltime * maxthreshold, clamp)
815
816
816 def poplast():
817 def poplast():
817 oldsid = stackid(tuple(laststack))
818 oldsid = stackid(tuple(laststack))
818 oldcat, oldfunc = laststack.popleft()
819 oldcat, oldfunc = laststack.popleft()
819 oldtime, oldidx = lastseen.popleft()
820 oldtime, oldidx = lastseen.popleft()
820 duration = sample.time - oldtime
821 duration = sample.time - oldtime
821 if minthreshold <= duration <= maxthreshold:
822 if minthreshold <= duration <= maxthreshold:
822 # ensure no zero-duration events
823 # ensure no zero-duration events
823 sampletime = max(oldtime + clamp, sample.time)
824 sampletime = max(oldtime + clamp, sample.time)
824 samples.append(dict(ph='E', name=oldfunc, cat=oldcat, sf=oldsid,
825 samples.append(dict(ph='E', name=oldfunc, cat=oldcat, sf=oldsid,
825 ts=sampletime*1e6, pid=0))
826 ts=sampletime*1e6, pid=0))
826 else:
827 else:
827 blacklist.add(oldidx)
828 blacklist.add(oldidx)
828
829
829 # Much fiddling to synthesize correctly(ish) nested begin/end
830 # Much fiddling to synthesize correctly(ish) nested begin/end
830 # events given only stack snapshots.
831 # events given only stack snapshots.
831
832
832 for sample in data.samples:
833 for sample in data.samples:
833 tos = sample.stack[0]
834 tos = sample.stack[0]
834 name = tos.function
835 name = tos.function
835 path = simplifypath(tos.path)
836 path = simplifypath(tos.path)
836 stack = tuple((('%s:%d' % (simplifypath(frame.path), frame.lineno),
837 stack = tuple((('%s:%d' % (simplifypath(frame.path), frame.lineno),
837 frame.function) for frame in sample.stack))
838 frame.function) for frame in sample.stack))
838 qstack = collections.deque(stack)
839 qstack = collections.deque(stack)
839 if laststack == qstack:
840 if laststack == qstack:
840 continue
841 continue
841 while laststack and qstack and laststack[-1] == qstack[-1]:
842 while laststack and qstack and laststack[-1] == qstack[-1]:
842 laststack.pop()
843 laststack.pop()
843 qstack.pop()
844 qstack.pop()
844 while laststack:
845 while laststack:
845 poplast()
846 poplast()
846 for f in reversed(qstack):
847 for f in reversed(qstack):
847 lastseen.appendleft((sample.time, len(samples)))
848 lastseen.appendleft((sample.time, len(samples)))
848 laststack.appendleft(f)
849 laststack.appendleft(f)
849 path, name = f
850 path, name = f
850 sid = stackid(tuple(laststack))
851 sid = stackid(tuple(laststack))
851 samples.append(dict(ph='B', name=name, cat=path, ts=sample.time*1e6,
852 samples.append(dict(ph='B', name=name, cat=path, ts=sample.time*1e6,
852 sf=sid, pid=0))
853 sf=sid, pid=0))
853 laststack = collections.deque(stack)
854 laststack = collections.deque(stack)
854 while laststack:
855 while laststack:
855 poplast()
856 poplast()
856 events = [s[1] for s in enumerate(samples) if s[0] not in blacklist]
857 events = [s[1] for s in enumerate(samples) if s[0] not in blacklist]
857 frames = collections.OrderedDict((str(k), v)
858 frames = collections.OrderedDict((str(k), v)
858 for (k,v) in enumerate(id2stack))
859 for (k,v) in enumerate(id2stack))
859 json.dump(dict(traceEvents=events, stackFrames=frames), fp, indent=1)
860 json.dump(dict(traceEvents=events, stackFrames=frames), fp, indent=1)
860 fp.write('\n')
861 fp.write('\n')
861
862
862 def printusage():
863 def printusage():
863 print("""
864 print("""
864 The statprof command line allows you to inspect the last profile's results in
865 The statprof command line allows you to inspect the last profile's results in
865 the following forms:
866 the following forms:
866
867
867 usage:
868 usage:
868 hotpath [-l --limit percent]
869 hotpath [-l --limit percent]
869 Shows a graph of calls with the percent of time each takes.
870 Shows a graph of calls with the percent of time each takes.
870 Red calls take over 10%% of the total time themselves.
871 Red calls take over 10%% of the total time themselves.
871 lines
872 lines
872 Shows the actual sampled lines.
873 Shows the actual sampled lines.
873 functions
874 functions
874 Shows the samples grouped by function.
875 Shows the samples grouped by function.
875 function [filename:]functionname
876 function [filename:]functionname
876 Shows the callers and callees of a particular function.
877 Shows the callers and callees of a particular function.
877 flame [-s --script-path] [-o --output-file path]
878 flame [-s --script-path] [-o --output-file path]
878 Writes out a flamegraph to output-file (defaults to ~/flamegraph.svg)
879 Writes out a flamegraph to output-file (defaults to ~/flamegraph.svg)
879 Requires that ~/flamegraph.pl exist.
880 Requires that ~/flamegraph.pl exist.
880 (Specify alternate script path with --script-path.)""")
881 (Specify alternate script path with --script-path.)""")
881
882
882 def main(argv=None):
883 def main(argv=None):
883 if argv is None:
884 if argv is None:
884 argv = sys.argv
885 argv = sys.argv
885
886
886 if len(argv) == 1:
887 if len(argv) == 1:
887 printusage()
888 printusage()
888 return 0
889 return 0
889
890
890 displayargs = {}
891 displayargs = {}
891
892
892 optstart = 2
893 optstart = 2
893 displayargs['function'] = None
894 displayargs['function'] = None
894 if argv[1] == 'hotpath':
895 if argv[1] == 'hotpath':
895 displayargs['format'] = DisplayFormats.Hotpath
896 displayargs['format'] = DisplayFormats.Hotpath
896 elif argv[1] == 'lines':
897 elif argv[1] == 'lines':
897 displayargs['format'] = DisplayFormats.ByLine
898 displayargs['format'] = DisplayFormats.ByLine
898 elif argv[1] == 'functions':
899 elif argv[1] == 'functions':
899 displayargs['format'] = DisplayFormats.ByMethod
900 displayargs['format'] = DisplayFormats.ByMethod
900 elif argv[1] == 'function':
901 elif argv[1] == 'function':
901 displayargs['format'] = DisplayFormats.AboutMethod
902 displayargs['format'] = DisplayFormats.AboutMethod
902 displayargs['function'] = argv[2]
903 displayargs['function'] = argv[2]
903 optstart = 3
904 optstart = 3
904 elif argv[1] == 'flame':
905 elif argv[1] == 'flame':
905 displayargs['format'] = DisplayFormats.FlameGraph
906 displayargs['format'] = DisplayFormats.FlameGraph
906 else:
907 else:
907 printusage()
908 printusage()
908 return 0
909 return 0
909
910
910 # process options
911 # process options
911 try:
912 try:
912 opts, args = pycompat.getoptb(sys.argv[optstart:], "hl:f:o:p:",
913 opts, args = pycompat.getoptb(sys.argv[optstart:], "hl:f:o:p:",
913 ["help", "limit=", "file=", "output-file=", "script-path="])
914 ["help", "limit=", "file=", "output-file=", "script-path="])
914 except getopt.error as msg:
915 except getopt.error as msg:
915 print(msg)
916 print(msg)
916 printusage()
917 printusage()
917 return 2
918 return 2
918
919
919 displayargs['limit'] = 0.05
920 displayargs['limit'] = 0.05
920 path = None
921 path = None
921 for o, value in opts:
922 for o, value in opts:
922 if o in ("-l", "--limit"):
923 if o in ("-l", "--limit"):
923 displayargs['limit'] = float(value)
924 displayargs['limit'] = float(value)
924 elif o in ("-f", "--file"):
925 elif o in ("-f", "--file"):
925 path = value
926 path = value
926 elif o in ("-o", "--output-file"):
927 elif o in ("-o", "--output-file"):
927 displayargs['outputfile'] = value
928 displayargs['outputfile'] = value
928 elif o in ("-p", "--script-path"):
929 elif o in ("-p", "--script-path"):
929 displayargs['scriptpath'] = value
930 displayargs['scriptpath'] = value
930 elif o in ("-h", "help"):
931 elif o in ("-h", "help"):
931 printusage()
932 printusage()
932 return 0
933 return 0
933 else:
934 else:
934 assert False, "unhandled option %s" % o
935 assert False, "unhandled option %s" % o
935
936
936 if not path:
937 if not path:
937 print('must specify --file to load')
938 print('must specify --file to load')
938 return 1
939 return 1
939
940
940 load_data(path=path)
941 load_data(path=path)
941
942
942 display(**pycompat.strkwargs(displayargs))
943 display(**pycompat.strkwargs(displayargs))
943
944
944 return 0
945 return 0
945
946
946 if __name__ == "__main__":
947 if __name__ == "__main__":
947 sys.exit(main())
948 sys.exit(main())
General Comments 0
You need to be logged in to leave comments. Login now