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