2015-09-07 23:46:29 +03:00
|
|
|
#!/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.
|
|
|
|
"""
|
|
|
|
from __future__ import division
|
|
|
|
|
|
|
|
import os, signal, tempfile, sys, getopt
|
|
|
|
|
|
|
|
from collections import defaultdict
|
|
|
|
from contextlib import contextmanager
|
|
|
|
from subprocess import call
|
|
|
|
|
|
|
|
__all__ = ['start', 'stop', 'reset', 'display', 'profile']
|
|
|
|
|
|
|
|
|
|
|
|
###########################################################################
|
|
|
|
## Utils
|
|
|
|
|
|
|
|
def clock():
|
|
|
|
times = os.times()
|
|
|
|
return times[0] + times[1]
|
|
|
|
|
|
|
|
|
|
|
|
###########################################################################
|
|
|
|
## Collection data structures
|
|
|
|
|
|
|
|
class ProfileState(object):
|
|
|
|
def __init__(self, frequency=None):
|
|
|
|
self.reset(frequency)
|
|
|
|
|
|
|
|
def reset(self, frequency=None):
|
|
|
|
# total so far
|
|
|
|
self.accumulated_time = 0.0
|
|
|
|
# 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):
|
|
|
|
self.accumulated_time += stop_time - self.last_start_time
|
|
|
|
|
|
|
|
def seconds_per_sample(self):
|
|
|
|
return self.accumulated_time / len(self.samples)
|
|
|
|
|
|
|
|
state = ProfileState()
|
|
|
|
|
|
|
|
|
|
|
|
class CodeSite(object):
|
|
|
|
cache = {}
|
|
|
|
|
|
|
|
__slots__ = ('path', 'lineno', 'function', 'source')
|
|
|
|
|
|
|
|
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 == 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 == 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):
|
|
|
|
__slots__ = ('stack', 'time')
|
|
|
|
|
|
|
|
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:
|
|
|
|
state.accumulate_time(clock())
|
|
|
|
|
|
|
|
state.samples.append(Sample.from_frame(frame, state.accumulated_time))
|
|
|
|
|
|
|
|
signal.setitimer(signal.ITIMER_PROF,
|
|
|
|
state.sample_interval, 0.0)
|
|
|
|
state.last_start_time = clock()
|
|
|
|
|
|
|
|
|
|
|
|
###########################################################################
|
|
|
|
## Profiling API
|
|
|
|
|
|
|
|
def is_active():
|
|
|
|
return state.profile_level > 0
|
|
|
|
|
|
|
|
|
|
|
|
def start():
|
|
|
|
'''Install the profiling signal handler, and start profiling.'''
|
|
|
|
state.profile_level += 1
|
|
|
|
if state.profile_level == 1:
|
|
|
|
state.last_start_time = clock()
|
|
|
|
rpt = state.remaining_prof_time
|
|
|
|
state.remaining_prof_time = None
|
|
|
|
signal.signal(signal.SIGPROF, profile_signal_handler)
|
|
|
|
signal.setitimer(signal.ITIMER_PROF,
|
|
|
|
rpt or state.sample_interval, 0.0)
|
|
|
|
|
|
|
|
|
|
|
|
def stop():
|
|
|
|
'''Stop profiling, and uninstall the profiling signal handler.'''
|
|
|
|
state.profile_level -= 1
|
|
|
|
if state.profile_level == 0:
|
|
|
|
state.accumulate_time(clock())
|
|
|
|
state.last_start_time = None
|
|
|
|
rpt = signal.setitimer(signal.ITIMER_PROF, 0.0, 0.0)
|
|
|
|
signal.signal(signal.SIGPROF, signal.SIG_IGN)
|
|
|
|
state.remaining_prof_time = rpt[0]
|
|
|
|
|
2015-12-03 08:54:56 +03:00
|
|
|
statprofpath = os.environ.get('STATPROF_DEST')
|
|
|
|
save_data(statprofpath)
|
2015-09-07 23:46:29 +03:00
|
|
|
|
|
|
|
def save_data(path=None):
|
2015-09-08 03:32:12 +03:00
|
|
|
try:
|
|
|
|
path = path or (os.environ['HOME'] + '/statprof.data')
|
|
|
|
file = open(path, "w+")
|
|
|
|
|
|
|
|
file.write(str(state.accumulated_time) + '\n')
|
|
|
|
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]
|
|
|
|
file.write(time + '\0' + '\0'.join(sites) + '\n')
|
|
|
|
|
|
|
|
file.close()
|
|
|
|
except (IOError, OSError) as ex:
|
|
|
|
# The home directory probably didn't exist, or wasn't writable. Oh well.
|
|
|
|
pass
|
2015-09-07 23:46:29 +03:00
|
|
|
|
|
|
|
def load_data(path=None):
|
|
|
|
path = path or (os.environ['HOME'] + '/statprof.data')
|
|
|
|
lines = open(path, 'r').read().splitlines()
|
|
|
|
|
|
|
|
state.accumulated_time = float(lines[0])
|
|
|
|
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
|
|
|
|
|
|
|
|
def display(fp=None, format=3, **kwargs):
|
|
|
|
'''Print statistics, either to stdout or the given file object.'''
|
|
|
|
|
|
|
|
if fp is None:
|
|
|
|
import sys
|
|
|
|
fp = sys.stdout
|
|
|
|
if len(state.samples) == 0:
|
|
|
|
print >> fp, ('No samples recorded.')
|
|
|
|
return
|
|
|
|
|
|
|
|
if format == DisplayFormats.ByLine:
|
|
|
|
display_by_line(fp)
|
|
|
|
elif format == DisplayFormats.ByMethod:
|
|
|
|
display_by_method(fp)
|
|
|
|
elif format == DisplayFormats.AboutMethod:
|
|
|
|
display_about_method(fp, **kwargs)
|
|
|
|
elif format == DisplayFormats.Hotpath:
|
|
|
|
display_hotpath(fp, **kwargs)
|
|
|
|
elif format == DisplayFormats.FlameGraph:
|
|
|
|
write_to_flame(fp)
|
|
|
|
else:
|
|
|
|
raise Exception("Invalid display format")
|
|
|
|
|
|
|
|
print >> fp, ('---')
|
|
|
|
print >> fp, ('Sample count: %d' % len(state.samples))
|
|
|
|
print >> fp, ('Total time: %f seconds' % state.accumulated_time)
|
|
|
|
|
|
|
|
def display_by_line(fp):
|
|
|
|
'''Print the profiler data with each sample line represented
|
|
|
|
as one row in a table. Sorted by self-time per line.'''
|
|
|
|
stats = SiteStats.buildstats(state.samples)
|
|
|
|
stats.sort(reverse=True, key=lambda x: x.selfseconds())
|
|
|
|
|
|
|
|
print >> fp, ('%5.5s %10.10s %7.7s %-8.8s' %
|
|
|
|
('% ', 'cumulative', 'self', ''))
|
|
|
|
print >> fp, ('%5.5s %9.9s %8.8s %-8.8s' %
|
|
|
|
("time", "seconds", "seconds", "name"))
|
|
|
|
|
|
|
|
for stat in stats:
|
|
|
|
site = stat.site
|
|
|
|
sitelabel = '%s:%d:%s' % (site.filename(), site.lineno, site.function)
|
|
|
|
print >> fp, ('%6.2f %9.2f %9.2f %s' % (stat.selfpercent(),
|
|
|
|
stat.totalseconds(),
|
|
|
|
stat.selfseconds(),
|
|
|
|
sitelabel))
|
|
|
|
|
|
|
|
def display_by_method(fp):
|
|
|
|
'''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.'''
|
|
|
|
print >> fp, ('%5.5s %10.10s %7.7s %-8.8s' %
|
|
|
|
('% ', 'cumulative', 'self', ''))
|
|
|
|
print >> fp, ('%5.5s %9.9s %8.8s %-8.8s' %
|
|
|
|
("time", "seconds", "seconds", "name"))
|
|
|
|
|
|
|
|
stats = SiteStats.buildstats(state.samples)
|
|
|
|
|
|
|
|
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
|
|
|
|
print >> fp, ('%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
|
|
|
|
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)
|
|
|
|
|
|
|
|
print >> fp, ('%33.0f%% %6.2f line %s: %s' % (stat.selfpercent(),
|
|
|
|
stat.selfseconds(),
|
|
|
|
stat.site.lineno,
|
|
|
|
source))
|
|
|
|
|
|
|
|
def display_about_method(fp, function=None, **kwargs):
|
|
|
|
if function == None:
|
|
|
|
raise Exception("Invalid function")
|
|
|
|
|
|
|
|
filename = None
|
|
|
|
if ':' in function:
|
|
|
|
filename, function = function.split(':')
|
|
|
|
|
|
|
|
relevant_samples = 0
|
|
|
|
parents = {}
|
|
|
|
children = {}
|
|
|
|
|
|
|
|
for sample in state.samples:
|
|
|
|
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:
|
|
|
|
print >> fp, ('%6.2f%% %s:%s line %s: %s' %
|
|
|
|
(count / relevant_samples * 100, parent.filename(), parent.function, parent.lineno, parent.getsource(50)))
|
|
|
|
|
|
|
|
stats = SiteStats.buildstats(state.samples)
|
|
|
|
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()
|
|
|
|
|
|
|
|
print >> fp, ('\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))
|
|
|
|
|
|
|
|
children = [(child, count) for child, count in children.iteritems()]
|
|
|
|
children.sort(reverse=True, key=lambda x: x[1])
|
|
|
|
for child, count in children:
|
|
|
|
print >> fp, (' %6.2f%% line %s: %s' %
|
|
|
|
(count / relevant_samples * 100, child.lineno, child.getsource(50)))
|
|
|
|
|
|
|
|
def display_hotpath(fp, limit=0.05, **kwargs):
|
|
|
|
class HotNode(object):
|
|
|
|
def __init__(self, site):
|
|
|
|
self.site = site
|
|
|
|
self.count = 0
|
|
|
|
self.children = {}
|
|
|
|
|
|
|
|
def add(self, stack):
|
|
|
|
self.count += 1
|
|
|
|
site = stack[0]
|
|
|
|
child = self.children.get(site)
|
|
|
|
if not child:
|
|
|
|
child = HotNode(site)
|
|
|
|
self.children[site] = child
|
|
|
|
|
|
|
|
if len(stack) > 1:
|
|
|
|
child.add(stack[1:])
|
|
|
|
|
|
|
|
root = HotNode(None)
|
|
|
|
for sample in state.samples:
|
|
|
|
root.add(sample.stack[::-1])
|
|
|
|
|
|
|
|
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 and (node.count < root.count * 0.98 or len(visiblechildren) > 1):
|
|
|
|
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()])
|
|
|
|
if node.count - childrensamples > (0.1 * root.count):
|
|
|
|
finalstring = '\033[91m' + finalstring + '\033[0m'
|
|
|
|
print >> fp, finalstring
|
|
|
|
|
|
|
|
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)
|
|
|
|
|
|
|
|
_write(root, 0, False)
|
|
|
|
|
|
|
|
def write_to_flame(fp):
|
|
|
|
scriptpath = os.environ['HOME'] + '/flamegraph.pl'
|
|
|
|
if not os.path.exists(scriptpath):
|
|
|
|
print >> fp, "error: missing ~/flamegraph.pl"
|
|
|
|
print >> fp, "get it here: https://github.com/brendangregg/FlameGraph"
|
|
|
|
return
|
|
|
|
|
|
|
|
fd, path = tempfile.mkstemp()
|
|
|
|
|
|
|
|
file = open(path, "w+")
|
|
|
|
|
|
|
|
lines = {}
|
|
|
|
for sample in state.samples:
|
|
|
|
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()
|
|
|
|
|
|
|
|
os.system("perl ~/flamegraph.pl %s > ~/flamegraph.svg" % path)
|
|
|
|
print "Written to ~/flamegraph.svg"
|
|
|
|
|
|
|
|
def printusage():
|
|
|
|
print """
|
|
|
|
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
|
|
|
|
Writes out a flamegraph to ~/flamegraph.svg
|
|
|
|
Requires that ~/flamegraph.pl exist."""
|
|
|
|
|
|
|
|
def main(argv=None):
|
|
|
|
if argv == None:
|
|
|
|
argv = sys.argv
|
|
|
|
|
|
|
|
if len(argv) == 1:
|
|
|
|
printusage()
|
|
|
|
return 0
|
|
|
|
|
|
|
|
optstart = 2
|
|
|
|
function = None
|
|
|
|
if argv[1] == 'hotpath':
|
|
|
|
mode = DisplayFormats.Hotpath
|
|
|
|
elif argv[1] == 'lines':
|
|
|
|
mode = DisplayFormats.ByLine
|
|
|
|
elif argv[1] == 'functions':
|
|
|
|
mode = DisplayFormats.ByMethod
|
|
|
|
elif argv[1] == 'function':
|
|
|
|
mode = DisplayFormats.AboutMethod
|
|
|
|
function = argv[2]
|
|
|
|
optstart = 3
|
|
|
|
elif argv[1] == 'flame':
|
|
|
|
mode = DisplayFormats.FlameGraph
|
|
|
|
else:
|
|
|
|
printusage()
|
|
|
|
return 0
|
|
|
|
|
|
|
|
# process options
|
|
|
|
try:
|
|
|
|
opts, args = getopt.getopt(sys.argv[optstart:], "hl:", ["help", "limit="])
|
|
|
|
except getopt.error, msg:
|
|
|
|
print msg
|
|
|
|
printusage()
|
|
|
|
return 2
|
|
|
|
|
|
|
|
limit = 0.05
|
|
|
|
for o, value in opts:
|
|
|
|
if o in ("-l", "--limit"):
|
|
|
|
limit = float(value)
|
|
|
|
elif o in ("-h", "help"):
|
|
|
|
printusage()
|
|
|
|
return 0
|
|
|
|
else:
|
|
|
|
assert False, "unhandled option"
|
|
|
|
|
|
|
|
load_data()
|
|
|
|
|
|
|
|
display(format = mode, limit = limit, function = function)
|
|
|
|
|
|
|
|
return 0
|
|
|
|
|
|
|
|
if __name__ == "__main__":
|
|
|
|
sys.exit(main())
|