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