progress: add a changedelay to prevent parallel topics from flapping (issue2698)

When combined with the earlier change to make the progress object
truly a singleton, this prevents the progress bar swapping on 'hg
clone --pull' on a local filesystem.

Thanks to timeless for lots of debugging help at the Copenhagen sprint
to isolate the root cause of this and a first draft an idea that would
fix it.

hgext/progress.py

@@ -1,289 +1,302 b''
 # progress.py show progress bars for some actions
 #
 # Copyright (C) 2010 Augie Fackler <[e-mail]>
 #
 # This program is free software; you can redistribute it and/or modify it
 # under the terms of the GNU General Public License as published by the
 # Free Software Foundation; either version 2 of the License, or (at your
 # option) any later version.
 #
 # This program is distributed in the hope that it will be useful, but
 # WITHOUT ANY WARRANTY; without even the implied warranty of
 # MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General
 # Public License for more details.
 #
 # You should have received a copy of the GNU General Public License along
 # with this program; if not, write to the Free Software Foundation, Inc.,
 # 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
 
 """show progress bars for some actions
 
 This extension uses the progress information logged by hg commands
 to draw progress bars that are as informative as possible. Some progress
 bars only offer indeterminate information, while others have a definite
 end point.
 
 The following settings are available::
 
   [progress]
   delay = 3 # number of seconds (float) before showing the progress bar
+  changedelay = 1 # changedelay: minimum delay before showing a new topic.
+                  # If set to less than 3 * refresh, that value will
+                  # be used instead.
   refresh = 0.1 # time in seconds between refreshes of the progress bar
   format = topic bar number estimate # format of the progress bar
   width = <none> # if set, the maximum width of the progress information
                  # (that is, min(width, term width) will be used)
   clear-complete = True # clear the progress bar after it's done
   disable = False # if true, don't show a progress bar
   assume-tty = False # if true, ALWAYS show a progress bar, unless
                      # disable is given
 
 Valid entries for the format field are topic, bar, number, unit,
 estimate, speed, and item. item defaults to the last 20 characters of
 the item, but this can be changed by adding either ``-<num>`` which
 would take the last num characters, or ``+<num>`` for the first num
 characters.
 """
 
 import sys
 import time
 
 from mercurial import util
 from mercurial.i18n import _
 
 def spacejoin(*args):
     return ' '.join(s for s in args if s)
 
 def shouldprint(ui):
     return util.isatty(sys.stderr) or ui.configbool('progress', 'assume-tty')
 
 def fmtremaining(seconds):
     if seconds < 60:
         # i18n: format XX seconds as "XXs"
         return _("%02ds") % (seconds)
     minutes = seconds // 60
     if minutes < 60:
         seconds -= minutes * 60
         # i18n: format X minutes and YY seconds as "XmYYs"
         return _("%dm%02ds") % (minutes, seconds)
     # we're going to ignore seconds in this case
     minutes += 1
     hours = minutes // 60
     minutes -= hours * 60
     if hours < 30:
         # i18n: format X hours and YY minutes as "XhYYm"
         return _("%dh%02dm") % (hours, minutes)
     # we're going to ignore minutes in this case
     hours += 1
     days = hours // 24
     hours -= days * 24
     if days < 15:
         # i18n: format X days and YY hours as "XdYYh"
         return _("%dd%02dh") % (days, hours)
     # we're going to ignore hours in this case
     days += 1
     weeks = days // 7
     days -= weeks * 7
     if weeks < 55:
         # i18n: format X weeks and YY days as "XwYYd"
         return _("%dw%02dd") % (weeks, days)
     # we're going to ignore days and treat a year as 52 weeks
     weeks += 1
     years = weeks // 52
     weeks -= years * 52
     # i18n: format X years and YY weeks as "XyYYw"
     return _("%dy%02dw") % (years, weeks)
 
 class progbar(object):
     def __init__(self, ui):
         self.ui = ui
         self.resetstate()
 
     def resetstate(self):
         self.topics = []
         self.topicstates = {}
         self.starttimes = {}
         self.startvals = {}
         self.printed = False
         self.lastprint = time.time() + float(self.ui.config(
             'progress', 'delay', default=3))
+        self.lasttopic = None
         self.indetcount = 0
         self.refresh = float(self.ui.config(
             'progress', 'refresh', default=0.1))
