annotate tests/test-fncache.t @ 44950:f9734b2d59cc

py3: make stdout line-buffered if connected to a TTY

Status messages that are to be shown on the terminal should be written to the
file descriptor before anything further is done, to keep the user updated.

One common way to achieve this is to make stdout line-buffered if it is
connected to a TTY. This is done on Python 2 (except on Windows, where libc,
which the CPython 2 streams depend on, does not properly support this).

Python 3 rolls it own I/O streams. On Python 3, buffered binary streams can't be
set line-buffered. The previous code (added in 227ba1afcb65) incorrectly
assumed that on Python 3, pycompat.stdout (sys.stdout.buffer) is already
line-buffered. However the interpreter initializes it with a block-buffered
stream or an unbuffered stream (when the -u option or the PYTHONUNBUFFERED
environment variable is set), never with a line-buffered stream.

One example where the current behavior is unacceptable is when running
`hg pull https://www.mercurial-scm.org/repo/hg` on Python 3, where the line
"pulling from https://www.mercurial-scm.org/repo/hg" does not appear on the
terminal before the hg process blocks while waiting for the server.

Various approaches to fix this problem are possible, including:

1. Weaken the contract of procutil.stdout to not give any guarantees about
   buffering behavior. In this case, users of procutil.stdout need to be
   changed to do enough flushes. In particular,
  1. either ui must insert enough flushes for ui.write() and friends, or
  2. ui.write() and friends get split into flushing and fully buffered
     methods, or
  3. users of ui.write() and friends must flush explicitly.
2. Make stdout unbuffered.
3. Make stdout line-buffered. Since Python 3 does not natively support that for
   binary streams, we must implement it ourselves.

(2.) is problematic because using unbuffered I/O changes the performance
characteristics significantly compared to line-buffered (which is used on
Python 2) and this would be a regression.

(1.2.) and (1.3) are a substantial amount of work. It’s unclear whether the
added complexity would be justified, given that raw performance doesn’t matter
that much when writing to a terminal much faster than the user could read it.

(1.1.) pushes complexity into the ui class instead of separating the concern of
how stdout is buffered. Other users of procutil.stdout would still need to take
care of the flushes.

This patch implements (3.). The general performance considerations are very
similar to (1.1.). The extra method invocation and method forwarding add a
little more overhead if the class is used. In exchange, it doesn’t add overhead
if not used.


For the benchmarks, I compared the previous implementation (incorrect on Python
3), (1.1.), (3.) and (2.). The command was chosen so that the streams were
configured as if they were writing to a TTY, but actually write to a pager,
which is also the default:
HGRCPATH=/dev/null python3 ./hg --cwd ~/vcs/mozilla-central --time --pager yes --config pager.pager='cat > /dev/null' status --all

previous:
time: real 7.880 secs (user 7.290+0.050 sys 0.580+0.170)
time: real 7.830 secs (user 7.220+0.070 sys 0.590+0.140)
time: real 7.800 secs (user 7.210+0.050 sys 0.570+0.170)

(1.1.) using Yuya Nishihara’s patch:
time: real 9.860 secs (user 8.670+0.350 sys 1.160+0.830)
time: real 9.540 secs (user 8.430+0.370 sys 1.100+0.770)
time: real 9.830 secs (user 8.630+0.370 sys 1.180+0.840)

(3.) using this patch:
time: real 9.580 secs (user 8.480+0.350 sys 1.090+0.770)
time: real 9.670 secs (user 8.480+0.330 sys 1.170+0.860)
time: real 9.640 secs (user 8.500+0.350 sys 1.130+0.810)

(2.) using a previous patch by me:
time: real 10.480 secs (user 8.850+0.720 sys 1.590+1.500)
time: real 10.490 secs (user 8.750+0.750 sys 1.710+1.470)
time: real 10.240 secs (user 8.600+0.700 sys 1.590+1.510)


As expected, there’s no difference on Python 2, as exactly the same code paths
are used:

