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