tests/test-blackbox.t

revlog: use existing file handle when reading during _addrevision

_addrevision() may need to read from revlogs as part of computing
deltas. Previously, we would flush existing file handles and open
a new, short-lived file handle to perform the reading.

If we have an existing file handle, it seems logical to reuse it
for reading instead of opening a new file handle. This patch
makes that the new behavior.

After this patch, revlog files are only reopened when adding
revisions if the revlog is switched from inline to non-inline.

On Linux when unbundling a bundle of the mozilla-central repo, this
patch has the following impact on system call counts:

Call     Before     After       Delta
write    827,639    673,390   -154,249
open     700,103    684,089    -16,014
read      74,489     74,489          0
fstat    493,924    461,896    -32,028
close    249,131    233,117    -16,014
stat     242,001    242,001          0
lstat     18,676     18,676          0
lseek     20,268     20,268          0
ioctl     14,652     13,173     -1,479
TOTAL  3,180,758  2,930,679   -250,079

It's worth noting that many of the open() calls fail due to missing
files. That's why there are many more open() calls than close().

Despite the significant system call reduction, this change does not
seem to have a significant performance impact on Linux.

On Windows 10 (not a VM, on a SSD), this patch appears to reduce
unbundle time for mozilla-central from ~960s to ~920s. This isn't
as significant as I was hoping. But a decrease it is nonetheless.
Still, Windows unbundle performance is still >2x slower than Linux.

Despite the lack of significant gains, fewer system calls is fewer
system calls. If nothing else, this will narrow the focus of potential
areas to optimize in the future.

setup
  $ cat >> $HGRCPATH <<EOF
  > [extensions]
  > blackbox=
  > mock=$TESTDIR/mockblackbox.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 (glob)
  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 5
  1970/01/01 00:00:00 bob (*)> pull (glob)
  1970/01/01 00:00:00 bob (*)> updated served branch cache in ?.???? seconds (glob)
  1970/01/01 00:00:00 bob (*)> wrote served branch cache with 1 labels and 2 nodes (glob)
  1970/01/01 00:00:00 bob (*)> 1 incoming changes - new heads: d02f48003e62 (glob)
  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 5
  1970/01/01 00:00:00 bob (*)> strip tip (glob)
  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 (*)> updated base branch cache in ?.???? seconds (glob)
  1970/01/01 00:00:00 bob (*)> wrote base branch cache with 1 labels and 2 nodes (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
  1 files updated, 0 files merged, 0 files removed, 0 files unresolved
  hooked
  $ hg blackbox -l 5
  1970/01/01 00:00:00 bob (*)> update (glob)
  1970/01/01 00:00:00 bob (*)> writing .hg/cache/tags2-visible with 0 tags (glob)
  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 ..