view tests/test-logtoprocess.t @ 40326:fed697fa1734

sqlitestore: file storage backend using SQLite

This commit provides an extension which uses SQLite to store file
data (as opposed to revlogs).

As the inline documentation describes, there are still several
aspects to the extension that are incomplete. But it's a start.
The extension does support basic clone, checkout, and commit
workflows, which makes it suitable for simple use cases.

One notable missing feature is support for "bundlerepos." This is
probably responsible for the most test failures when the extension
is activated as part of the test suite.

All revision data is stored in SQLite. Data is stored as zstd
compressed chunks (default if zstd is available), zlib compressed
chunks (default if zstd is not available), or raw chunks (if
configured or if a compressed delta is not smaller than the raw
delta). This makes things very similar to revlogs.

Unlike revlogs, the extension doesn't yet enforce a limit on delta
chain length. This is an obvious limitation and should be addressed.
This is somewhat mitigated by the use of zstd, which is much faster
than zlib to decompress.

There is a dedicated table for storing deltas. Deltas are stored
by the SHA-1 hash of their uncompressed content. The "fileindex" table
has columns that reference the delta for each revision and the base
delta that delta should be applied against. A recursive SQL query
is used to resolve the delta chain along with the delta data.

By storing deltas by hash, we are able to de-duplicate delta storage!
With revlogs, the same deltas in different revlogs would result in
duplicate storage of that delta. In this scheme, inserting the
duplicate delta is a no-op and delta chains simply reference the
existing delta.

When initially implementing this extension, I did not have
content-indexed deltas and deltas could be duplicated across files
(just like revlogs). When I implemented content-indexed deltas, the
size of the SQLite database for a full clone of mozilla-unified
dropped:

before: 2,554,261,504 bytes
after:  2,488,754,176 bytes

Surprisingly, this is still larger than the bytes size of revlog
files:

revlog files: 2,104,861,230 bytes
du -b:        2,254,381,614

I would have expected storage to be smaller since we're not limiting
delta chain length and since we're using zstd instead of zlib. I
suspect the SQLite indexes and per-column overhead account for the
bulk of the differences. (Keep in mind that revlog uses a 64-byte
packed struct for revision index data and deltas are stored without
padding. Aside from the 12 unused bytes in the 32 byte node field,
revlogs are pretty efficient.) Another source of overhead is file
name storage. With revlogs, file names are stored in the filesystem.
But with SQLite, we need to store file names in the database. This is
roughly equivalent to the size of the fncache file, which for the
mozilla-unified repository is ~34MB.

Since the SQLite database isn't append-only and since delta chains
can reference any delta, this opens some interesting possibilities.
For example, we could store deltas in reverse, such that fulltexts
are stored for newer revisions and deltas are applied to reconstruct
older revisions. This is likely a more optimal storage strategy for
version control, as new data tends to be more frequently accessed
than old data. We would obviously need wire protocol support for
transferring revision data from newest to oldest. And we would
probably need some kind of mechanism for "re-encoding" stores. But
it should be doable.

This extension is very much experimental quality. There are a handful
of features that don't work. It probably isn't suitable for day-to-day
use. But it could be used in limited cases (e.g. read-only checkouts
like in CI). And it is also a good proving ground for alternate
storage backends. As we continue to define interfaces for all things
storage, it will be useful to have a viable alternate storage backend
to see how things shake out in practice.

test-storage.py passes on Python 2 and introduces no new test failures on
Python 3. Having the storage-level unit tests has proved to be insanely
useful when developing this extension. Those tests caught numerous bugs
during development and I'm convinced this style of testing is the way
forward for ensuring alternate storage backends work as intended. Of
course, test coverage isn't close to what it needs to be. But it is
a start. And what coverage we have gives me confidence that basic store
functionality is implemented properly.

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

#require no-windows

ATTENTION: logtoprocess runs commands asynchronously. Be sure to append "| cat"
to hg commands, to wait for the output, if you want to test its output.
Otherwise the test will be flaky.

