view tests/test-extension-timing.t @ 42743:8c9a6adec67a

rust-discovery: using the children cache in add_missing

The DAG range computation often needs to get back to very old
revisions, and turns out to be disproportionately long, given
that the end goal is to remove the descendents of the given
missing revisons from the undecided set.

The fast iteration capabilities available in the Rust case make
it possible to avoid the DAG range entirely, at the cost of
precomputing the children cache, and to simply iterate on
children of the given missing revisions.

This is a case where staying on the same side of the interface
between the two languages has clear benefits.

On discoveries with initial undecided sets
small enough to bypass sampling entirely, the total cost of
computing the children cache and the subsequent iteration
becomes better than the Python + C counterpart, which relies on
reachableroots2.

For example, on a repo with more than one million revisions with
an initial undecided set of 11 elements, we get these figures:

Rust version with simple iteration
  addcommons: 57.287us
  first undecided computation: 184.278334ms
  first children cache computation: 131.056us
  addmissings iteration: 42.766us
  first addinfo total: 185.24 ms

Python + C version
  first addcommons: 0.29 ms
  addcommons 0.21 ms
  first undecided computation 191.35 ms
  addmissings 45.75 ms
  first addinfo total: 237.77 ms

On discoveries with large undecided sets, the initial price paid
makes the first addinfo slower than the Python + C version,
but that's more than compensated by the gain in sampling and
subsequent iterations.
Here's an extreme example with an undecided set of a million revisions:

Rust version:
  first undecided computation: 293.842629ms
  first children cache computation: 407.911297ms
  addmissings iteration: 34.312869ms
  first addinfo total: 776.02 ms
  taking initial sample
  query 2: sampling time: 1318.38 ms
  query 2; still undecided: 1005013, sample size is: 200
  addmissings: 143.062us

Python + C version:
  first undecided computation 298.13 ms
  addmissings 80.13 ms
  first addinfo total: 399.62 ms
  taking initial sample
  query 2: sampling time: 3957.23 ms
  query 2; still undecided: 1005013, sample size is: 200
  addmissings 52.88 ms

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

Test basic extension support

  $ cat > foobar.py <<EOF
  > import os
  > from mercurial import commands, registrar
  > cmdtable = {}
  > command = registrar.command(cmdtable)
  > configtable = {}
  > configitem = registrar.configitem(configtable)
  > configitem(b'tests', b'foo', default=b"Foo")
  > def uisetup(ui):
  >     ui.debug(b"uisetup called [debug]\\n")
  >     ui.write(b"uisetup called\\n")
  >     ui.status(b"uisetup called [status]\\n")
  >     ui.flush()
  > def reposetup(ui, repo):
  >     ui.write(b"reposetup called for %s\\n" % os.path.basename(repo.root))
  >     ui.write(b"ui %s= repo.ui\\n" % (ui == repo.ui and b"=" or b"!"))
  >     ui.flush()
  > @command(b'foo', [], b'hg foo')
  > def foo(ui, *args, **kwargs):
  >     foo = ui.config(b'tests', b'foo')
  >     ui.write(foo)
  >     ui.write(b"\\n")
  > @command(b'bar', [], b'hg bar', norepo=True)
  > def bar(ui, *args, **kwargs):
  >     ui.write(b"Bar\\n")
  > EOF
  $ abspath=`pwd`/foobar.py

  $ mkdir barfoo
  $ cp foobar.py barfoo/__init__.py
  $ barfoopath=`pwd`/barfoo

  $ hg init a
  $ cd a
  $ echo foo > file
  $ hg add file
  $ hg commit -m 'add file'

  $ echo '[extensions]' >> $HGRCPATH
  $ echo "foobar = $abspath" >> $HGRCPATH

  $ filterlog () {
  >   sed -e 's!^[0-9/]* [0-9:]* ([0-9]*)>!YYYY/MM/DD HH:MM:SS (PID)>!'
  > }

