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