+        self.changedelay = max(3 * self.refresh,
+                               float(self.ui.config(
+                                   'progress', 'changedelay', default=1)))
         self.order = self.ui.configlist(
             'progress', 'format',
             default=['topic', 'bar', 'number', 'estimate'])
 
     def show(self, now, topic, pos, item, unit, total):
         if not shouldprint(self.ui):
             return
         termwidth = self.width()
         self.printed = True
         head = ''
         needprogress = False
         tail = ''
         for indicator in self.order:
             add = ''
             if indicator == 'topic':
                 add = topic
             elif indicator == 'number':
                 if total:
                     add = ('% ' + str(len(str(total))) +
                            's/%s') % (pos, total)
                 else:
                     add = str(pos)
             elif indicator.startswith('item') and item:
                 slice = 'end'
                 if '-' in indicator:
                     wid = int(indicator.split('-')[1])
                 elif '+' in indicator:
                     slice = 'beginning'
                     wid = int(indicator.split('+')[1])
                 else:
                     wid = 20
                 if slice == 'end':
                     add = item[-wid:]
                 else:
                     add = item[:wid]
                 add += (wid - len(add)) * ' '
             elif indicator == 'bar':
                 add = ''
                 needprogress = True
             elif indicator == 'unit' and unit:
                 add = unit
             elif indicator == 'estimate':
                 add = self.estimate(topic, pos, total, now)
             elif indicator == 'speed':
                 add = self.speed(topic, pos, unit, now)
             if not needprogress:
                 head = spacejoin(head, add)
             else:
                 tail = spacejoin(tail, add)
         if needprogress:
             used = 0
             if head:
                 used += len(head) + 1
             if tail:
                 used += len(tail) + 1
             progwidth = termwidth - used - 3
             if total and pos <= total:
                 amt = pos * progwidth // total
                 bar = '=' * (amt - 1)
                 if amt > 0:
                     bar += '>'
                 bar += ' ' * (progwidth - amt)
             else:
                 progwidth -= 3
                 self.indetcount += 1
                 # mod the count by twice the width so we can make the
                 # cursor bounce between the right and left sides
                 amt = self.indetcount % (2 * progwidth)
                 amt -= progwidth
                 bar = (' ' * int(progwidth - abs(amt)) + '<=>' +
                        ' ' * int(abs(amt)))
             prog = ''.join(('[', bar , ']'))
             out = spacejoin(head, prog, tail)
         else:
             out = spacejoin(head, tail)
         sys.stderr.write('\r' + out[:termwidth])
+        self.lasttopic = topic
         sys.stderr.flush()
 
     def clear(self):
         if not shouldprint(self.ui):
             return
         sys.stderr.write('\r%s\r' % (' ' * self.width()))
 
     def complete(self):
         if not shouldprint(self.ui):
             return
         if self.ui.configbool('progress', 'clear-complete', default=True):
             self.clear()
         else:
             sys.stderr.write('\n')
         sys.stderr.flush()
 
     def width(self):
         tw = self.ui.termwidth()
         return min(int(self.ui.config('progress', 'width', default=tw)), tw)
 
     def estimate(self, topic, pos, total, now):
         if total is None:
             return ''
         initialpos = self.startvals[topic]
         target = total - initialpos
         delta = pos - initialpos
         if delta > 0:
             elapsed = now - self.starttimes[topic]
             if elapsed > float(
                 self.ui.config('progress', 'estimate', default=2)):
                 seconds = (elapsed * (target - delta)) // delta + 1
                 return fmtremaining(seconds)
         return ''
 
     def speed(self, topic, pos, unit, now):
         initialpos = self.startvals[topic]
         delta = pos - initialpos
         elapsed = now - self.starttimes[topic]
         if elapsed > float(
             self.ui.config('progress', 'estimate', default=2)):
             return _('%d %s/sec') % (delta / elapsed, unit)
         return ''
 
     def progress(self, topic, pos, item='', unit='', total=None):
         now = time.time()
         if pos is None:
             self.starttimes.pop(topic, None)
             self.startvals.pop(topic, None)
             self.topicstates.pop(topic, None)
             # reset the progress bar if this is the outermost topic
             if self.topics and self.topics[0] == topic and self.printed:
                 self.complete()
                 self.resetstate()
             # truncate the list of topics assuming all topics within
             # this one are also closed
             if topic in self.topics:
               self.topics = self.topics[:self.topics.index(topic)]
         else:
             if topic not in self.topics:
                 self.starttimes[topic] = now
                 self.startvals[topic] = pos
                 self.topics.append(topic)
             self.topicstates[topic] = pos, item, unit, total
             if now - self.lastprint >= self.refresh and self.topics:
