##// END OF EJS Templates
statprof: use context manager for file when writing flame graph...
Martin von Zweigbergk -
r43103:db6d7cbd default
parent child Browse files
Show More
@@ -1,969 +1,966 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 fd, path = pycompat.mkstemp()
733
734 file = open(path, "w+")
735
736 732 lines = {}
737 733 for sample in data.samples:
738 734 sites = [s.function for s in sample.stack]
739 735 sites.reverse()
740 736 line = ';'.join(sites)
741 737 if line in lines:
742 738 lines[line] = lines[line] + 1
743 739 else:
744 740 lines[line] = 1
745 741
746 for line, count in lines.iteritems():
747 file.write("%s %d\n" % (line, count))
742 fd, path = pycompat.mkstemp()
748 743
749 file.close()
744 with open(path, "w+") as file:
745 for line, count in lines.iteritems():
746 file.write("%s %d\n" % (line, count))
750 747
751 748 if outputfile is None:
752 749 outputfile = '~/flamegraph.svg'
753 750
754 751 os.system("perl ~/flamegraph.pl %s > %s" % (path, outputfile))
755 752 fp.write(b'Written to %s\n' % outputfile)
756 753
757 754 _pathcache = {}
758 755 def simplifypath(path):
759 756 '''Attempt to make the path to a Python module easier to read by
760 757 removing whatever part of the Python search path it was found
761 758 on.'''
762 759
763 760 if path in _pathcache:
764 761 return _pathcache[path]
765 762 hgpath = pycompat.fsencode(encoding.__file__).rsplit(os.sep, 2)[0]
766 763 for p in [hgpath] + sys.path:
767 764 prefix = p + os.sep
768 765 if path.startswith(prefix):
769 766 path = path[len(prefix):]
770 767 break
771 768 _pathcache[path] = path
772 769 return path
773 770
774 771 def write_to_json(data, fp):
775 772 samples = []
776 773
777 774 for sample in data.samples:
778 775 stack = []
779 776
780 777 for frame in sample.stack:
781 778 stack.append(
782 779 (pycompat.sysstr(frame.path),
783 780 frame.lineno,
784 781 pycompat.sysstr(frame.function)))
785 782
786 783 samples.append((sample.time, stack))
787 784
788 785 data = json.dumps(samples)
789 786 if not isinstance(data, bytes):
790 787 data = data.encode('utf-8')
791 788
792 789 fp.write(data)
793 790
794 791 def write_to_chrome(data, fp, minthreshold=0.005, maxthreshold=0.999):
795 792 samples = []
796 793 laststack = collections.deque()
797 794 lastseen = collections.deque()
798 795
799 796 # The Chrome tracing format allows us to use a compact stack
800 797 # representation to save space. It's fiddly but worth it.
801 798 # We maintain a bijection between stack and ID.
802 799 stack2id = {}
803 800 id2stack = [] # will eventually be rendered
804 801
805 802 def stackid(stack):
806 803 if not stack:
807 804 return
808 805 if stack in stack2id:
809 806 return stack2id[stack]
810 807 parent = stackid(stack[1:])
811 808 myid = len(stack2id)
812 809 stack2id[stack] = myid
813 810 id2stack.append(dict(category=stack[0][0], name='%s %s' % stack[0]))
814 811 if parent is not None:
815 812 id2stack[-1].update(parent=parent)
816 813 return myid
817 814
818 815 # The sampling profiler can sample multiple times without
819 816 # advancing the clock, potentially causing the Chrome trace viewer
820 817 # to render single-pixel columns that we cannot zoom in on. We
821 818 # work around this by pretending that zero-duration samples are a
822 819 # millisecond in length.
823 820
824 821 clamp = 0.001
825 822
826 823 # We provide knobs that by default attempt to filter out stack
827 824 # frames that are too noisy:
828 825 #
829 826 # * A few take almost all execution time. These are usually boring
830 827 # setup functions, giving a stack that is deep but uninformative.
831 828 #
832 829 # * Numerous samples take almost no time, but introduce lots of
833 830 # noisy, oft-deep "spines" into a rendered profile.
834 831
835 832 blacklist = set()
836 833 totaltime = data.samples[-1].time - data.samples[0].time
837 834 minthreshold = totaltime * minthreshold
838 835 maxthreshold = max(totaltime * maxthreshold, clamp)
839 836
840 837 def poplast():
841 838 oldsid = stackid(tuple(laststack))
842 839 oldcat, oldfunc = laststack.popleft()
843 840 oldtime, oldidx = lastseen.popleft()
844 841 duration = sample.time - oldtime
845 842 if minthreshold <= duration <= maxthreshold:
846 843 # ensure no zero-duration events
847 844 sampletime = max(oldtime + clamp, sample.time)
848 845 samples.append(dict(ph='E', name=oldfunc, cat=oldcat, sf=oldsid,
849 846 ts=sampletime*1e6, pid=0))
850 847 else:
851 848 blacklist.add(oldidx)
852 849
853 850 # Much fiddling to synthesize correctly(ish) nested begin/end
854 851 # events given only stack snapshots.
855 852
856 853 for sample in data.samples:
857 854 stack = tuple((('%s:%d' % (simplifypath(frame.path), frame.lineno),
858 855 frame.function) for frame in sample.stack))
859 856 qstack = collections.deque(stack)
860 857 if laststack == qstack:
861 858 continue
862 859 while laststack and qstack and laststack[-1] == qstack[-1]:
863 860 laststack.pop()
864 861 qstack.pop()
865 862 while laststack:
866 863 poplast()
867 864 for f in reversed(qstack):
868 865 lastseen.appendleft((sample.time, len(samples)))
869 866 laststack.appendleft(f)
870 867 path, name = f
871 868 sid = stackid(tuple(laststack))
872 869 samples.append(dict(ph='B', name=name, cat=path, ts=sample.time*1e6,
873 870 sf=sid, pid=0))
874 871 laststack = collections.deque(stack)
875 872 while laststack:
876 873 poplast()
877 874 events = [sample for idx, sample in enumerate(samples)
878 875 if idx not in blacklist]
879 876 frames = collections.OrderedDict((str(k), v)
880 877 for (k,v) in enumerate(id2stack))
881 878 json.dump(dict(traceEvents=events, stackFrames=frames), fp, indent=1)
882 879 fp.write('\n')
883 880
884 881 def printusage():
885 882 print(r"""
886 883 The statprof command line allows you to inspect the last profile's results in
887 884 the following forms:
888 885
889 886 usage:
890 887 hotpath [-l --limit percent]
891 888 Shows a graph of calls with the percent of time each takes.
892 889 Red calls take over 10%% of the total time themselves.
893 890 lines
894 891 Shows the actual sampled lines.
895 892 functions
896 893 Shows the samples grouped by function.
897 894 function [filename:]functionname
898 895 Shows the callers and callees of a particular function.
899 896 flame [-s --script-path] [-o --output-file path]
900 897 Writes out a flamegraph to output-file (defaults to ~/flamegraph.svg)
901 898 Requires that ~/flamegraph.pl exist.
902 899 (Specify alternate script path with --script-path.)""")
903 900
904 901 def main(argv=None):
905 902 if argv is None:
906 903 argv = sys.argv
907 904
908 905 if len(argv) == 1:
909 906 printusage()
910 907 return 0
911 908
912 909 displayargs = {}
913 910
914 911 optstart = 2
915 912 displayargs['function'] = None
916 913 if argv[1] == r'hotpath':
917 914 displayargs['format'] = DisplayFormats.Hotpath
918 915 elif argv[1] == r'lines':
919 916 displayargs['format'] = DisplayFormats.ByLine
920 917 elif argv[1] == r'functions':
921 918 displayargs['format'] = DisplayFormats.ByMethod
922 919 elif argv[1] == r'function':
923 920 displayargs['format'] = DisplayFormats.AboutMethod
924 921 displayargs['function'] = argv[2]
925 922 optstart = 3
926 923 elif argv[1] == r'flame':
927 924 displayargs['format'] = DisplayFormats.FlameGraph
928 925 else:
929 926 printusage()
930 927 return 0
931 928
932 929 # process options
933 930 try:
934 931 opts, args = pycompat.getoptb(sys.argv[optstart:], "hl:f:o:p:",
935 932 ["help", "limit=", "file=", "output-file=", "script-path="])
936 933 except getopt.error as msg:
937 934 print(msg)
938 935 printusage()
939 936 return 2
940 937
941 938 displayargs['limit'] = 0.05
942 939 path = None
943 940 for o, value in opts:
944 941 if o in (r"-l", r"--limit"):
945 942 displayargs['limit'] = float(value)
946 943 elif o in (r"-f", r"--file"):
947 944 path = value
948 945 elif o in (r"-o", r"--output-file"):
949 946 displayargs['outputfile'] = value
950 947 elif o in (r"-p", r"--script-path"):
951 948 displayargs['scriptpath'] = value
952 949 elif o in (r"-h", r"help"):
953 950 printusage()
954 951 return 0
955 952 else:
956 953 assert False, "unhandled option %s" % o
957 954
958 955 if not path:
959 956 print(r'must specify --file to load')
960 957 return 1
961 958
962 959 load_data(path=path)
963 960
964 961 display(**pycompat.strkwargs(displayargs))
965 962
966 963 return 0
967 964
968 965 if __name__ == r"__main__":
969 966 sys.exit(main())
General Comments 0
You need to be logged in to leave comments. Login now