view tests/test-propertycache.py.out @ 20182:04036798ebed

branches: avoid unnecessary changectx.branch() calls

This requires reading from the changelog, which can be costly over NFS.

Note that this does not totally remove reading from the changelog; we
still do that when calling changectx.closesbranch(). That call will be
removed in a later patch.

Running hg branches on the PyPy repo (with 996) over a busy NFS server,
before this change:

$ time hg --profile branches > /dev/null
   CallCount    Recursive     Total(s)    Inline(s) module:lineno(function)
        2042            0      2.2827      2.2827   <open>
        2036            0      0.9840      0.9840   <method 'close' of 'file' objects>
        2036            0      0.0464      0.0464   <method 'read' of 'file' objects>
        5233            0      0.1985      0.0453   mercurial.repoview:161(changelog)
       10462            0      0.0791      0.0314       mercurial.changelog:133(tip)
        5233            0      0.0388      0.0176       mercurial.localrepo:26(__get__)
       10462            0      0.0250      0.0126       <len>
        5233            0      0.0059      0.0039       mercurial.repoview:112(filterrevs)
       10462            0      0.0029      0.0029       <hash>
        2034            0      0.0444      0.0444   <method 'seek' of 'file' objects>
        5340            0      0.0390      0.0390   mercurial.revlog:296(rev)
        2582            0      0.0371      0.0371   <zlib.decompress>
        3155            0      0.1963      0.0366   mercurial.context:202(__init__)
        3155            0      0.1238      0.0306       mercurial.repoview:161(changelog)
        3155            0      0.0261      0.0080       mercurial.changelog:183(rev)
        9465            0      0.0061      0.0061       <isinstance>
        1096            0      0.0023      0.0023       <binascii.unhexlify>
        4251            0      0.0014      0.0014       <len>
        2059            0      3.7341      0.0332   mercurial.changelog:270(read)
        2059            0      3.6304      0.0307       mercurial.revlog:907(revision)
        2057            0      0.0262      0.0137       mercurial.changelog:28(decodeextra)
        4118            0      0.0094      0.0094       <method 'split' of 'str' objects>
        4118            0      0.0270      0.0048       mercurial.encoding:61(tolocal)
        2059            0      0.0040      0.0040       <method 'index' of 'str' objects>
       10462            0      0.0791      0.0314   mercurial.changelog:133(tip)
       10462            0      0.0289      0.0207       mercurial.changelog:190(node)
       10462            0      0.0188      0.0091       <len>
       52433        20932      0.0478      0.0310   <len>
       20932            0      0.0221      0.0168       mercurial.revlog:262(__len__)
        2059            0      3.6304      0.0307   mercurial.revlog:907(revision)

real    0m4.361s
user    0m0.986s
sys     0m0.237s

After this change:

$ time hg --profile branches > /dev/null
   CallCount    Recursive     Total(s)    Inline(s) module:lineno(function)
        1069            0      1.1098      1.1098   <open>
        1063            0      0.4865      0.4865   <method 'close' of 'file' objects>
        4122            0      0.1811      0.0404   mercurial.repoview:161(changelog)
        8240            0      0.0712      0.0272       mercurial.changelog:133(tip)
        4122            0      0.0378      0.0177       mercurial.localrepo:26(__get__)
        8240            0      0.0221      0.0115       <len>
        4122            0      0.0057      0.0033       mercurial.repoview:112(filterrevs)
        8240            0      0.0025      0.0025       <hash>
        3029            0      0.1979      0.0371   mercurial.context:202(__init__)
        3029            0      0.1278      0.0310       mercurial.repoview:161(changelog)
        3029            0      0.0230      0.0081       mercurial.changelog:183(rev)
        9087            0      0.0061      0.0061       <isinstance>
        1096            0      0.0026      0.0026       <binascii.unhexlify>
        4125            0      0.0014      0.0014       <len>
        4229            0      0.0337      0.0337   mercurial.revlog:296(rev)
        1061            0      0.0296      0.0296   <method 'seek' of 'file' objects>
        1063            0      0.0292      0.0292   <method 'read' of 'file' objects>
        8240            0      0.0712      0.0272   mercurial.changelog:133(tip)
        8240            0      0.0271      0.0196       mercurial.changelog:190(node)
        8240            0      0.0169      0.0083       <len>
       40476        16488      0.0422      0.0271   <len>
       16488            0      0.0193      0.0152       mercurial.revlog:262(__len__)
        1342            0      0.0241      0.0241   <zlib.decompress>
        9445            0      0.0336      0.0224   mercurial.changelog:190(node)
        9445            0      0.0112      0.0112       mercurial.revlog:317(node)
        1074            0      1.9102      0.0224   mercurial.changelog:270(read)
        1074            0      1.8397      0.0202       mercurial.revlog:907(revision)
        1073            0      0.0187      0.0099       mercurial.changelog:28(decodeextra)
        2148            0      0.0061      0.0061       <method 'split' of 'str' objects>
        2148            0      0.0184      0.0034       mercurial.encoding:61(tolocal)

real    0m2.402s
user    0m0.735s
sys     0m0.177s

=== property cache ===

calllog: []
cached value (unfiltered): NOCACHE

= first access on unfiltered, should do a call
access: 0
calllog: [0]
cached value (unfiltered): 0

= second access on unfiltered, should not do call
access 0
calllog: [0]
cached value (unfiltered): 0

= first access on "visible" view, should do a call
cached value ("visible" view): NOCACHE
access: 7
calllog: [0, 7]
cached value (unfiltered): 0
cached value ("visible" view): 7

= second access on "visible view", should not do call
access: 7
calllog: [0, 7]
cached value (unfiltered): 0
cached value ("visible" view): 7

= no effect on other view
cached value ("immutable" view): NOCACHE
access: 9
calllog: [0, 7, 9]
cached value (unfiltered): 0
cached value ("visible" view): 7
cached value ("immutable" view): 9


=== unfiltered property cache ===

unficalllog: []
cached value (unfiltered):       NOCACHE
cached value ("visible" view):   NOCACHE
cached value ("immutable" view): NOCACHE

= first access on unfiltered, should do a call
access (unfiltered): 100
unficalllog: [100]
cached value (unfiltered):       100

= second access on unfiltered, should not do call
access (unfiltered): 100
unficalllog: [100]
cached value (unfiltered):       100

= access on view should use the unfiltered cache
access (unfiltered):       100
access ("visible" view):   100
access ("immutable" view): 100
unficalllog: [100]
cached value (unfiltered):       100
cached value ("visible" view):   NOCACHE
cached value ("immutable" view): NOCACHE

= even if we clear the unfiltered cache
cached value (unfiltered):       NOCACHE
cached value ("visible" view):   NOCACHE
cached value ("immutable" view): NOCACHE
unficalllog: [100]
access ("visible" view):   100
unficalllog: [100, 100]
cached value (unfiltered):       100
cached value ("visible" view):   NOCACHE
cached value ("immutable" view): NOCACHE
access ("immutable" view): 100
unficalllog: [100, 100]
cached value (unfiltered):       100
cached value ("visible" view):   NOCACHE
cached value ("immutable" view): NOCACHE
access (unfiltered):       100
unficalllog: [100, 100]
cached value (unfiltered):       100
cached value ("visible" view):   NOCACHE
cached value ("immutable" view): NOCACHE