view mercurial/lsprof.py @ 33171:6d678ab1b10d

revlog: C implementation of delta chain resolution

I've seen revlog._deltachain() appear in a number of performance
profiles. I suspect there are 2 reasons for this:

1. Delta chain resolution performs many index lookups, thus triggering
   population of index tuples. Creating possibly tens of thousands of
   PyObject will have overhead.
2. Delta chain resolution is a tight loop.

By moving delta chain resolution to C, we can defer instantiation
of full index entry tuples and make the loop faster courtesy of
not running in Python.

We can measure the impact to delta chain resolution via
`hg perflogrevision` using the mozilla-central repo with a recent
manifest having delta chain length of 33726:

$ hg perfrevlogrevision -m 364895
! full
! wall 0.367585 comb 0.370000 user 0.340000 sys 0.030000 (best of 27)
! wall 0.357581 comb 0.360000 user 0.350000 sys 0.010000 (best of 28)
! deltachain
! wall 0.010644 comb 0.010000 user 0.010000 sys 0.000000 (best of 270)
! wall 0.000292 comb 0.000000 user 0.000000 sys 0.000000 (best of 8729)

$ hg perfrevlogrevision --cache -m 364895
! deltachain
! wall 0.003904 comb 0.000000 user 0.000000 sys 0.000000 (best of 712)
! wall 0.000284 comb 0.000000 user 0.000000 sys 0.000000 (best of 9926)

The first test measures savings from both not instantiating index
entries and moving to C. The second test (which doesn't clear the
index caches) essentially isolates the benefits of moving from Python
to C. It still shows a 13.7x speedup (versus 36.4x). And there are
multiple milliseconds of savings within the critical path for resolving
revision data. I think that justifies the existence of C code.

A more striking example of the benefits of this change can be
demonstrated by timing `hg debugdeltachain -m` for the mozilla-central
repo:

$ time hg debugdeltachain -m > /dev/null
before:        1057.4s
after:          503.3s
PyPy2.7 5.8.0:  220.0s

It's worth noting that the C code isn't as optimal as it could be.
We're still instantiating a new PyObject for every revision. A future
optimization would be to reuse the PyObject on the cached index tuple.
We could potentially also get wins by using a memory array of raw
integers. There is also room for a delta chain cache on revlog
instances. Of course, the best optimization is to implement revlog
reading outside of Python so Python doesn't need to be concerned
about the relatively expensive index entries and operations on them.

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="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()