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