Test if logtoprocess correctly captures command-related log calls.

  $ hg init
  $ cat > $TESTTMP/foocommand.py << EOF
  > from __future__ import absolute_import
  > from mercurial import registrar
  > cmdtable = {}
  > command = registrar.command(cmdtable)
  > configtable = {}
  > configitem = registrar.configitem(configtable)
  > configitem('logtoprocess', 'foo',
  >     default=None,
  > )
  > @command(b'foo', [])
  > def foo(ui, repo):
  >     ui.log('foo', 'a message: %(bar)s\n', bar='spam')
  > EOF
  $ cp $HGRCPATH $HGRCPATH.bak
  $ cat >> $HGRCPATH << EOF
  > [extensions]
  > logtoprocess=
  > foocommand=$TESTTMP/foocommand.py
  > [logtoprocess]
  > command=(echo 'logtoprocess command output:';
  >     echo "\$EVENT";
  >     echo "\$MSG1";
  >     echo "\$MSG2") > $TESTTMP/command.log
  > commandfinish=(echo 'logtoprocess commandfinish output:';
  >     echo "\$EVENT";
  >     echo "\$MSG1";
  >     echo "\$MSG2";
  >     echo "\$MSG3") > $TESTTMP/commandfinish.log
  > foo=(echo 'logtoprocess foo output:';
  >     echo "\$EVENT";
  >     echo "\$MSG1";
  >     echo "\$OPT_BAR") > $TESTTMP/foo.log
  > EOF

Running a command triggers both a ui.log('command') and a
ui.log('commandfinish') call. The foo command also uses ui.log.

Use sort to avoid ordering issues between the various processes we spawn:
  $ hg foo
  $ sleep 0.2
  $ cat $TESTTMP/command.log | sort
  
  command
  foo
  foo
  logtoprocess command output:

#if no-chg
  $ cat $TESTTMP/commandfinish.log | sort
  
  0
  commandfinish
  foo
  foo exited 0 after * seconds (glob)
  logtoprocess commandfinish output:
  $ cat $TESTTMP/foo.log | sort
  
  a message: spam
  foo
  logtoprocess foo output:
  spam
#endif

Confirm that logging blocked time catches stdio properly:
  $ cp $HGRCPATH.bak $HGRCPATH
  $ cat >> $HGRCPATH << EOF
  > [extensions]
  > logtoprocess=
  > pager=
  > [logtoprocess]
  > uiblocked=echo "\$EVENT stdio \$OPT_STDIO_BLOCKED ms command \$OPT_COMMAND_DURATION ms" > $TESTTMP/uiblocked.log
  > [ui]
  > logblockedtimes=True
  > EOF

  $ hg log
  $ sleep 0.2
  $ cat $TESTTMP/uiblocked.log
  uiblocked stdio [0-9]+.[0-9]* ms command [0-9]+.[0-9]* ms (re)

Try to confirm that pager wait on logtoprocess:

Add a script that wait on a file to appears for 5 seconds, if it sees it touch
another file or die after 5 seconds. If the scripts is awaited by hg, the
script will die after the timeout before we could touch the file and the
resulting file will not exists. If not, we will touch the file and see it.

  $ cat > $TESTTMP/wait-output.sh << EOF
  > #!/bin/sh
  > for i in \`$TESTDIR/seq.py 50\`; do
  >   if [ -f "$TESTTMP/wait-for-touched" ];
  >   then
  >     touch "$TESTTMP/touched";
  >     break;
  >   else
  >     sleep 0.1;
  >   fi
  > done
  > EOF
  $ chmod +x $TESTTMP/wait-output.sh

  $ cat >> $HGRCPATH << EOF
  > [extensions]
  > logtoprocess=
  > pager=
  > [logtoprocess]
  > commandfinish=$TESTTMP/wait-output.sh
  > EOF
  $ hg version -q --pager=always
  Mercurial Distributed SCM (version *) (glob)
  $ touch $TESTTMP/wait-for-touched
  $ sleep 0.2
  $ test -f $TESTTMP/touched && echo "SUCCESS Pager is not waiting on ltp" || echo "FAIL Pager is waiting on ltp"
  SUCCESS Pager is not waiting on ltp