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