previous:
time: real 6.950 secs (user 5.870+0.330 sys 1.070+0.770)
time: real 7.040 secs (user 6.040+0.360 sys 0.980+0.750)
time: real 7.070 secs (user 5.950+0.360 sys 1.100+0.760)

this patch:
time: real 7.010 secs (user 5.900+0.390 sys 1.070+0.730)
time: real 7.000 secs (user 5.850+0.350 sys 1.120+0.760)
time: real 7.000 secs (user 5.790+0.380 sys 1.170+0.710)

#require repofncache

An extension which will set fncache chunksize to 1 byte to make sure that logic
does not break

  $ cat > chunksize.py <<EOF
  > from __future__ import absolute_import
  > from mercurial import store
  > store.fncache_chunksize = 1
  > EOF

  $ cat >> $HGRCPATH <<EOF
  > [extensions]
  > chunksize = $TESTTMP/chunksize.py
  > EOF

Init repo1:

  $ hg init repo1
  $ cd repo1
  $ echo "some text" > a
  $ hg add
  adding a
  $ hg ci -m first
  $ cat .hg/store/fncache | sort
  data/a.i

Testing a.i/b:

  $ mkdir a.i
  $ echo "some other text" > a.i/b
  $ hg add
  adding a.i/b
  $ hg ci -m second
  $ cat .hg/store/fncache | sort
  data/a.i
  data/a.i.hg/b.i

Testing a.i.hg/c:

  $ mkdir a.i.hg
  $ echo "yet another text" > a.i.hg/c
  $ hg add
  adding a.i.hg/c
  $ hg ci -m third
  $ cat .hg/store/fncache | sort
  data/a.i
  data/a.i.hg.hg/c.i
  data/a.i.hg/b.i

Testing verify:

  $ hg verify
  checking changesets
  checking manifests
  crosschecking files in changesets and manifests
  checking files
  checked 3 changesets with 3 changes to 3 files

  $ rm .hg/store/fncache

  $ hg verify
  checking changesets
  checking manifests
  crosschecking files in changesets and manifests
  checking files
   warning: revlog 'data/a.i' not in fncache!
   warning: revlog 'data/a.i.hg/c.i' not in fncache!
   warning: revlog 'data/a.i/b.i' not in fncache!
  checked 3 changesets with 3 changes to 3 files
  3 warnings encountered!
  hint: run "hg debugrebuildfncache" to recover from corrupt fncache

Follow the hint to make sure it works

  $ hg debugrebuildfncache
  adding data/a.i
  adding data/a.i.hg/c.i
  adding data/a.i/b.i
  3 items added, 0 removed from fncache

  $ hg verify
  checking changesets
  checking manifests
  crosschecking files in changesets and manifests
  checking files
  checked 3 changesets with 3 changes to 3 files

  $ cd ..

Non store repo:

  $ hg --config format.usestore=False init foo
  $ cd foo
  $ mkdir tst.d
  $ echo foo > tst.d/foo
  $ hg ci -Amfoo
  adding tst.d/foo
  $ find .hg | sort
  .hg
  .hg/00changelog.i
  .hg/00manifest.i
  .hg/cache
  .hg/cache/branch2-served
  .hg/cache/rbc-names-v1
  .hg/cache/rbc-revs-v1
  .hg/data
  .hg/data/tst.d.hg
  .hg/data/tst.d.hg/foo.i
  .hg/dirstate
  .hg/fsmonitor.state (fsmonitor !)
  .hg/last-message.txt
  .hg/phaseroots
  .hg/requires
  .hg/undo
  .hg/undo.backup.dirstate
  .hg/undo.backupfiles
  .hg/undo.bookmarks
  .hg/undo.branch
  .hg/undo.desc
  .hg/undo.dirstate
  .hg/undo.phaseroots
  .hg/wcache
  .hg/wcache/checkisexec (execbit !)
  .hg/wcache/checklink (symlink !)
  .hg/wcache/checklink-target (symlink !)
  .hg/wcache/manifestfulltextcache (reporevlogstore !)
  $ cd ..

