view tests/test-logtoprocess.t @ 43198:c16fe77e340a

pathcopies: give up any optimization based on `introrev` Between 8a0136f69027 and d98fb3f42f33, we sped up the search for the introduction revision during path copies. However, further checking show that finding the introduction revision is still expensive and that we are better off without it. So we simply drop it and only rely on the linkrev optimisation. I ran `perfpathcopies` on 6989 pair of revision in the pypy repository (`hg perfhelper-pathcopies`. The result is massively in favor of dropping this condition. The result of the copy tracing are unchanged. Attempt to use a smaller changes preserving linkrev usage were unsuccessful, it can return wrong result. The following changesets broke test-mv-cp-st-diff.t - if not f.isintroducedafter(limit): + if limit >= 0 and f.linkrev() < limit: return None Here are various numbers (before this changeset/after this changesets) source destination before after saved-time ratio worth cases e66f24650daf 695dfb0f493b 1.062843 1.246369 -0.183526 1.172675 c979853a3b6a 8d60fe293e79 1.036985 1.196414 -0.159429 1.153743 22349fa2fc33 fbb1c9fd86c0 0.879926 1.038682 -0.158756 1.180420 682b98f3e672 a4878080a536 0.909952 1.063801 -0.153849 1.169074 5adabc9b9848 920958a93997 0.993622 1.147452 -0.153830 1.154817 worse 1% dbfbfcf077e9 aea8f2fd3593 1.016595 1.082999 -0.066404 1.065320 worse 5% c95f1ced15f2 7d29d5e39734 0.453694 0.471156 -0.017462 1.038488 worse 10% 3e144ed1d5b7 2aef0e942480 0.035140 0.037535 -0.002395 1.068156 worse 25% 321fc60db035 801748ba582a 0.009267 0.009325 -0.000058 1.006259 median 2088ce763fc2 e6991321d78b 0.000665 0.000651 0.000014 0.978947 best 25% 915631a97de6 385b31354be6 0.040743 0.040363 0.000380 0.990673 best 10% ad495c36a765 19c10384d3e7 0.431658 0.411490 0.020168 0.953278 best 5% d13ae7d283ae 813c99f810ac 1.141404 1.075346 0.066058 0.942126 best 1% 81593cb4a496 99ae11866969 1.833297 0.063823 1.769474 0.034813 best cases c3b14617fbd7 743a0fcaa4eb 1101.811740 2.735970 1099.075770 0.002483 c3b14617fbd7 9ba6ab77fd29 1116.753953 2.800729 1113.953224 0.002508 058b99d6e81f 57e249b7a3ea 1246.128485 3.042762 1243.085723 0.002442 9a8c361aab49 0354a250d371 1253.111894 3.085796 1250.026098 0.002463 442dbbc53c68 3ec1002a818c 1261.786294 3.138607 1258.647687 0.002487 As one can see, the average case is not really impacted. However, the worth case we get after this changeset are much better than the one we had before it. We have 30 pairs where improvements are above 10 minutes. This reflect in the combined time for all pairs before: 26256s after: 1300s (-95%) If we remove these pathological 30 cases, we still see a significant improvements: before: 1631s after: 1245s (-24%)
author Pierre-Yves David <pierre-yves.david@octobus.net>
date Thu, 10 Oct 2019 03:49:33 +0200
parents 44378796c5e5
children 42d2b31cee0b
line wrap: on
line source

#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(b'logtoprocess', b'foo',
  >     default=None,
  > )
  > @command(b'foobar', [])
  > def foo(ui, repo):
  >     ui.log(b'foo', b'a message: %s\n', b'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") > $TESTTMP/command.log
  > commandfinish=(echo 'logtoprocess commandfinish output:';
  >     echo "\$EVENT";
  >     echo "\$MSG1";
  >     echo "canonical: \$OPT_CANONICAL_COMMAND") > $TESTTMP/commandfinish.log
  > foo=(echo 'logtoprocess foo output:';
  >     echo "\$EVENT";
  >     echo "\$MSG1") > $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 fooba
  $ sleep 1
  $ cat $TESTTMP/command.log | sort
  
  command
  fooba
  logtoprocess command output:

#if no-chg
  $ cat $TESTTMP/commandfinish.log | sort
  
  canonical: foobar
  commandfinish
  fooba exited 0 after * seconds (glob)
  logtoprocess commandfinish output:
  $ cat $TESTTMP/foo.log | sort
  
  a message: spam
  foo
  logtoprocess foo output:
#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 1
  $ 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 >> fakepager.py <<EOF
  > import sys
  > printed = False
  > for line in sys.stdin:
  >     sys.stdout.write(line)
  >     printed = True
  > if not printed:
  >     sys.stdout.write('paged empty output!\n')
  > EOF

  $ 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=
  > [pager]
  > pager = "$PYTHON" $TESTTMP/fakepager.py
  > [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