tests/test-progress.t

mdiff: speed up showfunc for large diffs

This addresses the following issues with showfunc:

- Silly usage of regular expressions.
- Doing str.rstrip() needlessly in an inner loop.
- Doing catastrophic backtracking when trying to find a function line.

Finding function text is now at worst O(n lines in the old file), and
at best close to O(n hunks).

Given a diff like this[1]:

 src/main/antlr3/uk/ac/cam/ch/wwmm/pregenerated/ChemicalChunker.g        |      4 +-
 src/main/java/uk/ac/cam/ch/wwmm/pregenerated/ChemicalChunkerLexer.java  |      2 +-
 src/main/java/uk/ac/cam/ch/wwmm/pregenerated/ChemicalChunkerParser.java |  29189 +++++----
 3 files changed, 14741 insertions(+), 14454 deletions(-)

[1]: https://bitbucket.org/wwmm/chemicaltagger/changeset/d2bfbaecd4fc/raw

Without this change, hg log --stat --config diff.showfunc=1 takes an
absurdly long time to complete:

   CallCount    Recursive    Total(ms)   Inline(ms) module:lineno(function)
       32813            0     80.3546     40.6086   mercurial.mdiff:160(yieldhunk)
   [phone]            0     25.7227     25.7227   +<method 'match' of '_sre.SRE_Pattern' objects>
   [phone]            0     14.0221     14.0221   +<method 'rstrip' of 'str' objects>
       +1809            0      0.0009      0.0009   +mercurial.mdiff:148(contextend)
       +1809            0      0.0003      0.0003   +<len>
    65062746            0     25.7227     25.7227   <method 'match' of '_sre.SRE_Pattern' objects>
    65062763            0     14.0221     14.0221   <method 'rstrip' of 'str' objects>
         543            0      0.1631      0.1631   <zlib.decompress>
           3            0      0.0505      0.0505   <mercurial.bdiff.blocks>
       31007            0     80.4564      0.0477   mercurial.mdiff:147(_unidiff)
      +32813            0     80.3546     40.6086   +mercurial.mdiff:160(yieldhunk)
          +3            0      0.0505      0.0505   +<mercurial.bdiff.blocks>
       +3618            0      0.0022      0.0022   +mercurial.mdiff:154(contextstart)
       +5427            0      0.0013      0.0013   +<len>
          +3            0      0.0001      0.0000   +re:188(compile)
           1            0     80.8381      0.0322   mercurial.patch:1777(diffstatdata)
     +107499            0      0.0235      0.0235   +<method 'startswith' of 'str' objects>
      +31014            0     80.7820      0.0071   +mercurial.util:1284(iterlines)
          +3            0      0.0000      0.0000   +<method 'search' of '_sre.SRE_Pattern' objects>
          +4            0      0.0000      0.0000   +mercurial.patch:1783(addresult)
          +3            0      0.0000      0.0000   +<method 'group' of '_sre.SRE_Match' objects>
           6            0      0.0444      0.0283   mercurial.mdiff:12(splitnewlines)
          +6            0      0.0160      0.0160   +<method 'split' of 'str' objects>
          32            0      0.0246      0.0246   <method 'update' of '_hashlib.HASH' objects>
          11            0      0.0236      0.0236   <method 'read' of 'file' objects>
Time: real 80.880 secs (user 80.200+0.000 sys 0.380+0.000)

