##// END OF EJS Templates
tracing: add support for emitting counters...
tracing: add support for emitting counters Differential Revision: https://phab.mercurial-scm.org/D6526

File last commit:

r42615:0ae593e7 default
r42677:e658ac39 default
Show More
statprof.py
972 lines | 30.8 KiB | text/x-python | PythonLexer
Gregory Szorc
statprof: vendor statprof.py...
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
statprof: use print function
r30257 from __future__ import absolute_import, division, print_function
Gregory Szorc
statprof: vendor statprof.py...
r30253
Gregory Szorc
statprof: use absolute_imports...
r30256 import collections
import contextlib
import getopt
import inspect
import json
import os
import signal
import sys
import threading
Gregory Szorc
statprof: vendor statprof.py...
r30253 import time
Gregory Szorc
statprof: use absolute_imports...
r30256
Pulkit Goyal
py3: make a bytes version of getopt.getopt()...
r30578 from . import (
Pulkit Goyal
py3: replace os.environ with encoding.environ (part 4 of 5)
r30637 encoding,
Pulkit Goyal
py3: make a bytes version of getopt.getopt()...
r30578 pycompat,
)
Gregory Szorc
statprof: use absolute_imports...
r30256 defaultdict = collections.defaultdict
contextmanager = contextlib.contextmanager
Gregory Szorc
statprof: vendor statprof.py...
r30253
__all__ = ['start', 'stop', 'reset', 'display', 'profile']
Gregory Szorc
py3: use raw strings for stack names...
r40232 skips = {
r"util.py:check",
r"extensions.py:closure",
r"color.py:colorcmd",
r"dispatch.py:checkargs",
r"dispatch.py:<lambda>",
r"dispatch.py:_runcatch",
r"dispatch.py:_dispatch",
r"dispatch.py:_runcommand",
r"pager.py:pagecmd",
r"dispatch.py:run",
r"dispatch.py:dispatch",
r"dispatch.py:runcommand",
r"hg.py:<module>",
r"evolve.py:warnobserrors",
Martin von Zweigbergk
cleanup: use set literals...
r32291 }
Gregory Szorc
statprof: vendor statprof.py...
r30253
###########################################################################
## Utils
def clock():
times = os.times()
Boris Feld
statprof: also gather wall time...
r38278 return (times[0] + times[1], times[4])
Gregory Szorc
statprof: vendor statprof.py...
r30253
###########################################################################
## Collection data structures
class ProfileState(object):
def __init__(self, frequency=None):
self.reset(frequency)
Boris Feld
profiling: introduce a "profiling.time-track" option...
r38279 self.track = 'cpu'
Gregory Szorc
statprof: vendor statprof.py...
r30253
def reset(self, frequency=None):
# total so far
Boris Feld
statprof: also gather wall time...
r38278 self.accumulated_time = (0.0, 0.0)
Gregory Szorc
statprof: vendor statprof.py...
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
statprof: also gather wall 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],
)
Gregory Szorc
statprof: vendor statprof.py...
r30253
def seconds_per_sample(self):
Boris Feld
profiling: introduce a "profiling.time-track" option...
r38279 return self.accumulated_time[self.timeidx] / len(self.samples)
@property
def timeidx(self):
if self.track == 'real':
return 1
return 0
Gregory Szorc
statprof: vendor statprof.py...
r30253
state = ProfileState()
class CodeSite(object):
cache = {}
Gregory Szorc
global: use raw strings for __slots__...
r41997 __slots__ = (r'path', r'lineno', r'function', r'source')
Gregory Szorc
statprof: vendor statprof.py...
r30253
def __init__(self, path, lineno, function):
Augie Fackler
statprof: add a couple of asserts to avoid storing unicodes...
r40518 assert isinstance(path, bytes)
Gregory Szorc
statprof: vendor statprof.py...
r30253 self.path = path
self.lineno = lineno
Augie Fackler
statprof: add a couple of asserts to avoid storing unicodes...
r40518 assert isinstance(function, bytes)
Gregory Szorc
statprof: vendor statprof.py...
r30253 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:
Augie Fackler
statprof: clean up unicode/bytes a little...
r40519 fp = open(self.path, 'rb')
Gregory Szorc
statprof: vendor statprof.py...
r30253 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)
Yuya Nishihara
statprof: fix overflow while skipping boilerplate parts...
r40421 def skipname(self):
return r'%s:%s' % (self.filename(), self.function)
Gregory Szorc
statprof: vendor statprof.py...
r30253 class Sample(object):
Gregory Szorc
global: use raw strings for __slots__...
r41997 __slots__ = (r'stack', r'time')
Gregory Szorc
statprof: vendor statprof.py...
r30253
def __init__(self, stack, time):
self.stack = stack
self.time = time
@classmethod
def from_frame(cls, frame, time):
stack = []
while frame:
Augie Fackler
statprof: clean up unicode/bytes a little...
r40519 stack.append(CodeSite.get(
pycompat.sysbytes(frame.f_code.co_filename),
frame.f_lineno,
pycompat.sysbytes(frame.f_code.co_name)))
Gregory Szorc
statprof: vendor statprof.py...
r30253 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
profiling: introduce a "profiling.time-track" option...
r38279 timestamp = state.accumulated_time[state.timeidx]
state.samples.append(Sample.from_frame(frame, timestamp))
Gregory Szorc
statprof: vendor statprof.py...
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
profiling: introduce a "profiling.time-track" option...
r38279
timestamp = state.accumulated_time[state.timeidx]
state.samples.append(Sample.from_frame(frame, timestamp))
Gregory Szorc
statprof: vendor statprof.py...
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
profiling: introduce a "profiling.time-track" option...
r38279 def start(mechanism='thread', track='cpu'):
Gregory Szorc
statprof: vendor statprof.py...
r30253 '''Install the profiling signal handler, and start profiling.'''
Boris Feld
profiling: introduce a "profiling.time-track" option...
r38279 state.track = track # note: nesting different mode won't work
Gregory Szorc
statprof: vendor statprof.py...
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
py3: replace os.environ with encoding.environ (part 4 of 5)
r30637 statprofpath = encoding.environ.get('STATPROF_DEST')
Gregory Szorc
statprof: require paths to save or load profile data...
r30255 if statprofpath:
save_data(statprofpath)
Gregory Szorc
statprof: vendor statprof.py...
r30253
Gregory Szorc
statprof: return state from stop()...
r30299 return state
Gregory Szorc
statprof: require paths to save or load profile data...
r30255 def save_data(path):
with open(path, 'w+') as file:
Boris Feld
statprof: fix save and load...
r38293 file.write("%f %f\n" % state.accumulated_time)
Gregory Szorc
statprof: vendor statprof.py...
r30253 for sample in state.samples:
Gregory Szorc
py3: use %d in a few places...
r40233 time = sample.time
Gregory Szorc
statprof: vendor statprof.py...
r30253 stack = sample.stack
Gregory Szorc
py3: sprinkle statprof.py with utf-8 encoding...
r40237 sites = ['\1'.join([s.path, b'%d' % s.lineno, s.function])
Gregory Szorc
statprof: vendor statprof.py...
r30253 for s in stack]
Gregory Szorc
py3: use %d in a few places...
r40233 file.write("%d\0%s\n" % (time, '\0'.join(sites)))
Gregory Szorc
statprof: vendor statprof.py...
r30253
Gregory Szorc
statprof: require paths to save or load profile data...
r30255 def load_data(path):
Augie Fackler
statprof: clean up unicode/bytes a little...
r40519 lines = open(path, 'rb').read().splitlines()
Gregory Szorc
statprof: vendor statprof.py...
r30253
Boris Feld
statprof: fix save and load...
r38293 state.accumulated_time = [float(value) for value in lines[0].split()]
Gregory Szorc
statprof: vendor statprof.py...
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
statprof: allow rendering in the Chrome trace viewer format
r30929 Chrome = 6
Gregory Szorc
statprof: vendor statprof.py...
r30253
Gregory Szorc
statprof: pass data structure to display functions...
r30258 def display(fp=None, format=3, data=None, **kwargs):
Gregory Szorc
statprof: vendor statprof.py...
r30253 '''Print statistics, either to stdout or the given file object.'''
Boris Feld
statprof: small if cleanup...
r38719 if data is None:
data = state
Gregory Szorc
statprof: vendor statprof.py...
r30253
if fp is None:
import sys
fp = sys.stdout
Gregory Szorc
statprof: pass data structure to display functions...
r30258 if len(data.samples) == 0:
Gregory Szorc
py3: switch from print(..., file=) to write()...
r40234 fp.write(b'No samples recorded.\n')
Gregory Szorc
statprof: vendor statprof.py...
r30253 return
if format == DisplayFormats.ByLine:
Gregory Szorc
statprof: pass data structure to display functions...
r30258 display_by_line(data, fp)
Gregory Szorc
statprof: vendor statprof.py...
r30253 elif format == DisplayFormats.ByMethod:
Gregory Szorc
statprof: pass data structure to display functions...
r30258 display_by_method(data, fp)
Gregory Szorc
statprof: vendor statprof.py...
r30253 elif format == DisplayFormats.AboutMethod:
Gregory Szorc
statprof: pass data structure to display functions...
r30258 display_about_method(data, fp, **kwargs)
Gregory Szorc
statprof: vendor statprof.py...
r30253 elif format == DisplayFormats.Hotpath:
Gregory Szorc
statprof: pass data structure to display functions...
r30258 display_hotpath(data, fp, **kwargs)
Gregory Szorc
statprof: vendor statprof.py...
r30253 elif format == DisplayFormats.FlameGraph:
Gregory Szorc
statprof: pass data structure to display functions...
r30258 write_to_flame(data, fp, **kwargs)
Gregory Szorc
statprof: vendor statprof.py...
r30253 elif format == DisplayFormats.Json:
Gregory Szorc
statprof: pass data structure to display functions...
r30258 write_to_json(data, fp)
Bryan O'Sullivan
statprof: allow rendering in the Chrome trace viewer format
r30929 elif format == DisplayFormats.Chrome:
write_to_chrome(data, fp, **kwargs)
Gregory Szorc
statprof: vendor statprof.py...
r30253 else:
raise Exception("Invalid display format")
Bryan O'Sullivan
statprof: allow rendering in the Chrome trace viewer format
r30929 if format not in (DisplayFormats.Json, DisplayFormats.Chrome):
Gregory Szorc
py3: switch from print(..., file=) to write()...
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)
Gregory Szorc
statprof: vendor statprof.py...
r30253
Gregory Szorc
statprof: pass data structure to display functions...
r30258 def display_by_line(data, fp):
Gregory Szorc
statprof: vendor statprof.py...
r30253 '''Print the profiler data with each sample line represented
as one row in a table. Sorted by self-time per line.'''
Gregory Szorc
statprof: pass data structure to display functions...
r30258 stats = SiteStats.buildstats(data.samples)
Gregory Szorc
statprof: vendor statprof.py...
r30253 stats.sort(reverse=True, key=lambda x: x.selfseconds())
Gregory Szorc
py3: switch from print(..., file=) to write()...
r40234 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"))
Gregory Szorc
statprof: vendor statprof.py...
r30253
for stat in stats:
site = stat.site
Augie Fackler
statprof: clean up unicode/bytes a little...
r40519 sitelabel = '%s:%d:%s' % (site.filename(),
Gregory Szorc
py3: sprinkle statprof.py with utf-8 encoding...
r40237 site.lineno,
Augie Fackler
statprof: clean up unicode/bytes a little...
r40519 site.function)
Gregory Szorc
py3: switch from print(..., file=) to write()...
r40234 fp.write(b'%6.2f %9.2f %9.2f %s\n' % (
stat.selfpercent(), stat.totalseconds(),
stat.selfseconds(), sitelabel))
Gregory Szorc
statprof: vendor statprof.py...
r30253
Gregory Szorc
statprof: pass data structure to display functions...
r30258 def display_by_method(data, fp):
Gregory Szorc
statprof: vendor statprof.py...
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
py3: switch from print(..., file=) to write()...
r40234 fp.write(b'%5.5s %10.10s %7.7s %-8.8s\n' %
('% ', 'cumulative', 'self', ''))
fp.write(b'%5.5s %9.9s %8.8s %-8.8s\n' %
("time", "seconds", "seconds", "name"))
Gregory Szorc
statprof: vendor statprof.py...
r30253
Gregory Szorc
statprof: pass data structure to display functions...
r30258 stats = SiteStats.buildstats(data.samples)
Gregory Szorc
statprof: vendor statprof.py...
r30253
grouped = defaultdict(list)
for stat in stats:
Augie Fackler
statprof: clean up unicode/bytes a little...
r40519 grouped[stat.site.filename() + b":" + stat.site.function].append(stat)
Gregory Szorc
statprof: vendor statprof.py...
r30253
# 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
py3: switch from print(..., file=) to write()...
r40234 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
Augie Fackler
statprof: clean up unicode/bytes a little...
r40519 function[0])) # file:function
Gregory Szorc
py3: switch from print(..., file=) to write()...
r40234
Gregory Szorc
statprof: vendor statprof.py...
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)
Gregory Szorc
py3: sprinkle statprof.py with utf-8 encoding...
r40237 if sys.version_info.major >= 3 and not isinstance(source, bytes):
source = pycompat.bytestr(source)
Gregory Szorc
statprof: vendor statprof.py...
r30253 stattuple = (stat.selfpercent(), stat.selfseconds(),
stat.site.lineno, source)
Gregory Szorc
py3: switch from print(..., file=) to write()...
r40234 fp.write(b'%33.0f%% %6.2f line %d: %s\n' % stattuple)
Gregory Szorc
statprof: vendor statprof.py...
r30253
Gregory Szorc
statprof: pass data structure to display functions...
r30258 def display_about_method(data, fp, function=None, **kwargs):
Gregory Szorc
statprof: vendor statprof.py...
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
statprof: pass data structure to display functions...
r30258 for sample in data.samples:
Gregory Szorc
statprof: vendor statprof.py...
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
py3: switch from print(..., file=) to write()...
r40234 fp.write(b'%6.2f%% %s:%s line %s: %s\n' %
Gregory Szorc
py3: sprinkle statprof.py with utf-8 encoding...
r40237 (count / relevant_samples * 100,
pycompat.fsencode(parent.filename()),
pycompat.sysbytes(parent.function),
parent.lineno,
pycompat.sysbytes(parent.getsource(50))))
Gregory Szorc
statprof: vendor statprof.py...
r30253
Gregory Szorc
statprof: pass data structure to display functions...
r30258 stats = SiteStats.buildstats(data.samples)
Gregory Szorc
statprof: vendor statprof.py...
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
py3: switch from print(..., file=) to write()...
r40234 fp.write(
b'\n %s:%s Total: %0.2fs (%0.2f%%) Self: %0.2fs (%0.2f%%)\n\n'
% (
Gregory Szorc
py3: sprinkle statprof.py with utf-8 encoding...
r40237 pycompat.sysbytes(filename or '___'),
pycompat.sysbytes(function),
Gregory Szorc
statprof: vendor statprof.py...
r30253 total_cum_sec,
total_cum_percent,
total_self_sec,
total_self_percent
Gregory Szorc
py3: switch from print(..., file=) to write()...
r40234 ))
Gregory Szorc
statprof: vendor statprof.py...
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
py3: switch from print(..., file=) to write()...
r40234 fp.write(b' %6.2f%% line %s: %s\n' %
Gregory Szorc
statprof: use print function
r30257 (count / relevant_samples * 100, child.lineno,
Gregory Szorc
py3: sprinkle statprof.py with utf-8 encoding...
r40237 pycompat.sysbytes(child.getsource(50))))
Gregory Szorc
statprof: vendor statprof.py...
r30253
Gregory Szorc
statprof: pass data structure to display functions...
r30258 def display_hotpath(data, fp, limit=0.05, **kwargs):
Gregory Szorc
statprof: vendor statprof.py...
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
Yuya Nishihara
statprof: fix overflow while skipping boilerplate parts...
r40421 while i < len(stack) and stack[i].skipname() in skips:
Gregory Szorc
statprof: vendor statprof.py...
r30253 i += 1
if i < len(stack):
child.add(stack[i:], time)
root = HotNode(None)
Gregory Szorc
statprof: pass data structure to display functions...
r30258 lasttime = data.samples[0].time
for sample in data.samples:
Gregory Szorc
statprof: vendor statprof.py...
r30253 root.add(sample.stack[::-1], sample.time - lasttime)
lasttime = sample.time
Valentin Gatien-Baron
profiling: show actual time spent in hotpath display...
r42615 showtime = kwargs.get(r'showtime', True)
Gregory Szorc
statprof: vendor statprof.py...
r30253
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 '|') +\
Valentin Gatien-Baron
profiling: show actual time spent in hotpath display...
r42615 ' %4.1f%%' +\
(' %5.2fs' % node.count if showtime else '') +\
' %s %s'
Gregory Szorc
statprof: vendor statprof.py...
r30253 liststring = listpattern % (node.count / root.count * 100,
filename, function)
Augie Fackler
statprof: clean up unicode/bytes a little...
r40519 codepattern = '%' + ('%d' % (55 - len(liststring))) + 's %d: %s'
Gregory Szorc
statprof: vendor statprof.py...
r30253 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'
Yuya Nishihara
statprof: fix indent level of fp.write() (issue6004)...
r40420 fp.write(finalstring + b'\n')
Gregory Szorc
statprof: vendor statprof.py...
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
statprof: pass data structure to display functions...
r30258 def write_to_flame(data, fp, scriptpath=None, outputfile=None, **kwargs):
Gregory Szorc
statprof: vendor statprof.py...
r30253 if scriptpath is None:
Pulkit Goyal
py3: replace os.environ with encoding.environ (part 4 of 5)
r30637 scriptpath = encoding.environ['HOME'] + '/flamegraph.pl'
Gregory Szorc
statprof: vendor statprof.py...
r30253 if not os.path.exists(scriptpath):
Gregory Szorc
py3: switch from print(..., file=) to write()...
r40234 fp.write(b'error: missing %s\n' % scriptpath)
fp.write(b'get it here: https://github.com/brendangregg/FlameGraph\n')
Gregory Szorc
statprof: vendor statprof.py...
r30253 return
Yuya Nishihara
py3: wrap tempfile.mkstemp() to use bytes path...
r38182 fd, path = pycompat.mkstemp()
Gregory Szorc
statprof: vendor statprof.py...
r30253
file = open(path, "w+")
lines = {}
Gregory Szorc
statprof: pass data structure to display functions...
r30258 for sample in data.samples:
Gregory Szorc
statprof: vendor statprof.py...
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():
Gregory Szorc
py3: use %d in a few places...
r40233 file.write("%s %d\n" % (line, count))
Gregory Szorc
statprof: vendor statprof.py...
r30253
file.close()
if outputfile is None:
outputfile = '~/flamegraph.svg'
os.system("perl ~/flamegraph.pl %s > %s" % (path, outputfile))
Gregory Szorc
py3: switch from print(..., file=) to write()...
r40234 fp.write(b'Written to %s\n' % outputfile)
Gregory Szorc
statprof: vendor statprof.py...
r30253
Bryan O'Sullivan
statprof: add a path simplification function
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
py3: use pycompat.fsencode() to convert __file__ to bytes...
r31074 hgpath = pycompat.fsencode(encoding.__file__).rsplit(os.sep, 2)[0]
Bryan O'Sullivan
statprof: add a path simplification function
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
statprof: pass data structure to display functions...
r30258 def write_to_json(data, fp):
Gregory Szorc
statprof: vendor statprof.py...
r30253 samples = []
Gregory Szorc
statprof: pass data structure to display functions...
r30258 for sample in data.samples:
Gregory Szorc
statprof: vendor statprof.py...
r30253 stack = []
for frame in sample.stack:
Augie Fackler
statprof: clean up unicode/bytes a little...
r40519 stack.append(
(pycompat.sysstr(frame.path),
frame.lineno,
pycompat.sysstr(frame.function)))
Gregory Szorc
statprof: vendor statprof.py...
r30253
samples.append((sample.time, stack))
Gregory Szorc
py3: encode json output to bytes and use write()...
r40227 data = json.dumps(samples)
if not isinstance(data, bytes):
data = data.encode('utf-8')
fp.write(data)
Gregory Szorc
statprof: vendor statprof.py...
r30253
Bryan O'Sullivan
statprof: allow rendering in the Chrome trace viewer format
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
# 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:
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
statprof: vendor statprof.py...
r30253 def printusage():
Gregory Szorc
py3: switch from print(..., file=) to write()...
r40234 print(r"""
Gregory Szorc
statprof: vendor statprof.py...
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
statprof: use print function
r30257 (Specify alternate script path with --script-path.)""")
Gregory Szorc
statprof: vendor statprof.py...
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
Gregory Szorc
py3: use raw strings in statprof.py...
r40235 if argv[1] == r'hotpath':
Gregory Szorc
statprof: vendor statprof.py...
r30253 displayargs['format'] = DisplayFormats.Hotpath
Gregory Szorc
py3: use raw strings in statprof.py...
r40235 elif argv[1] == r'lines':
Gregory Szorc
statprof: vendor statprof.py...
r30253 displayargs['format'] = DisplayFormats.ByLine
Gregory Szorc
py3: use raw strings in statprof.py...
r40235 elif argv[1] == r'functions':
Gregory Szorc
statprof: vendor statprof.py...
r30253 displayargs['format'] = DisplayFormats.ByMethod
Gregory Szorc
py3: use raw strings in statprof.py...
r40235 elif argv[1] == r'function':
Gregory Szorc
statprof: vendor statprof.py...
r30253 displayargs['format'] = DisplayFormats.AboutMethod
displayargs['function'] = argv[2]
optstart = 3
Gregory Szorc
py3: use raw strings in statprof.py...
r40235 elif argv[1] == r'flame':
Gregory Szorc
statprof: vendor statprof.py...
r30253 displayargs['format'] = DisplayFormats.FlameGraph
else:
printusage()
return 0
# process options
try:
Pulkit Goyal
py3: make a bytes version of getopt.getopt()...
r30578 opts, args = pycompat.getoptb(sys.argv[optstart:], "hl:f:o:p:",
Gregory Szorc
statprof: vendor statprof.py...
r30253 ["help", "limit=", "file=", "output-file=", "script-path="])
except getopt.error as msg:
Gregory Szorc
statprof: use print function
r30257 print(msg)
Gregory Szorc
statprof: vendor statprof.py...
r30253 printusage()
return 2
displayargs['limit'] = 0.05
path = None
for o, value in opts:
Gregory Szorc
py3: use raw strings in statprof.py...
r40235 if o in (r"-l", r"--limit"):
Gregory Szorc
statprof: vendor statprof.py...
r30253 displayargs['limit'] = float(value)
Gregory Szorc
py3: use raw strings in statprof.py...
r40235 elif o in (r"-f", r"--file"):
Gregory Szorc
statprof: vendor statprof.py...
r30253 path = value
Gregory Szorc
py3: use raw strings in statprof.py...
r40235 elif o in (r"-o", r"--output-file"):
Gregory Szorc
statprof: vendor statprof.py...
r30253 displayargs['outputfile'] = value
Gregory Szorc
py3: use raw strings in statprof.py...
r40235 elif o in (r"-p", r"--script-path"):
Gregory Szorc
statprof: vendor statprof.py...
r30253 displayargs['scriptpath'] = value
Gregory Szorc
py3: use raw strings in statprof.py...
r40235 elif o in (r"-h", r"help"):
Gregory Szorc
statprof: vendor statprof.py...
r30253 printusage()
return 0
else:
assert False, "unhandled option %s" % o
Gregory Szorc
statprof: require input file...
r30845 if not path:
Gregory Szorc
py3: use raw strings in statprof.py...
r40235 print(r'must specify --file to load')
Gregory Szorc
statprof: require input file...
r30845 return 1
Gregory Szorc
statprof: vendor statprof.py...
r30253 load_data(path=path)
Pulkit Goyal
py3: handle keyword arguments correctly in statprof.py...
r35371 display(**pycompat.strkwargs(displayargs))
Gregory Szorc
statprof: vendor statprof.py...
r30253
return 0
Gregory Szorc
py3: use raw strings in statprof.py...
r40235 if __name__ == r"__main__":
Gregory Szorc
statprof: vendor statprof.py...
r30253 sys.exit(main())