-                self.lastprint = now
-                self.show(now, topic, *self.topicstates[topic])
+                if (self.lasttopic is None # first time we printed
+                    # not a topic change
+                    or topic == self.lasttopic
+                    # it's been long enough we should print anyway
+                    or now - self.lastprint >= self.changedelay):
+                    self.lastprint = now
+                    self.show(now, topic, *self.topicstates[topic])
 
 _singleton = None
 
 def uisetup(ui):
     global _singleton
     class progressui(ui.__class__):
         _progbar = None
 
         def progress(self, *args, **opts):
             self._progbar.progress(*args, **opts)
             return super(progressui, self).progress(*args, **opts)
 
         def write(self, *args, **opts):
             if self._progbar.printed:
                 self._progbar.clear()
             return super(progressui, self).write(*args, **opts)
 
         def write_err(self, *args, **opts):
             if self._progbar.printed:
                 self._progbar.clear()
             return super(progressui, self).write_err(*args, **opts)
 
     # Apps that derive a class from ui.ui() can use
     # setconfig('progress', 'disable', 'True') to disable this extension
     if ui.configbool('progress', 'disable'):
         return
     if shouldprint(ui) and not ui.debugflag and not ui.quiet:
         ui.__class__ = progressui
         # we instantiate one globally shared progress bar to avoid
         # competing progress bars when multiple UI objects get created
         if not progressui._progbar:
             if _singleton is None:
                 _singleton = progbar(ui)
             progressui._progbar = _singleton
 
 def reposetup(ui, repo):
     uisetup(repo.ui)

tests/test-convert-svn-move.t

@@ -1,248 +1,249 b''
 
   $ "$TESTDIR/hghave" svn svn-bindings || exit 80
 
   $ fixpath()
   > {
   >     tr '\\' /
   > }
   $ cat >> $HGRCPATH <<EOF
   > [extensions]
   > convert = 
   > graphlog =
   > EOF
 
   $ svnadmin create svn-repo
   $ svnadmin load -q svn-repo < "$TESTDIR/svn/move.svndump"
   $ svnpath=`pwd | fixpath`
 
 SVN wants all paths to start with a slash. Unfortunately,
 Windows ones don't. Handle that.
 
   $ expr "$svnpath" : "\/" > /dev/null
   > if [ $? -ne 0 ]; then
   >   svnpath="/$svnpath"
   > fi
   > svnurl="file://$svnpath/svn-repo"
 
 Convert trunk and branches
 
   $ hg convert --datesort "$svnurl"/subproject A-hg
   initializing destination A-hg repository
   scanning source...
   sorting...
   converting...
   13 createtrunk
   12 moved1
   11 moved1
   10 moved2
   9 changeb and rm d2
   8 changeb and rm d2
   7 moved1again
   6 moved1again
   5 copyfilefrompast
   4 copydirfrompast
   3 add d3
   2 copy dir and remove subdir
   1 add d4old
   0 rename d4old into d4new
 
   $ cd A-hg
   $ hg glog --template '{rev} {desc|firstline} files: {files}\n'
   o  13 rename d4old into d4new files: d4new/g d4old/g
   |
   o  12 add d4old files: d4old/g
   |
   o  11 copy dir and remove subdir files: d3/d31/e d4/d31/e d4/f
   |
   o  10 add d3 files: d3/d31/e d3/f
   |
   o  9 copydirfrompast files: d2/d
   |
   o  8 copyfilefrompast files: d
   |
   o  7 moved1again files: d1/b d1/c
   |
   | o  6 moved1again files:
   | |
   o |  5 changeb and rm d2 files: d1/b d2/d
   | |
   | o  4 changeb and rm d2 files: b
   | |
   o |  3 moved2 files: d2/d
   | |
   o |  2 moved1 files: d1/b d1/c
   | |
   | o  1 moved1 files: b c
   |
   o  0 createtrunk files:
   
 
 Check move copy records
 
   $ hg st --rev 12:13 --copies
   A d4new/g
     d4old/g
   R d4old/g
 
 Check branches
 
   $ hg branches
   default                       13:* (glob)
   d1                             6:* (glob)
   $ cd ..
 
   $ mkdir test-replace
   $ cd test-replace
   $ svnadmin create svn-repo
   $ svnadmin load -q svn-repo < "$TESTDIR/svn/replace.svndump"
 
 Convert files being replaced by directories
 
   $ hg convert svn-repo hg-repo
   initializing destination hg-repo repository
   scanning source...
   sorting...
   converting...
   6 initial
   5 clobber symlink
   4 clobber1
   3 clobber2
   2 adddb
   1 branch
   0 clobberdir
 
   $ cd hg-repo
 
 Manifest before
 
   $ hg -v manifest -r 1
   644   a
   644   d/b
   644   d2/a
   644 @ dlink
   644 @ dlink2
   644   dlink3
 
 Manifest after clobber1
 
   $ hg -v manifest -r 2
   644   a/b
   644   d/b
   644   d2/a
   644   dlink/b
   644 @ dlink2
   644   dlink3
 
 Manifest after clobber2
 
   $ hg -v manifest -r 3
   644   a/b
   644   d/b
   644   d2/a
   644   dlink/b
   644 @ dlink2
   644 @ dlink3
 
 Manifest after clobberdir
 
   $ hg -v manifest -r 6
   644   a/b
   644   d/b
   644   d2/a
   644   d2/c
   644   dlink/b
   644 @ dlink2
   644 @ dlink3
 
 Try updating
 
   $ hg up -qC default
   $ cd ..
 
 Test convert progress bar'
 
   $ cat >> $HGRCPATH <<EOF
   > [extensions]
   > progress = 
   > [progress]
   > assume-tty = 1
   > delay = 0
