view mercurial/lsprof.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 d4e5b2653693
children b25fbe7e494e
line wrap: on
line source

from __future__ import absolute_import, print_function

import _lsprof
import sys

Profiler = _lsprof.Profiler

# PyPy doesn't expose profiler_entry from the module.
profiler_entry = getattr(_lsprof, 'profiler_entry', None)

__all__ = ['profile', 'Stats']

def profile(f, *args, **kwds):
    """XXX docstring"""
    p = Profiler()
    p.enable(subcalls=True, builtins=True)
    try:
        f(*args, **kwds)
    finally:
        p.disable()
    return Stats(p.getstats())


class Stats(object):
    """XXX docstring"""

    def __init__(self, data):
        self.data = data

    def sort(self, crit=r"inlinetime"):
        """XXX docstring"""
        # profiler_entries isn't defined when running under PyPy.
        if profiler_entry:
            if crit not in profiler_entry.__dict__:
                raise ValueError("Can't sort by %s" % crit)
        elif self.data and not getattr(self.data[0], crit, None):
            raise ValueError("Can't sort by %s" % crit)

        self.data.sort(key=lambda x: getattr(x, crit), reverse=True)
        for e in self.data:
            if e.calls:
                e.calls.sort(key=lambda x: getattr(x, crit), reverse=True)

    def pprint(self, top=None, file=None, limit=None, climit=None):
        """XXX docstring"""
        if file is None:
            file = sys.stdout
        d = self.data
        if top is not None:
            d = d[:top]
        cols = "% 12s %12s %11.4f %11.4f   %s\n"
        hcols = "% 12s %12s %12s %12s %s\n"
        file.write(hcols % ("CallCount", "Recursive", "Total(s)",
                            "Inline(s)", "module:lineno(function)"))
        count = 0
        for e in d:
            file.write(cols % (e.callcount, e.reccallcount, e.totaltime,
                               e.inlinetime, label(e.code)))
            count += 1
            if limit is not None and count == limit:
                return
            ccount = 0
            if climit and e.calls:
                for se in e.calls:
                    file.write(cols % (se.callcount, se.reccallcount,
                                       se.totaltime, se.inlinetime,
                                       "    %s" % label(se.code)))
                    count += 1
                    ccount += 1
                    if limit is not None and count == limit:
                        return
                    if climit is not None and ccount == climit:
                        break

    def freeze(self):
        """Replace all references to code objects with string
        descriptions; this makes it possible to pickle the instance."""

        # this code is probably rather ickier than it needs to be!
        for i in range(len(self.data)):
            e = self.data[i]
            if not isinstance(e.code, str):
                self.data[i] = type(e)((label(e.code),) + e[1:])
            if e.calls:
                for j in range(len(e.calls)):
                    se = e.calls[j]
                    if not isinstance(se.code, str):
                        e.calls[j] = type(se)((label(se.code),) + se[1:])

_fn2mod = {}

def label(code):
    if isinstance(code, str):
        return code
    try:
        mname = _fn2mod[code.co_filename]
    except KeyError:
        for k, v in list(sys.modules.iteritems()):
            if v is None:
                continue
            if not isinstance(getattr(v, '__file__', None), str):
                continue
            if v.__file__.startswith(code.co_filename):
                mname = _fn2mod[code.co_filename] = k
                break
        else:
            mname = _fn2mod[code.co_filename] = '<%s>' % code.co_filename

    return '%s:%d(%s)' % (mname, code.co_firstlineno, code.co_name)


if __name__ == '__main__':
    import os
    sys.argv = sys.argv[1:]
    if not sys.argv:
        print("usage: lsprof.py <script> <arguments...>", file=sys.stderr)
        sys.exit(2)
    sys.path.insert(0, os.path.abspath(os.path.dirname(sys.argv[0])))
    stats = profile(execfile, sys.argv[0], globals(), locals())
    stats.sort()
    stats.pprint()