# HG changeset patch # User Gregory Szorc # Date 2016-11-02 01:54:03 # Node ID b032a7b676c6637b2ac6f3ef29431013b15a08f9 # Parent bb586966818986131068280bfd95fc96fbdaaa0d statprof: vendor statprof.py Vendored from https://bitbucket.org/facebook/hg-experimental changeset 73f9db47ae5a1a9fa29a98dfe92d557ad51234c3 without modification. This introduces a number of code style violations. The file already has the magic words to skip test-check-code.t. I'll make additional changes to clean up the test-check-py3-compat.t warnings and to change some behavior in the code that isn't suitable for general use. test-check-commit.t also complains about numerous things. But there's nothing we can do if we're importing as-is. diff --git a/mercurial/statprof.py b/mercurial/statprof.py new file mode 100755 --- /dev/null +++ b/mercurial/statprof.py @@ -0,0 +1,797 @@ +#!/usr/bin/env python +## statprof.py +## Copyright (C) 2012 Bryan O'Sullivan +## Copyright (C) 2011 Alex Fraser +## Copyright (C) 2004,2005 Andy Wingo +## Copyright (C) 2001 Rob Browning + +## 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 +from __future__ import division + +import inspect, json, os, signal, tempfile, sys, getopt, threading, traceback +import time +from collections import defaultdict +from contextlib import contextmanager +from subprocess import call + +__all__ = ['start', 'stop', 'reset', 'display', 'profile'] + +skips = set(["util.py:check", "extensions.py:closure", + "color.py:colorcmd", "dispatch.py:checkargs", + "dispatch.py:", "dispatch.py:_runcatch", + "dispatch.py:_dispatch", "dispatch.py:_runcommand", + "pager.py:pagecmd", "dispatch.py:run", + "dispatch.py:dispatch", "dispatch.py:runcommand", + "hg.py:", "evolve.py:warnobserrors", + ]) + +########################################################################### +## 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 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): + __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: + now = clock() + state.accumulate_time(now) + + state.samples.append(Sample.from_frame(frame, state.accumulated_time)) + + 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] + state.samples.append(Sample.from_frame(frame, state.accumulated_time)) + + state.last_start_time = now + time.sleep(state.sample_interval) + + stopthread.clear() + +########################################################################### +## Profiling API + +def is_active(): + return state.profile_level > 0 + +lastmechanism = None +def start(mechanism='thread'): + '''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 + + 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 + statprofpath = os.environ.get('STATPROF_DEST') + save_data(statprofpath) + +def save_data(path=None): + 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 + +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 + Json = 5 + +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, **kwargs) + elif format == DisplayFormats.Json: + write_to_json(fp) + else: + raise Exception("Invalid display format") + + if format != DisplayFormats.Json: + 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) + stattuple = (stat.selfpercent(), stat.selfseconds(), + stat.site.lineno, source) + + print >> fp, ('%33.0f%% %6.2f line %s: %s' % (stattuple)) + +def display_about_method(fp, function=None, **kwargs): + if function is 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, 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) + lasttime = state.samples[0].time + for sample in state.samples: + 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' + 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) + + if root.count > 0: + _write(root, 0, False) + +def write_to_flame(fp, scriptpath=None, outputfile=None, **kwargs): + if scriptpath is None: + scriptpath = os.environ['HOME'] + '/flamegraph.pl' + if not os.path.exists(scriptpath): + print >> fp, "error: missing %s" % scriptpath + 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() + + if outputfile is None: + outputfile = '~/flamegraph.svg' + + os.system("perl ~/flamegraph.pl %s > %s" % (path, outputfile)) + print "Written to %s" % outputfile + +def write_to_json(fp): + samples = [] + + for sample in state.samples: + stack = [] + + for frame in sample.stack: + stack.append((frame.path, frame.lineno, frame.function)) + + samples.append((sample.time, stack)) + + print >> fp, json.dumps(samples) + +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 [-s --script-path] [-o --output-file path] + Writes out a flamegraph to output-file (defaults to ~/flamegraph.svg) + Requires that ~/flamegraph.pl exist. + (Specify alternate script path with --script-path.)""" + +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: + opts, args = getopt.getopt(sys.argv[optstart:], "hl:f:o:p:", + ["help", "limit=", "file=", "output-file=", "script-path="]) + except getopt.error as msg: + print msg + 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 + + load_data(path=path) + + display(**displayargs) + + return 0 + +if __name__ == "__main__": + sys.exit(main()) diff --git a/tests/test-check-code.t b/tests/test-check-code.t --- a/tests/test-check-code.t +++ b/tests/test-check-code.t @@ -17,3 +17,4 @@ New errors are not allowed. Warnings are Skipping i18n/polib.py it has no-che?k-code (glob) Skipping mercurial/httpclient/__init__.py it has no-che?k-code (glob) Skipping mercurial/httpclient/_readers.py it has no-che?k-code (glob) + Skipping mercurial/statprof.py it has no-che?k-code (glob) diff --git a/tests/test-check-py3-compat.t b/tests/test-check-py3-compat.t --- a/tests/test-check-py3-compat.t +++ b/tests/test-check-py3-compat.t @@ -9,6 +9,8 @@ hgext/fsmonitor/pywatchman/capabilities.py not using absolute_import hgext/fsmonitor/pywatchman/pybser.py not using absolute_import i18n/check-translation.py not using absolute_import + mercurial/statprof.py not using absolute_import + mercurial/statprof.py requires print_function setup.py not using absolute_import tests/test-demandimport.py not using absolute_import @@ -22,6 +24,7 @@ hgext/fsmonitor/watchmanclient.py: error importing: No module named 'pybser' (error at __init__.py:*) hgext/mq.py: error importing: __import__() argument 1 must be str, not bytes (error at extensions.py:*) mercurial/scmwindows.py: error importing: No module named 'winreg' (error at scmwindows.py:*) + mercurial/statprof.py: invalid syntax: Missing parentheses in call to 'print' (, line *) mercurial/win32.py: error importing: No module named 'msvcrt' (error at win32.py:*) mercurial/windows.py: error importing: No module named 'msvcrt' (error at windows.py:*)