statprof.py
1097 lines
| 32.2 KiB
| text/x-python
|
PythonLexer
/ mercurial / statprof.py
|
r30253 | ## statprof.py | ||
## Copyright (C) 2012 Bryan O'Sullivan <bos@serpentine.com> | ||||
## Copyright (C) 2011 Alex Fraser <alex at phatcore dot com> | ||||
## Copyright (C) 2004,2005 Andy Wingo <wingo at pobox dot com> | ||||
## Copyright (C) 2001 Rob Browning <rlb at defaultvalue dot org> | ||||
## This library is free software; you can redistribute it and/or | ||||
## modify it under the terms of the GNU Lesser General Public | ||||
## License as published by the Free Software Foundation; either | ||||
## version 2.1 of the License, or (at your option) any later version. | ||||
## | ||||
## This library is distributed in the hope that it will be useful, | ||||
## but WITHOUT ANY WARRANTY; without even the implied warranty of | ||||
## MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU | ||||
## Lesser General Public License for more details. | ||||
## | ||||
## You should have received a copy of the GNU Lesser General Public | ||||
## License along with this program; if not, contact: | ||||
## | ||||
## Free Software Foundation Voice: +1-617-542-5942 | ||||
## 59 Temple Place - Suite 330 Fax: +1-617-542-2652 | ||||
## Boston, MA 02111-1307, USA gnu@gnu.org | ||||
""" | ||||
statprof is intended to be a fairly simple statistical profiler for | ||||
python. It was ported directly from a statistical profiler for guile, | ||||
also named statprof, available from guile-lib [0]. | ||||
[0] http://wingolog.org/software/guile-lib/statprof/ | ||||
To start profiling, call statprof.start(): | ||||
>>> start() | ||||
Then run whatever it is that you want to profile, for example: | ||||
>>> import test.pystone; test.pystone.pystones() | ||||
Then stop the profiling and print out the results: | ||||
>>> stop() | ||||
>>> display() | ||||
% cumulative self | ||||
time seconds seconds name | ||||
26.72 1.40 0.37 pystone.py:79:Proc0 | ||||
13.79 0.56 0.19 pystone.py:133:Proc1 | ||||
13.79 0.19 0.19 pystone.py:208:Proc8 | ||||
10.34 0.16 0.14 pystone.py:229:Func2 | ||||
6.90 0.10 0.10 pystone.py:45:__init__ | ||||
4.31 0.16 0.06 pystone.py:53:copy | ||||
... | ||||
All of the numerical data is statistically approximate. In the | ||||
following column descriptions, and in all of statprof, "time" refers | ||||
to execution time (both user and system), not wall clock time. | ||||
% time | ||||
The percent of the time spent inside the procedure itself (not | ||||
counting children). | ||||
cumulative seconds | ||||
The total number of seconds spent in the procedure, including | ||||
children. | ||||
self seconds | ||||
The total number of seconds spent in the procedure itself (not | ||||
counting children). | ||||
name | ||||
The name of the procedure. | ||||
By default statprof keeps the data collected from previous runs. If you | ||||
want to clear the collected data, call reset(): | ||||
>>> reset() | ||||
reset() can also be used to change the sampling frequency from the | ||||
default of 1000 Hz. For example, to tell statprof to sample 50 times a | ||||
second: | ||||
>>> reset(50) | ||||
This means that statprof will sample the call stack after every 1/50 of | ||||
a second of user + system time spent running on behalf of the python | ||||
process. When your process is idle (for example, blocking in a read(), | ||||
as is the case at the listener), the clock does not advance. For this | ||||
reason statprof is not currently not suitable for profiling io-bound | ||||
operations. | ||||
The profiler uses the hash of the code object itself to identify the | ||||
procedures, so it won't confuse different procedures with the same name. | ||||
They will show up as two different rows in the output. | ||||
Right now the profiler is quite simplistic. I cannot provide | ||||
call-graphs or other higher level information. What you see in the | ||||
table is pretty much all there is. Patches are welcome :-) | ||||
Threading | ||||
--------- | ||||
Because signals only get delivered to the main thread in Python, | ||||
statprof only profiles the main thread. However because the time | ||||
reporting function uses per-process timers, the results can be | ||||
significantly off if other threads' work patterns are not similar to the | ||||
main thread's work patterns. | ||||
""" | ||||
# no-check-code | ||||
|
r30257 | from __future__ import absolute_import, division, print_function | ||
|
r30253 | |||
|
r30256 | import collections | ||
import contextlib | ||||
import getopt | ||||
import inspect | ||||
import json | ||||
import os | ||||
import signal | ||||
import sys | ||||
import threading | ||||
|
r30253 | import time | ||
|
r30256 | |||
|
r43355 | from .pycompat import open | ||
|
r30578 | from . import ( | ||
|
r30637 | encoding, | ||
|
r30578 | pycompat, | ||
) | ||||
|
r30256 | defaultdict = collections.defaultdict | ||
contextmanager = contextlib.contextmanager | ||||
|
r30253 | |||
|
r43347 | __all__ = [b'start', b'stop', b'reset', b'display', b'profile'] | ||
|
r30253 | |||
|
r40232 | skips = { | ||
|
r43809 | "util.py:check", | ||
"extensions.py:closure", | ||||
"color.py:colorcmd", | ||||
"dispatch.py:checkargs", | ||||
"dispatch.py:<lambda>", | ||||
"dispatch.py:_runcatch", | ||||
"dispatch.py:_dispatch", | ||||
"dispatch.py:_runcommand", | ||||
"pager.py:pagecmd", | ||||
"dispatch.py:run", | ||||
"dispatch.py:dispatch", | ||||
"dispatch.py:runcommand", | ||||
"hg.py:<module>", | ||||
"evolve.py:warnobserrors", | ||||
|
r32291 | } | ||
|
r30253 | |||
########################################################################### | ||||
## Utils | ||||
|
r43346 | |||
|
r30253 | def clock(): | ||
times = os.times() | ||||
|
r38278 | return (times[0] + times[1], times[4]) | ||
|
r30253 | |||
########################################################################### | ||||
## Collection data structures | ||||
|
r43346 | |||
|
r30253 | class ProfileState(object): | ||
def __init__(self, frequency=None): | ||||
self.reset(frequency) | ||||
|
r43347 | self.track = b'cpu' | ||
|
r30253 | |||
def reset(self, frequency=None): | ||||
# total so far | ||||
|
r38278 | self.accumulated_time = (0.0, 0.0) | ||
|
r30253 | # start_time when timer is active | ||
self.last_start_time = None | ||||
# a float | ||||
if frequency: | ||||
self.sample_interval = 1.0 / frequency | ||||
|
r43358 | elif not pycompat.hasattr(self, 'sample_interval'): | ||
|
r30253 | # default to 1000 Hz | ||
self.sample_interval = 1.0 / 1000.0 | ||||
else: | ||||
# leave the frequency as it was | ||||
pass | ||||
self.remaining_prof_time = None | ||||
# for user start/stop nesting | ||||
self.profile_level = 0 | ||||
self.samples = [] | ||||
def accumulate_time(self, stop_time): | ||||
|
r38278 | increment = ( | ||
stop_time[0] - self.last_start_time[0], | ||||
stop_time[1] - self.last_start_time[1], | ||||
) | ||||
self.accumulated_time = ( | ||||
self.accumulated_time[0] + increment[0], | ||||
self.accumulated_time[1] + increment[1], | ||||
) | ||||
|
r30253 | |||
def seconds_per_sample(self): | ||||
|
r38279 | return self.accumulated_time[self.timeidx] / len(self.samples) | ||
@property | ||||
def timeidx(self): | ||||
|
r43347 | if self.track == b'real': | ||
|
r38279 | return 1 | ||
return 0 | ||||
|
r30253 | |||
|
r43346 | |||
|
r30253 | state = ProfileState() | ||
class CodeSite(object): | ||||
cache = {} | ||||
|
r43906 | __slots__ = ('path', 'lineno', 'function', 'source') | ||
|
r30253 | |||
def __init__(self, path, lineno, function): | ||||
|
r40518 | assert isinstance(path, bytes) | ||
|
r30253 | self.path = path | ||
self.lineno = lineno | ||||
|
r40518 | assert isinstance(function, bytes) | ||
|
r30253 | self.function = function | ||
self.source = None | ||||
def __eq__(self, other): | ||||
try: | ||||
|
r43346 | return self.lineno == other.lineno and self.path == other.path | ||
|
r30253 | except: | ||
return False | ||||
def __hash__(self): | ||||
return hash((self.lineno, self.path)) | ||||
@classmethod | ||||
def get(cls, path, lineno, function): | ||||
k = (path, lineno) | ||||
try: | ||||
return cls.cache[k] | ||||
except KeyError: | ||||
v = cls(path, lineno, function) | ||||
cls.cache[k] = v | ||||
return v | ||||
def getsource(self, length): | ||||
if self.source is None: | ||||
lineno = self.lineno - 1 | ||||
try: | ||||
|
r43347 | with open(self.path, b'rb') as fp: | ||
|
r43102 | for i, line in enumerate(fp): | ||
if i == lineno: | ||||
self.source = line.strip() | ||||
break | ||||
|
r30253 | except: | ||
pass | ||||
if self.source is None: | ||||
|
r43347 | self.source = b'' | ||
|
r30253 | |||
source = self.source | ||||
if len(source) > length: | ||||
|
r43347 | source = source[: (length - 3)] + b"..." | ||
|
r30253 | return source | ||
def filename(self): | ||||
return os.path.basename(self.path) | ||||
|
r40421 | def skipname(self): | ||
|
r43906 | return '%s:%s' % (self.filename(), self.function) | ||
|
r40421 | |||
|
r43346 | |||
|
r30253 | class Sample(object): | ||
|
r43906 | __slots__ = ('stack', 'time') | ||
|
r30253 | |||
def __init__(self, stack, time): | ||||
self.stack = stack | ||||
self.time = time | ||||
@classmethod | ||||
def from_frame(cls, frame, time): | ||||
stack = [] | ||||
while frame: | ||||
|
r43346 | stack.append( | ||
CodeSite.get( | ||||
pycompat.sysbytes(frame.f_code.co_filename), | ||||
frame.f_lineno, | ||||
pycompat.sysbytes(frame.f_code.co_name), | ||||
) | ||||
) | ||||
|
r30253 | frame = frame.f_back | ||
return Sample(stack, time) | ||||
|
r43346 | |||
|
r30253 | ########################################################################### | ||
## SIGPROF handler | ||||
|
r43346 | |||
|
r30253 | def profile_signal_handler(signum, frame): | ||
if state.profile_level > 0: | ||||
now = clock() | ||||
state.accumulate_time(now) | ||||
|
r38279 | timestamp = state.accumulated_time[state.timeidx] | ||
state.samples.append(Sample.from_frame(frame, timestamp)) | ||||
|
r30253 | |||
|
r43346 | signal.setitimer(signal.ITIMER_PROF, state.sample_interval, 0.0) | ||
|
r30253 | state.last_start_time = now | ||
|
r43346 | |||
|
r30253 | stopthread = threading.Event() | ||
|
r43346 | |||
|
r30253 | def samplerthread(tid): | ||
while not stopthread.is_set(): | ||||
now = clock() | ||||
state.accumulate_time(now) | ||||
frame = sys._current_frames()[tid] | ||||
|
r38279 | |||
timestamp = state.accumulated_time[state.timeidx] | ||||
state.samples.append(Sample.from_frame(frame, timestamp)) | ||||
|
r30253 | |||
state.last_start_time = now | ||||
time.sleep(state.sample_interval) | ||||
stopthread.clear() | ||||
|
r43346 | |||
|
r30253 | ########################################################################### | ||
## Profiling API | ||||
|
r43346 | |||
|
r30253 | def is_active(): | ||
return state.profile_level > 0 | ||||
|
r43346 | |||
|
r30253 | lastmechanism = None | ||
|
r43346 | |||
|
r43347 | def start(mechanism=b'thread', track=b'cpu'): | ||
|
r30253 | '''Install the profiling signal handler, and start profiling.''' | ||
|
r43346 | state.track = track # note: nesting different mode won't work | ||
|
r30253 | state.profile_level += 1 | ||
if state.profile_level == 1: | ||||
state.last_start_time = clock() | ||||
rpt = state.remaining_prof_time | ||||
state.remaining_prof_time = None | ||||
global lastmechanism | ||||
lastmechanism = mechanism | ||||
|
r43347 | if mechanism == b'signal': | ||
|
r30253 | signal.signal(signal.SIGPROF, profile_signal_handler) | ||
|
r43346 | signal.setitimer( | ||
signal.ITIMER_PROF, rpt or state.sample_interval, 0.0 | ||||
) | ||||
|
r43347 | elif mechanism == b'thread': | ||
|
r30253 | frame = inspect.currentframe() | ||
tid = [k for k, f in sys._current_frames().items() if f == frame][0] | ||||
|
r43346 | state.thread = threading.Thread( | ||
|
r43762 | target=samplerthread, args=(tid,), name="samplerthread" | ||
|
r43346 | ) | ||
|
r30253 | state.thread.start() | ||
|
r43346 | |||
|
r30253 | def stop(): | ||
'''Stop profiling, and uninstall the profiling signal handler.''' | ||||
state.profile_level -= 1 | ||||
if state.profile_level == 0: | ||||
|
r43347 | if lastmechanism == b'signal': | ||
|
r30253 | rpt = signal.setitimer(signal.ITIMER_PROF, 0.0, 0.0) | ||
signal.signal(signal.SIGPROF, signal.SIG_IGN) | ||||
state.remaining_prof_time = rpt[0] | ||||
|
r43347 | elif lastmechanism == b'thread': | ||
|
r30253 | stopthread.set() | ||
state.thread.join() | ||||
state.accumulate_time(clock()) | ||||
state.last_start_time = None | ||||
|
r43347 | statprofpath = encoding.environ.get(b'STATPROF_DEST') | ||
|
r30255 | if statprofpath: | ||
save_data(statprofpath) | ||||
|
r30253 | |||
|
r30299 | return state | ||
|
r43346 | |||
|
r30255 | def save_data(path): | ||
|
r43347 | with open(path, b'w+') as file: | ||
file.write(b"%f %f\n" % state.accumulated_time) | ||||
|
r30253 | for sample in state.samples: | ||
|
r40233 | time = sample.time | ||
|
r30253 | stack = sample.stack | ||
|
r43346 | sites = [ | ||
|
r43347 | b'\1'.join([s.path, b'%d' % s.lineno, s.function]) | ||
for s in stack | ||||
|
r43346 | ] | ||
|
r43347 | file.write(b"%d\0%s\n" % (time, b'\0'.join(sites))) | ||
|
r30253 | |||
|
r43346 | |||
|
r30255 | def load_data(path): | ||
|
r43347 | lines = open(path, b'rb').read().splitlines() | ||
|
r30253 | |||
|
r38293 | state.accumulated_time = [float(value) for value in lines[0].split()] | ||
|
r30253 | state.samples = [] | ||
for line in lines[1:]: | ||||
|
r43347 | parts = line.split(b'\0') | ||
|
r30253 | time = float(parts[0]) | ||
rawsites = parts[1:] | ||||
sites = [] | ||||
for rawsite in rawsites: | ||||
|
r43347 | siteparts = rawsite.split(b'\1') | ||
|
r43346 | sites.append( | ||
CodeSite.get(siteparts[0], int(siteparts[1]), siteparts[2]) | ||||
) | ||||
|
r30253 | |||
state.samples.append(Sample(sites, time)) | ||||
def reset(frequency=None): | ||||
|
r46554 | """Clear out the state of the profiler. Do not call while the | ||
|
r30253 | profiler is running. | ||
The optional frequency argument specifies the number of samples to | ||||
|
r46554 | collect per second.""" | ||
|
r43347 | assert state.profile_level == 0, b"Can't reset() while statprof is running" | ||
|
r30253 | CodeSite.cache.clear() | ||
state.reset(frequency) | ||||
@contextmanager | ||||
def profile(): | ||||
start() | ||||
try: | ||||
yield | ||||
finally: | ||||
stop() | ||||
display() | ||||
########################################################################### | ||||
## Reporting API | ||||
|
r43346 | |||
|
r30253 | class SiteStats(object): | ||
def __init__(self, site): | ||||
self.site = site | ||||
self.selfcount = 0 | ||||
self.totalcount = 0 | ||||
def addself(self): | ||||
self.selfcount += 1 | ||||
def addtotal(self): | ||||
self.totalcount += 1 | ||||
def selfpercent(self): | ||||
return self.selfcount / len(state.samples) * 100 | ||||
def totalpercent(self): | ||||
return self.totalcount / len(state.samples) * 100 | ||||
def selfseconds(self): | ||||
return self.selfcount * state.seconds_per_sample() | ||||
def totalseconds(self): | ||||
return self.totalcount * state.seconds_per_sample() | ||||
@classmethod | ||||
def buildstats(cls, samples): | ||||
stats = {} | ||||
for sample in samples: | ||||
for i, site in enumerate(sample.stack): | ||||
sitestat = stats.get(site) | ||||
if not sitestat: | ||||
sitestat = SiteStats(site) | ||||
stats[site] = sitestat | ||||
sitestat.addtotal() | ||||
if i == 0: | ||||
sitestat.addself() | ||||
|
r43374 | return [s for s in pycompat.itervalues(stats)] | ||
|
r30253 | |||
|
r43346 | |||
|
r30253 | class DisplayFormats: | ||
ByLine = 0 | ||||
ByMethod = 1 | ||||
AboutMethod = 2 | ||||
Hotpath = 3 | ||||
FlameGraph = 4 | ||||
Json = 5 | ||||
|
r30929 | Chrome = 6 | ||
|
r30253 | |||
|
r43346 | |||
|
r30258 | def display(fp=None, format=3, data=None, **kwargs): | ||
|
r30253 | '''Print statistics, either to stdout or the given file object.''' | ||
|
r38719 | if data is None: | ||
data = state | ||||
|
r30253 | |||
if fp is None: | ||||
|
r49313 | from .utils import procutil | ||
|
r43346 | |||
|
r49313 | fp = procutil.stdout | ||
|
r30258 | if len(data.samples) == 0: | ||
|
r40234 | fp.write(b'No samples recorded.\n') | ||
|
r30253 | return | ||
if format == DisplayFormats.ByLine: | ||||
|
r30258 | display_by_line(data, fp) | ||
|
r30253 | elif format == DisplayFormats.ByMethod: | ||
|
r30258 | display_by_method(data, fp) | ||
|
r30253 | elif format == DisplayFormats.AboutMethod: | ||
|
r30258 | display_about_method(data, fp, **kwargs) | ||
|
r30253 | elif format == DisplayFormats.Hotpath: | ||
|
r30258 | display_hotpath(data, fp, **kwargs) | ||
|
r30253 | elif format == DisplayFormats.FlameGraph: | ||
|
r30258 | write_to_flame(data, fp, **kwargs) | ||
|
r30253 | elif format == DisplayFormats.Json: | ||
|
r30258 | write_to_json(data, fp) | ||
|
r30929 | elif format == DisplayFormats.Chrome: | ||
write_to_chrome(data, fp, **kwargs) | ||||
|
r30253 | else: | ||
|
r49312 | raise Exception("Invalid display format") | ||
|
r30253 | |||
|
r30929 | if format not in (DisplayFormats.Json, DisplayFormats.Chrome): | ||
|
r40234 | fp.write(b'---\n') | ||
fp.write(b'Sample count: %d\n' % len(data.samples)) | ||||
fp.write(b'Total time: %f seconds (%f wall)\n' % data.accumulated_time) | ||||
|
r30253 | |||
|
r43346 | |||
|
r30258 | def display_by_line(data, fp): | ||
|
r46554 | """Print the profiler data with each sample line represented | ||
as one row in a table. Sorted by self-time per line.""" | ||||
|
r30258 | stats = SiteStats.buildstats(data.samples) | ||
|
r30253 | stats.sort(reverse=True, key=lambda x: x.selfseconds()) | ||
|
r43346 | fp.write( | ||
b'%5.5s %10.10s %7.7s %-8.8s\n' | ||||
% (b'% ', b'cumulative', b'self', b'') | ||||
) | ||||
fp.write( | ||||
b'%5.5s %9.9s %8.8s %-8.8s\n' | ||||
% (b"time", b"seconds", b"seconds", b"name") | ||||
) | ||||
|
r30253 | |||
for stat in stats: | ||||
site = stat.site | ||||
|
r43347 | sitelabel = b'%s:%d:%s' % (site.filename(), site.lineno, site.function) | ||
|
r43346 | fp.write( | ||
b'%6.2f %9.2f %9.2f %s\n' | ||||
% ( | ||||
stat.selfpercent(), | ||||
stat.totalseconds(), | ||||
stat.selfseconds(), | ||||
sitelabel, | ||||
) | ||||
) | ||||
|
r30253 | |||
|
r30258 | def display_by_method(data, fp): | ||
|
r46554 | """Print the profiler data with each sample function represented | ||
|
r30253 | as one row in a table. Important lines within that function are | ||
|
r46554 | output as nested rows. Sorted by self-time per line.""" | ||
|
r43346 | fp.write( | ||
|
r43347 | b'%5.5s %10.10s %7.7s %-8.8s\n' | ||
% (b'% ', b'cumulative', b'self', b'') | ||||
|
r43346 | ) | ||
fp.write( | ||||
b'%5.5s %9.9s %8.8s %-8.8s\n' | ||||
|
r43347 | % (b"time", b"seconds", b"seconds", b"name") | ||
|
r43346 | ) | ||
|
r30253 | |||
|
r30258 | stats = SiteStats.buildstats(data.samples) | ||
|
r30253 | |||
grouped = defaultdict(list) | ||||
for stat in stats: | ||||
|
r40519 | grouped[stat.site.filename() + b":" + stat.site.function].append(stat) | ||
|
r30253 | |||
# compute sums for each function | ||||
functiondata = [] | ||||
|
r43376 | for fname, sitestats in pycompat.iteritems(grouped): | ||
|
r30253 | total_cum_sec = 0 | ||
total_self_sec = 0 | ||||
total_percent = 0 | ||||
for stat in sitestats: | ||||
total_cum_sec += stat.totalseconds() | ||||
total_self_sec += stat.selfseconds() | ||||
total_percent += stat.selfpercent() | ||||
|
r43346 | functiondata.append( | ||
(fname, total_cum_sec, total_self_sec, total_percent, sitestats) | ||||
) | ||||
|
r30253 | |||
# sort by total self sec | ||||
functiondata.sort(reverse=True, key=lambda x: x[2]) | ||||
for function in functiondata: | ||||
if function[3] < 0.05: | ||||
continue | ||||
|
r43346 | fp.write( | ||
b'%6.2f %9.2f %9.2f %s\n' | ||||
% ( | ||||
function[3], # total percent | ||||
function[1], # total cum sec | ||||
function[2], # total self sec | ||||
function[0], | ||||
) | ||||
) # file:function | ||||
|
r40234 | |||
|
r30253 | function[4].sort(reverse=True, key=lambda i: i.selfseconds()) | ||
for stat in function[4]: | ||||
# only show line numbers for significant locations (>1% time spent) | ||||
if stat.selfpercent() > 1: | ||||
source = stat.site.getsource(25) | ||||
|
r43346 | if sys.version_info.major >= 3 and not isinstance( | ||
source, bytes | ||||
): | ||||
|
r40237 | source = pycompat.bytestr(source) | ||
|
r43346 | stattuple = ( | ||
stat.selfpercent(), | ||||
stat.selfseconds(), | ||||
stat.site.lineno, | ||||
source, | ||||
) | ||||
|
r30253 | |||
|
r40234 | fp.write(b'%33.0f%% %6.2f line %d: %s\n' % stattuple) | ||
|
r30253 | |||
|
r43346 | |||
|
r30258 | def display_about_method(data, fp, function=None, **kwargs): | ||
|
r30253 | if function is None: | ||
|
r49312 | raise Exception("Invalid function") | ||
|
r30253 | |||
filename = None | ||||
|
r43347 | if b':' in function: | ||
filename, function = function.split(b':') | ||||
|
r30253 | |||
relevant_samples = 0 | ||||
parents = {} | ||||
children = {} | ||||
|
r30258 | for sample in data.samples: | ||
|
r30253 | for i, site in enumerate(sample.stack): | ||
|
r43346 | if site.function == function and ( | ||
not filename or site.filename() == filename | ||||
): | ||||
|
r30253 | relevant_samples += 1 | ||
if i != len(sample.stack) - 1: | ||||
parent = sample.stack[i + 1] | ||||
if parent in parents: | ||||
parents[parent] = parents[parent] + 1 | ||||
else: | ||||
parents[parent] = 1 | ||||
if site in children: | ||||
children[site] = children[site] + 1 | ||||
else: | ||||
children[site] = 1 | ||||
|
r43376 | parents = [(parent, count) for parent, count in pycompat.iteritems(parents)] | ||
|
r30253 | parents.sort(reverse=True, key=lambda x: x[1]) | ||
for parent, count in parents: | ||||
|
r43346 | fp.write( | ||
b'%6.2f%% %s:%s line %s: %s\n' | ||||
% ( | ||||
count / relevant_samples * 100, | ||||
pycompat.fsencode(parent.filename()), | ||||
pycompat.sysbytes(parent.function), | ||||
parent.lineno, | ||||
pycompat.sysbytes(parent.getsource(50)), | ||||
) | ||||
) | ||||
|
r30253 | |||
|
r30258 | stats = SiteStats.buildstats(data.samples) | ||
|
r43346 | stats = [ | ||
s | ||||
for s in stats | ||||
if s.site.function == function | ||||
and (not filename or s.site.filename() == filename) | ||||
] | ||||
|
r30253 | |||
total_cum_sec = 0 | ||||
total_self_sec = 0 | ||||
total_self_percent = 0 | ||||
total_cum_percent = 0 | ||||
for stat in stats: | ||||
total_cum_sec += stat.totalseconds() | ||||
total_self_sec += stat.selfseconds() | ||||
total_self_percent += stat.selfpercent() | ||||
total_cum_percent += stat.totalpercent() | ||||
|
r40234 | fp.write( | ||
b'\n %s:%s Total: %0.2fs (%0.2f%%) Self: %0.2fs (%0.2f%%)\n\n' | ||||
% ( | ||||
|
r43347 | pycompat.sysbytes(filename or b'___'), | ||
|
r43346 | pycompat.sysbytes(function), | ||
total_cum_sec, | ||||
total_cum_percent, | ||||
total_self_sec, | ||||
total_self_percent, | ||||
) | ||||
) | ||||
|
r30253 | |||
|
r43376 | children = [(child, count) for child, count in pycompat.iteritems(children)] | ||
|
r30253 | children.sort(reverse=True, key=lambda x: x[1]) | ||
for child, count in children: | ||||
|
r43346 | fp.write( | ||
b' %6.2f%% line %s: %s\n' | ||||
% ( | ||||
count / relevant_samples * 100, | ||||
child.lineno, | ||||
pycompat.sysbytes(child.getsource(50)), | ||||
) | ||||
) | ||||
|
r30253 | |||
|
r30258 | def display_hotpath(data, fp, limit=0.05, **kwargs): | ||
|
r30253 | class HotNode(object): | ||
def __init__(self, site): | ||||
self.site = site | ||||
self.count = 0 | ||||
self.children = {} | ||||
def add(self, stack, time): | ||||
self.count += time | ||||
site = stack[0] | ||||
child = self.children.get(site) | ||||
if not child: | ||||
child = HotNode(site) | ||||
self.children[site] = child | ||||
if len(stack) > 1: | ||||
i = 1 | ||||
# Skip boiler plate parts of the stack | ||||
|
r40421 | while i < len(stack) and stack[i].skipname() in skips: | ||
|
r30253 | i += 1 | ||
if i < len(stack): | ||||
child.add(stack[i:], time) | ||||
|
r46638 | else: | ||
# Normally this is done by the .add() calls | ||||
child.count += time | ||||
|
r30253 | |||
root = HotNode(None) | ||||
|
r30258 | lasttime = data.samples[0].time | ||
for sample in data.samples: | ||||
|
r30253 | root.add(sample.stack[::-1], sample.time - lasttime) | ||
lasttime = sample.time | ||||
|
r43906 | showtime = kwargs.get('showtime', True) | ||
|
r30253 | |||
def _write(node, depth, multiple_siblings): | ||||
site = node.site | ||||
|
r43346 | visiblechildren = [ | ||
c | ||||
|
r43374 | for c in pycompat.itervalues(node.children) | ||
|
r43346 | if c.count >= (limit * root.count) | ||
] | ||||
|
r30253 | if site: | ||
indent = depth * 2 - 1 | ||||
|
r46638 | filename = (site.filename() + b':').ljust(15) | ||
function = site.function | ||||
|
r30253 | |||
# lots of string formatting | ||||
|
r43346 | listpattern = ( | ||
|
r43347 | b''.ljust(indent) | ||
+ (b'\\' if multiple_siblings else b'|') | ||||
+ b' %4.1f%%' | ||||
+ (b' %5.2fs' % node.count if showtime else b'') | ||||
+ b' %s %s' | ||||
|
r43346 | ) | ||
liststring = listpattern % ( | ||||
node.count / root.count * 100, | ||||
filename, | ||||
function, | ||||
) | ||||
|
r46639 | # 4 to account for the word 'line' | ||
spacing_len = max(4, 55 - len(liststring)) | ||||
prefix = b'' | ||||
if spacing_len == 4: | ||||
prefix = b', ' | ||||
codepattern = b'%s%s %d: %s%s' | ||||
|
r43347 | codestring = codepattern % ( | ||
|
r46639 | prefix, | ||
b'line'.rjust(spacing_len), | ||||
|
r43347 | site.lineno, | ||
|
r46639 | b''.ljust(max(0, 4 - len(str(site.lineno)))), | ||
|
r43347 | site.getsource(30), | ||
) | ||||
|
r30253 | |||
finalstring = liststring + codestring | ||||
|
r43374 | childrensamples = sum( | ||
[c.count for c in pycompat.itervalues(node.children)] | ||||
) | ||||
|
r30253 | # Make frames that performed more than 10% of the operation red | ||
if node.count - childrensamples > (0.1 * root.count): | ||||
|
r43347 | finalstring = b'\033[91m' + finalstring + b'\033[0m' | ||
|
r30253 | # Make frames that didn't actually perform work dark grey | ||
elif node.count - childrensamples == 0: | ||||
|
r43347 | finalstring = b'\033[90m' + finalstring + b'\033[0m' | ||
|
r40420 | fp.write(finalstring + b'\n') | ||
|
r30253 | |||
newdepth = depth | ||||
if len(visiblechildren) > 1 or multiple_siblings: | ||||
newdepth += 1 | ||||
visiblechildren.sort(reverse=True, key=lambda x: x.count) | ||||
for child in visiblechildren: | ||||
_write(child, newdepth, len(visiblechildren) > 1) | ||||
if root.count > 0: | ||||
_write(root, 0, False) | ||||
|
r43346 | |||
|
r30258 | def write_to_flame(data, fp, scriptpath=None, outputfile=None, **kwargs): | ||
|
r30253 | if scriptpath is None: | ||
|
r43347 | scriptpath = encoding.environ[b'HOME'] + b'/flamegraph.pl' | ||
|
r30253 | if not os.path.exists(scriptpath): | ||
|
r40234 | fp.write(b'error: missing %s\n' % scriptpath) | ||
fp.write(b'get it here: https://github.com/brendangregg/FlameGraph\n') | ||||
|
r30253 | return | ||
lines = {} | ||||
|
r30258 | for sample in data.samples: | ||
|
r30253 | sites = [s.function for s in sample.stack] | ||
sites.reverse() | ||||
|
r43347 | line = b';'.join(sites) | ||
|
r30253 | if line in lines: | ||
lines[line] = lines[line] + 1 | ||||
else: | ||||
lines[line] = 1 | ||||
|
r43103 | fd, path = pycompat.mkstemp() | ||
|
r30253 | |||
|
r43347 | with open(path, b"w+") as file: | ||
|
r43376 | for line, count in pycompat.iteritems(lines): | ||
|
r43347 | file.write(b"%s %d\n" % (line, count)) | ||
|
r30253 | |||
if outputfile is None: | ||||
|
r43347 | outputfile = b'~/flamegraph.svg' | ||
|
r30253 | |||
|
r43347 | os.system(b"perl ~/flamegraph.pl %s > %s" % (path, outputfile)) | ||
|
r40234 | fp.write(b'Written to %s\n' % outputfile) | ||
|
r30253 | |||
|
r43346 | |||
|
r30928 | _pathcache = {} | ||
|
r43346 | |||
|
r30928 | def simplifypath(path): | ||
|
r46554 | """Attempt to make the path to a Python module easier to read by | ||
|
r30928 | removing whatever part of the Python search path it was found | ||
|
r46554 | on.""" | ||
|
r30928 | |||
if path in _pathcache: | ||||
return _pathcache[path] | ||||
|
r43105 | hgpath = encoding.__file__.rsplit(os.sep, 2)[0] | ||
|
r30928 | for p in [hgpath] + sys.path: | ||
prefix = p + os.sep | ||||
if path.startswith(prefix): | ||||
|
r43346 | path = path[len(prefix) :] | ||
|
r30928 | break | ||
_pathcache[path] = path | ||||
return path | ||||
|
r43346 | |||
|
r30258 | def write_to_json(data, fp): | ||
|
r30253 | samples = [] | ||
|
r30258 | for sample in data.samples: | ||
|
r30253 | stack = [] | ||
for frame in sample.stack: | ||||
|
r40519 | stack.append( | ||
|
r43346 | ( | ||
pycompat.sysstr(frame.path), | ||||
frame.lineno, | ||||
pycompat.sysstr(frame.function), | ||||
) | ||||
) | ||||
|
r30253 | |||
samples.append((sample.time, stack)) | ||||
|
r40227 | data = json.dumps(samples) | ||
if not isinstance(data, bytes): | ||||
data = data.encode('utf-8') | ||||
fp.write(data) | ||||
|
r30253 | |||
|
r43346 | |||
|
r30929 | def write_to_chrome(data, fp, minthreshold=0.005, maxthreshold=0.999): | ||
samples = [] | ||||
laststack = collections.deque() | ||||
lastseen = collections.deque() | ||||
# The Chrome tracing format allows us to use a compact stack | ||||
# representation to save space. It's fiddly but worth it. | ||||
# We maintain a bijection between stack and ID. | ||||
stack2id = {} | ||||
|
r43346 | id2stack = [] # will eventually be rendered | ||
|
r30929 | |||
def stackid(stack): | ||||
if not stack: | ||||
return | ||||
if stack in stack2id: | ||||
return stack2id[stack] | ||||
parent = stackid(stack[1:]) | ||||
myid = len(stack2id) | ||||
stack2id[stack] = myid | ||||
|
r43906 | id2stack.append(dict(category=stack[0][0], name='%s %s' % stack[0])) | ||
|
r30929 | if parent is not None: | ||
id2stack[-1].update(parent=parent) | ||||
return myid | ||||
# The sampling profiler can sample multiple times without | ||||
# advancing the clock, potentially causing the Chrome trace viewer | ||||
# to render single-pixel columns that we cannot zoom in on. We | ||||
# work around this by pretending that zero-duration samples are a | ||||
# millisecond in length. | ||||
clamp = 0.001 | ||||
# We provide knobs that by default attempt to filter out stack | ||||
# frames that are too noisy: | ||||
# | ||||
# * A few take almost all execution time. These are usually boring | ||||
# setup functions, giving a stack that is deep but uninformative. | ||||
# | ||||
# * Numerous samples take almost no time, but introduce lots of | ||||
# noisy, oft-deep "spines" into a rendered profile. | ||||
blacklist = set() | ||||
totaltime = data.samples[-1].time - data.samples[0].time | ||||
minthreshold = totaltime * minthreshold | ||||
maxthreshold = max(totaltime * maxthreshold, clamp) | ||||
def poplast(): | ||||
oldsid = stackid(tuple(laststack)) | ||||
oldcat, oldfunc = laststack.popleft() | ||||
oldtime, oldidx = lastseen.popleft() | ||||
duration = sample.time - oldtime | ||||
if minthreshold <= duration <= maxthreshold: | ||||
# ensure no zero-duration events | ||||
sampletime = max(oldtime + clamp, sample.time) | ||||
|
r43346 | samples.append( | ||
dict( | ||||
|
r43906 | ph='E', | ||
|
r43346 | name=oldfunc, | ||
cat=oldcat, | ||||
sf=oldsid, | ||||
ts=sampletime * 1e6, | ||||
pid=0, | ||||
) | ||||
) | ||||
|
r30929 | else: | ||
blacklist.add(oldidx) | ||||
# Much fiddling to synthesize correctly(ish) nested begin/end | ||||
# events given only stack snapshots. | ||||
for sample in data.samples: | ||||
|
r43346 | stack = tuple( | ||
( | ||||
( | ||||
|
r43906 | '%s:%d' | ||
|
r43346 | % (simplifypath(pycompat.sysstr(frame.path)), frame.lineno), | ||
pycompat.sysstr(frame.function), | ||||
) | ||||
for frame in sample.stack | ||||
) | ||||
) | ||||
|
r30929 | qstack = collections.deque(stack) | ||
if laststack == qstack: | ||||
continue | ||||
while laststack and qstack and laststack[-1] == qstack[-1]: | ||||
laststack.pop() | ||||
qstack.pop() | ||||
while laststack: | ||||
poplast() | ||||
for f in reversed(qstack): | ||||
lastseen.appendleft((sample.time, len(samples))) | ||||
laststack.appendleft(f) | ||||
path, name = f | ||||
sid = stackid(tuple(laststack)) | ||||
|
r43346 | samples.append( | ||
dict( | ||||
|
r43906 | ph='B', | ||
|
r43346 | name=name, | ||
cat=path, | ||||
ts=sample.time * 1e6, | ||||
sf=sid, | ||||
pid=0, | ||||
) | ||||
) | ||||
|
r30929 | laststack = collections.deque(stack) | ||
while laststack: | ||||
poplast() | ||||
|
r43346 | events = [ | ||
sample for idx, sample in enumerate(samples) if idx not in blacklist | ||||
] | ||||
frames = collections.OrderedDict( | ||||
(str(k), v) for (k, v) in enumerate(id2stack) | ||||
) | ||||
|
r43104 | data = json.dumps(dict(traceEvents=events, stackFrames=frames), indent=1) | ||
if not isinstance(data, bytes): | ||||
data = data.encode('utf-8') | ||||
fp.write(data) | ||||
|
r43347 | fp.write(b'\n') | ||
|
r30929 | |||
|
r43346 | |||
|
r30253 | def printusage(): | ||
|
r43346 | print( | ||
r""" | ||||
|
r30253 | The statprof command line allows you to inspect the last profile's results in | ||
the following forms: | ||||
usage: | ||||
hotpath [-l --limit percent] | ||||
Shows a graph of calls with the percent of time each takes. | ||||
Red calls take over 10%% of the total time themselves. | ||||
lines | ||||
Shows the actual sampled lines. | ||||
functions | ||||
Shows the samples grouped by function. | ||||
function [filename:]functionname | ||||
Shows the callers and callees of a particular function. | ||||
flame [-s --script-path] [-o --output-file path] | ||||
Writes out a flamegraph to output-file (defaults to ~/flamegraph.svg) | ||||
Requires that ~/flamegraph.pl exist. | ||||
|
r43346 | (Specify alternate script path with --script-path.)""" | ||
) | ||||
|
r30253 | |||
def main(argv=None): | ||||
if argv is None: | ||||
argv = sys.argv | ||||
if len(argv) == 1: | ||||
printusage() | ||||
return 0 | ||||
displayargs = {} | ||||
optstart = 2 | ||||
|
r43347 | displayargs[b'function'] = None | ||
|
r43906 | if argv[1] == 'hotpath': | ||
|
r43347 | displayargs[b'format'] = DisplayFormats.Hotpath | ||
|
r43906 | elif argv[1] == 'lines': | ||
|
r43347 | displayargs[b'format'] = DisplayFormats.ByLine | ||
|
r43906 | elif argv[1] == 'functions': | ||
|
r43347 | displayargs[b'format'] = DisplayFormats.ByMethod | ||
|
r43906 | elif argv[1] == 'function': | ||
|
r43347 | displayargs[b'format'] = DisplayFormats.AboutMethod | ||
displayargs[b'function'] = argv[2] | ||||
|
r30253 | optstart = 3 | ||
|
r43906 | elif argv[1] == 'flame': | ||
|
r43347 | displayargs[b'format'] = DisplayFormats.FlameGraph | ||
|
r30253 | else: | ||
printusage() | ||||
return 0 | ||||
# process options | ||||
try: | ||||
|
r43346 | opts, args = pycompat.getoptb( | ||
sys.argv[optstart:], | ||||
|
r43347 | b"hl:f:o:p:", | ||
[b"help", b"limit=", b"file=", b"output-file=", b"script-path="], | ||||
|
r43346 | ) | ||
|
r30253 | except getopt.error as msg: | ||
|
r30257 | print(msg) | ||
|
r30253 | printusage() | ||
return 2 | ||||
|
r43347 | displayargs[b'limit'] = 0.05 | ||
|
r30253 | path = None | ||
for o, value in opts: | ||||
|
r43809 | if o in ("-l", "--limit"): | ||
|
r43347 | displayargs[b'limit'] = float(value) | ||
|
r43809 | elif o in ("-f", "--file"): | ||
|
r30253 | path = value | ||
|
r43809 | elif o in ("-o", "--output-file"): | ||
|
r43347 | displayargs[b'outputfile'] = value | ||
|
r43809 | elif o in ("-p", "--script-path"): | ||
|
r43347 | displayargs[b'scriptpath'] = value | ||
|
r43809 | elif o in ("-h", "help"): | ||
|
r30253 | printusage() | ||
return 0 | ||||
else: | ||||
|
r49312 | assert False, "unhandled option %s" % o | ||
|
r30253 | |||
|
r30845 | if not path: | ||
|
r43906 | print('must specify --file to load') | ||
|
r30845 | return 1 | ||
|
r30253 | load_data(path=path) | ||
|
r35371 | display(**pycompat.strkwargs(displayargs)) | ||
|
r30253 | |||
return 0 | ||||
|
r43346 | |||
|
r43809 | if __name__ == "__main__": | ||
|
r30253 | sys.exit(main()) | ||