##// END OF EJS Templates
py3: make statprof's chrome output work...
Martin von Zweigbergk -
r43105:cde1c101 default
parent child Browse files
Show More
@@ -1,969 +1,971 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__ = (r'path', r'lineno', r'function', r'source')
207 207
208 208 def __init__(self, path, lineno, function):
209 209 assert isinstance(path, bytes)
210 210 self.path = path
211 211 self.lineno = lineno
212 212 assert isinstance(function, bytes)
213 213 self.function = function
214 214 self.source = None
215 215
216 216 def __eq__(self, other):
217 217 try:
218 218 return (self.lineno == other.lineno and
219 219 self.path == other.path)
220 220 except:
221 221 return False
222 222
223 223 def __hash__(self):
224 224 return hash((self.lineno, self.path))
225 225
226 226 @classmethod
227 227 def get(cls, path, lineno, function):
228 228 k = (path, lineno)
229 229 try:
230 230 return cls.cache[k]
231 231 except KeyError:
232 232 v = cls(path, lineno, function)
233 233 cls.cache[k] = v
234 234 return v
235 235
236 236 def getsource(self, length):
237 237 if self.source is None:
238 238 lineno = self.lineno - 1
239 239 try:
240 240 with open(self.path, 'rb') as fp:
241 241 for i, line in enumerate(fp):
242 242 if i == lineno:
243 243 self.source = line.strip()
244 244 break
245 245 except:
246 246 pass
247 247 if self.source is None:
248 248 self.source = ''
249 249
250 250 source = self.source
251 251 if len(source) > length:
252 252 source = source[:(length - 3)] + "..."
253 253 return source
254 254
255 255 def filename(self):
256 256 return os.path.basename(self.path)
257 257
258 258 def skipname(self):
259 259 return r'%s:%s' % (self.filename(), self.function)
260 260
261 261 class Sample(object):
262 262 __slots__ = (r'stack', r'time')
263 263
264 264 def __init__(self, stack, time):
265 265 self.stack = stack
266 266 self.time = time
267 267
268 268 @classmethod
269 269 def from_frame(cls, frame, time):
270 270 stack = []
271 271
272 272 while frame:
273 273 stack.append(CodeSite.get(
274 274 pycompat.sysbytes(frame.f_code.co_filename),
275 275 frame.f_lineno,
276 276 pycompat.sysbytes(frame.f_code.co_name)))
277 277 frame = frame.f_back
278 278
279 279 return Sample(stack, time)
280 280
281 281 ###########################################################################
282 282 ## SIGPROF handler
283 283
284 284 def profile_signal_handler(signum, frame):
285 285 if state.profile_level > 0:
286 286 now = clock()
287 287 state.accumulate_time(now)
288 288
289 289 timestamp = state.accumulated_time[state.timeidx]
290 290 state.samples.append(Sample.from_frame(frame, timestamp))
291 291
292 292 signal.setitimer(signal.ITIMER_PROF,
293 293 state.sample_interval, 0.0)
294 294 state.last_start_time = now
295 295
296 296 stopthread = threading.Event()
297 297 def samplerthread(tid):
298 298 while not stopthread.is_set():
299 299 now = clock()
300 300 state.accumulate_time(now)
301 301
302 302 frame = sys._current_frames()[tid]
303 303
304 304 timestamp = state.accumulated_time[state.timeidx]
305 305 state.samples.append(Sample.from_frame(frame, timestamp))
306 306
307 307 state.last_start_time = now
308 308 time.sleep(state.sample_interval)
309 309
310 310 stopthread.clear()
311 311
312 312 ###########################################################################
313 313 ## Profiling API
314 314
315 315 def is_active():
316 316 return state.profile_level > 0
317 317
318 318 lastmechanism = None
319 319 def start(mechanism='thread', track='cpu'):
320 320 '''Install the profiling signal handler, and start profiling.'''
321 321 state.track = track # note: nesting different mode won't work
322 322 state.profile_level += 1
323 323 if state.profile_level == 1:
324 324 state.last_start_time = clock()
325 325 rpt = state.remaining_prof_time
326 326 state.remaining_prof_time = None
327 327
328 328 global lastmechanism
329 329 lastmechanism = mechanism
330 330
331 331 if mechanism == 'signal':
332 332 signal.signal(signal.SIGPROF, profile_signal_handler)
333 333 signal.setitimer(signal.ITIMER_PROF,
334 334 rpt or state.sample_interval, 0.0)
335 335 elif mechanism == 'thread':
336 336 frame = inspect.currentframe()
337 337 tid = [k for k, f in sys._current_frames().items() if f == frame][0]
338 338 state.thread = threading.Thread(target=samplerthread,
339 339 args=(tid,), name="samplerthread")
340 340 state.thread.start()
341 341
342 342 def stop():
343 343 '''Stop profiling, and uninstall the profiling signal handler.'''
344 344 state.profile_level -= 1
345 345 if state.profile_level == 0:
346 346 if lastmechanism == 'signal':
347 347 rpt = signal.setitimer(signal.ITIMER_PROF, 0.0, 0.0)
348 348 signal.signal(signal.SIGPROF, signal.SIG_IGN)
349 349 state.remaining_prof_time = rpt[0]
350 350 elif lastmechanism == 'thread':
351 351 stopthread.set()
352 352 state.thread.join()
353 353
354 354 state.accumulate_time(clock())
355 355 state.last_start_time = None
356 356 statprofpath = encoding.environ.get('STATPROF_DEST')
357 357 if statprofpath:
358 358 save_data(statprofpath)
359 359
360 360 return state
361 361
362 362 def save_data(path):
363 363 with open(path, 'w+') as file:
364 364 file.write("%f %f\n" % state.accumulated_time)
365 365 for sample in state.samples:
366 366 time = sample.time
367 367 stack = sample.stack
368 368 sites = ['\1'.join([s.path, b'%d' % s.lineno, s.function])
369 369 for s in stack]
370 370 file.write("%d\0%s\n" % (time, '\0'.join(sites)))
371 371
372 372 def load_data(path):
373 373 lines = open(path, 'rb').read().splitlines()
374 374
375 375 state.accumulated_time = [float(value) for value in lines[0].split()]
376 376 state.samples = []
377 377 for line in lines[1:]:
378 378 parts = line.split('\0')
379 379 time = float(parts[0])
380 380 rawsites = parts[1:]
381 381 sites = []
382 382 for rawsite in rawsites:
383 383 siteparts = rawsite.split('\1')
384 384 sites.append(CodeSite.get(siteparts[0], int(siteparts[1]),
385 385 siteparts[2]))
386 386
387 387 state.samples.append(Sample(sites, time))
388 388
389 389
390 390
391 391 def reset(frequency=None):
392 392 '''Clear out the state of the profiler. Do not call while the
393 393 profiler is running.
394 394
395 395 The optional frequency argument specifies the number of samples to
396 396 collect per second.'''
397 397 assert state.profile_level == 0, "Can't reset() while statprof is running"
398 398 CodeSite.cache.clear()
399 399 state.reset(frequency)
400 400
401 401
402 402 @contextmanager
403 403 def profile():
404 404 start()
405 405 try:
406 406 yield
407 407 finally:
408 408 stop()
409 409 display()
410 410
411 411
412 412 ###########################################################################
413 413 ## Reporting API
414 414
415 415 class SiteStats(object):
416 416 def __init__(self, site):
417 417 self.site = site
418 418 self.selfcount = 0
419 419 self.totalcount = 0
420 420
421 421 def addself(self):
422 422 self.selfcount += 1
423 423
424 424 def addtotal(self):
425 425 self.totalcount += 1
426 426
427 427 def selfpercent(self):
428 428 return self.selfcount / len(state.samples) * 100
429 429
430 430 def totalpercent(self):
431 431 return self.totalcount / len(state.samples) * 100
432 432
433 433 def selfseconds(self):
434 434 return self.selfcount * state.seconds_per_sample()
435 435
436 436 def totalseconds(self):
437 437 return self.totalcount * state.seconds_per_sample()
438 438
439 439 @classmethod
440 440 def buildstats(cls, samples):
441 441 stats = {}
442 442
443 443 for sample in samples:
444 444 for i, site in enumerate(sample.stack):
445 445 sitestat = stats.get(site)
446 446 if not sitestat:
447 447 sitestat = SiteStats(site)
448 448 stats[site] = sitestat
449 449
450 450 sitestat.addtotal()
451 451
452 452 if i == 0:
453 453 sitestat.addself()
454 454
455 455 return [s for s in stats.itervalues()]
456 456
457 457 class DisplayFormats:
458 458 ByLine = 0
459 459 ByMethod = 1
460 460 AboutMethod = 2
461 461 Hotpath = 3
462 462 FlameGraph = 4
463 463 Json = 5
464 464 Chrome = 6
465 465
466 466 def display(fp=None, format=3, data=None, **kwargs):
467 467 '''Print statistics, either to stdout or the given file object.'''
468 468 if data is None:
469 469 data = state
470 470
471 471 if fp is None:
472 472 import sys
473 473 fp = sys.stdout
474 474 if len(data.samples) == 0:
475 475 fp.write(b'No samples recorded.\n')
476 476 return
477 477
478 478 if format == DisplayFormats.ByLine:
479 479 display_by_line(data, fp)
480 480 elif format == DisplayFormats.ByMethod:
481 481 display_by_method(data, fp)
482 482 elif format == DisplayFormats.AboutMethod:
483 483 display_about_method(data, fp, **kwargs)
484 484 elif format == DisplayFormats.Hotpath:
485 485 display_hotpath(data, fp, **kwargs)
486 486 elif format == DisplayFormats.FlameGraph:
487 487 write_to_flame(data, fp, **kwargs)
488 488 elif format == DisplayFormats.Json:
489 489 write_to_json(data, fp)
490 490 elif format == DisplayFormats.Chrome:
491 491 write_to_chrome(data, fp, **kwargs)
492 492 else:
493 493 raise Exception("Invalid display format")
494 494
495 495 if format not in (DisplayFormats.Json, DisplayFormats.Chrome):
496 496 fp.write(b'---\n')
497 497 fp.write(b'Sample count: %d\n' % len(data.samples))
498 498 fp.write(b'Total time: %f seconds (%f wall)\n' % data.accumulated_time)
499 499
500 500 def display_by_line(data, fp):
501 501 '''Print the profiler data with each sample line represented
502 502 as one row in a table. Sorted by self-time per line.'''
503 503 stats = SiteStats.buildstats(data.samples)
504 504 stats.sort(reverse=True, key=lambda x: x.selfseconds())
505 505
506 506 fp.write(b'%5.5s %10.10s %7.7s %-8.8s\n' % (
507 507 b'% ', b'cumulative', b'self', b''))
508 508 fp.write(b'%5.5s %9.9s %8.8s %-8.8s\n' % (
509 509 b"time", b"seconds", b"seconds", b"name"))
510 510
511 511 for stat in stats:
512 512 site = stat.site
513 513 sitelabel = '%s:%d:%s' % (site.filename(),
514 514 site.lineno,
515 515 site.function)
516 516 fp.write(b'%6.2f %9.2f %9.2f %s\n' % (
517 517 stat.selfpercent(), stat.totalseconds(),
518 518 stat.selfseconds(), sitelabel))
519 519
520 520 def display_by_method(data, fp):
521 521 '''Print the profiler data with each sample function represented
522 522 as one row in a table. Important lines within that function are
523 523 output as nested rows. Sorted by self-time per line.'''
524 524 fp.write(b'%5.5s %10.10s %7.7s %-8.8s\n' %
525 525 ('% ', 'cumulative', 'self', ''))
526 526 fp.write(b'%5.5s %9.9s %8.8s %-8.8s\n' %
527 527 ("time", "seconds", "seconds", "name"))
528 528
529 529 stats = SiteStats.buildstats(data.samples)
530 530
531 531 grouped = defaultdict(list)
532 532 for stat in stats:
533 533 grouped[stat.site.filename() + b":" + stat.site.function].append(stat)
534 534
535 535 # compute sums for each function
536 536 functiondata = []
537 537 for fname, sitestats in grouped.iteritems():
538 538 total_cum_sec = 0
539 539 total_self_sec = 0
540 540 total_percent = 0
541 541 for stat in sitestats:
542 542 total_cum_sec += stat.totalseconds()
543 543 total_self_sec += stat.selfseconds()
544 544 total_percent += stat.selfpercent()
545 545
546 546 functiondata.append((fname,
547 547 total_cum_sec,
548 548 total_self_sec,
549 549 total_percent,
550 550 sitestats))
551 551
552 552 # sort by total self sec
553 553 functiondata.sort(reverse=True, key=lambda x: x[2])
554 554
555 555 for function in functiondata:
556 556 if function[3] < 0.05:
557 557 continue
558 558 fp.write(b'%6.2f %9.2f %9.2f %s\n' % (
559 559 function[3], # total percent
560 560 function[1], # total cum sec
561 561 function[2], # total self sec
562 562 function[0])) # file:function
563 563
564 564 function[4].sort(reverse=True, key=lambda i: i.selfseconds())
565 565 for stat in function[4]:
566 566 # only show line numbers for significant locations (>1% time spent)
567 567 if stat.selfpercent() > 1:
568 568 source = stat.site.getsource(25)
569 569 if sys.version_info.major >= 3 and not isinstance(source, bytes):
570 570 source = pycompat.bytestr(source)
571 571
572 572 stattuple = (stat.selfpercent(), stat.selfseconds(),
573 573 stat.site.lineno, source)
574 574
575 575 fp.write(b'%33.0f%% %6.2f line %d: %s\n' % stattuple)
576 576
577 577 def display_about_method(data, fp, function=None, **kwargs):
578 578 if function is None:
579 579 raise Exception("Invalid function")
580 580
581 581 filename = None
582 582 if ':' in function:
583 583 filename, function = function.split(':')
584 584
585 585 relevant_samples = 0
586 586 parents = {}
587 587 children = {}
588 588
589 589 for sample in data.samples:
590 590 for i, site in enumerate(sample.stack):
591 591 if site.function == function and (not filename
592 592 or site.filename() == filename):
593 593 relevant_samples += 1
594 594 if i != len(sample.stack) - 1:
595 595 parent = sample.stack[i + 1]
596 596 if parent in parents:
597 597 parents[parent] = parents[parent] + 1
598 598 else:
599 599 parents[parent] = 1
600 600
601 601 if site in children:
602 602 children[site] = children[site] + 1
603 603 else:
604 604 children[site] = 1
605 605
606 606 parents = [(parent, count) for parent, count in parents.iteritems()]
607 607 parents.sort(reverse=True, key=lambda x: x[1])
608 608 for parent, count in parents:
609 609 fp.write(b'%6.2f%% %s:%s line %s: %s\n' %
610 610 (count / relevant_samples * 100,
611 611 pycompat.fsencode(parent.filename()),
612 612 pycompat.sysbytes(parent.function),
613 613 parent.lineno,
614 614 pycompat.sysbytes(parent.getsource(50))))
615 615
616 616 stats = SiteStats.buildstats(data.samples)
617 617 stats = [s for s in stats
618 618 if s.site.function == function and
619 619 (not filename or s.site.filename() == filename)]
620 620
621 621 total_cum_sec = 0
622 622 total_self_sec = 0
623 623 total_self_percent = 0
624 624 total_cum_percent = 0
625 625 for stat in stats:
626 626 total_cum_sec += stat.totalseconds()
627 627 total_self_sec += stat.selfseconds()
628 628 total_self_percent += stat.selfpercent()
629 629 total_cum_percent += stat.totalpercent()
630 630
631 631 fp.write(
632 632 b'\n %s:%s Total: %0.2fs (%0.2f%%) Self: %0.2fs (%0.2f%%)\n\n'
633 633 % (
634 634 pycompat.sysbytes(filename or '___'),
635 635 pycompat.sysbytes(function),
636 636 total_cum_sec,
637 637 total_cum_percent,
638 638 total_self_sec,
639 639 total_self_percent
640 640 ))
641 641
642 642 children = [(child, count) for child, count in children.iteritems()]
643 643 children.sort(reverse=True, key=lambda x: x[1])
644 644 for child, count in children:
645 645 fp.write(b' %6.2f%% line %s: %s\n' %
646 646 (count / relevant_samples * 100, child.lineno,
647 647 pycompat.sysbytes(child.getsource(50))))
648 648
649 649 def display_hotpath(data, fp, limit=0.05, **kwargs):
650 650 class HotNode(object):
651 651 def __init__(self, site):
652 652 self.site = site
653 653 self.count = 0
654 654 self.children = {}
655 655
656 656 def add(self, stack, time):
657 657 self.count += time
658 658 site = stack[0]
659 659 child = self.children.get(site)
660 660 if not child:
661 661 child = HotNode(site)
662 662 self.children[site] = child
663 663
664 664 if len(stack) > 1:
665 665 i = 1
666 666 # Skip boiler plate parts of the stack
667 667 while i < len(stack) and stack[i].skipname() in skips:
668 668 i += 1
669 669 if i < len(stack):
670 670 child.add(stack[i:], time)
671 671
672 672 root = HotNode(None)
673 673 lasttime = data.samples[0].time
674 674 for sample in data.samples:
675 675 root.add(sample.stack[::-1], sample.time - lasttime)
676 676 lasttime = sample.time
677 677 showtime = kwargs.get(r'showtime', True)
678 678
679 679 def _write(node, depth, multiple_siblings):
680 680 site = node.site
681 681 visiblechildren = [c for c in node.children.itervalues()
682 682 if c.count >= (limit * root.count)]
683 683 if site:
684 684 indent = depth * 2 - 1
685 685 filename = ''
686 686 function = ''
687 687 if len(node.children) > 0:
688 688 childsite = list(node.children.itervalues())[0].site
689 689 filename = (childsite.filename() + ':').ljust(15)
690 690 function = childsite.function
691 691
692 692 # lots of string formatting
693 693 listpattern = ''.ljust(indent) +\
694 694 ('\\' if multiple_siblings else '|') +\
695 695 ' %4.1f%%' +\
696 696 (' %5.2fs' % node.count if showtime else '') +\
697 697 ' %s %s'
698 698 liststring = listpattern % (node.count / root.count * 100,
699 699 filename, function)
700 700 codepattern = '%' + ('%d' % (55 - len(liststring))) + 's %d: %s'
701 701 codestring = codepattern % ('line', site.lineno, site.getsource(30))
702 702
703 703 finalstring = liststring + codestring
704 704 childrensamples = sum([c.count for c in node.children.itervalues()])
705 705 # Make frames that performed more than 10% of the operation red
706 706 if node.count - childrensamples > (0.1 * root.count):
707 707 finalstring = '\033[91m' + finalstring + '\033[0m'
708 708 # Make frames that didn't actually perform work dark grey
709 709 elif node.count - childrensamples == 0:
710 710 finalstring = '\033[90m' + finalstring + '\033[0m'
711 711 fp.write(finalstring + b'\n')
712 712
713 713 newdepth = depth
714 714 if len(visiblechildren) > 1 or multiple_siblings:
715 715 newdepth += 1
716 716
717 717 visiblechildren.sort(reverse=True, key=lambda x: x.count)
718 718 for child in visiblechildren:
719 719 _write(child, newdepth, len(visiblechildren) > 1)
720 720
721 721 if root.count > 0:
722 722 _write(root, 0, False)
723 723
724 724 def write_to_flame(data, fp, scriptpath=None, outputfile=None, **kwargs):
725 725 if scriptpath is None:
726 726 scriptpath = encoding.environ['HOME'] + '/flamegraph.pl'
727 727 if not os.path.exists(scriptpath):
728 728 fp.write(b'error: missing %s\n' % scriptpath)
729 729 fp.write(b'get it here: https://github.com/brendangregg/FlameGraph\n')
730 730 return
731 731
732 732 lines = {}
733 733 for sample in data.samples:
734 734 sites = [s.function for s in sample.stack]
735 735 sites.reverse()
736 736 line = ';'.join(sites)
737 737 if line in lines:
738 738 lines[line] = lines[line] + 1
739 739 else:
740 740 lines[line] = 1
741 741
742 742 fd, path = pycompat.mkstemp()
743 743
744 744 with open(path, "w+") as file:
745 745 for line, count in lines.iteritems():
746 746 file.write("%s %d\n" % (line, count))
747 747
748 748 if outputfile is None:
749 749 outputfile = '~/flamegraph.svg'
750 750
751 751 os.system("perl ~/flamegraph.pl %s > %s" % (path, outputfile))
752 752 fp.write(b'Written to %s\n' % outputfile)
753 753
754 754 _pathcache = {}
755 755 def simplifypath(path):
756 756 '''Attempt to make the path to a Python module easier to read by
757 757 removing whatever part of the Python search path it was found
758 758 on.'''
759 759
760 760 if path in _pathcache:
761 761 return _pathcache[path]
762 hgpath = pycompat.fsencode(encoding.__file__).rsplit(os.sep, 2)[0]
762 hgpath = encoding.__file__.rsplit(os.sep, 2)[0]
763 763 for p in [hgpath] + sys.path:
764 764 prefix = p + os.sep
765 765 if path.startswith(prefix):
766 766 path = path[len(prefix):]
767 767 break
768 768 _pathcache[path] = path
769 769 return path
770 770
771 771 def write_to_json(data, fp):
772 772 samples = []
773 773
774 774 for sample in data.samples:
775 775 stack = []
776 776
777 777 for frame in sample.stack:
778 778 stack.append(
779 779 (pycompat.sysstr(frame.path),
780 780 frame.lineno,
781 781 pycompat.sysstr(frame.function)))
782 782
783 783 samples.append((sample.time, stack))
784 784
785 785 data = json.dumps(samples)
786 786 if not isinstance(data, bytes):
787 787 data = data.encode('utf-8')
788 788
789 789 fp.write(data)
790 790
791 791 def write_to_chrome(data, fp, minthreshold=0.005, maxthreshold=0.999):
792 792 samples = []
793 793 laststack = collections.deque()
794 794 lastseen = collections.deque()
795 795
796 796 # The Chrome tracing format allows us to use a compact stack
797 797 # representation to save space. It's fiddly but worth it.
798 798 # We maintain a bijection between stack and ID.
799 799 stack2id = {}
800 800 id2stack = [] # will eventually be rendered
801 801
802 802 def stackid(stack):
803 803 if not stack:
804 804 return
805 805 if stack in stack2id:
806 806 return stack2id[stack]
807 807 parent = stackid(stack[1:])
808 808 myid = len(stack2id)
809 809 stack2id[stack] = myid
810 id2stack.append(dict(category=stack[0][0], name='%s %s' % stack[0]))
810 id2stack.append(dict(category=stack[0][0], name=r'%s %s' % stack[0]))
811 811 if parent is not None:
812 812 id2stack[-1].update(parent=parent)
813 813 return myid
814 814
815 815 # The sampling profiler can sample multiple times without
816 816 # advancing the clock, potentially causing the Chrome trace viewer
817 817 # to render single-pixel columns that we cannot zoom in on. We
818 818 # work around this by pretending that zero-duration samples are a
819 819 # millisecond in length.
820 820
821 821 clamp = 0.001
822 822
823 823 # We provide knobs that by default attempt to filter out stack
824 824 # frames that are too noisy:
825 825 #
826 826 # * A few take almost all execution time. These are usually boring
827 827 # setup functions, giving a stack that is deep but uninformative.
828 828 #
829 829 # * Numerous samples take almost no time, but introduce lots of
830 830 # noisy, oft-deep "spines" into a rendered profile.
831 831
832 832 blacklist = set()
833 833 totaltime = data.samples[-1].time - data.samples[0].time
834 834 minthreshold = totaltime * minthreshold
835 835 maxthreshold = max(totaltime * maxthreshold, clamp)
836 836
837 837 def poplast():
838 838 oldsid = stackid(tuple(laststack))
839 839 oldcat, oldfunc = laststack.popleft()
840 840 oldtime, oldidx = lastseen.popleft()
841 841 duration = sample.time - oldtime
842 842 if minthreshold <= duration <= maxthreshold:
843 843 # ensure no zero-duration events
844 844 sampletime = max(oldtime + clamp, sample.time)
845 samples.append(dict(ph='E', name=oldfunc, cat=oldcat, sf=oldsid,
845 samples.append(dict(ph=r'E', name=oldfunc, cat=oldcat, sf=oldsid,
846 846 ts=sampletime*1e6, pid=0))
847 847 else:
848 848 blacklist.add(oldidx)
849 849
850 850 # Much fiddling to synthesize correctly(ish) nested begin/end
851 851 # events given only stack snapshots.
852 852
853 853 for sample in data.samples:
854 stack = tuple((('%s:%d' % (simplifypath(frame.path), frame.lineno),
855 frame.function) for frame in sample.stack))
854 stack = tuple(((r'%s:%d' % (simplifypath(pycompat.sysstr(frame.path)),
855 frame.lineno),
856 pycompat.sysstr(frame.function))
857 for frame in sample.stack))
856 858 qstack = collections.deque(stack)
857 859 if laststack == qstack:
858 860 continue
859 861 while laststack and qstack and laststack[-1] == qstack[-1]:
860 862 laststack.pop()
861 863 qstack.pop()
862 864 while laststack:
863 865 poplast()
864 866 for f in reversed(qstack):
865 867 lastseen.appendleft((sample.time, len(samples)))
866 868 laststack.appendleft(f)
867 869 path, name = f
868 870 sid = stackid(tuple(laststack))
869 samples.append(dict(ph='B', name=name, cat=path, ts=sample.time*1e6,
870 sf=sid, pid=0))
871 samples.append(dict(ph=r'B', name=name, cat=path,
872 ts=sample.time*1e6, sf=sid, pid=0))
871 873 laststack = collections.deque(stack)
872 874 while laststack:
873 875 poplast()
874 876 events = [sample for idx, sample in enumerate(samples)
875 877 if idx not in blacklist]
876 878 frames = collections.OrderedDict((str(k), v)
877 879 for (k,v) in enumerate(id2stack))
878 880 data = json.dumps(dict(traceEvents=events, stackFrames=frames), indent=1)
879 881 if not isinstance(data, bytes):
880 882 data = data.encode('utf-8')
881 883 fp.write(data)
882 884 fp.write('\n')
883 885
884 886 def printusage():
885 887 print(r"""
886 888 The statprof command line allows you to inspect the last profile's results in
887 889 the following forms:
888 890
889 891 usage:
890 892 hotpath [-l --limit percent]
891 893 Shows a graph of calls with the percent of time each takes.
892 894 Red calls take over 10%% of the total time themselves.
893 895 lines
894 896 Shows the actual sampled lines.
895 897 functions
896 898 Shows the samples grouped by function.
897 899 function [filename:]functionname
898 900 Shows the callers and callees of a particular function.
899 901 flame [-s --script-path] [-o --output-file path]
900 902 Writes out a flamegraph to output-file (defaults to ~/flamegraph.svg)
901 903 Requires that ~/flamegraph.pl exist.
902 904 (Specify alternate script path with --script-path.)""")
903 905
904 906 def main(argv=None):
905 907 if argv is None:
906 908 argv = sys.argv
907 909
908 910 if len(argv) == 1:
909 911 printusage()
910 912 return 0
911 913
912 914 displayargs = {}
913 915
914 916 optstart = 2
915 917 displayargs['function'] = None
916 918 if argv[1] == r'hotpath':
917 919 displayargs['format'] = DisplayFormats.Hotpath
918 920 elif argv[1] == r'lines':
919 921 displayargs['format'] = DisplayFormats.ByLine
920 922 elif argv[1] == r'functions':
921 923 displayargs['format'] = DisplayFormats.ByMethod
922 924 elif argv[1] == r'function':
923 925 displayargs['format'] = DisplayFormats.AboutMethod
924 926 displayargs['function'] = argv[2]
925 927 optstart = 3
926 928 elif argv[1] == r'flame':
927 929 displayargs['format'] = DisplayFormats.FlameGraph
928 930 else:
929 931 printusage()
930 932 return 0
931 933
932 934 # process options
933 935 try:
934 936 opts, args = pycompat.getoptb(sys.argv[optstart:], "hl:f:o:p:",
935 937 ["help", "limit=", "file=", "output-file=", "script-path="])
936 938 except getopt.error as msg:
937 939 print(msg)
938 940 printusage()
939 941 return 2
940 942
941 943 displayargs['limit'] = 0.05
942 944 path = None
943 945 for o, value in opts:
944 946 if o in (r"-l", r"--limit"):
945 947 displayargs['limit'] = float(value)
946 948 elif o in (r"-f", r"--file"):
947 949 path = value
948 950 elif o in (r"-o", r"--output-file"):
949 951 displayargs['outputfile'] = value
950 952 elif o in (r"-p", r"--script-path"):
951 953 displayargs['scriptpath'] = value
952 954 elif o in (r"-h", r"help"):
953 955 printusage()
954 956 return 0
955 957 else:
956 958 assert False, "unhandled option %s" % o
957 959
958 960 if not path:
959 961 print(r'must specify --file to load')
960 962 return 1
961 963
962 964 load_data(path=path)
963 965
964 966 display(**pycompat.strkwargs(displayargs))
965 967
966 968 return 0
967 969
968 970 if __name__ == r"__main__":
969 971 sys.exit(main())
General Comments 0
You need to be logged in to leave comments. Login now