+  > changedelay = 0
   > format = topic bar number
   > refresh = 0
   > width = 60
   > EOF
 
   $ hg convert svn-repo hg-progress 2>&1 | $TESTDIR/filtercr.py
   
   scanning [ <=>                                          ] 1
   scanning [  <=>                                         ] 2
   scanning [   <=>                                        ] 3
   scanning [    <=>                                       ] 4
   scanning [     <=>                                      ] 5
   scanning [      <=>                                     ] 6
   scanning [       <=>                                    ] 7
                                                               
   converting [                                          ] 0/7
   getting files [=====>                                 ] 1/6
   getting files [============>                          ] 2/6
   getting files [==================>                    ] 3/6
   getting files [=========================>             ] 4/6
   getting files [===============================>       ] 5/6
   getting files [======================================>] 6/6
                                                               
   converting [=====>                                    ] 1/7
   scanning paths [                                      ] 0/1
   getting files [======================================>] 1/1
                                                               
   converting [===========>                              ] 2/7
   scanning paths [                                      ] 0/2
   scanning paths [==================>                   ] 1/2
   getting files [========>                              ] 1/4
   getting files [==================>                    ] 2/4
   getting files [============================>          ] 3/4
   getting files [======================================>] 4/4
                                                               
   converting [=================>                        ] 3/7
   scanning paths [                                      ] 0/1
   getting files [======================================>] 1/1
                                                               
   converting [=======================>                  ] 4/7
   scanning paths [                                      ] 0/1
   getting files [======================================>] 1/1
                                                               
   converting [=============================>            ] 5/7
   scanning paths [                                      ] 0/3
   scanning paths [===========>                          ] 1/3
   scanning paths [========================>             ] 2/3
   getting files [===>                                   ] 1/8
   getting files [========>                              ] 2/8
   getting files [=============>                         ] 3/8
   getting files [==================>                    ] 4/8
   getting files [=======================>               ] 5/8
   getting files [============================>          ] 6/8
   getting files [=================================>     ] 7/8
   getting files [======================================>] 8/8
                                                               
   converting [===================================>      ] 6/7
   scanning paths [                                      ] 0/1
   getting files [===>                                   ] 1/8
   getting files [========>                              ] 2/8
   getting files [=============>                         ] 3/8
   getting files [==================>                    ] 4/8
   getting files [=======================>               ] 5/8
   getting files [============================>          ] 6/8
   getting files [=================================>     ] 7/8
   getting files [======================================>] 8/8
                                                               
   initializing destination hg-progress repository
   scanning source...
   sorting...
   converting...
   6 initial
   5 clobber symlink
   4 clobber1
   3 clobber2
   2 adddb
   1 branch
   0 clobberdir
   

tests/test-progress.t

@@ -1,166 +1,214 b''
 
   $ 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')],
+  >     "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)