view tests/test-logtoprocess.t @ 39270:37e56607cbb9

lfs: add a progress bar when searching for blobs to upload

The search itself can take an extreme amount of time if there are a lot of
revisions involved.  I've got a local repo that took 6 minutes to push 1850
commits, and 60% of that time was spent here (there are ~70K files):

     \ 58.1%  wrapper.py:     extractpointers      line 297:  pointers = extractpointers(...
       | 57.7%  wrapper.py:     pointersfromctx    line 352:  for p in pointersfromctx(ct...
       | 57.4%  wrapper.py:     pointerfromctx     line 397:  p = pointerfromctx(ctx, f, ...
         \ 38.7%  context.py:     __contains__     line 368:  if f not in ctx:
           | 38.7%  util.py:        __get__        line 82:  return key in self._manifest
           | 38.7%  context.py:     _manifest      line 1416:  result = self.func(obj)
           | 38.7%  manifest.py:    read           line 472:  return self._manifestctx.re...
             \ 25.6%  revlog.py:      revision     line 1562:  text = rl.revision(self._node)
               \ 12.8%  revlog.py:      _chunks    line 2217:  bins = self._chunks(chain, ...
                 | 12.0%  revlog.py:      decompressline 2112:  ladd(decomp(buffer(data, ch...
               \  7.8%  revlog.py:      checkhash  line 2232:  self.checkhash(text, node, ...
                 |  7.8%  revlog.py:      hash     line 2315:  if node != self.hash(text, ...
                 |  7.8%  revlog.py:      hash     line 2242:  return hash(text, p1, p2)
             \ 12.0%  manifest.py:    __init__     line 1565:  self._data = manifestdict(t...
         \ 16.8%  context.py:     filenode         line 378:  if not _islfs(fctx.filelog(...
           | 15.7%  util.py:        __get__        line 706:  return self._filelog
           | 14.8%  context.py:     _filelog       line 1416:  result = self.func(obj)
           | 14.8%  localrepo.py:   file           line 629:  return self._repo.file(self...
           | 14.8%  filelog.py:     __init__       line 1134:  return filelog.filelog(self...
           | 14.5%  revlog.py:      __init__       line 24:  censorable=True)

#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"
  > commandfinish=echo 'logtoprocess commandfinish output:';
  >     echo "\$EVENT";
  >     echo "\$MSG1";
  >     echo "\$MSG2";
  >     echo "\$MSG3"
  > foo=echo 'logtoprocess foo output:';
  >     echo "\$EVENT";
  >     echo "\$MSG1";
  >     echo "\$OPT_BAR"
  > 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 | cat | sort
  
  
  
   (chg !)
  0
  a message: spam
  command
  command (chg !)
  commandfinish
  foo
  foo
  foo
  foo
  foo exited 0 after * seconds (glob)
  logtoprocess command output:
  logtoprocess command output: (chg !)
  logtoprocess commandfinish output:
  logtoprocess foo output:
  serve --cmdserver chgunix * (glob) (chg !)
  serve --cmdserver chgunix * (glob) (chg !)
  spam

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"
  > [ui]
  > logblockedtimes=True
  > EOF

  $ hg log | cat
  uiblocked stdio [0-9]+.[0-9]* ms command [0-9]+.[0-9]* ms (re)