Non fncache repo:

  $ hg --config format.usefncache=False init bar
  $ cd bar
  $ mkdir tst.d
  $ echo foo > tst.d/Foo
  $ hg ci -Amfoo
  adding tst.d/Foo
  $ find .hg | sort
  .hg
  .hg/00changelog.i
  .hg/cache
  .hg/cache/branch2-served
  .hg/cache/rbc-names-v1
  .hg/cache/rbc-revs-v1
  .hg/dirstate
  .hg/fsmonitor.state (fsmonitor !)
  .hg/last-message.txt
  .hg/requires
  .hg/store
  .hg/store/00changelog.i
  .hg/store/00manifest.i
  .hg/store/data
  .hg/store/data/tst.d.hg
  .hg/store/data/tst.d.hg/_foo.i
  .hg/store/phaseroots
  .hg/store/undo
  .hg/store/undo.backupfiles
  .hg/store/undo.phaseroots
  .hg/undo.backup.dirstate
  .hg/undo.bookmarks
  .hg/undo.branch
  .hg/undo.desc
  .hg/undo.dirstate
  .hg/wcache
  .hg/wcache/checkisexec (execbit !)
  .hg/wcache/checklink (symlink !)
  .hg/wcache/checklink-target (symlink !)
  .hg/wcache/manifestfulltextcache (reporevlogstore !)
  $ cd ..

Encoding of reserved / long paths in the store

  $ hg init r2
  $ cd r2
  $ cat <<EOF > .hg/hgrc
  > [ui]
  > portablefilenames = ignore
  > EOF

  $ hg import -q --bypass - <<EOF
  > # HG changeset patch
  > # User test
  > # Date 0 0
  > # Node ID 1c7a2f7cb77be1a0def34e4c7cabc562ad98fbd7
  > # Parent  0000000000000000000000000000000000000000
  > 1
  > 
  > diff --git a/12345678/12345678/12345678/12345678/12345678/12345678/12345678/12345/xxxxxxxxx-xxxxxxxxx-xxxxxxxxx-123456789-12.3456789-12345-ABCDEFGHIJKLMNOPRSTUVWXYZ-abcdefghjiklmnopqrstuvwxyz b/12345678/12345678/12345678/12345678/12345678/12345678/12345678/12345/xxxxxxxxx-xxxxxxxxx-xxxxxxxxx-123456789-12.3456789-12345-ABCDEFGHIJKLMNOPRSTUVWXYZ-abcdefghjiklmnopqrstuvwxyz
  > new file mode 100644
  > --- /dev/null
  > +++ b/12345678/12345678/12345678/12345678/12345678/12345678/12345678/12345/xxxxxxxxx-xxxxxxxxx-xxxxxxxxx-123456789-12.3456789-12345-ABCDEFGHIJKLMNOPRSTUVWXYZ-abcdefghjiklmnopqrstuvwxyz
  > @@ -0,0 +1,1 @@
  > +foo
  > diff --git a/AUX/SECOND/X.PRN/FOURTH/FI:FTH/SIXTH/SEVENTH/EIGHTH/NINETH/TENTH/ELEVENTH/LOREMIPSUM.TXT b/AUX/SECOND/X.PRN/FOURTH/FI:FTH/SIXTH/SEVENTH/EIGHTH/NINETH/TENTH/ELEVENTH/LOREMIPSUM.TXT
  > new file mode 100644
  > --- /dev/null
  > +++ b/AUX/SECOND/X.PRN/FOURTH/FI:FTH/SIXTH/SEVENTH/EIGHTH/NINETH/TENTH/ELEVENTH/LOREMIPSUM.TXT
  > @@ -0,0 +1,1 @@
  > +foo
  > diff --git a/Project Planning/Resources/AnotherLongDirectoryName/Followedbyanother/AndAnother/AndThenAnExtremelyLongFileName.txt b/Project Planning/Resources/AnotherLongDirectoryName/Followedbyanother/AndAnother/AndThenAnExtremelyLongFileName.txt
  > new file mode 100644
  > --- /dev/null
  > +++ b/Project Planning/Resources/AnotherLongDirectoryName/Followedbyanother/AndAnother/AndThenAnExtremelyLongFileName.txt	
  > @@ -0,0 +1,1 @@
  > +foo
  > diff --git a/bla.aux/prn/PRN/lpt/com3/nul/coma/foo.NUL/normal.c b/bla.aux/prn/PRN/lpt/com3/nul/coma/foo.NUL/normal.c
  > new file mode 100644
  > --- /dev/null
  > +++ b/bla.aux/prn/PRN/lpt/com3/nul/coma/foo.NUL/normal.c
  > @@ -0,0 +1,1 @@
  > +foo
  > diff --git a/enterprise/openesbaddons/contrib-imola/corba-bc/netbeansplugin/wsdlExtension/src/main/java/META-INF/services/org.netbeans.modules.xml.wsdl.bindingsupport.spi.ExtensibilityElementTemplateProvider b/enterprise/openesbaddons/contrib-imola/corba-bc/netbeansplugin/wsdlExtension/src/main/java/META-INF/services/org.netbeans.modules.xml.wsdl.bindingsupport.spi.ExtensibilityElementTemplateProvider
  > new file mode 100644
  > --- /dev/null
  > +++ b/enterprise/openesbaddons/contrib-imola/corba-bc/netbeansplugin/wsdlExtension/src/main/java/META-INF/services/org.netbeans.modules.xml.wsdl.bindingsupport.spi.ExtensibilityElementTemplateProvider
  > @@ -0,0 +1,1 @@
  > +foo
  > EOF

  $ find .hg/store -name *.i  | sort
  .hg/store/00changelog.i
  .hg/store/00manifest.i
  .hg/store/data/bla.aux/pr~6e/_p_r_n/lpt/co~6d3/nu~6c/coma/foo._n_u_l/normal.c.i
  .hg/store/dh/12345678/12345678/12345678/12345678/12345678/12345678/12345678/12345/xxxxxx168e07b38e65eff86ab579afaaa8e30bfbe0f35f.i
  .hg/store/dh/au~78/second/x.prn/fourth/fi~3afth/sixth/seventh/eighth/nineth/tenth/loremia20419e358ddff1bf8751e38288aff1d7c32ec05.i
  .hg/store/dh/enterpri/openesba/contrib-/corba-bc/netbeans/wsdlexte/src/main/java/org.net7018f27961fdf338a598a40c4683429e7ffb9743.i
  .hg/store/dh/project_/resource/anotherl/followed/andanoth/andthenanextremelylongfilename0d8e1f4187c650e2f1fdca9fd90f786bc0976b6b.i

  $ cd ..

