Mercurial > hg
view mercurial/profiling.py @ 39627:ee7ee0c516ca
narrow: intersect provided matcher with narrowmatcher in `hg diff`
This provides significant speedups when running diff, and no change in behavior
that I'm aware of (or that the tests found). I tested with a repo that I started
using narrow in after it was created and attempted to run `hg diff -c .` and
similar commands in it on a commit that had files not in the narrowspec.
Timing numbers below, using a similar setup as my previous commits.
before=9db85644, m-u is mozilla-unified at eb39298e432d (flatmanifest) and
0553b7f29eaf (treemanifest). l-d-r is a repo simulating a situation I've
encountered where there's one directory with 30k+ subdirectories. N means
narrow, T means treemanifest. The narrowspec is pretty small when in use, and
importantly the narrowspec is applied *after* doing the initial checkout
(without narrowing), so all of these files exist in the filesystem, which is not
normally the case if someone has been using narrow for the entire life of the
clone.
Anything less than a 5% difference in performance is most likely noise.
diff --git:
repo | N | T | before (mean +- stdev) | after (mean +- stdev) | % of before
------+---+---+------------------------+-----------------------+------------
m-u | | | 1.292 s +- 0.009 s | 1.295 s +- 0.010 s | 100.2%
m-u | | x | 1.296 s +- 0.042 s | 1.299 s +- 0.026 s | 100.2%
m-u | x | | 1.292 s +- 0.010 s | 1.297 s +- 0.021 s | 100.4%
m-u | x | x | 84.2 ms +- 1.2 ms | 83.6 ms +- 0.2 ms | 99.3%
l-d-r | | | 188.7 ms +- 2.7 ms | 188.8 ms +- 2.0 ms | 100.1%
l-d-r | | x | 189.9 ms +- 1.5 ms | 189.4 ms +- 1.2 ms | 99.7%
l-d-r | x | | 97.1 ms +- 1.0 ms | 87.1 ms +- 1.0 ms | 89.7% <--
l-d-r | x | x | 96.9 ms +- 0.8 ms | 87.2 ms +- 0.7 ms | 90.0% <--
diff -c . --git:
repo | N | T | before (mean +- stdev) | after (mean +- stdev) | % of before
------+---+---+------------------------+-----------------------+------------
m-u | | | 231.6 ms +- 3.1 ms | 228.9 ms +- 1.6 ms | 98.8%
m-u | | x | 150.5 ms +- 1.7 ms | 150.7 ms +- 1.4 ms | 100.1%
m-u | x | | 233.7 ms +- 2.4 ms | 232.2 ms +- 1.9 ms | 99.4%
m-u | x | x | 126.1 ms +- 1.2 ms | 126.8 ms +- 1.2 ms | 100.6%
l-d-r | | | 82.1 ms +- 2.0 ms | 81.8 ms +- 1.4 ms | 99.6%
l-d-r | | x | 3.732 s +- 0.020 s | 3.746 s +- 0.027 s | 100.4%
l-d-r | x | | 83.1 ms +- 0.8 ms | 107.6 ms +- 2.4 ms | 129.5% <--
l-d-r | x | x | 758.2 ms +- 38.8 ms | 188.5 ms +- 1.8 ms | 24.9% <--
rebase -r . --keep -d .^^:
repo | N | T | before (mean +- stdev) | after (mean +- stdev) | % of before
------+---+---+------------------------+-----------------------+------------
m-u | | | 5.532 s +- 0.087 s | 5.496 s +- 0.016 s | 99.3%
m-u | | x | 5.554 s +- 0.061 s | 5.532 s +- 0.013 s | 99.6%
m-u | x | | 5.602 s +- 0.134 s | 5.508 s +- 0.035 s | 98.3%
m-u | x | x | 582.2 ms +- 15.2 ms | 572.9 ms +- 12.0 ms | 98.4%
l-d-r | | | 629.5 ms +- 12.3 ms | 622.5 ms +- 7.3 ms | 98.9%
l-d-r | | x | 6.173 s +- 0.062 s | 6.185 s +- 0.076 s | 100.2%
l-d-r | x | | 274.5 ms +- 10.0 ms | 272.1 ms +- 6.2 ms | 99.1%
l-d-r | x | x | 4.835 s +- 0.056 s | 4.826 s +- 0.034 s | 99.8%
status --change . --copies:
repo | N | T | before (mean +- stdev) | after (mean +- stdev) | % of before
------+---+---+------------------------+-----------------------+------------
m-u | | | 214.4 ms +- 1.4 ms | 212.2 ms +- 1.7 ms | 99.0%
m-u | | x | 130.9 ms +- 1.2 ms | 131.7 ms +- 1.1 ms | 100.6%
m-u | x | | 215.0 ms +- 2.1 ms | 214.9 ms +- 2.7 ms | 100.0%
m-u | x | x | 109.5 ms +- 2.3 ms | 107.8 ms +- 0.9 ms | 98.4%
l-d-r | | | 79.6 ms +- 0.9 ms | 79.8 ms +- 1.6 ms | 100.3%
l-d-r | | x | 3.799 s +- 0.037 s | 3.928 s +- 0.021 s | 103.4% <--?
l-d-r | x | | 82.7 ms +- 0.7 ms | 83.2 ms +- 1.0 ms | 100.6%
l-d-r | x | x | 746.8 ms +- 6.1 ms | 739.0 ms +- 4.2 ms | 99.0%
status --copies:
repo | N | T | before (mean +- stdev) | after (mean +- stdev) | % of before
------+---+---+------------------------+-----------------------+------------
m-u | | | 1.884 s +- 0.012 s | 1.885 s +- 0.013 s | 100.1%
m-u | | x | 1.897 s +- 0.027 s | 1.909 s +- 0.077 s | 100.6%
m-u | x | | 1.886 s +- 0.021 s | 1.891 s +- 0.030 s | 100.3%
m-u | x | x | 92.0 ms +- 0.7 ms | 92.4 ms +- 0.4 ms | 100.4%
l-d-r | | | 570.3 ms +- 18.7 ms | 552.2 ms +- 4.5 ms | 96.8%
l-d-r | | x | 568.9 ms +- 16.1 ms | 567.2 ms +- 11.9 ms | 99.7%
l-d-r | x | | 171.1 ms +- 2.5 ms | 170.4 ms +- 1.2 ms | 99.6%
l-d-r | x | x | 171.6 ms +- 3.4 ms | 171.5 ms +- 1.7 ms | 99.9%
update $rev^; ~/src/hg/hg{hg}/hg update $rev:
repo | N | T | before (mean +- stdev) | after (mean +- stdev) | % of before
------+---+---+------------------------+-----------------------+------------
m-u | | | 3.107 s +- 0.017 s | 3.116 s +- 0.012 s | 100.3%
m-u | | x | 2.943 s +- 0.010 s | 2.945 s +- 0.019 s | 100.1%
m-u | x | | 3.116 s +- 0.033 s | 3.118 s +- 0.027 s | 100.1%
m-u | x | x | 318.5 ms +- 2.7 ms | 320.8 ms +- 4.8 ms | 100.7%
l-d-r | | | 428.9 ms +- 4.4 ms | 429.5 ms +- 4.0 ms | 100.1%
l-d-r | | x | 9.593 s +- 0.081 s | 9.869 s +- 0.043 s | 102.9%
l-d-r | x | | 253.2 ms +- 3.6 ms | 254.0 ms +- 2.8 ms | 100.3%
l-d-r | x | x | 1.613 s +- 0.009 s | 1.630 s +- 0.017 s | 101.1%
Differential Revision: https://phab.mercurial-scm.org/D4587
author | spectral <spectral@google.com> |
---|---|
date | Thu, 13 Sep 2018 22:48:27 -0700 |
parents | 15a1e37f80bd |
children | b8f6a99ad89b |
line wrap: on
line source
# profiling.py - profiling functions # # Copyright 2016 Gregory Szorc <gregory.szorc@gmail.com> # # This software may be used and distributed according to the terms of the # GNU General Public License version 2 or any later version. from __future__ import absolute_import, print_function import contextlib from .i18n import _ from . import ( encoding, error, extensions, pycompat, util, ) def _loadprofiler(ui, profiler): """load profiler extension. return profile method, or None on failure""" extname = profiler extensions.loadall(ui, whitelist=[extname]) try: mod = extensions.find(extname) except KeyError: return None else: return getattr(mod, 'profile', None) @contextlib.contextmanager def lsprofile(ui, fp): format = ui.config('profiling', 'format') field = ui.config('profiling', 'sort') limit = ui.configint('profiling', 'limit') climit = ui.configint('profiling', 'nested') if format not in ['text', 'kcachegrind']: ui.warn(_("unrecognized profiling format '%s'" " - Ignored\n") % format) format = 'text' try: from . import lsprof except ImportError: raise error.Abort(_( 'lsprof not available - install from ' 'http://codespeak.net/svn/user/arigo/hack/misc/lsprof/')) p = lsprof.Profiler() p.enable(subcalls=True) try: yield finally: p.disable() if format == 'kcachegrind': from . import lsprofcalltree calltree = lsprofcalltree.KCacheGrind(p) calltree.output(fp) else: # format == 'text' stats = lsprof.Stats(p.getstats()) stats.sort(field) stats.pprint(limit=limit, file=fp, climit=climit) @contextlib.contextmanager def flameprofile(ui, fp): try: from flamegraph import flamegraph except ImportError: raise error.Abort(_( 'flamegraph not available - install from ' 'https://github.com/evanhempel/python-flamegraph')) # developer config: profiling.freq freq = ui.configint('profiling', 'freq') filter_ = None collapse_recursion = True thread = flamegraph.ProfileThread(fp, 1.0 / freq, filter_, collapse_recursion) start_time = util.timer() try: thread.start() yield finally: thread.stop() thread.join() print('Collected %d stack frames (%d unique) in %2.2f seconds.' % ( util.timer() - start_time, thread.num_frames(), thread.num_frames(unique=True))) @contextlib.contextmanager def statprofile(ui, fp): from . import statprof freq = ui.configint('profiling', 'freq') if freq > 0: # Cannot reset when profiler is already active. So silently no-op. if statprof.state.profile_level == 0: statprof.reset(freq) else: ui.warn(_("invalid sampling frequency '%s' - ignoring\n") % freq) track = ui.config('profiling', 'time-track') statprof.start(mechanism='thread', track=track) try: yield finally: data = statprof.stop() profformat = ui.config('profiling', 'statformat') formats = { 'byline': statprof.DisplayFormats.ByLine, 'bymethod': statprof.DisplayFormats.ByMethod, 'hotpath': statprof.DisplayFormats.Hotpath, 'json': statprof.DisplayFormats.Json, 'chrome': statprof.DisplayFormats.Chrome, } if profformat in formats: displayformat = formats[profformat] else: ui.warn(_('unknown profiler output format: %s\n') % profformat) displayformat = statprof.DisplayFormats.Hotpath kwargs = {} def fraction(s): if isinstance(s, (float, int)): return float(s) if s.endswith('%'): v = float(s[:-1]) / 100 else: v = float(s) if 0 <= v <= 1: return v raise ValueError(s) if profformat == 'chrome': showmin = ui.configwith(fraction, 'profiling', 'showmin', 0.005) showmax = ui.configwith(fraction, 'profiling', 'showmax') kwargs.update(minthreshold=showmin, maxthreshold=showmax) elif profformat == 'hotpath': # inconsistent config: profiling.showmin limit = ui.configwith(fraction, 'profiling', 'showmin', 0.05) kwargs[r'limit'] = limit statprof.display(fp, data=data, format=displayformat, **kwargs) class profile(object): """Start profiling. Profiling is active when the context manager is active. When the context manager exits, profiling results will be written to the configured output. """ def __init__(self, ui, enabled=True): self._ui = ui self._output = None self._fp = None self._fpdoclose = True self._profiler = None self._enabled = enabled self._entered = False self._started = False def __enter__(self): self._entered = True if self._enabled: self.start() return self def start(self): """Start profiling. The profiling will stop at the context exit. If the profiler was already started, this has no effect.""" if not self._entered: raise error.ProgrammingError() if self._started: return self._started = True profiler = encoding.environ.get('HGPROF') proffn = None if profiler is None: profiler = self._ui.config('profiling', 'type') if profiler not in ('ls', 'stat', 'flame'): # try load profiler from extension with the same name proffn = _loadprofiler(self._ui, profiler) if proffn is None: self._ui.warn(_("unrecognized profiler '%s' - ignored\n") % profiler) profiler = 'stat' self._output = self._ui.config('profiling', 'output') try: if self._output == 'blackbox': self._fp = util.stringio() elif self._output: path = self._ui.expandpath(self._output) self._fp = open(path, 'wb') elif pycompat.iswindows: # parse escape sequence by win32print() class uifp(object): def __init__(self, ui): self._ui = ui def write(self, data): self._ui.write_err(data) def flush(self): self._ui.flush() self._fpdoclose = False self._fp = uifp(self._ui) else: self._fpdoclose = False self._fp = self._ui.ferr if proffn is not None: pass elif profiler == 'ls': proffn = lsprofile elif profiler == 'flame': proffn = flameprofile else: proffn = statprofile self._profiler = proffn(self._ui, self._fp) self._profiler.__enter__() except: # re-raises self._closefp() raise def __exit__(self, exception_type, exception_value, traceback): propagate = None if self._profiler is not None: propagate = self._profiler.__exit__(exception_type, exception_value, traceback) if self._output == 'blackbox': val = 'Profile:\n%s' % self._fp.getvalue() # ui.log treats the input as a format string, # so we need to escape any % signs. val = val.replace('%', '%%') self._ui.log('profile', val) self._closefp() return propagate def _closefp(self): if self._fpdoclose and self._fp is not None: self._fp.close()