With this change, it's almost as fast as not using showfunc at all:

   CallCount    Recursive    Total(ms)   Inline(ms) module:lineno(function)
         543            0      0.1699      0.1699   <zlib.decompress>
           3            0      0.0501      0.0501   <mercurial.bdiff.blocks>
       32813            0      0.0415      0.0348   mercurial.mdiff:161(yieldhunk)
      +70837            0      0.0058      0.0058   +<method 'isalnum' of 'str' objects>
       +1809            0      0.0006      0.0006   +mercurial.mdiff:148(contextend)
       +1809            0      0.0002      0.0002   +<len>
           1            0      0.4879      0.0310   mercurial.patch:1777(diffstatdata)
     +107499            0      0.0230      0.0230   +<method 'startswith' of 'str' objects>
      +31014            0      0.4335      0.0065   +mercurial.util:1284(iterlines)
          +3            0      0.0000      0.0000   +<method 'search' of '_sre.SRE_Pattern' objects>
          +4            0      0.0000      0.0000   +mercurial.patch:1783(addresult)
          +1            0      0.0004      0.0000   +re:188(compile)
          32            0      0.0293      0.0293   <method 'update' of '_hashlib.HASH' objects>
           6            0      0.0427      0.0279   mercurial.mdiff:12(splitnewlines)
          +6            0      0.0147      0.0147   +<method 'split' of 'str' objects>
       31007            0      0.1169      0.0235   mercurial.mdiff:147(_unidiff)
          +3            0      0.0501      0.0501   +<mercurial.bdiff.blocks>
      +32813            0      0.0415      0.0348   +mercurial.mdiff:161(yieldhunk)
       +3618            0      0.0012      0.0012   +mercurial.mdiff:154(contextstart)
       +5427            0      0.0006      0.0006   +<len>
      107597            0      0.0230      0.0230   <method 'startswith' of 'str' objects>
          16            0      0.0213      0.0213   <mercurial.mpatch.patches>
         194            0      0.0149      0.0149   <method 'split' of 'str' objects>
Time: real 0.530 secs (user 0.450+0.000 sys 0.070+0.000)

  $ cat > loop.py <<EOF
  > from mercurial import commands
  > 
  > def loop(ui, loops, **opts):
  >     loops = int(loops)
  >     total = None
  >     if loops >= 0:
  >         total = loops
  >     if opts.get('total', None):
  >         total = int(opts.get('total'))
  >     nested = False
  >     if opts.get('nested', None):
  >         nested = True
  >     loops = abs(loops)
  > 
  >     for i in range(loops):
  >         ui.progress('loop', i, 'loop.%d' % i, 'loopnum', total)
  >         if opts.get('parallel'):
  >             ui.progress('other', i, 'other.%d' % i, 'othernum', total)
  >         if nested:
  >             for j in range(2):
  >                 ui.progress('nested', j, 'nested.%d' % j, 'nestnum', 2)
  >             ui.progress('nested', None, 'nested.done', 'nestnum', 2)
  >     ui.progress('loop', None, 'loop.done', 'loopnum', total)
  > 
  > commands.norepo += " loop"
  > 
  > cmdtable = {
  >     "loop": (loop, [('', 'total', '', 'override for total'),
  >                     ('', 'nested', False, 'show nested results'),
  >                     ('', 'parallel', False, 'show parallel sets of results'),
  >                    ],
  >              'hg loop LOOPS'),
  > }
  > EOF

  $ echo "[extensions]" >> $HGRCPATH
  $ echo "progress=" >> $HGRCPATH
  $ echo "loop=`pwd`/loop.py" >> $HGRCPATH
  $ echo "[progress]" >> $HGRCPATH
  $ echo  "format = topic bar number" >> $HGRCPATH
  $ echo "assume-tty=1" >> $HGRCPATH
  $ echo "width=60" >> $HGRCPATH

test default params, display nothing because of delay

  $ hg -y loop 3 2>&1 | $TESTDIR/filtercr.py
  
  $ echo "delay=0" >> $HGRCPATH
  $ echo "refresh=0" >> $HGRCPATH

test with delay=0, refresh=0

  $ hg -y loop 3 2>&1 | $TESTDIR/filtercr.py
  
  loop [                                                ] 0/3
  loop [===============>                                ] 1/3
  loop [===============================>                ] 2/3
                                                              \r (esc)


