mercurial/lsprof.py

copies: cache the ancestor checking call when tracing copy

A good share of the time spent in this function is spent doing ancestors
checking. To avoid spending time in duplicated call, we cache the result of
calls.

In the slower case, this provide a quite significant performance boost. Below
are the result for a set of selected pairs (many of them pathological):

(And further down is another table that summarize the current state of filelog
based vs changeset base copy tracing)


The benchmark have been configured to be killed after 6 minutes of runtime,
which mean that any detect slower than 2 minutes will be marked as "killed".
This drop some useful information about how much slower these case are… but also
prevent 99% of the benchmark time to be spent on case that can be labelled "very
slow" anyway.


Repo            Case                                  Source-Rev   Dest-Rev         Old-Time      New-Time     Difference   Factor
------------------------------------------------------------------------------------------------------------------------------------
mercurial       x_revs_x_added_0_copies               ad6b123de1c7 39cfcef4f463 :   0.000044 s,   0.000044 s,  +0.000000 s, × 1.0000
mercurial       x_revs_x_added_x_copies               2b1c78674230 0c1d10351869 :   0.000138 s,   0.000138 s,  +0.000000 s, × 1.0000
mercurial       x000_revs_x000_added_x_copies         81f8ff2a9bf2 dd3267698d84 :   0.005067 s,   0.005052 s,  -0.000015 s, × 0.9970
pypy            x_revs_x_added_0_copies               aed021ee8ae8 099ed31b181b :   0.000218 s,   0.000219 s,  +0.000001 s, × 1.0046
pypy            x_revs_x000_added_0_copies            4aa4e1f8e19a 359343b9ac0e :   0.000053 s,   0.000055 s,  +0.000002 s, × 1.0377
pypy            x_revs_x_added_x_copies               ac52eb7bbbb0 72e022663155 :   0.000125 s,   0.000128 s,  +0.000003 s, × 1.0240
pypy            x_revs_x00_added_x_copies             c3b14617fbd7 ace7255d9a26 :   0.001098 s,   0.001089 s,  -0.000009 s, × 0.9918
pypy            x_revs_x000_added_x000_copies         df6f7a526b60 a83dc6a2d56f :   0.017546 s,   0.017407 s,  -0.000139 s, × 0.9921
pypy            x000_revs_xx00_added_0_copies         89a76aede314 2f22446ff07e :   0.096723 s,   0.094175 s,  -0.002548 s, × 0.9737
pypy            x000_revs_x000_added_x_copies         8a3b5bfd266e 2c68e87c3efe :   0.271796 s,   0.238009 s,  -0.033787 s, × 0.8757
pypy            x000_revs_x000_added_x000_copies      89a76aede314 7b3dda341c84 :   0.128602 s,   0.125876 s,  -0.002726 s, × 0.9788
pypy            x0000_revs_x_added_0_copies           d1defd0dc478 c9cb1334cc78 :   7.086742 s,   3.581556 s,  -3.505186 s, × 0.5054
pypy            x0000_revs_xx000_added_0_copies       bf2c629d0071 4ffed77c095c :   0.016634 s,   0.016721 s,  +0.000087 s, × 1.0052
pypy            x0000_revs_xx000_added_x000_copies    08ea3258278e d9fa043f30c0 :   0.254225 s,   0.242367 s,  -0.011858 s, × 0.9534
netbeans        x_revs_x_added_0_copies               fb0955ffcbcd a01e9239f9e7 :   0.000166 s,   0.000165 s,  -0.000001 s, × 0.9940
netbeans        x_revs_x000_added_0_copies            6f360122949f 20eb231cc7d0 :   0.000118 s,   0.000114 s,  -0.000004 s, × 0.9661
netbeans        x_revs_x_added_x_copies               1ada3faf6fb6 5a39d12eecf4 :   0.000296 s,   0.000296 s,  +0.000000 s, × 1.0000
netbeans        x_revs_x00_added_x_copies             35be93ba1e2c 9eec5e90c05f :   0.001137 s,   0.001124 s,  -0.000013 s, × 0.9886
netbeans        x000_revs_xx00_added_0_copies         eac3045b4fdd 51d4ae7f1290 :   0.014133 s,   0.013060 s,  -0.001073 s, × 0.9241
netbeans        x000_revs_x000_added_x_copies         e2063d266acd 6081d72689dc :   0.016988 s,   0.017112 s,  +0.000124 s, × 1.0073
netbeans        x000_revs_x000_added_x000_copies      ff453e9fee32 411350406ec2 :   0.676361 s,   0.660350 s,  -0.016011 s, × 0.9763
netbeans        x0000_revs_xx000_added_x000_copies    588c2d1ced70 1aad62e59ddd :  12.515149 s,  10.032499 s,  -2.482650 s, × 0.8016
mozilla-central x_revs_x_added_0_copies               3697f962bb7b 7015fcdd43a2 :   0.000186 s,   0.000189 s,  +0.000003 s, × 1.0161
mozilla-central x_revs_x000_added_0_copies            dd390860c6c9 40d0c5bed75d :   0.000459 s,   0.000462 s,  +0.000003 s, × 1.0065
mozilla-central x_revs_x_added_x_copies               8d198483ae3b 14207ffc2b2f :   0.000273 s,   0.000270 s,  -0.000003 s, × 0.9890
mozilla-central x_revs_x00_added_x_copies             98cbc58cc6bc 446a150332c3 :   0.001503 s,   0.001474 s,  -0.000029 s, × 0.9807
mozilla-central x_revs_x000_added_x000_copies         3c684b4b8f68 0a5e72d1b479 :   0.004862 s,   0.004806 s,  -0.000056 s, × 0.9885
mozilla-central x_revs_x0000_added_x0000_copies       effb563bb7e5 c07a39dc4e80 :   0.088291 s,   0.085150 s,  -0.003141 s, × 0.9644
mozilla-central x000_revs_xx00_added_0_copies         6100d773079a 04a55431795e :   0.007113 s,   0.007064 s,  -0.000049 s, × 0.9931
mozilla-central x000_revs_x000_added_x_copies         9f17a6fc04f9 2d37b966abed :   0.004687 s,   0.004741 s,  +0.000054 s, × 1.0115
mozilla-central x000_revs_x000_added_x000_copies      7c97034feb78 4407bd0c6330 :   0.198710 s,   0.190133 s,  -0.008577 s, × 0.9568
mozilla-central x0000_revs_xx000_added_0_copies       9eec5917337d 67118cc6dcad :   0.036068 s,   0.035651 s,  -0.000417 s, × 0.9884
mozilla-central x0000_revs_xx000_added_x000_copies    f78c615a656c 96a38b690156 :   0.465362 s,   0.440694 s,  -0.024668 s, × 0.9470
mozilla-central x00000_revs_x0000_added_x0000_copies  6832ae71433c 4c222a1d9a00 :  24.519684 s,  18.454163 s,  -6.065521 s, × 0.7526
mozilla-central x00000_revs_x00000_added_x000_copies  76caed42cf7c 1daa622bbe42 :  42.711897 s,  31.562719 s, -11.149178 s, × 0.7390
mozilla-try     x_revs_x_added_0_copies               aaf6dde0deb8 9790f499805a :   0.001201 s,   0.001189 s,  -0.000012 s, × 0.9900
mozilla-try     x_revs_x000_added_0_copies            d8d0222927b4 5bb8ce8c7450 :   0.001216 s,   0.001204 s,  -0.000012 s, × 0.9901
mozilla-try     x_revs_x_added_x_copies               092fcca11bdb 936255a0384a :   0.000595 s,   0.000586 s,  -0.000009 s, × 0.9849
mozilla-try     x_revs_x00_added_x_copies             b53d2fadbdb5 017afae788ec :   0.001856 s,   0.001845 s,  -0.000011 s, × 0.9941
mozilla-try     x_revs_x000_added_x000_copies         20408ad61ce5 6f0ee96e21ad :   0.064936 s,   0.063822 s,  -0.001114 s, × 0.9828
mozilla-try     x_revs_x0000_added_x0000_copies       effb563bb7e5 c07a39dc4e80 :   0.090601 s,   0.088038 s,  -0.002563 s, × 0.9717
mozilla-try     x000_revs_xx00_added_0_copies         6100d773079a 04a55431795e :   0.007510 s,   0.007389 s,  -0.000121 s, × 0.9839
mozilla-try     x000_revs_x000_added_x_copies         9f17a6fc04f9 2d37b966abed :   0.004911 s,   0.004868 s,  -0.000043 s, × 0.9912
mozilla-try     x000_revs_x000_added_x000_copies      1346fd0130e4 4c65cbdabc1f :   0.233231 s,   0.222450 s,  -0.010781 s, × 0.9538
mozilla-try     x0000_revs_x_added_0_copies           63519bfd42ee a36a2a865d92 :   0.419989 s,   0.370675 s,  -0.049314 s, × 0.8826
mozilla-try     x0000_revs_x_added_x_copies           9fe69ff0762d bcabf2a78927 :   0.401521 s,   0.358020 s,  -0.043501 s, × 0.8917
mozilla-try     x0000_revs_xx000_added_x_copies       156f6e2674f2 4d0f2c178e66 :   0.179555 s,   0.145235 s,  -0.034320 s, × 0.8089
mozilla-try     x0000_revs_xx000_added_0_copies       9eec5917337d 67118cc6dcad :   0.038004 s,   0.037606 s,  -0.000398 s, × 0.9895
mozilla-try     x0000_revs_xx000_added_x000_copies    89294cd501d9 7ccb2fc7ccb5 :  52.838482 s,   7.382439 s, -45.456043 s, × 0.1397
mozilla-try     x0000_revs_x0000_added_x0000_copies   e928c65095ed e951f4ad123a :   8.705874 s,   7.273506 s,  -1.432368 s, × 0.8355
mozilla-try     x00000_revs_x00000_added_0_copies     dc8a3ca7010e d16fde900c9c :   1.126708 s,   1.074593 s,  -0.052115 s, × 0.9537
mozilla-try     x00000_revs_x0000_added_x0000_copies  8d3fafa80d4b eb884023b810 :  83.854020 s,  27.746195 s, -56.107825 s, × 0.3309


