view tests/test-blackbox.t @ 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

setup
  $ cat > mock.py <<EOF
  > from mercurial import util
  > 
  > def makedate():
  >     return 0, 0
  > def getuser():
  >     return 'bob'
  > # mock the date and user apis so the output is always the same
  > def uisetup(ui):
  >     util.makedate = makedate
  >     util.getuser = getuser
  > EOF
  $ cat >> $HGRCPATH <<EOF
  > [extensions]
  > blackbox=
  > mock=`pwd`/mock.py
  > mq=
  > EOF
  $ hg init blackboxtest
  $ cd blackboxtest

command, exit codes, and duration

  $ echo a > a
  $ hg add a
  $ hg blackbox
  1970/01/01 00:00:00 bob> add a
  1970/01/01 00:00:00 bob> add a exited 0 after * seconds (glob)

incoming change tracking

create two heads to verify that we only see one change in the log later
  $ hg commit -ma
  $ hg up null
  0 files updated, 0 files merged, 1 files removed, 0 files unresolved
  $ echo b > b
  $ hg commit -Amb
  adding b
  created new head

clone, commit, pull
  $ hg clone . ../blackboxtest2
  updating to branch default
  1 files updated, 0 files merged, 0 files removed, 0 files unresolved
  $ echo c > c
  $ hg commit -Amc
  adding c
  $ cd ../blackboxtest2
  $ hg pull
  pulling from $TESTTMP/blackboxtest (glob)
  searching for changes
  adding changesets
  adding manifests
  adding file changes
  added 1 changesets with 1 changes to 1 files
  (run 'hg update' to get a working copy)
  $ hg blackbox -l 3
  1970/01/01 00:00:00 bob> pull
  1970/01/01 00:00:00 bob> 1 incoming changes - new heads: d02f48003e62
  1970/01/01 00:00:00 bob> pull exited 0 after * seconds (glob)

we must not cause a failure if we cannot write to the log

  $ hg rollback
  repository tip rolled back to revision 1 (undo pull)

#if unix-permissions no-root
  $ chmod 000 .hg/blackbox.log
  $ hg --debug incoming
  warning: cannot write to blackbox.log: Permission denied
  comparing with $TESTTMP/blackboxtest (glob)
  query 1; heads
  searching for changes
  all local heads known remotely
  changeset:   2:d02f48003e62c24e2659d97d30f2a83abe5d5d51
  tag:         tip
  phase:       draft
  parent:      1:6563da9dcf87b1949716e38ff3e3dfaa3198eb06
  parent:      -1:0000000000000000000000000000000000000000
  manifest:    2:ab9d46b053ebf45b7996f2922b9893ff4b63d892
  user:        test
  date:        Thu Jan 01 00:00:00 1970 +0000
  files+:      c
  extra:       branch=default
  description:
  c
  
  
#endif
  $ hg pull
  pulling from $TESTTMP/blackboxtest (glob)
  searching for changes
  adding changesets
  adding manifests
  adding file changes
  added 1 changesets with 1 changes to 1 files
  (run 'hg update' to get a working copy)

a failure reading from the log is fine
#if unix-permissions no-root
  $ hg blackbox -l 3
  abort: Permission denied: $TESTTMP/blackboxtest2/.hg/blackbox.log
  [255]

  $ chmod 600 .hg/blackbox.log
#endif

backup bundles get logged

  $ touch d
  $ hg commit -Amd
  adding d
  created new head
  $ hg strip tip
  0 files updated, 0 files merged, 1 files removed, 0 files unresolved
  saved backup bundle to $TESTTMP/blackboxtest2/.hg/strip-backup/*-backup.hg (glob)
  $ hg blackbox -l 3
  1970/01/01 00:00:00 bob> strip tip
  1970/01/01 00:00:00 bob> saved backup bundle to $TESTTMP/blackboxtest2/.hg/strip-backup/*-backup.hg (glob)
  1970/01/01 00:00:00 bob> strip tip exited 0 after * seconds (glob)

extension and python hooks - use the eol extension for a pythonhook

  $ echo '[extensions]' >> .hg/hgrc
  $ echo 'eol=' >> .hg/hgrc
  $ echo '[hooks]' >> .hg/hgrc
  $ echo 'update = echo hooked' >> .hg/hgrc
  $ hg update
  hooked
  1 files updated, 0 files merged, 0 files removed, 0 files unresolved
  $ hg blackbox -l 4
  1970/01/01 00:00:00 bob> update
  1970/01/01 00:00:00 bob> pythonhook-preupdate: hgext.eol.preupdate finished in * seconds (glob)
  1970/01/01 00:00:00 bob> exthook-update: echo hooked finished in * seconds (glob)
  1970/01/01 00:00:00 bob> update exited 0 after * seconds (glob)

log rotation

  $ echo '[blackbox]' >> .hg/hgrc
  $ echo 'maxsize = 20 b' >> .hg/hgrc
  $ echo 'maxfiles = 3' >> .hg/hgrc
  $ hg status
  $ hg status
  $ hg status
  $ hg tip -q
  2:d02f48003e62
  $ ls .hg/blackbox.log*
  .hg/blackbox.log
  .hg/blackbox.log.1
  .hg/blackbox.log.2

cleanup
  $ cd ..