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