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