test nested short-lived topics (which shouldn't display with nestdelay):

  $ hg -y loop 3 --nested 2>&1 | \
  > python $TESTDIR/filtercr.py
  
  loop [                                                ] 0/3
  loop [===============>                                ] 1/3
  loop [===============================>                ] 2/3
                                                              \r (esc)


  $ hg --config progress.changedelay=0 -y loop 3 --nested 2>&1 | \
  > python $TESTDIR/filtercr.py
  
  loop [                                                ] 0/3
  nested [                                              ] 0/2
  nested [======================>                       ] 1/2
  loop [===============>                                ] 1/3
  nested [                                              ] 0/2
  nested [======================>                       ] 1/2
  loop [===============================>                ] 2/3
  nested [                                              ] 0/2
  nested [======================>                       ] 1/2
                                                              \r (esc)


test two topics being printed in parallel (as when we're doing a local
--pull clone, where you get the unbundle and bundle progress at the
same time):
  $ hg loop 3 --parallel 2>&1 | python $TESTDIR/filtercr.py
  
  loop [                                                ] 0/3
  loop [===============>                                ] 1/3
  loop [===============================>                ] 2/3
                                                              \r (esc)
test refresh is taken in account

  $ hg -y --config progress.refresh=100 loop 3 2>&1 | $TESTDIR/filtercr.py
  

test format options 1

  $ hg -y --config 'progress.format=number topic item+2' loop 2 2>&1 \
  > | $TESTDIR/filtercr.py
  
  0/2 loop lo
  1/2 loop lo
                                                              \r (esc)

test format options 2

  $ hg -y --config 'progress.format=number item-3 bar' loop 2 2>&1 \
  > | $TESTDIR/filtercr.py
  
  0/2 p.0 [                                                 ]
  1/2 p.1 [=======================>                         ]
                                                              \r (esc)

test format options and indeterminate progress

  $ hg -y --config 'progress.format=number item bar' loop -- -2 2>&1 \
  > | $TESTDIR/filtercr.py
  
  0 loop.0               [ <=>                              ]
  1 loop.1               [  <=>                             ]
                                                              \r (esc)

make sure things don't fall over if count > total

  $ hg -y loop --total 4 6 2>&1 | $TESTDIR/filtercr.py
  
  loop [                                                ] 0/4
  loop [===========>                                    ] 1/4
  loop [=======================>                        ] 2/4
  loop [===================================>            ] 3/4
  loop [===============================================>] 4/4
  loop [ <=>                                            ] 5/4
                                                              \r (esc)

test immediate progress completion

  $ hg -y loop 0 2>&1 | $TESTDIR/filtercr.py
  

test delay time estimates

  $ cat > mocktime.py <<EOF
  > import os
  > import time
  > 
  > class mocktime(object):
  >     def __init__(self, increment):
  >         self.time = 0
  >         self.increment = increment
  >     def __call__(self):
  >         self.time += self.increment
  >         return self.time
  > 
  > def uisetup(ui):
  >     time.time = mocktime(int(os.environ.get('MOCKTIME', '11')))
  > EOF

  $ echo "[extensions]" > $HGRCPATH
  $ echo "mocktime=`pwd`/mocktime.py" >> $HGRCPATH
  $ echo "progress=" >> $HGRCPATH
  $ echo "loop=`pwd`/loop.py" >> $HGRCPATH
  $ echo "[progress]" >> $HGRCPATH
  $ echo "assume-tty=1" >> $HGRCPATH
  $ echo "delay=25" >> $HGRCPATH
  $ echo "width=60" >> $HGRCPATH

  $ hg -y loop 8 2>&1 | python $TESTDIR/filtercr.py
  
  loop [=========>                                ] 2/8 1m07s
  loop [===============>                            ] 3/8 56s
  loop [=====================>                      ] 4/8 45s
  loop [==========================>                 ] 5/8 34s
  loop [================================>           ] 6/8 23s
  loop [=====================================>      ] 7/8 12s
                                                              \r (esc)

  $ MOCKTIME=10000 hg -y loop 4 2>&1 | python $TESTDIR/filtercr.py
  
  loop [                                                ] 0/4
  loop [=========>                                ] 1/4 8h21m
  loop [====================>                     ] 2/4 5h34m
  loop [==============================>           ] 3/4 2h47m
                                                              \r (esc)

  $ MOCKTIME=1000000 hg -y loop 4 2>&1 | python $TESTDIR/filtercr.py
  
  loop [                                                ] 0/4
  loop [=========>                                ] 1/4 5w00d
  loop [====================>                     ] 2/4 3w03d
  loop [=============================>           ] 3/4 11d14h
                                                              \r (esc)


  $ MOCKTIME=14000000 hg -y loop 4 2>&1 | python $TESTDIR/filtercr.py
  
  loop [                                                ] 0/4
  loop [=========>                                ] 1/4 1y18w
  loop [===================>                     ] 2/4 46w03d
  loop [=============================>           ] 3/4 23w02d
                                                              \r (esc)

Time estimates should not fail when there's no end point:
  $ hg -y loop -- -4 2>&1 | python $TESTDIR/filtercr.py
  
  loop [ <=>                                              ] 2
  loop [  <=>                                             ] 3
                                                              \r (esc)