##// END OF EJS Templates
statprof: with Python 3.12, lineno is (more) often None...
Mads Kiilerich -
r51230:972f3e5c stable
parent child Browse files
Show More
@@ -1,1090 +1,1094 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 pycompat.hasattr(self, 'sample_interval'):
170 elif not pycompat.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, 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' % (site.filename(), site.lineno, site.function)
543 sitelabel = b'%s:%d:%s' % (
544 site.filename(),
545 site.lineno or -1,
546 site.function,
547 )
544 fp.write(
548 fp.write(
545 b'%6.2f %9.2f %9.2f %s\n'
549 b'%6.2f %9.2f %9.2f %s\n'
546 % (
550 % (
547 stat.selfpercent(),
551 stat.selfpercent(),
548 stat.totalseconds(),
552 stat.totalseconds(),
549 stat.selfseconds(),
553 stat.selfseconds(),
550 sitelabel,
554 sitelabel,
551 )
555 )
552 )
556 )
553
557
554
558
555 def display_by_method(data, fp):
559 def display_by_method(data, fp):
556 """Print the profiler data with each sample function represented
560 """Print the profiler data with each sample function represented
557 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
558 output as nested rows. Sorted by self-time per line."""
562 output as nested rows. Sorted by self-time per line."""
559 fp.write(
563 fp.write(
560 b'%5.5s %10.10s %7.7s %-8.8s\n'
564 b'%5.5s %10.10s %7.7s %-8.8s\n'
561 % (b'% ', b'cumulative', b'self', b'')
565 % (b'% ', b'cumulative', b'self', b'')
562 )
566 )
563 fp.write(
567 fp.write(
564 b'%5.5s %9.9s %8.8s %-8.8s\n'
568 b'%5.5s %9.9s %8.8s %-8.8s\n'
565 % (b"time", b"seconds", b"seconds", b"name")
569 % (b"time", b"seconds", b"seconds", b"name")
566 )
570 )
567
571
568 stats = SiteStats.buildstats(data.samples)
572 stats = SiteStats.buildstats(data.samples)
569
573
570 grouped = defaultdict(list)
574 grouped = defaultdict(list)
571 for stat in stats:
575 for stat in stats:
572 grouped[stat.site.filename() + b":" + stat.site.function].append(stat)
576 grouped[stat.site.filename() + b":" + stat.site.function].append(stat)
573
577
574 # compute sums for each function
578 # compute sums for each function
575 functiondata = []
579 functiondata = []
576 for fname, sitestats in grouped.items():
580 for fname, sitestats in grouped.items():
577 total_cum_sec = 0
581 total_cum_sec = 0
578 total_self_sec = 0
582 total_self_sec = 0
579 total_percent = 0
583 total_percent = 0
580 for stat in sitestats:
584 for stat in sitestats:
581 total_cum_sec += stat.totalseconds()
585 total_cum_sec += stat.totalseconds()
582 total_self_sec += stat.selfseconds()
586 total_self_sec += stat.selfseconds()
583 total_percent += stat.selfpercent()
587 total_percent += stat.selfpercent()
584
588
585 functiondata.append(
589 functiondata.append(
586 (fname, total_cum_sec, total_self_sec, total_percent, sitestats)
590 (fname, total_cum_sec, total_self_sec, total_percent, sitestats)
587 )
591 )
588
592
589 # sort by total self sec
593 # sort by total self sec
590 functiondata.sort(reverse=True, key=lambda x: x[2])
594 functiondata.sort(reverse=True, key=lambda x: x[2])
591
595
592 for function in functiondata:
596 for function in functiondata:
593 if function[3] < 0.05:
597 if function[3] < 0.05:
594 continue
598 continue
595 fp.write(
599 fp.write(
596 b'%6.2f %9.2f %9.2f %s\n'
600 b'%6.2f %9.2f %9.2f %s\n'
597 % (
601 % (
598 function[3], # total percent
602 function[3], # total percent
599 function[1], # total cum sec
603 function[1], # total cum sec
600 function[2], # total self sec
604 function[2], # total self sec
601 function[0],
605 function[0],
602 )
606 )
603 ) # file:function
607 ) # file:function
604
608
605 function[4].sort(reverse=True, key=lambda i: i.selfseconds())
609 function[4].sort(reverse=True, key=lambda i: i.selfseconds())
606 for stat in function[4]:
610 for stat in function[4]:
607 # only show line numbers for significant locations (>1% time spent)
611 # only show line numbers for significant locations (>1% time spent)
608 if stat.selfpercent() > 1:
612 if stat.selfpercent() > 1:
609 source = stat.site.getsource(25)
613 source = stat.site.getsource(25)
610 if not isinstance(source, bytes):
614 if not isinstance(source, bytes):
611 source = pycompat.bytestr(source)
615 source = pycompat.bytestr(source)
612
616
613 stattuple = (
617 stattuple = (
614 stat.selfpercent(),
618 stat.selfpercent(),
615 stat.selfseconds(),
619 stat.selfseconds(),
616 stat.site.lineno,
620 stat.site.lineno or -1,
617 source,
621 source,
618 )
622 )
619
623
620 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)
621
625
622
626
623 def display_about_method(data, fp, function=None, **kwargs):
627 def display_about_method(data, fp, function=None, **kwargs):
624 if function is None:
628 if function is None:
625 raise Exception("Invalid function")
629 raise Exception("Invalid function")
626
630
627 filename = None
631 filename = None
628 if b':' in function:
632 if b':' in function:
629 filename, function = function.split(b':')
633 filename, function = function.split(b':')
630
634
631 relevant_samples = 0
635 relevant_samples = 0
632 parents = {}
636 parents = {}
633 children = {}
637 children = {}
634
638
635 for sample in data.samples:
639 for sample in data.samples:
636 for i, site in enumerate(sample.stack):
640 for i, site in enumerate(sample.stack):
637 if site.function == function and (
641 if site.function == function and (
638 not filename or site.filename() == filename
642 not filename or site.filename() == filename
639 ):
643 ):
640 relevant_samples += 1
644 relevant_samples += 1
641 if i != len(sample.stack) - 1:
645 if i != len(sample.stack) - 1:
642 parent = sample.stack[i + 1]
646 parent = sample.stack[i + 1]
643 if parent in parents:
647 if parent in parents:
644 parents[parent] = parents[parent] + 1
648 parents[parent] = parents[parent] + 1
645 else:
649 else:
646 parents[parent] = 1
650 parents[parent] = 1
647
651
648 if site in children:
652 if site in children:
649 children[site] = children[site] + 1
653 children[site] = children[site] + 1
650 else:
654 else:
651 children[site] = 1
655 children[site] = 1
652
656
653 parents = [(parent, count) for parent, count in parents.items()]
657 parents = [(parent, count) for parent, count in parents.items()]
654 parents.sort(reverse=True, key=lambda x: x[1])
658 parents.sort(reverse=True, key=lambda x: x[1])
655 for parent, count in parents:
659 for parent, count in parents:
656 fp.write(
660 fp.write(
657 b'%6.2f%% %s:%s line %s: %s\n'
661 b'%6.2f%% %s:%s line %s: %s\n'
658 % (
662 % (
659 count / relevant_samples * 100,
663 count / relevant_samples * 100,
660 pycompat.fsencode(parent.filename()),
664 pycompat.fsencode(parent.filename()),
661 pycompat.sysbytes(parent.function),
665 pycompat.sysbytes(parent.function),
662 parent.lineno,
666 parent.lineno,
663 pycompat.sysbytes(parent.getsource(50)),
667 pycompat.sysbytes(parent.getsource(50)),
664 )
668 )
665 )
669 )
666
670
667 stats = SiteStats.buildstats(data.samples)
671 stats = SiteStats.buildstats(data.samples)
668 stats = [
672 stats = [
669 s
673 s
670 for s in stats
674 for s in stats
671 if s.site.function == function
675 if s.site.function == function
672 and (not filename or s.site.filename() == filename)
676 and (not filename or s.site.filename() == filename)
673 ]
677 ]
674
678
675 total_cum_sec = 0
679 total_cum_sec = 0
676 total_self_sec = 0
680 total_self_sec = 0
677 total_self_percent = 0
681 total_self_percent = 0
678 total_cum_percent = 0
682 total_cum_percent = 0
679 for stat in stats:
683 for stat in stats:
680 total_cum_sec += stat.totalseconds()
684 total_cum_sec += stat.totalseconds()
681 total_self_sec += stat.selfseconds()
685 total_self_sec += stat.selfseconds()
682 total_self_percent += stat.selfpercent()
686 total_self_percent += stat.selfpercent()
683 total_cum_percent += stat.totalpercent()
687 total_cum_percent += stat.totalpercent()
684
688
685 fp.write(
689 fp.write(
686 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'
687 % (
691 % (
688 pycompat.sysbytes(filename or b'___'),
692 pycompat.sysbytes(filename or b'___'),
689 pycompat.sysbytes(function),
693 pycompat.sysbytes(function),
690 total_cum_sec,
694 total_cum_sec,
691 total_cum_percent,
695 total_cum_percent,
692 total_self_sec,
696 total_self_sec,
693 total_self_percent,
697 total_self_percent,
694 )
698 )
695 )
699 )
696
700
697 children = [(child, count) for child, count in children.items()]
701 children = [(child, count) for child, count in children.items()]
698 children.sort(reverse=True, key=lambda x: x[1])
702 children.sort(reverse=True, key=lambda x: x[1])
699 for child, count in children:
703 for child, count in children:
700 fp.write(
704 fp.write(
701 b' %6.2f%% line %s: %s\n'
705 b' %6.2f%% line %s: %s\n'
702 % (
706 % (
703 count / relevant_samples * 100,
707 count / relevant_samples * 100,
704 child.lineno,
708 child.lineno,
705 pycompat.sysbytes(child.getsource(50)),
709 pycompat.sysbytes(child.getsource(50)),
706 )
710 )
707 )
711 )
708
712
709
713
710 def display_hotpath(data, fp, limit=0.05, **kwargs):
714 def display_hotpath(data, fp, limit=0.05, **kwargs):
711 class HotNode:
715 class HotNode:
712 def __init__(self, site):
716 def __init__(self, site):
713 self.site = site
717 self.site = site
714 self.count = 0
718 self.count = 0
715 self.children = {}
719 self.children = {}
716
720
717 def add(self, stack, time):
721 def add(self, stack, time):
718 self.count += time
722 self.count += time
719 site = stack[0]
723 site = stack[0]
720 child = self.children.get(site)
724 child = self.children.get(site)
721 if not child:
725 if not child:
722 child = HotNode(site)
726 child = HotNode(site)
723 self.children[site] = child
727 self.children[site] = child
724
728
725 if len(stack) > 1:
729 if len(stack) > 1:
726 i = 1
730 i = 1
727 # Skip boiler plate parts of the stack
731 # Skip boiler plate parts of the stack
728 while i < len(stack) and stack[i].skipname() in skips:
732 while i < len(stack) and stack[i].skipname() in skips:
729 i += 1
733 i += 1
730 if i < len(stack):
734 if i < len(stack):
731 child.add(stack[i:], time)
735 child.add(stack[i:], time)
732 else:
736 else:
733 # Normally this is done by the .add() calls
737 # Normally this is done by the .add() calls
734 child.count += time
738 child.count += time
735
739
736 root = HotNode(None)
740 root = HotNode(None)
737 lasttime = data.samples[0].time
741 lasttime = data.samples[0].time
738 for sample in data.samples:
742 for sample in data.samples:
739 root.add(sample.stack[::-1], sample.time - lasttime)
743 root.add(sample.stack[::-1], sample.time - lasttime)
740 lasttime = sample.time
744 lasttime = sample.time
741 showtime = kwargs.get('showtime', True)
745 showtime = kwargs.get('showtime', True)
742
746
743 def _write(node, depth, multiple_siblings):
747 def _write(node, depth, multiple_siblings):
744 site = node.site
748 site = node.site
745 visiblechildren = [
749 visiblechildren = [
746 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)
747 ]
751 ]
748 if site:
752 if site:
749 indent = depth * 2 - 1
753 indent = depth * 2 - 1
750 filename = (site.filename() + b':').ljust(15)
754 filename = (site.filename() + b':').ljust(15)
751 function = site.function
755 function = site.function
752
756
753 # lots of string formatting
757 # lots of string formatting
754 listpattern = (
758 listpattern = (
755 b''.ljust(indent)
759 b''.ljust(indent)
756 + (b'\\' if multiple_siblings else b'|')
760 + (b'\\' if multiple_siblings else b'|')
757 + b' %4.1f%%'
761 + b' %4.1f%%'
758 + (b' %5.2fs' % node.count if showtime else b'')
762 + (b' %5.2fs' % node.count if showtime else b'')
759 + b' %s %s'
763 + b' %s %s'
760 )
764 )
761 liststring = listpattern % (
765 liststring = listpattern % (
762 node.count / root.count * 100,
766 node.count / root.count * 100,
763 filename,
767 filename,
764 function,
768 function,
765 )
769 )
766 # 4 to account for the word 'line'
770 # 4 to account for the word 'line'
767 spacing_len = max(4, 55 - len(liststring))
771 spacing_len = max(4, 55 - len(liststring))
768 prefix = b''
772 prefix = b''
769 if spacing_len == 4:
773 if spacing_len == 4:
770 prefix = b', '
774 prefix = b', '
771
775
772 codepattern = b'%s%s %d: %s%s'
776 codepattern = b'%s%s %d: %s%s'
773 codestring = codepattern % (
777 codestring = codepattern % (
774 prefix,
778 prefix,
775 b'line'.rjust(spacing_len),
779 b'line'.rjust(spacing_len),
776 site.lineno if site.lineno is not None else -1,
780 site.lineno if site.lineno is not None else -1,
777 b''.ljust(max(0, 4 - len(str(site.lineno)))),
781 b''.ljust(max(0, 4 - len(str(site.lineno)))),
778 site.getsource(30),
782 site.getsource(30),
779 )
783 )
780
784
781 finalstring = liststring + codestring
785 finalstring = liststring + codestring
782 childrensamples = sum([c.count for c in node.children.values()])
786 childrensamples = sum([c.count for c in node.children.values()])
783 # Make frames that performed more than 10% of the operation red
787 # Make frames that performed more than 10% of the operation red
784 if node.count - childrensamples > (0.1 * root.count):
788 if node.count - childrensamples > (0.1 * root.count):
785 finalstring = b'\033[91m' + finalstring + b'\033[0m'
789 finalstring = b'\033[91m' + finalstring + b'\033[0m'
786 # Make frames that didn't actually perform work dark grey
790 # Make frames that didn't actually perform work dark grey
787 elif node.count - childrensamples == 0:
791 elif node.count - childrensamples == 0:
788 finalstring = b'\033[90m' + finalstring + b'\033[0m'
792 finalstring = b'\033[90m' + finalstring + b'\033[0m'
789 fp.write(finalstring + b'\n')
793 fp.write(finalstring + b'\n')
790
794
791 newdepth = depth
795 newdepth = depth
792 if len(visiblechildren) > 1 or multiple_siblings:
796 if len(visiblechildren) > 1 or multiple_siblings:
793 newdepth += 1
797 newdepth += 1
794
798
795 visiblechildren.sort(reverse=True, key=lambda x: x.count)
799 visiblechildren.sort(reverse=True, key=lambda x: x.count)
796 for child in visiblechildren:
800 for child in visiblechildren:
797 _write(child, newdepth, len(visiblechildren) > 1)
801 _write(child, newdepth, len(visiblechildren) > 1)
798
802
799 if root.count > 0:
803 if root.count > 0:
800 _write(root, 0, False)
804 _write(root, 0, False)
801
805
802
806
803 def write_to_flame(data, fp, scriptpath=None, outputfile=None, **kwargs):
807 def write_to_flame(data, fp, scriptpath=None, outputfile=None, **kwargs):
804 if scriptpath is None:
808 if scriptpath is None:
805 scriptpath = encoding.environ[b'HOME'] + b'/flamegraph.pl'
809 scriptpath = encoding.environ[b'HOME'] + b'/flamegraph.pl'
806 if not os.path.exists(scriptpath):
810 if not os.path.exists(scriptpath):
807 fp.write(b'error: missing %s\n' % scriptpath)
811 fp.write(b'error: missing %s\n' % scriptpath)
808 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')
809 return
813 return
810
814
811 lines = {}
815 lines = {}
812 for sample in data.samples:
816 for sample in data.samples:
813 sites = [s.function for s in sample.stack]
817 sites = [s.function for s in sample.stack]
814 sites.reverse()
818 sites.reverse()
815 line = b';'.join(sites)
819 line = b';'.join(sites)
816 if line in lines:
820 if line in lines:
817 lines[line] = lines[line] + 1
821 lines[line] = lines[line] + 1
818 else:
822 else:
819 lines[line] = 1
823 lines[line] = 1
820
824
821 fd, path = pycompat.mkstemp()
825 fd, path = pycompat.mkstemp()
822
826
823 with open(path, b"w+") as file:
827 with open(path, b"w+") as file:
824 for line, count in lines.items():
828 for line, count in lines.items():
825 file.write(b"%s %d\n" % (line, count))
829 file.write(b"%s %d\n" % (line, count))
826
830
827 if outputfile is None:
831 if outputfile is None:
828 outputfile = b'~/flamegraph.svg'
832 outputfile = b'~/flamegraph.svg'
829
833
830 os.system(b"perl ~/flamegraph.pl %s > %s" % (path, outputfile))
834 os.system(b"perl ~/flamegraph.pl %s > %s" % (path, outputfile))
831 fp.write(b'Written to %s\n' % outputfile)
835 fp.write(b'Written to %s\n' % outputfile)
832
836
833
837
834 _pathcache = {}
838 _pathcache = {}
835
839
836
840
837 def simplifypath(path):
841 def simplifypath(path):
838 """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
839 removing whatever part of the Python search path it was found
843 removing whatever part of the Python search path it was found
840 on."""
844 on."""
841
845
842 if path in _pathcache:
846 if path in _pathcache:
843 return _pathcache[path]
847 return _pathcache[path]
844 hgpath = encoding.__file__.rsplit(os.sep, 2)[0]
848 hgpath = encoding.__file__.rsplit(os.sep, 2)[0]
845 for p in [hgpath] + sys.path:
849 for p in [hgpath] + sys.path:
846 prefix = p + os.sep
850 prefix = p + os.sep
847 if path.startswith(prefix):
851 if path.startswith(prefix):
848 path = path[len(prefix) :]
852 path = path[len(prefix) :]
849 break
853 break
850 _pathcache[path] = path
854 _pathcache[path] = path
851 return path
855 return path
852
856
853
857
854 def write_to_json(data, fp):
858 def write_to_json(data, fp):
855 samples = []
859 samples = []
856
860
857 for sample in data.samples:
861 for sample in data.samples:
858 stack = []
862 stack = []
859
863
860 for frame in sample.stack:
864 for frame in sample.stack:
861 stack.append(
865 stack.append(
862 (
866 (
863 pycompat.sysstr(frame.path),
867 pycompat.sysstr(frame.path),
864 frame.lineno,
868 frame.lineno,
865 pycompat.sysstr(frame.function),
869 pycompat.sysstr(frame.function),
866 )
870 )
867 )
871 )
868
872
869 samples.append((sample.time, stack))
873 samples.append((sample.time, stack))
870
874
871 data = json.dumps(samples)
875 data = json.dumps(samples)
872 if not isinstance(data, bytes):
876 if not isinstance(data, bytes):
873 data = data.encode('utf-8')
877 data = data.encode('utf-8')
874
878
875 fp.write(data)
879 fp.write(data)
876
880
877
881
878 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):
879 samples = []
883 samples = []
880 laststack = collections.deque()
884 laststack = collections.deque()
881 lastseen = collections.deque()
885 lastseen = collections.deque()
882
886
883 # The Chrome tracing format allows us to use a compact stack
887 # The Chrome tracing format allows us to use a compact stack
884 # representation to save space. It's fiddly but worth it.
888 # representation to save space. It's fiddly but worth it.
885 # We maintain a bijection between stack and ID.
889 # We maintain a bijection between stack and ID.
886 stack2id = {}
890 stack2id = {}
887 id2stack = [] # will eventually be rendered
891 id2stack = [] # will eventually be rendered
888
892
889 def stackid(stack):
893 def stackid(stack):
890 if not stack:
894 if not stack:
891 return
895 return
892 if stack in stack2id:
896 if stack in stack2id:
893 return stack2id[stack]
897 return stack2id[stack]
894 parent = stackid(stack[1:])
898 parent = stackid(stack[1:])
895 myid = len(stack2id)
899 myid = len(stack2id)
896 stack2id[stack] = myid
900 stack2id[stack] = myid
897 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]))
898 if parent is not None:
902 if parent is not None:
899 id2stack[-1].update(parent=parent)
903 id2stack[-1].update(parent=parent)
900 return myid
904 return myid
901
905
902 # The sampling profiler can sample multiple times without
906 # The sampling profiler can sample multiple times without
903 # advancing the clock, potentially causing the Chrome trace viewer
907 # advancing the clock, potentially causing the Chrome trace viewer
904 # 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
905 # work around this by pretending that zero-duration samples are a
909 # work around this by pretending that zero-duration samples are a
906 # millisecond in length.
910 # millisecond in length.
907
911
908 clamp = 0.001
912 clamp = 0.001
909
913
910 # We provide knobs that by default attempt to filter out stack
914 # We provide knobs that by default attempt to filter out stack
911 # frames that are too noisy:
915 # frames that are too noisy:
912 #
916 #
913 # * A few take almost all execution time. These are usually boring
917 # * A few take almost all execution time. These are usually boring
914 # setup functions, giving a stack that is deep but uninformative.
918 # setup functions, giving a stack that is deep but uninformative.
915 #
919 #
916 # * Numerous samples take almost no time, but introduce lots of
920 # * Numerous samples take almost no time, but introduce lots of
917 # noisy, oft-deep "spines" into a rendered profile.
921 # noisy, oft-deep "spines" into a rendered profile.
918
922
919 blacklist = set()
923 blacklist = set()
920 totaltime = data.samples[-1].time - data.samples[0].time
924 totaltime = data.samples[-1].time - data.samples[0].time
921 minthreshold = totaltime * minthreshold
925 minthreshold = totaltime * minthreshold
922 maxthreshold = max(totaltime * maxthreshold, clamp)
926 maxthreshold = max(totaltime * maxthreshold, clamp)
923
927
924 def poplast():
928 def poplast():
925 oldsid = stackid(tuple(laststack))
929 oldsid = stackid(tuple(laststack))
926 oldcat, oldfunc = laststack.popleft()
930 oldcat, oldfunc = laststack.popleft()
927 oldtime, oldidx = lastseen.popleft()
931 oldtime, oldidx = lastseen.popleft()
928 duration = sample.time - oldtime
932 duration = sample.time - oldtime
929 if minthreshold <= duration <= maxthreshold:
933 if minthreshold <= duration <= maxthreshold:
930 # ensure no zero-duration events
934 # ensure no zero-duration events
931 sampletime = max(oldtime + clamp, sample.time)
935 sampletime = max(oldtime + clamp, sample.time)
932 samples.append(
936 samples.append(
933 dict(
937 dict(
934 ph='E',
938 ph='E',
935 name=oldfunc,
939 name=oldfunc,
936 cat=oldcat,
940 cat=oldcat,
937 sf=oldsid,
941 sf=oldsid,
938 ts=sampletime * 1e6,
942 ts=sampletime * 1e6,
939 pid=0,
943 pid=0,
940 )
944 )
941 )
945 )
942 else:
946 else:
943 blacklist.add(oldidx)
947 blacklist.add(oldidx)
944
948
945 # Much fiddling to synthesize correctly(ish) nested begin/end
949 # Much fiddling to synthesize correctly(ish) nested begin/end
946 # events given only stack snapshots.
950 # events given only stack snapshots.
947
951
948 for sample in data.samples:
952 for sample in data.samples:
949 stack = tuple(
953 stack = tuple(
950 (
954 (
951 (
955 (
952 '%s:%d'
956 '%s:%d'
953 % (simplifypath(pycompat.sysstr(frame.path)), frame.lineno),
957 % (simplifypath(pycompat.sysstr(frame.path)), frame.lineno),
954 pycompat.sysstr(frame.function),
958 pycompat.sysstr(frame.function),
955 )
959 )
956 for frame in sample.stack
960 for frame in sample.stack
957 )
961 )
958 )
962 )
959 qstack = collections.deque(stack)
963 qstack = collections.deque(stack)
960 if laststack == qstack:
964 if laststack == qstack:
961 continue
965 continue
962 while laststack and qstack and laststack[-1] == qstack[-1]:
966 while laststack and qstack and laststack[-1] == qstack[-1]:
963 laststack.pop()
967 laststack.pop()
964 qstack.pop()
968 qstack.pop()
965 while laststack:
969 while laststack:
966 poplast()
970 poplast()
967 for f in reversed(qstack):
971 for f in reversed(qstack):
968 lastseen.appendleft((sample.time, len(samples)))
972 lastseen.appendleft((sample.time, len(samples)))
969 laststack.appendleft(f)
973 laststack.appendleft(f)
970 path, name = f
974 path, name = f
971 sid = stackid(tuple(laststack))
975 sid = stackid(tuple(laststack))
972 samples.append(
976 samples.append(
973 dict(
977 dict(
974 ph='B',
978 ph='B',
975 name=name,
979 name=name,
976 cat=path,
980 cat=path,
977 ts=sample.time * 1e6,
981 ts=sample.time * 1e6,
978 sf=sid,
982 sf=sid,
979 pid=0,
983 pid=0,
980 )
984 )
981 )
985 )
982 laststack = collections.deque(stack)
986 laststack = collections.deque(stack)
983 while laststack:
987 while laststack:
984 poplast()
988 poplast()
985 events = [
989 events = [
986 sample for idx, sample in enumerate(samples) if idx not in blacklist
990 sample for idx, sample in enumerate(samples) if idx not in blacklist
987 ]
991 ]
988 frames = collections.OrderedDict(
992 frames = collections.OrderedDict(
989 (str(k), v) for (k, v) in enumerate(id2stack)
993 (str(k), v) for (k, v) in enumerate(id2stack)
990 )
994 )
991 data = json.dumps(dict(traceEvents=events, stackFrames=frames), indent=1)
995 data = json.dumps(dict(traceEvents=events, stackFrames=frames), indent=1)
992 if not isinstance(data, bytes):
996 if not isinstance(data, bytes):
993 data = data.encode('utf-8')
997 data = data.encode('utf-8')
994 fp.write(data)
998 fp.write(data)
995 fp.write(b'\n')
999 fp.write(b'\n')
996
1000
997
1001
998 def printusage():
1002 def printusage():
999 print(
1003 print(
1000 r"""
1004 r"""
1001 The statprof command line allows you to inspect the last profile's results in
1005 The statprof command line allows you to inspect the last profile's results in
1002 the following forms:
1006 the following forms:
1003
1007
1004 usage:
1008 usage:
1005 hotpath [-l --limit percent]
1009 hotpath [-l --limit percent]
1006 Shows a graph of calls with the percent of time each takes.
1010 Shows a graph of calls with the percent of time each takes.
1007 Red calls take over 10%% of the total time themselves.
1011 Red calls take over 10%% of the total time themselves.
1008 lines
1012 lines
1009 Shows the actual sampled lines.
1013 Shows the actual sampled lines.
1010 functions
1014 functions
1011 Shows the samples grouped by function.
1015 Shows the samples grouped by function.
1012 function [filename:]functionname
1016 function [filename:]functionname
1013 Shows the callers and callees of a particular function.
1017 Shows the callers and callees of a particular function.
1014 flame [-s --script-path] [-o --output-file path]
1018 flame [-s --script-path] [-o --output-file path]
1015 Writes out a flamegraph to output-file (defaults to ~/flamegraph.svg)
1019 Writes out a flamegraph to output-file (defaults to ~/flamegraph.svg)
1016 Requires that ~/flamegraph.pl exist.
1020 Requires that ~/flamegraph.pl exist.
1017 (Specify alternate script path with --script-path.)"""
1021 (Specify alternate script path with --script-path.)"""
1018 )
1022 )
1019
1023
1020
1024
1021 def main(argv=None):
1025 def main(argv=None):
1022 if argv is None:
1026 if argv is None:
1023 argv = sys.argv
1027 argv = sys.argv
1024
1028
1025 if len(argv) == 1:
1029 if len(argv) == 1:
1026 printusage()
1030 printusage()
1027 return 0
1031 return 0
1028
1032
1029 displayargs = {}
1033 displayargs = {}
1030
1034
1031 optstart = 2
1035 optstart = 2
1032 displayargs[b'function'] = None
1036 displayargs[b'function'] = None
1033 if argv[1] == 'hotpath':
1037 if argv[1] == 'hotpath':
1034 displayargs[b'format'] = DisplayFormats.Hotpath
1038 displayargs[b'format'] = DisplayFormats.Hotpath
1035 elif argv[1] == 'lines':
1039 elif argv[1] == 'lines':
1036 displayargs[b'format'] = DisplayFormats.ByLine
1040 displayargs[b'format'] = DisplayFormats.ByLine
1037 elif argv[1] == 'functions':
1041 elif argv[1] == 'functions':
1038 displayargs[b'format'] = DisplayFormats.ByMethod
1042 displayargs[b'format'] = DisplayFormats.ByMethod
1039 elif argv[1] == 'function':
1043 elif argv[1] == 'function':
1040 displayargs[b'format'] = DisplayFormats.AboutMethod
1044 displayargs[b'format'] = DisplayFormats.AboutMethod
1041 displayargs[b'function'] = argv[2]
1045 displayargs[b'function'] = argv[2]
1042 optstart = 3
1046 optstart = 3
1043 elif argv[1] == 'flame':
1047 elif argv[1] == 'flame':
1044 displayargs[b'format'] = DisplayFormats.FlameGraph
1048 displayargs[b'format'] = DisplayFormats.FlameGraph
1045 else:
1049 else:
1046 printusage()
1050 printusage()
1047 return 0
1051 return 0
1048
1052
1049 # process options
1053 # process options
1050 try:
1054 try:
1051 opts, args = pycompat.getoptb(
1055 opts, args = pycompat.getoptb(
1052 pycompat.sysargv[optstart:],
1056 pycompat.sysargv[optstart:],
1053 b"hl:f:o:p:",
1057 b"hl:f:o:p:",
1054 [b"help", b"limit=", b"file=", b"output-file=", b"script-path="],
1058 [b"help", b"limit=", b"file=", b"output-file=", b"script-path="],
1055 )
1059 )
1056 except getopt.error as msg:
1060 except getopt.error as msg:
1057 print(msg)
1061 print(msg)
1058 printusage()
1062 printusage()
1059 return 2
1063 return 2
1060
1064
1061 displayargs[b'limit'] = 0.05
1065 displayargs[b'limit'] = 0.05
1062 path = None
1066 path = None
1063 for o, value in opts:
1067 for o, value in opts:
1064 if o in ("-l", "--limit"):
1068 if o in ("-l", "--limit"):
1065 displayargs[b'limit'] = float(value)
1069 displayargs[b'limit'] = float(value)
1066 elif o in ("-f", "--file"):
1070 elif o in ("-f", "--file"):
1067 path = value
1071 path = value
1068 elif o in ("-o", "--output-file"):
1072 elif o in ("-o", "--output-file"):
1069 displayargs[b'outputfile'] = value
1073 displayargs[b'outputfile'] = value
1070 elif o in ("-p", "--script-path"):
1074 elif o in ("-p", "--script-path"):
1071 displayargs[b'scriptpath'] = value
1075 displayargs[b'scriptpath'] = value
1072 elif o in ("-h", "help"):
1076 elif o in ("-h", "help"):
1073 printusage()
1077 printusage()
1074 return 0
1078 return 0
1075 else:
1079 else:
1076 assert False, "unhandled option %s" % o
1080 assert False, "unhandled option %s" % o
1077
1081
1078 if not path:
1082 if not path:
1079 print('must specify --file to load')
1083 print('must specify --file to load')
1080 return 1
1084 return 1
1081
1085
1082 load_data(path=path)
1086 load_data(path=path)
1083
1087
1084 display(**pycompat.strkwargs(displayargs))
1088 display(**pycompat.strkwargs(displayargs))
1085
1089
1086 return 0
1090 return 0
1087
1091
1088
1092
1089 if __name__ == "__main__":
1093 if __name__ == "__main__":
1090 sys.exit(main())
1094 sys.exit(main())
General Comments 0
You need to be logged in to leave comments. Login now