Aborting lock does not prevent fncache writes

  $ cat > exceptionext.py <<EOF
  > from __future__ import absolute_import
  > import os
  > from mercurial import commands, error, extensions
  > 
  > def lockexception(orig, vfs, lockname, wait, releasefn, *args, **kwargs):
  >     def releasewrap():
  >         l.held = False # ensure __del__ is a noop
  >         raise error.Abort("forced lock failure")
  >     l = orig(vfs, lockname, wait, releasewrap, *args, **kwargs)
  >     return l
  > 
  > def reposetup(ui, repo):
  >     extensions.wrapfunction(repo, '_lock', lockexception)
  > 
  > cmdtable = {}
  > 
  > # wrap "commit" command to prevent wlock from being '__del__()'-ed
  > # at the end of dispatching (for intentional "forced lcok failure")
  > def commitwrap(orig, ui, repo, *pats, **opts):
  >     repo = repo.unfiltered() # to use replaced repo._lock certainly
  >     wlock = repo.wlock()
  >     try:
  >         return orig(ui, repo, *pats, **opts)
  >     finally:
  >         # multiple 'relase()' is needed for complete releasing wlock,
  >         # because "forced" abort at last releasing store lock
  >         # prevents wlock from being released at same 'lockmod.release()'
  >         for i in range(wlock.held):
  >             wlock.release()
  > 
  > def extsetup(ui):
  >     extensions.wrapcommand(commands.table, b"commit", commitwrap)
  > EOF
  $ extpath=`pwd`/exceptionext.py
  $ hg init fncachetxn
  $ cd fncachetxn
  $ printf "[extensions]\nexceptionext=$extpath\n" >> .hg/hgrc
  $ touch y
  $ hg ci -qAm y
  abort: forced lock failure
  [255]
  $ cat .hg/store/fncache
  data/y.i

