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