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