Aborting transaction prevents fncache change

  $ cat > ../exceptionext.py <<EOF
  > from __future__ import absolute_import
  > import os
  > from mercurial import commands, error, extensions, localrepo
  > 
  > def wrapper(orig, self, *args, **kwargs):
  >     tr = orig(self, *args, **kwargs)
  >     def fail(tr):
  >         raise error.Abort(b"forced transaction failure")
  >     # zzz prefix to ensure it sorted after store.write
  >     tr.addfinalize(b'zzz-forcefails', fail)
  >     return tr
  > 
  > def uisetup(ui):
  >     extensions.wrapfunction(
  >         localrepo.localrepository, b'transaction', wrapper)
  > 
  > cmdtable = {}
  > 
  > EOF

Clean cached version
  $ rm -f "${extpath}c"
  $ rm -Rf "`dirname $extpath`/__pycache__"

  $ touch z
  $ hg ci -qAm z
  transaction abort!
  rollback completed
  abort: forced transaction failure
  [255]
  $ cat .hg/store/fncache
  data/y.i

Aborted transactions can be recovered later

  $ cat > ../exceptionext.py <<EOF
  > from __future__ import absolute_import
  > import os
  > from mercurial import (
  >   commands,
  >   error,
  >   extensions,
  >   localrepo,
  >   transaction,
  > )
  > 
  > def trwrapper(orig, self, *args, **kwargs):
  >     tr = orig(self, *args, **kwargs)
  >     def fail(tr):
  >         raise error.Abort(b"forced transaction failure")
  >     # zzz prefix to ensure it sorted after store.write
  >     tr.addfinalize(b'zzz-forcefails', fail)
  >     return tr
  > 
  > def abortwrapper(orig, self, *args, **kwargs):
  >     raise error.Abort(b"forced transaction failure")
  > 
  > def uisetup(ui):
  >     extensions.wrapfunction(localrepo.localrepository, 'transaction',
  >                             trwrapper)
  >     extensions.wrapfunction(transaction.transaction, '_abort',
  >                             abortwrapper)
  > 
  > cmdtable = {}
  > 
  > EOF

Clean cached versions
  $ rm -f "${extpath}c"
  $ rm -Rf "`dirname $extpath`/__pycache__"

  $ hg up -q 1
  $ touch z
  $ hg ci -qAm z 2>/dev/null
  [255]
  $ cat .hg/store/fncache | sort
  data/y.i
  data/z.i
  $ hg recover --verify
  rolling back interrupted transaction
  checking changesets
  checking manifests
  crosschecking files in changesets and manifests
  checking files
  checked 1 changesets with 1 changes to 1 files
  $ cat .hg/store/fncache
  data/y.i

  $ cd ..

debugrebuildfncache does nothing unless repo has fncache requirement

  $ hg --config format.usefncache=false init nofncache
  $ cd nofncache
  $ hg debugrebuildfncache
  (not rebuilding fncache because repository does not support fncache)

  $ cd ..

debugrebuildfncache works on empty repository

  $ hg init empty
  $ cd empty
  $ hg debugrebuildfncache
  fncache already up to date
  $ cd ..

debugrebuildfncache on an up to date repository no-ops

  $ hg init repo
  $ cd repo
  $ echo initial > foo
  $ echo initial > .bar
  $ hg commit -A -m initial
  adding .bar
  adding foo

  $ cat .hg/store/fncache | sort
  data/.bar.i
  data/foo.i

  $ hg debugrebuildfncache
  fncache already up to date

debugrebuildfncache restores deleted fncache file

  $ rm -f .hg/store/fncache
  $ hg debugrebuildfncache
  adding data/.bar.i
  adding data/foo.i
  2 items added, 0 removed from fncache

  $ cat .hg/store/fncache | sort
  data/.bar.i
  data/foo.i

