statprof.py
948 lines
| 30.3 KiB
| text/x-python
|
PythonLexer
/ mercurial / statprof.py
Gregory Szorc
|
r30253 | #!/usr/bin/env python | ||
## 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 | ||||
Gregory Szorc
|
r30257 | from __future__ import absolute_import, division, print_function | ||
Gregory Szorc
|
r30253 | |||
Gregory Szorc
|
r30256 | import collections | ||
import contextlib | ||||
import getopt | ||||
import inspect | ||||
import json | ||||
import os | ||||
import signal | ||||
import sys | ||||
import threading | ||||
Gregory Szorc
|
r30253 | import time | ||
Gregory Szorc
|
r30256 | |||
Pulkit Goyal
|
r30578 | from . import ( | ||
Pulkit Goyal
|
r30637 | encoding, | ||
Pulkit Goyal
|
r30578 | pycompat, | ||
) | ||||
Gregory Szorc
|
r30256 | defaultdict = collections.defaultdict | ||
contextmanager = contextlib.contextmanager | ||||
Gregory Szorc
|
r30253 | |||
__all__ = ['start', 'stop', 'reset', 'display', 'profile'] | ||||
Martin von Zweigbergk
|
r32291 | skips = {"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", | ||||
} | ||||
Gregory Szorc
|
r30253 | |||
########################################################################### | ||||
## Utils | ||||
def clock(): | ||||
times = os.times() | ||||
Boris Feld
|
r38278 | return (times[0] + times[1], times[4]) | ||
Gregory Szorc
|
r30253 | |||
########################################################################### | ||||
## Collection data structures | ||||
class ProfileState(object): | ||||
def __init__(self, frequency=None): | ||||
self.reset(frequency) | ||||
Boris Feld
|
r38279 | self.track = 'cpu' | ||
Gregory Szorc
|
r30253 | |||
def reset(self, frequency=None): | ||||
# total so far | ||||
Boris Feld
|
r38278 | self.accumulated_time = (0.0, 0.0) | ||
Gregory Szorc
|
r30253 | # start_time when timer is active | ||
self.last_start_time = None | ||||
# a float | ||||
if frequency: | ||||
self.sample_interval = 1.0 / frequency | ||||
elif not hasattr(self, 'sample_interval'): | ||||
# 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): | ||||
Boris Feld
|
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], | ||||
) | ||||
Gregory Szorc
|
r30253 | |||
def seconds_per_sample(self): | ||||
Boris Feld
|
r38279 | return self.accumulated_time[self.timeidx] / len(self.samples) | ||
@property | ||||
def timeidx(self): | ||||
if self.track == 'real': | ||||
return 1 | ||||
return 0 | ||||
Gregory Szorc
|
r30253 | |||
state = ProfileState() | ||||
class CodeSite(object): | ||||
cache = {} | ||||
Pulkit Goyal
|
r30568 | __slots__ = (u'path', u'lineno', u'function', u'source') | ||
Gregory Szorc
|
r30253 | |||
def __init__(self, path, lineno, function): | ||||
self.path = path | ||||
self.lineno = lineno | ||||
self.function = function | ||||
self.source = None | ||||
def __eq__(self, other): | ||||
try: | ||||
return (self.lineno == other.lineno and | ||||
self.path == other.path) | ||||
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 | ||||
fp = None | ||||
try: | ||||
fp = open(self.path) | ||||
for i, line in enumerate(fp): | ||||
if i == lineno: | ||||
self.source = line.strip() | ||||
break | ||||
except: | ||||
pass | ||||
finally: | ||||
if fp: | ||||
fp.close() | ||||
if self.source is None: | ||||
self.source = '' | ||||
source = self.source | ||||
if len(source) > length: | ||||
source = source[:(length - 3)] + "..." | ||||
return source | ||||
def filename(self): | ||||
return os.path.basename(self.path) | ||||
class Sample(object): | ||||
Pulkit Goyal
|
r30568 | __slots__ = (u'stack', u'time') | ||
Gregory Szorc
|
r30253 | |||
def __init__(self, stack, time): | ||||
self.stack = stack | ||||
self.time = time | ||||
@classmethod | ||||
def from_frame(cls, frame, time): | ||||
stack = [] | ||||
while frame: | ||||
stack.append(CodeSite.get(frame.f_code.co_filename, frame.f_lineno, | ||||
frame.f_code.co_name)) | ||||
frame = frame.f_back | ||||
return Sample(stack, time) | ||||
########################################################################### | ||||
## SIGPROF handler | ||||
def profile_signal_handler(signum, frame): | ||||
if state.profile_level > 0: | ||||
now = clock() | ||||
state.accumulate_time(now) | ||||
Boris Feld
|
r38279 | timestamp = state.accumulated_time[state.timeidx] | ||
state.samples.append(Sample.from_frame(frame, timestamp)) | ||||
Gregory Szorc
|
r30253 | |||
signal.setitimer(signal.ITIMER_PROF, | ||||
state.sample_interval, 0.0) | ||||
state.last_start_time = now | ||||
stopthread = threading.Event() | ||||
def samplerthread(tid): | ||||
while not stopthread.is_set(): | ||||
now = clock() | ||||
state.accumulate_time(now) | ||||
frame = sys._current_frames()[tid] | ||||
Boris Feld
|
r38279 | |||
timestamp = state.accumulated_time[state.timeidx] | ||||
state.samples.append(Sample.from_frame(frame, timestamp)) | ||||
Gregory Szorc
|
r30253 | |||
state.last_start_time = now | ||||
time.sleep(state.sample_interval) | ||||
stopthread.clear() | ||||
########################################################################### | ||||
## Profiling API | ||||
def is_active(): | ||||
return state.profile_level > 0 | ||||
lastmechanism = None | ||||
Boris Feld
|
r38279 | def start(mechanism='thread', track='cpu'): | ||
Gregory Szorc
|
r30253 | '''Install the profiling signal handler, and start profiling.''' | ||
Boris Feld
|
r38279 | state.track = track # note: nesting different mode won't work | ||
Gregory Szorc
|
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 | ||||
if mechanism == 'signal': | ||||
signal.signal(signal.SIGPROF, profile_signal_handler) | ||||
signal.setitimer(signal.ITIMER_PROF, | ||||
rpt or state.sample_interval, 0.0) | ||||
elif mechanism == 'thread': | ||||
frame = inspect.currentframe() | ||||
tid = [k for k, f in sys._current_frames().items() if f == frame][0] | ||||
state.thread = threading.Thread(target=samplerthread, | ||||
args=(tid,), name="samplerthread") | ||||
state.thread.start() | ||||
def stop(): | ||||
'''Stop profiling, and uninstall the profiling signal handler.''' | ||||
state.profile_level -= 1 | ||||
if state.profile_level == 0: | ||||
if lastmechanism == 'signal': | ||||
rpt = signal.setitimer(signal.ITIMER_PROF, 0.0, 0.0) | ||||
signal.signal(signal.SIGPROF, signal.SIG_IGN) | ||||
state.remaining_prof_time = rpt[0] | ||||
elif lastmechanism == 'thread': | ||||
stopthread.set() | ||||
state.thread.join() | ||||
state.accumulate_time(clock()) | ||||
state.last_start_time = None | ||||
Pulkit Goyal
|
r30637 | statprofpath = encoding.environ.get('STATPROF_DEST') | ||
Gregory Szorc
|
r30255 | if statprofpath: | ||
save_data(statprofpath) | ||||
Gregory Szorc
|
r30253 | |||
Gregory Szorc
|
r30299 | return state | ||
Gregory Szorc
|
r30255 | def save_data(path): | ||
with open(path, 'w+') as file: | ||||
Boris Feld
|
r38293 | file.write("%f %f\n" % state.accumulated_time) | ||
Gregory Szorc
|
r30253 | for sample in state.samples: | ||
time = str(sample.time) | ||||
stack = sample.stack | ||||
sites = ['\1'.join([s.path, str(s.lineno), s.function]) | ||||
for s in stack] | ||||
Boris Feld
|
r39127 | file.write("%s\0%s\n" % (time, '\0'.join(sites))) | ||
Gregory Szorc
|
r30253 | |||
Gregory Szorc
|
r30255 | def load_data(path): | ||
Gregory Szorc
|
r30253 | lines = open(path, 'r').read().splitlines() | ||
Boris Feld
|
r38293 | state.accumulated_time = [float(value) for value in lines[0].split()] | ||
Gregory Szorc
|
r30253 | state.samples = [] | ||
for line in lines[1:]: | ||||
parts = line.split('\0') | ||||
time = float(parts[0]) | ||||
rawsites = parts[1:] | ||||
sites = [] | ||||
for rawsite in rawsites: | ||||
siteparts = rawsite.split('\1') | ||||
sites.append(CodeSite.get(siteparts[0], int(siteparts[1]), | ||||
siteparts[2])) | ||||
state.samples.append(Sample(sites, time)) | ||||
def reset(frequency=None): | ||||
'''Clear out the state of the profiler. Do not call while the | ||||
profiler is running. | ||||
The optional frequency argument specifies the number of samples to | ||||
collect per second.''' | ||||
assert state.profile_level == 0, "Can't reset() while statprof is running" | ||||
CodeSite.cache.clear() | ||||
state.reset(frequency) | ||||
@contextmanager | ||||
def profile(): | ||||
start() | ||||
try: | ||||
yield | ||||
finally: | ||||
stop() | ||||
display() | ||||
########################################################################### | ||||
## Reporting API | ||||
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() | ||||
return [s for s in stats.itervalues()] | ||||
class DisplayFormats: | ||||
ByLine = 0 | ||||
ByMethod = 1 | ||||
AboutMethod = 2 | ||||
Hotpath = 3 | ||||
FlameGraph = 4 | ||||
Json = 5 | ||||
Bryan O'Sullivan
|
r30929 | Chrome = 6 | ||
Gregory Szorc
|
r30253 | |||
Gregory Szorc
|
r30258 | def display(fp=None, format=3, data=None, **kwargs): | ||
Gregory Szorc
|
r30253 | '''Print statistics, either to stdout or the given file object.''' | ||
Boris Feld
|
r38719 | if data is None: | ||
data = state | ||||
Gregory Szorc
|
r30253 | |||
if fp is None: | ||||
import sys | ||||
fp = sys.stdout | ||||
Gregory Szorc
|
r30258 | if len(data.samples) == 0: | ||
Gregory Szorc
|
r30257 | print('No samples recorded.', file=fp) | ||
Gregory Szorc
|
r30253 | return | ||
if format == DisplayFormats.ByLine: | ||||
Gregory Szorc
|
r30258 | display_by_line(data, fp) | ||
Gregory Szorc
|
r30253 | elif format == DisplayFormats.ByMethod: | ||
Gregory Szorc
|
r30258 | display_by_method(data, fp) | ||
Gregory Szorc
|
r30253 | elif format == DisplayFormats.AboutMethod: | ||
Gregory Szorc
|
r30258 | display_about_method(data, fp, **kwargs) | ||
Gregory Szorc
|
r30253 | elif format == DisplayFormats.Hotpath: | ||
Gregory Szorc
|
r30258 | display_hotpath(data, fp, **kwargs) | ||
Gregory Szorc
|
r30253 | elif format == DisplayFormats.FlameGraph: | ||
Gregory Szorc
|
r30258 | write_to_flame(data, fp, **kwargs) | ||
Gregory Szorc
|
r30253 | elif format == DisplayFormats.Json: | ||
Gregory Szorc
|
r30258 | write_to_json(data, fp) | ||
Bryan O'Sullivan
|
r30929 | elif format == DisplayFormats.Chrome: | ||
write_to_chrome(data, fp, **kwargs) | ||||
Gregory Szorc
|
r30253 | else: | ||
raise Exception("Invalid display format") | ||||
Bryan O'Sullivan
|
r30929 | if format not in (DisplayFormats.Json, DisplayFormats.Chrome): | ||
Gregory Szorc
|
r30257 | print('---', file=fp) | ||
Gregory Szorc
|
r30258 | print('Sample count: %d' % len(data.samples), file=fp) | ||
Boris Feld
|
r38278 | print('Total time: %f seconds (%f wall)' % data.accumulated_time, | ||
file=fp) | ||||
Gregory Szorc
|
r30253 | |||
Gregory Szorc
|
r30258 | def display_by_line(data, fp): | ||
Gregory Szorc
|
r30253 | '''Print the profiler data with each sample line represented | ||
as one row in a table. Sorted by self-time per line.''' | ||||
Gregory Szorc
|
r30258 | stats = SiteStats.buildstats(data.samples) | ||
Gregory Szorc
|
r30253 | stats.sort(reverse=True, key=lambda x: x.selfseconds()) | ||
Gregory Szorc
|
r30257 | print('%5.5s %10.10s %7.7s %-8.8s' % | ||
('% ', 'cumulative', 'self', ''), file=fp) | ||||
print('%5.5s %9.9s %8.8s %-8.8s' % | ||||
("time", "seconds", "seconds", "name"), file=fp) | ||||
Gregory Szorc
|
r30253 | |||
for stat in stats: | ||||
site = stat.site | ||||
sitelabel = '%s:%d:%s' % (site.filename(), site.lineno, site.function) | ||||
Gregory Szorc
|
r30257 | print('%6.2f %9.2f %9.2f %s' % (stat.selfpercent(), | ||
stat.totalseconds(), | ||||
stat.selfseconds(), | ||||
sitelabel), | ||||
file=fp) | ||||
Gregory Szorc
|
r30253 | |||
Gregory Szorc
|
r30258 | def display_by_method(data, fp): | ||
Gregory Szorc
|
r30253 | '''Print the profiler data with each sample function represented | ||
as one row in a table. Important lines within that function are | ||||
output as nested rows. Sorted by self-time per line.''' | ||||
Gregory Szorc
|
r30257 | print('%5.5s %10.10s %7.7s %-8.8s' % | ||
('% ', 'cumulative', 'self', ''), file=fp) | ||||
print('%5.5s %9.9s %8.8s %-8.8s' % | ||||
("time", "seconds", "seconds", "name"), file=fp) | ||||
Gregory Szorc
|
r30253 | |||
Gregory Szorc
|
r30258 | stats = SiteStats.buildstats(data.samples) | ||
Gregory Szorc
|
r30253 | |||
grouped = defaultdict(list) | ||||
for stat in stats: | ||||
grouped[stat.site.filename() + ":" + stat.site.function].append(stat) | ||||
# compute sums for each function | ||||
functiondata = [] | ||||
for fname, sitestats in grouped.iteritems(): | ||||
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() | ||||
functiondata.append((fname, | ||||
total_cum_sec, | ||||
total_self_sec, | ||||
total_percent, | ||||
sitestats)) | ||||
# sort by total self sec | ||||
functiondata.sort(reverse=True, key=lambda x: x[2]) | ||||
for function in functiondata: | ||||
if function[3] < 0.05: | ||||
continue | ||||
Gregory Szorc
|
r30257 | print('%6.2f %9.2f %9.2f %s' % (function[3], # total percent | ||
function[1], # total cum sec | ||||
function[2], # total self sec | ||||
function[0]), # file:function | ||||
file=fp) | ||||
Gregory Szorc
|
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) | ||||
stattuple = (stat.selfpercent(), stat.selfseconds(), | ||||
stat.site.lineno, source) | ||||
Gregory Szorc
|
r30257 | print('%33.0f%% %6.2f line %s: %s' % (stattuple), file=fp) | ||
Gregory Szorc
|
r30253 | |||
Gregory Szorc
|
r30258 | def display_about_method(data, fp, function=None, **kwargs): | ||
Gregory Szorc
|
r30253 | if function is None: | ||
raise Exception("Invalid function") | ||||
filename = None | ||||
if ':' in function: | ||||
filename, function = function.split(':') | ||||
relevant_samples = 0 | ||||
parents = {} | ||||
children = {} | ||||
Gregory Szorc
|
r30258 | for sample in data.samples: | ||
Gregory Szorc
|
r30253 | for i, site in enumerate(sample.stack): | ||
if site.function == function and (not filename | ||||
or site.filename() == filename): | ||||
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 | ||||
parents = [(parent, count) for parent, count in parents.iteritems()] | ||||
parents.sort(reverse=True, key=lambda x: x[1]) | ||||
for parent, count in parents: | ||||
Gregory Szorc
|
r30257 | print('%6.2f%% %s:%s line %s: %s' % | ||
Gregory Szorc
|
r30253 | (count / relevant_samples * 100, parent.filename(), | ||
Gregory Szorc
|
r30257 | parent.function, parent.lineno, parent.getsource(50)), file=fp) | ||
Gregory Szorc
|
r30253 | |||
Gregory Szorc
|
r30258 | stats = SiteStats.buildstats(data.samples) | ||
Gregory Szorc
|
r30253 | stats = [s for s in stats | ||
if s.site.function == function and | ||||
(not filename or s.site.filename() == filename)] | ||||
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() | ||||
Gregory Szorc
|
r30257 | print( | ||
Gregory Szorc
|
r30253 | '\n %s:%s Total: %0.2fs (%0.2f%%) Self: %0.2fs (%0.2f%%)\n' % | ||
( | ||||
filename or '___', | ||||
function, | ||||
total_cum_sec, | ||||
total_cum_percent, | ||||
total_self_sec, | ||||
total_self_percent | ||||
Gregory Szorc
|
r30257 | ), file=fp) | ||
Gregory Szorc
|
r30253 | |||
children = [(child, count) for child, count in children.iteritems()] | ||||
children.sort(reverse=True, key=lambda x: x[1]) | ||||
for child, count in children: | ||||
Gregory Szorc
|
r30257 | print(' %6.2f%% line %s: %s' % | ||
(count / relevant_samples * 100, child.lineno, | ||||
child.getsource(50)), file=fp) | ||||
Gregory Szorc
|
r30253 | |||
Gregory Szorc
|
r30258 | def display_hotpath(data, fp, limit=0.05, **kwargs): | ||
Gregory Szorc
|
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 | ||||
while i < len(stack) and '%s:%s' % (stack[i].filename(), stack[i].function) in skips: | ||||
i += 1 | ||||
if i < len(stack): | ||||
child.add(stack[i:], time) | ||||
root = HotNode(None) | ||||
Gregory Szorc
|
r30258 | lasttime = data.samples[0].time | ||
for sample in data.samples: | ||||
Gregory Szorc
|
r30253 | root.add(sample.stack[::-1], sample.time - lasttime) | ||
lasttime = sample.time | ||||
def _write(node, depth, multiple_siblings): | ||||
site = node.site | ||||
visiblechildren = [c for c in node.children.itervalues() | ||||
if c.count >= (limit * root.count)] | ||||
if site: | ||||
indent = depth * 2 - 1 | ||||
filename = '' | ||||
function = '' | ||||
if len(node.children) > 0: | ||||
childsite = list(node.children.itervalues())[0].site | ||||
filename = (childsite.filename() + ':').ljust(15) | ||||
function = childsite.function | ||||
# lots of string formatting | ||||
listpattern = ''.ljust(indent) +\ | ||||
('\\' if multiple_siblings else '|') +\ | ||||
' %4.1f%% %s %s' | ||||
liststring = listpattern % (node.count / root.count * 100, | ||||
filename, function) | ||||
codepattern = '%' + str(55 - len(liststring)) + 's %s: %s' | ||||
codestring = codepattern % ('line', site.lineno, site.getsource(30)) | ||||
finalstring = liststring + codestring | ||||
childrensamples = sum([c.count for c in node.children.itervalues()]) | ||||
# Make frames that performed more than 10% of the operation red | ||||
if node.count - childrensamples > (0.1 * root.count): | ||||
finalstring = '\033[91m' + finalstring + '\033[0m' | ||||
# Make frames that didn't actually perform work dark grey | ||||
elif node.count - childrensamples == 0: | ||||
finalstring = '\033[90m' + finalstring + '\033[0m' | ||||
Gregory Szorc
|
r30257 | print(finalstring, file=fp) | ||
Gregory Szorc
|
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) | ||||
Gregory Szorc
|
r30258 | def write_to_flame(data, fp, scriptpath=None, outputfile=None, **kwargs): | ||
Gregory Szorc
|
r30253 | if scriptpath is None: | ||
Pulkit Goyal
|
r30637 | scriptpath = encoding.environ['HOME'] + '/flamegraph.pl' | ||
Gregory Szorc
|
r30253 | if not os.path.exists(scriptpath): | ||
Gregory Szorc
|
r30257 | print("error: missing %s" % scriptpath, file=fp) | ||
print("get it here: https://github.com/brendangregg/FlameGraph", | ||||
file=fp) | ||||
Gregory Szorc
|
r30253 | return | ||
Yuya Nishihara
|
r38182 | fd, path = pycompat.mkstemp() | ||
Gregory Szorc
|
r30253 | |||
file = open(path, "w+") | ||||
lines = {} | ||||
Gregory Szorc
|
r30258 | for sample in data.samples: | ||
Gregory Szorc
|
r30253 | sites = [s.function for s in sample.stack] | ||
sites.reverse() | ||||
line = ';'.join(sites) | ||||
if line in lines: | ||||
lines[line] = lines[line] + 1 | ||||
else: | ||||
lines[line] = 1 | ||||
for line, count in lines.iteritems(): | ||||
file.write("%s %s\n" % (line, count)) | ||||
file.close() | ||||
if outputfile is None: | ||||
outputfile = '~/flamegraph.svg' | ||||
os.system("perl ~/flamegraph.pl %s > %s" % (path, outputfile)) | ||||
Gregory Szorc
|
r30257 | print("Written to %s" % outputfile, file=fp) | ||
Gregory Szorc
|
r30253 | |||
Bryan O'Sullivan
|
r30928 | _pathcache = {} | ||
def simplifypath(path): | ||||
'''Attempt to make the path to a Python module easier to read by | ||||
removing whatever part of the Python search path it was found | ||||
on.''' | ||||
if path in _pathcache: | ||||
return _pathcache[path] | ||||
Pulkit Goyal
|
r31074 | hgpath = pycompat.fsencode(encoding.__file__).rsplit(os.sep, 2)[0] | ||
Bryan O'Sullivan
|
r30928 | for p in [hgpath] + sys.path: | ||
prefix = p + os.sep | ||||
if path.startswith(prefix): | ||||
path = path[len(prefix):] | ||||
break | ||||
_pathcache[path] = path | ||||
return path | ||||
Gregory Szorc
|
r30258 | def write_to_json(data, fp): | ||
Gregory Szorc
|
r30253 | samples = [] | ||
Gregory Szorc
|
r30258 | for sample in data.samples: | ||
Gregory Szorc
|
r30253 | stack = [] | ||
for frame in sample.stack: | ||||
stack.append((frame.path, frame.lineno, frame.function)) | ||||
samples.append((sample.time, stack)) | ||||
Gregory Szorc
|
r30257 | print(json.dumps(samples), file=fp) | ||
Gregory Szorc
|
r30253 | |||
Bryan O'Sullivan
|
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 = {} | ||||
id2stack = [] # will eventually be rendered | ||||
def stackid(stack): | ||||
if not stack: | ||||
return | ||||
if stack in stack2id: | ||||
return stack2id[stack] | ||||
parent = stackid(stack[1:]) | ||||
myid = len(stack2id) | ||||
stack2id[stack] = myid | ||||
id2stack.append(dict(category=stack[0][0], name='%s %s' % stack[0])) | ||||
if parent is not None: | ||||
id2stack[-1].update(parent=parent) | ||||
return myid | ||||
def endswith(a, b): | ||||
return list(a)[-len(b):] == list(b) | ||||
# 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) | ||||
samples.append(dict(ph='E', name=oldfunc, cat=oldcat, sf=oldsid, | ||||
ts=sampletime*1e6, pid=0)) | ||||
else: | ||||
blacklist.add(oldidx) | ||||
# Much fiddling to synthesize correctly(ish) nested begin/end | ||||
# events given only stack snapshots. | ||||
for sample in data.samples: | ||||
tos = sample.stack[0] | ||||
name = tos.function | ||||
path = simplifypath(tos.path) | ||||
stack = tuple((('%s:%d' % (simplifypath(frame.path), frame.lineno), | ||||
frame.function) for frame in sample.stack)) | ||||
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)) | ||||
samples.append(dict(ph='B', name=name, cat=path, ts=sample.time*1e6, | ||||
sf=sid, pid=0)) | ||||
laststack = collections.deque(stack) | ||||
while laststack: | ||||
poplast() | ||||
events = [s[1] for s in enumerate(samples) if s[0] not in blacklist] | ||||
frames = collections.OrderedDict((str(k), v) | ||||
for (k,v) in enumerate(id2stack)) | ||||
json.dump(dict(traceEvents=events, stackFrames=frames), fp, indent=1) | ||||
fp.write('\n') | ||||
Gregory Szorc
|
r30253 | def printusage(): | ||
Gregory Szorc
|
r30257 | print(""" | ||
Gregory Szorc
|
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. | ||||
Gregory Szorc
|
r30257 | (Specify alternate script path with --script-path.)""") | ||
Gregory Szorc
|
r30253 | |||
def main(argv=None): | ||||
if argv is None: | ||||
argv = sys.argv | ||||
if len(argv) == 1: | ||||
printusage() | ||||
return 0 | ||||
displayargs = {} | ||||
optstart = 2 | ||||
displayargs['function'] = None | ||||
if argv[1] == 'hotpath': | ||||
displayargs['format'] = DisplayFormats.Hotpath | ||||
elif argv[1] == 'lines': | ||||
displayargs['format'] = DisplayFormats.ByLine | ||||
elif argv[1] == 'functions': | ||||
displayargs['format'] = DisplayFormats.ByMethod | ||||
elif argv[1] == 'function': | ||||
displayargs['format'] = DisplayFormats.AboutMethod | ||||
displayargs['function'] = argv[2] | ||||
optstart = 3 | ||||
elif argv[1] == 'flame': | ||||
displayargs['format'] = DisplayFormats.FlameGraph | ||||
else: | ||||
printusage() | ||||
return 0 | ||||
# process options | ||||
try: | ||||
Pulkit Goyal
|
r30578 | opts, args = pycompat.getoptb(sys.argv[optstart:], "hl:f:o:p:", | ||
Gregory Szorc
|
r30253 | ["help", "limit=", "file=", "output-file=", "script-path="]) | ||
except getopt.error as msg: | ||||
Gregory Szorc
|
r30257 | print(msg) | ||
Gregory Szorc
|
r30253 | printusage() | ||
return 2 | ||||
displayargs['limit'] = 0.05 | ||||
path = None | ||||
for o, value in opts: | ||||
if o in ("-l", "--limit"): | ||||
displayargs['limit'] = float(value) | ||||
elif o in ("-f", "--file"): | ||||
path = value | ||||
elif o in ("-o", "--output-file"): | ||||
displayargs['outputfile'] = value | ||||
elif o in ("-p", "--script-path"): | ||||
displayargs['scriptpath'] = value | ||||
elif o in ("-h", "help"): | ||||
printusage() | ||||
return 0 | ||||
else: | ||||
assert False, "unhandled option %s" % o | ||||
Gregory Szorc
|
r30845 | if not path: | ||
print('must specify --file to load') | ||||
return 1 | ||||
Gregory Szorc
|
r30253 | load_data(path=path) | ||
Pulkit Goyal
|
r35371 | display(**pycompat.strkwargs(displayargs)) | ||
Gregory Szorc
|
r30253 | |||
return 0 | ||||
if __name__ == "__main__": | ||||
sys.exit(main()) | ||||