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