Rebuild after rebuild should no-op

  $ hg debugrebuildfncache
  fncache already up to date

A single missing file should get restored, an extra file should be removed

  $ cat > .hg/store/fncache << EOF
  > data/foo.i
  > data/bad-entry.i
  > EOF

  $ hg debugrebuildfncache
  removing data/bad-entry.i
  adding data/.bar.i
  1 items added, 1 removed from fncache

  $ cat .hg/store/fncache | sort
  data/.bar.i
  data/foo.i

debugrebuildfncache recovers from truncated line in fncache

  $ printf a > .hg/store/fncache
  $ hg debugrebuildfncache
  fncache does not ends with a newline
  adding data/.bar.i
  adding data/foo.i
  2 items added, 0 removed from fncache

  $ cat .hg/store/fncache | sort
  data/.bar.i
  data/foo.i

  $ cd ..

Try a simple variation without dotencode to ensure fncache is ignorant of encoding

  $ hg --config format.dotencode=false init nodotencode
  $ cd nodotencode
  $ echo initial > foo
  $ echo initial > .bar
  $ hg commit -A -m initial
  adding .bar
  adding foo

  $ cat .hg/store/fncache | sort
  data/.bar.i
  data/foo.i

  $ rm .hg/store/fncache
  $ hg debugrebuildfncache
  adding data/.bar.i
  adding data/foo.i
  2 items added, 0 removed from fncache

  $ cat .hg/store/fncache | sort
  data/.bar.i
  data/foo.i

  $ cd ..

In repositories that have accumulated a large number of files over time, the
fncache file is going to be large. If we possibly can avoid loading it, so much the better.
The cache should not loaded when committing changes to existing files, or when unbundling
changesets that only contain changes to existing files:

  $ cat > fncacheloadwarn.py << EOF
  > from __future__ import absolute_import
  > from mercurial import extensions, localrepo
  > 
  > def extsetup(ui):
  >     def wrapstore(orig, requirements, *args):
  >         store = orig(requirements, *args)
  >         if b'store' in requirements and b'fncache' in requirements:
  >             instrumentfncachestore(store, ui)
  >         return store
  >     extensions.wrapfunction(localrepo, 'makestore', wrapstore)
  > 
  > def instrumentfncachestore(fncachestore, ui):
  >     class instrumentedfncache(type(fncachestore.fncache)):
  >         def _load(self):
  >             ui.warn(b'fncache load triggered!\n')
  >             super(instrumentedfncache, self)._load()
  >     fncachestore.fncache.__class__ = instrumentedfncache
  > EOF

  $ fncachextpath=`pwd`/fncacheloadwarn.py
  $ hg init nofncacheload
  $ cd nofncacheload
  $ printf "[extensions]\nfncacheloadwarn=$fncachextpath\n" >> .hg/hgrc

A new file should trigger a load, as we'd want to update the fncache set in that case:

  $ touch foo
  $ hg ci -qAm foo
  fncache load triggered!

But modifying that file should not:

  $ echo bar >> foo
  $ hg ci -qm foo

If a transaction has been aborted, the zero-size truncated index file will
not prevent the fncache from being loaded; rather than actually abort
a transaction, we simulate the situation by creating a zero-size index file:

  $ touch .hg/store/data/bar.i
  $ touch bar
  $ hg ci -qAm bar
  fncache load triggered!

Unbundling should follow the same rules; existing files should not cause a load:

  $ hg clone -q . tobundle
  $ echo 'new line' > tobundle/bar
  $ hg -R tobundle ci -qm bar
  $ hg -R tobundle bundle -q barupdated.hg
  $ hg unbundle -q barupdated.hg

but adding new files should:

  $ touch tobundle/newfile
  $ hg -R tobundle ci -qAm newfile
  $ hg -R tobundle bundle -q newfile.hg
  $ hg unbundle -q newfile.hg
  fncache load triggered!

  $ cd ..