Below is a table comparing the runtime of the current "filelog centric"
algorithm, with the "changeset centric" one, we just modified.

The changeset centric algorithm is a significant win in many scenario, but they
are still various cases where it is quite slower. When many revision  has to be
considered the cost of retrieving the copy information, creating new
dictionaries, merging dictionaries and checking if revision are ancestors of
each other can slow things down.

The rest of this series, will introduce a rust version of the copy tracing code
to deal with most of theses issues.


Repo            Case                                  Source-Rev   Dest-Rev         filelog     sidedata      Difference       Factor
---------------------------------------------------------------------------------------------------------------------------------------
mercurial       x_revs_x_added_0_copies               ad6b123de1c7 39cfcef4f463 :  0.000914 s,  0.000044 s, - 0.000870 s,    × 0.048140
mercurial       x_revs_x_added_x_copies               2b1c78674230 0c1d10351869 :  0.001812 s,  0.000138 s, - 0.001674 s,    × 0.076159
mercurial       x000_revs_x000_added_x_copies         81f8ff2a9bf2 dd3267698d84 :  0.017954 s,  0.005052 s, - 0.012902 s,    × 0.281386
pypy            x_revs_x_added_0_copies               aed021ee8ae8 099ed31b181b :  0.001509 s,  0.000219 s, - 0.001290 s,    × 0.145129
pypy            x_revs_x000_added_0_copies            4aa4e1f8e19a 359343b9ac0e :  0.206881 s,  0.000055 s, - 0.206826 s,    × 0.000266
pypy            x_revs_x_added_x_copies               ac52eb7bbbb0 72e022663155 :  0.016951 s,  0.000128 s, - 0.016823 s,    × 0.007551
pypy            x_revs_x00_added_x_copies             c3b14617fbd7 ace7255d9a26 :  0.019096 s,  0.001089 s, - 0.018007 s,    × 0.057028
pypy            x_revs_x000_added_x000_copies         df6f7a526b60 a83dc6a2d56f :  0.762506 s,  0.017407 s, - 0.745099 s,    × 0.022829
pypy            x000_revs_xx00_added_0_copies         89a76aede314 2f22446ff07e :  1.179211 s,  0.094175 s, - 1.085036 s,    × 0.079863
pypy            x000_revs_x000_added_x_copies         8a3b5bfd266e 2c68e87c3efe :  1.249058 s,  0.238009 s, - 1.011049 s,    × 0.190551
pypy            x000_revs_x000_added_x000_copies      89a76aede314 7b3dda341c84 :  1.614107 s,  0.125876 s, - 1.488231 s,    × 0.077985
pypy            x0000_revs_x_added_0_copies           d1defd0dc478 c9cb1334cc78 :  0.001064 s,  3.581556 s, + 3.580492 s, × 3366.124060
pypy            x0000_revs_xx000_added_0_copies       bf2c629d0071 4ffed77c095c :  1.061275 s,  0.016721 s, - 1.044554 s,    × 0.015756
pypy            x0000_revs_xx000_added_x000_copies    08ea3258278e d9fa043f30c0 :  1.341119 s,  0.242367 s, - 1.098752 s,    × 0.180720
netbeans        x_revs_x_added_0_copies               fb0955ffcbcd a01e9239f9e7 :  0.027803 s,  0.000165 s, - 0.027638 s,    × 0.005935
netbeans        x_revs_x000_added_0_copies            6f360122949f 20eb231cc7d0 :  0.130014 s,  0.000114 s, - 0.129900 s,    × 0.000877
netbeans        x_revs_x_added_x_copies               1ada3faf6fb6 5a39d12eecf4 :  0.024990 s,  0.000296 s, - 0.024694 s,    × 0.011845
netbeans        x_revs_x00_added_x_copies             35be93ba1e2c 9eec5e90c05f :  0.052201 s,  0.001124 s, - 0.051077 s,    × 0.021532
netbeans        x000_revs_xx00_added_0_copies         eac3045b4fdd 51d4ae7f1290 :  0.037642 s,  0.013060 s, - 0.024582 s,    × 0.346953
netbeans        x000_revs_x000_added_x_copies         e2063d266acd 6081d72689dc :  0.197086 s,  0.017112 s, - 0.179974 s,    × 0.086825
netbeans        x000_revs_x000_added_x000_copies      ff453e9fee32 411350406ec2 :  0.935148 s,  0.660350 s, - 0.274798 s,    × 0.706145
netbeans        x0000_revs_xx000_added_x000_copies    588c2d1ced70 1aad62e59ddd :  3.920674 s, 10.032499 s, + 6.111825 s,    × 2.558871
mozilla-central x_revs_x_added_0_copies               3697f962bb7b 7015fcdd43a2 :  0.024232 s,  0.000189 s, - 0.024043 s,    × 0.007800
mozilla-central x_revs_x000_added_0_copies            dd390860c6c9 40d0c5bed75d :  0.141483 s,  0.000462 s, - 0.141021 s,    × 0.003265
mozilla-central x_revs_x_added_x_copies               8d198483ae3b 14207ffc2b2f :  0.025775 s,  0.000270 s, - 0.025505 s,    × 0.010475
mozilla-central x_revs_x00_added_x_copies             98cbc58cc6bc 446a150332c3 :  0.084922 s,  0.001474 s, - 0.083448 s,    × 0.017357
mozilla-central x_revs_x000_added_x000_copies         3c684b4b8f68 0a5e72d1b479 :  0.194784 s,  0.004806 s, - 0.189978 s,    × 0.024673
mozilla-central x_revs_x0000_added_x0000_copies       effb563bb7e5 c07a39dc4e80 :  2.161103 s,  0.085150 s, - 2.075953 s,    × 0.039401
mozilla-central x000_revs_xx00_added_0_copies         6100d773079a 04a55431795e :  0.089347 s,  0.007064 s, - 0.082283 s,    × 0.079063
mozilla-central x000_revs_x000_added_x_copies         9f17a6fc04f9 2d37b966abed :  0.732171 s,  0.004741 s, - 0.727430 s,    × 0.006475
mozilla-central x000_revs_x000_added_x000_copies      7c97034feb78 4407bd0c6330 :  1.157287 s,  0.190133 s, - 0.967154 s,    × 0.164292
mozilla-central x0000_revs_xx000_added_0_copies       9eec5917337d 67118cc6dcad :  6.726568 s,  0.035651 s, - 6.690917 s,    × 0.005300
mozilla-central x0000_revs_xx000_added_x000_copies    f78c615a656c 96a38b690156 :  3.266229 s,  0.440694 s, - 2.825535 s,    × 0.134924
mozilla-central x00000_revs_x0000_added_x0000_copies  6832ae71433c 4c222a1d9a00 : 15.860534 s, 18.454163 s, + 2.593629 s,    × 1.163527
mozilla-central x00000_revs_x00000_added_x000_copies  76caed42cf7c 1daa622bbe42 : 20.450475 s, 31.562719 s, +11.112244 s,    × 1.543373
mozilla-try     x_revs_x_added_0_copies               aaf6dde0deb8 9790f499805a :  0.080442 s,  0.001189 s, - 0.079253 s,    × 0.014781
mozilla-try     x_revs_x000_added_0_copies            d8d0222927b4 5bb8ce8c7450 :  0.497672 s,  0.001204 s, - 0.496468 s,    × 0.002419
mozilla-try     x_revs_x_added_x_copies               092fcca11bdb 936255a0384a :  0.021183 s,  0.000586 s, - 0.020597 s,    × 0.027664
mozilla-try     x_revs_x00_added_x_copies             b53d2fadbdb5 017afae788ec :  0.230991 s,  0.001845 s, - 0.229146 s,    × 0.007987
mozilla-try     x_revs_x000_added_x000_copies         20408ad61ce5 6f0ee96e21ad :  1.118461 s,  0.063822 s, - 1.054639 s,    × 0.057062
mozilla-try     x_revs_x0000_added_x0000_copies       effb563bb7e5 c07a39dc4e80 :  2.206083 s,  0.088038 s, - 2.118045 s,    × 0.039907
mozilla-try     x000_revs_xx00_added_0_copies         6100d773079a 04a55431795e :  0.089404 s,  0.007389 s, - 0.082015 s,    × 0.082647
mozilla-try     x000_revs_x000_added_x_copies         9f17a6fc04f9 2d37b966abed :  0.733043 s,  0.004868 s, - 0.728175 s,    × 0.006641
mozilla-try     x000_revs_x000_added_x000_copies      1346fd0130e4 4c65cbdabc1f :  1.163367 s,  0.222450 s, - 0.940917 s,    × 0.191212
mozilla-try     x0000_revs_x_added_0_copies           63519bfd42ee a36a2a865d92 :  0.085456 s,  0.370675 s, + 0.285219 s,    × 4.337612
mozilla-try     x0000_revs_x_added_x_copies           9fe69ff0762d bcabf2a78927 :  0.083601 s,  0.358020 s, + 0.274419 s,    × 4.282485
mozilla-try     x0000_revs_xx000_added_x_copies       156f6e2674f2 4d0f2c178e66 :  7.366614 s,  0.145235 s, - 7.221379 s,    × 0.019715
mozilla-try     x0000_revs_xx000_added_0_copies       9eec5917337d 67118cc6dcad :  6.664464 s,  0.037606 s, - 6.626858 s,    × 0.005643
mozilla-try     x0000_revs_xx000_added_x000_copies    89294cd501d9 7ccb2fc7ccb5 :  7.467836 s,  7.382439 s, - 0.085397 s,    × 0.988565
mozilla-try     x0000_revs_x0000_added_x0000_copies   e928c65095ed e951f4ad123a :  9.801294 s,  7.273506 s, - 2.527788 s,    × 0.742097
mozilla-try     x00000_revs_x_added_0_copies          6a320851d377 1ebb79acd503 :  0.091886 s, killed
mozilla-try     x00000_revs_x00000_added_0_copies     dc8a3ca7010e d16fde900c9c : 26.491140 s,  1.074593 s, -25.416547 s,    × 0.040564
mozilla-try     x00000_revs_x_added_x_copies          5173c4b6f97c 95d83ee7242d :  0.092863 s, killed
mozilla-try     x00000_revs_x000_added_x_copies       9126823d0e9c ca82787bb23c :  0.226823 s, killed
mozilla-try     x00000_revs_x0000_added_x0000_copies  8d3fafa80d4b eb884023b810 : 18.914630 s, 27.746195 s, + 8.831565 s,    × 1.466917
mozilla-try     x00000_revs_x00000_added_x0000_copies 1b661134e2ca 1ae03d022d6d : 21.198903 s, killed
mozilla-try     x00000_revs_x00000_added_x000_copies  9b2a99adc05e 8e29777b48e6 : 24.952268 s, killed

Differential Revision: https://phab.mercurial-scm.org/D9296

from __future__ import absolute_import, print_function

import _lsprof
import sys

from .pycompat import getattr
from . import pycompat

Profiler = _lsprof.Profiler

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

__all__ = [b'profile', b'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(b"Can't sort by %s" % crit)
        elif self.data and not getattr(self.data[0], crit, None):
            raise ValueError(b"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 = b"% 12d %12d %11.4f %11.4f   %s\n"
        hcols = b"% 12s %12s %12s %12s %s\n"
        file.write(
            hcols
            % (
                b"CallCount",
                b"Recursive",
                b"Total(s)",
                b"Inline(s)",
                b"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,
                            b"    %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):
        if sys.version_info.major >= 3:
            code = code.encode('latin-1')
        return code
    try:
        mname = _fn2mod[code.co_filename]
    except KeyError:
        for k, v in list(pycompat.iteritems(sys.modules)):
            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

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

    if sys.version_info.major >= 3:
        res = res.encode('latin-1')

    return res