Test extension setup timings

  $ hg foo --traceback --config devel.debug.extensions=yes --debug 2>&1 | filterlog
  YYYY/MM/DD HH:MM:SS (PID)> loading extensions
  YYYY/MM/DD HH:MM:SS (PID)> - processing 1 entries
  YYYY/MM/DD HH:MM:SS (PID)>   - loading extension: foobar
  YYYY/MM/DD HH:MM:SS (PID)>   > foobar extension loaded in * (glob)
  YYYY/MM/DD HH:MM:SS (PID)>     - validating extension tables: foobar
  YYYY/MM/DD HH:MM:SS (PID)>     - invoking registered callbacks: foobar
  YYYY/MM/DD HH:MM:SS (PID)>     > callbacks completed in * (glob)
  YYYY/MM/DD HH:MM:SS (PID)> > loaded 1 extensions, total time * (glob)
  YYYY/MM/DD HH:MM:SS (PID)> - loading configtable attributes
  YYYY/MM/DD HH:MM:SS (PID)> - executing uisetup hooks
  YYYY/MM/DD HH:MM:SS (PID)>   - running uisetup for foobar
  uisetup called [debug]
  uisetup called
  uisetup called [status]
  YYYY/MM/DD HH:MM:SS (PID)>   > uisetup for foobar took * (glob)
  YYYY/MM/DD HH:MM:SS (PID)> > all uisetup took * (glob)
  YYYY/MM/DD HH:MM:SS (PID)> - executing extsetup hooks
  YYYY/MM/DD HH:MM:SS (PID)>   - running extsetup for foobar
  YYYY/MM/DD HH:MM:SS (PID)>   > extsetup for foobar took * (glob)
  YYYY/MM/DD HH:MM:SS (PID)> > all extsetup took * (glob)
  YYYY/MM/DD HH:MM:SS (PID)> - executing remaining aftercallbacks
  YYYY/MM/DD HH:MM:SS (PID)> > remaining aftercallbacks completed in * (glob)
  YYYY/MM/DD HH:MM:SS (PID)> - loading extension registration objects
  YYYY/MM/DD HH:MM:SS (PID)> > extension registration object loading took * (glob)
  YYYY/MM/DD HH:MM:SS (PID)> > extension foobar take a total of * to load (glob)
  YYYY/MM/DD HH:MM:SS (PID)> extension loading complete
  YYYY/MM/DD HH:MM:SS (PID)> loading additional extensions
  YYYY/MM/DD HH:MM:SS (PID)> - processing 1 entries
  YYYY/MM/DD HH:MM:SS (PID)> > loaded 0 extensions, total time * (glob)
  YYYY/MM/DD HH:MM:SS (PID)> - loading configtable attributes
  YYYY/MM/DD HH:MM:SS (PID)> - executing uisetup hooks
  YYYY/MM/DD HH:MM:SS (PID)> > all uisetup took * (glob)
  YYYY/MM/DD HH:MM:SS (PID)> - executing extsetup hooks
  YYYY/MM/DD HH:MM:SS (PID)> > all extsetup took * (glob)
  YYYY/MM/DD HH:MM:SS (PID)> - executing remaining aftercallbacks
  YYYY/MM/DD HH:MM:SS (PID)> > remaining aftercallbacks completed in * (glob)
  YYYY/MM/DD HH:MM:SS (PID)> - loading extension registration objects
  YYYY/MM/DD HH:MM:SS (PID)> > extension registration object loading took * (glob)
  YYYY/MM/DD HH:MM:SS (PID)> extension loading complete
  YYYY/MM/DD HH:MM:SS (PID)> - executing reposetup hooks
  YYYY/MM/DD HH:MM:SS (PID)>   - running reposetup for foobar
  reposetup called for a
  ui == repo.ui
  YYYY/MM/DD HH:MM:SS (PID)>   > reposetup for foobar took * (glob)
  YYYY/MM/DD HH:MM:SS (PID)> > all reposetup took * (glob)
  Foo

  $ cd ..

  $ echo 'foobar = !' >> $HGRCPATH