##// END OF EJS Templates
statprof: fix save and load...
Boris Feld -
r38293:99188a7c default
parent child Browse files
Show More
@@ -1,947 +1,947 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 file.write(str(state.accumulated_time) + '\n')
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 state.accumulated_time = float(lines[0])
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 457 data = data or state
458 458
459 459 if fp is None:
460 460 import sys
461 461 fp = sys.stdout
462 462 if len(data.samples) == 0:
463 463 print('No samples recorded.', file=fp)
464 464 return
465 465
466 466 if format == DisplayFormats.ByLine:
467 467 display_by_line(data, fp)
468 468 elif format == DisplayFormats.ByMethod:
469 469 display_by_method(data, fp)
470 470 elif format == DisplayFormats.AboutMethod:
471 471 display_about_method(data, fp, **kwargs)
472 472 elif format == DisplayFormats.Hotpath:
473 473 display_hotpath(data, fp, **kwargs)
474 474 elif format == DisplayFormats.FlameGraph:
475 475 write_to_flame(data, fp, **kwargs)
476 476 elif format == DisplayFormats.Json:
477 477 write_to_json(data, fp)
478 478 elif format == DisplayFormats.Chrome:
479 479 write_to_chrome(data, fp, **kwargs)
480 480 else:
481 481 raise Exception("Invalid display format")
482 482
483 483 if format not in (DisplayFormats.Json, DisplayFormats.Chrome):
484 484 print('---', file=fp)
485 485 print('Sample count: %d' % len(data.samples), file=fp)
486 486 print('Total time: %f seconds (%f wall)' % data.accumulated_time,
487 487 file=fp)
488 488
489 489 def display_by_line(data, fp):
490 490 '''Print the profiler data with each sample line represented
491 491 as one row in a table. Sorted by self-time per line.'''
492 492 stats = SiteStats.buildstats(data.samples)
493 493 stats.sort(reverse=True, key=lambda x: x.selfseconds())
494 494
495 495 print('%5.5s %10.10s %7.7s %-8.8s' %
496 496 ('% ', 'cumulative', 'self', ''), file=fp)
497 497 print('%5.5s %9.9s %8.8s %-8.8s' %
498 498 ("time", "seconds", "seconds", "name"), file=fp)
499 499
500 500 for stat in stats:
501 501 site = stat.site
502 502 sitelabel = '%s:%d:%s' % (site.filename(), site.lineno, site.function)
503 503 print('%6.2f %9.2f %9.2f %s' % (stat.selfpercent(),
504 504 stat.totalseconds(),
505 505 stat.selfseconds(),
506 506 sitelabel),
507 507 file=fp)
508 508
509 509 def display_by_method(data, fp):
510 510 '''Print the profiler data with each sample function represented
511 511 as one row in a table. Important lines within that function are
512 512 output as nested rows. Sorted by self-time per line.'''
513 513 print('%5.5s %10.10s %7.7s %-8.8s' %
514 514 ('% ', 'cumulative', 'self', ''), file=fp)
515 515 print('%5.5s %9.9s %8.8s %-8.8s' %
516 516 ("time", "seconds", "seconds", "name"), file=fp)
517 517
518 518 stats = SiteStats.buildstats(data.samples)
519 519
520 520 grouped = defaultdict(list)
521 521 for stat in stats:
522 522 grouped[stat.site.filename() + ":" + stat.site.function].append(stat)
523 523
524 524 # compute sums for each function
525 525 functiondata = []
526 526 for fname, sitestats in grouped.iteritems():
527 527 total_cum_sec = 0
528 528 total_self_sec = 0
529 529 total_percent = 0
530 530 for stat in sitestats:
531 531 total_cum_sec += stat.totalseconds()
532 532 total_self_sec += stat.selfseconds()
533 533 total_percent += stat.selfpercent()
534 534
535 535 functiondata.append((fname,
536 536 total_cum_sec,
537 537 total_self_sec,
538 538 total_percent,
539 539 sitestats))
540 540
541 541 # sort by total self sec
542 542 functiondata.sort(reverse=True, key=lambda x: x[2])
543 543
544 544 for function in functiondata:
545 545 if function[3] < 0.05:
546 546 continue
547 547 print('%6.2f %9.2f %9.2f %s' % (function[3], # total percent
548 548 function[1], # total cum sec
549 549 function[2], # total self sec
550 550 function[0]), # file:function
551 551 file=fp)
552 552 function[4].sort(reverse=True, key=lambda i: i.selfseconds())
553 553 for stat in function[4]:
554 554 # only show line numbers for significant locations (>1% time spent)
555 555 if stat.selfpercent() > 1:
556 556 source = stat.site.getsource(25)
557 557 stattuple = (stat.selfpercent(), stat.selfseconds(),
558 558 stat.site.lineno, source)
559 559
560 560 print('%33.0f%% %6.2f line %s: %s' % (stattuple), file=fp)
561 561
562 562 def display_about_method(data, fp, function=None, **kwargs):
563 563 if function is None:
564 564 raise Exception("Invalid function")
565 565
566 566 filename = None
567 567 if ':' in function:
568 568 filename, function = function.split(':')
569 569
570 570 relevant_samples = 0
571 571 parents = {}
572 572 children = {}
573 573
574 574 for sample in data.samples:
575 575 for i, site in enumerate(sample.stack):
576 576 if site.function == function and (not filename
577 577 or site.filename() == filename):
578 578 relevant_samples += 1
579 579 if i != len(sample.stack) - 1:
580 580 parent = sample.stack[i + 1]
581 581 if parent in parents:
582 582 parents[parent] = parents[parent] + 1
583 583 else:
584 584 parents[parent] = 1
585 585
586 586 if site in children:
587 587 children[site] = children[site] + 1
588 588 else:
589 589 children[site] = 1
590 590
591 591 parents = [(parent, count) for parent, count in parents.iteritems()]
592 592 parents.sort(reverse=True, key=lambda x: x[1])
593 593 for parent, count in parents:
594 594 print('%6.2f%% %s:%s line %s: %s' %
595 595 (count / relevant_samples * 100, parent.filename(),
596 596 parent.function, parent.lineno, parent.getsource(50)), file=fp)
597 597
598 598 stats = SiteStats.buildstats(data.samples)
599 599 stats = [s for s in stats
600 600 if s.site.function == function and
601 601 (not filename or s.site.filename() == filename)]
602 602
603 603 total_cum_sec = 0
604 604 total_self_sec = 0
605 605 total_self_percent = 0
606 606 total_cum_percent = 0
607 607 for stat in stats:
608 608 total_cum_sec += stat.totalseconds()
609 609 total_self_sec += stat.selfseconds()
610 610 total_self_percent += stat.selfpercent()
611 611 total_cum_percent += stat.totalpercent()
612 612
613 613 print(
614 614 '\n %s:%s Total: %0.2fs (%0.2f%%) Self: %0.2fs (%0.2f%%)\n' %
615 615 (
616 616 filename or '___',
617 617 function,
618 618 total_cum_sec,
619 619 total_cum_percent,
620 620 total_self_sec,
621 621 total_self_percent
622 622 ), file=fp)
623 623
624 624 children = [(child, count) for child, count in children.iteritems()]
625 625 children.sort(reverse=True, key=lambda x: x[1])
626 626 for child, count in children:
627 627 print(' %6.2f%% line %s: %s' %
628 628 (count / relevant_samples * 100, child.lineno,
629 629 child.getsource(50)), file=fp)
630 630
631 631 def display_hotpath(data, fp, limit=0.05, **kwargs):
632 632 class HotNode(object):
633 633 def __init__(self, site):
634 634 self.site = site
635 635 self.count = 0
636 636 self.children = {}
637 637
638 638 def add(self, stack, time):
639 639 self.count += time
640 640 site = stack[0]
641 641 child = self.children.get(site)
642 642 if not child:
643 643 child = HotNode(site)
644 644 self.children[site] = child
645 645
646 646 if len(stack) > 1:
647 647 i = 1
648 648 # Skip boiler plate parts of the stack
649 649 while i < len(stack) and '%s:%s' % (stack[i].filename(), stack[i].function) in skips:
650 650 i += 1
651 651 if i < len(stack):
652 652 child.add(stack[i:], time)
653 653
654 654 root = HotNode(None)
655 655 lasttime = data.samples[0].time
656 656 for sample in data.samples:
657 657 root.add(sample.stack[::-1], sample.time - lasttime)
658 658 lasttime = sample.time
659 659
660 660 def _write(node, depth, multiple_siblings):
661 661 site = node.site
662 662 visiblechildren = [c for c in node.children.itervalues()
663 663 if c.count >= (limit * root.count)]
664 664 if site:
665 665 indent = depth * 2 - 1
666 666 filename = ''
667 667 function = ''
668 668 if len(node.children) > 0:
669 669 childsite = list(node.children.itervalues())[0].site
670 670 filename = (childsite.filename() + ':').ljust(15)
671 671 function = childsite.function
672 672
673 673 # lots of string formatting
674 674 listpattern = ''.ljust(indent) +\
675 675 ('\\' if multiple_siblings else '|') +\
676 676 ' %4.1f%% %s %s'
677 677 liststring = listpattern % (node.count / root.count * 100,
678 678 filename, function)
679 679 codepattern = '%' + str(55 - len(liststring)) + 's %s: %s'
680 680 codestring = codepattern % ('line', site.lineno, site.getsource(30))
681 681
682 682 finalstring = liststring + codestring
683 683 childrensamples = sum([c.count for c in node.children.itervalues()])
684 684 # Make frames that performed more than 10% of the operation red
685 685 if node.count - childrensamples > (0.1 * root.count):
686 686 finalstring = '\033[91m' + finalstring + '\033[0m'
687 687 # Make frames that didn't actually perform work dark grey
688 688 elif node.count - childrensamples == 0:
689 689 finalstring = '\033[90m' + finalstring + '\033[0m'
690 690 print(finalstring, file=fp)
691 691
692 692 newdepth = depth
693 693 if len(visiblechildren) > 1 or multiple_siblings:
694 694 newdepth += 1
695 695
696 696 visiblechildren.sort(reverse=True, key=lambda x: x.count)
697 697 for child in visiblechildren:
698 698 _write(child, newdepth, len(visiblechildren) > 1)
699 699
700 700 if root.count > 0:
701 701 _write(root, 0, False)
702 702
703 703 def write_to_flame(data, fp, scriptpath=None, outputfile=None, **kwargs):
704 704 if scriptpath is None:
705 705 scriptpath = encoding.environ['HOME'] + '/flamegraph.pl'
706 706 if not os.path.exists(scriptpath):
707 707 print("error: missing %s" % scriptpath, file=fp)
708 708 print("get it here: https://github.com/brendangregg/FlameGraph",
709 709 file=fp)
710 710 return
711 711
712 712 fd, path = pycompat.mkstemp()
713 713
714 714 file = open(path, "w+")
715 715
716 716 lines = {}
717 717 for sample in data.samples:
718 718 sites = [s.function for s in sample.stack]
719 719 sites.reverse()
720 720 line = ';'.join(sites)
721 721 if line in lines:
722 722 lines[line] = lines[line] + 1
723 723 else:
724 724 lines[line] = 1
725 725
726 726 for line, count in lines.iteritems():
727 727 file.write("%s %s\n" % (line, count))
728 728
729 729 file.close()
730 730
731 731 if outputfile is None:
732 732 outputfile = '~/flamegraph.svg'
733 733
734 734 os.system("perl ~/flamegraph.pl %s > %s" % (path, outputfile))
735 735 print("Written to %s" % outputfile, file=fp)
736 736
737 737 _pathcache = {}
738 738 def simplifypath(path):
739 739 '''Attempt to make the path to a Python module easier to read by
740 740 removing whatever part of the Python search path it was found
741 741 on.'''
742 742
743 743 if path in _pathcache:
744 744 return _pathcache[path]
745 745 hgpath = pycompat.fsencode(encoding.__file__).rsplit(os.sep, 2)[0]
746 746 for p in [hgpath] + sys.path:
747 747 prefix = p + os.sep
748 748 if path.startswith(prefix):
749 749 path = path[len(prefix):]
750 750 break
751 751 _pathcache[path] = path
752 752 return path
753 753
754 754 def write_to_json(data, fp):
755 755 samples = []
756 756
757 757 for sample in data.samples:
758 758 stack = []
759 759
760 760 for frame in sample.stack:
761 761 stack.append((frame.path, frame.lineno, frame.function))
762 762
763 763 samples.append((sample.time, stack))
764 764
765 765 print(json.dumps(samples), file=fp)
766 766
767 767 def write_to_chrome(data, fp, minthreshold=0.005, maxthreshold=0.999):
768 768 samples = []
769 769 laststack = collections.deque()
770 770 lastseen = collections.deque()
771 771
772 772 # The Chrome tracing format allows us to use a compact stack
773 773 # representation to save space. It's fiddly but worth it.
774 774 # We maintain a bijection between stack and ID.
775 775 stack2id = {}
776 776 id2stack = [] # will eventually be rendered
777 777
778 778 def stackid(stack):
779 779 if not stack:
780 780 return
781 781 if stack in stack2id:
782 782 return stack2id[stack]
783 783 parent = stackid(stack[1:])
784 784 myid = len(stack2id)
785 785 stack2id[stack] = myid
786 786 id2stack.append(dict(category=stack[0][0], name='%s %s' % stack[0]))
787 787 if parent is not None:
788 788 id2stack[-1].update(parent=parent)
789 789 return myid
790 790
791 791 def endswith(a, b):
792 792 return list(a)[-len(b):] == list(b)
793 793
794 794 # The sampling profiler can sample multiple times without
795 795 # advancing the clock, potentially causing the Chrome trace viewer
796 796 # to render single-pixel columns that we cannot zoom in on. We
797 797 # work around this by pretending that zero-duration samples are a
798 798 # millisecond in length.
799 799
800 800 clamp = 0.001
801 801
802 802 # We provide knobs that by default attempt to filter out stack
803 803 # frames that are too noisy:
804 804 #
805 805 # * A few take almost all execution time. These are usually boring
806 806 # setup functions, giving a stack that is deep but uninformative.
807 807 #
808 808 # * Numerous samples take almost no time, but introduce lots of
809 809 # noisy, oft-deep "spines" into a rendered profile.
810 810
811 811 blacklist = set()
812 812 totaltime = data.samples[-1].time - data.samples[0].time
813 813 minthreshold = totaltime * minthreshold
814 814 maxthreshold = max(totaltime * maxthreshold, clamp)
815 815
816 816 def poplast():
817 817 oldsid = stackid(tuple(laststack))
818 818 oldcat, oldfunc = laststack.popleft()
819 819 oldtime, oldidx = lastseen.popleft()
820 820 duration = sample.time - oldtime
821 821 if minthreshold <= duration <= maxthreshold:
822 822 # ensure no zero-duration events
823 823 sampletime = max(oldtime + clamp, sample.time)
824 824 samples.append(dict(ph='E', name=oldfunc, cat=oldcat, sf=oldsid,
825 825 ts=sampletime*1e6, pid=0))
826 826 else:
827 827 blacklist.add(oldidx)
828 828
829 829 # Much fiddling to synthesize correctly(ish) nested begin/end
830 830 # events given only stack snapshots.
831 831
832 832 for sample in data.samples:
833 833 tos = sample.stack[0]
834 834 name = tos.function
835 835 path = simplifypath(tos.path)
836 836 stack = tuple((('%s:%d' % (simplifypath(frame.path), frame.lineno),
837 837 frame.function) for frame in sample.stack))
838 838 qstack = collections.deque(stack)
839 839 if laststack == qstack:
840 840 continue
841 841 while laststack and qstack and laststack[-1] == qstack[-1]:
842 842 laststack.pop()
843 843 qstack.pop()
844 844 while laststack:
845 845 poplast()
846 846 for f in reversed(qstack):
847 847 lastseen.appendleft((sample.time, len(samples)))
848 848 laststack.appendleft(f)
849 849 path, name = f
850 850 sid = stackid(tuple(laststack))
851 851 samples.append(dict(ph='B', name=name, cat=path, ts=sample.time*1e6,
852 852 sf=sid, pid=0))
853 853 laststack = collections.deque(stack)
854 854 while laststack:
855 855 poplast()
856 856 events = [s[1] for s in enumerate(samples) if s[0] not in blacklist]
857 857 frames = collections.OrderedDict((str(k), v)
858 858 for (k,v) in enumerate(id2stack))
859 859 json.dump(dict(traceEvents=events, stackFrames=frames), fp, indent=1)
860 860 fp.write('\n')
861 861
862 862 def printusage():
863 863 print("""
864 864 The statprof command line allows you to inspect the last profile's results in
865 865 the following forms:
866 866
867 867 usage:
868 868 hotpath [-l --limit percent]
869 869 Shows a graph of calls with the percent of time each takes.
870 870 Red calls take over 10%% of the total time themselves.
871 871 lines
872 872 Shows the actual sampled lines.
873 873 functions
874 874 Shows the samples grouped by function.
875 875 function [filename:]functionname
876 876 Shows the callers and callees of a particular function.
877 877 flame [-s --script-path] [-o --output-file path]
878 878 Writes out a flamegraph to output-file (defaults to ~/flamegraph.svg)
879 879 Requires that ~/flamegraph.pl exist.
880 880 (Specify alternate script path with --script-path.)""")
881 881
882 882 def main(argv=None):
883 883 if argv is None:
884 884 argv = sys.argv
885 885
886 886 if len(argv) == 1:
887 887 printusage()
888 888 return 0
889 889
890 890 displayargs = {}
891 891
892 892 optstart = 2
893 893 displayargs['function'] = None
894 894 if argv[1] == 'hotpath':
895 895 displayargs['format'] = DisplayFormats.Hotpath
896 896 elif argv[1] == 'lines':
897 897 displayargs['format'] = DisplayFormats.ByLine
898 898 elif argv[1] == 'functions':
899 899 displayargs['format'] = DisplayFormats.ByMethod
900 900 elif argv[1] == 'function':
901 901 displayargs['format'] = DisplayFormats.AboutMethod
902 902 displayargs['function'] = argv[2]
903 903 optstart = 3
904 904 elif argv[1] == 'flame':
905 905 displayargs['format'] = DisplayFormats.FlameGraph
906 906 else:
907 907 printusage()
908 908 return 0
909 909
910 910 # process options
911 911 try:
912 912 opts, args = pycompat.getoptb(sys.argv[optstart:], "hl:f:o:p:",
913 913 ["help", "limit=", "file=", "output-file=", "script-path="])
914 914 except getopt.error as msg:
915 915 print(msg)
916 916 printusage()
917 917 return 2
918 918
919 919 displayargs['limit'] = 0.05
920 920 path = None
921 921 for o, value in opts:
922 922 if o in ("-l", "--limit"):
923 923 displayargs['limit'] = float(value)
924 924 elif o in ("-f", "--file"):
925 925 path = value
926 926 elif o in ("-o", "--output-file"):
927 927 displayargs['outputfile'] = value
928 928 elif o in ("-p", "--script-path"):
929 929 displayargs['scriptpath'] = value
930 930 elif o in ("-h", "help"):
931 931 printusage()
932 932 return 0
933 933 else:
934 934 assert False, "unhandled option %s" % o
935 935
936 936 if not path:
937 937 print('must specify --file to load')
938 938 return 1
939 939
940 940 load_data(path=path)
941 941
942 942 display(**pycompat.strkwargs(displayargs))
943 943
944 944 return 0
945 945
946 946 if __name__ == "__main__":
947 947 sys.exit(main())
General Comments 0
You need to be logged in to leave comments. Login now