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