sync: Display total elapsed fetch time

Give users an indication that `repo sync` isn't stuck if taking a long
time to fetch.

Bug: https://crbug.com/gerrit/11293
Change-Id: Iccdaec918f86c9cc2db5dc12f9e3eef7ad0bcbda
Reviewed-on: https://gerrit-review.googlesource.com/c/git-repo/+/371414
Tested-by: Gavin Mak <gavinmak@google.com>
Reviewed-by: Josip Sokcevic <sokcevic@google.com>
Reviewed-by: Joanna Wang <jojwang@google.com>
Commit-Queue: Gavin Mak <gavinmak@google.com>

progress.py

@@ -14,7 +14,13 @@
 
 import os
 import sys
-from time import time
+import time
+
+try:
+    import threading as _threading
+except ImportError:
+    import dummy_threading as _threading
+
 from repo_trace import IsTraceToStderr
 
 _NOT_TTY = not os.isatty(2)
@@ -30,14 +36,20 @@ CSI_ERASE_LINE = "\x1b[2K"
 CSI_ERASE_LINE_AFTER = "\x1b[K"
 
 
+def convert_to_hms(total):
+    """Converts a period of seconds to hours, minutes, and seconds."""
+    hours, rem = divmod(total, 3600)
+    mins, secs = divmod(rem, 60)
+    return int(hours), int(mins), secs
+
+
 def duration_str(total):
     """A less noisy timedelta.__str__.
 
     The default timedelta stringification contains a lot of leading zeros and
     uses microsecond resolution.  This makes for noisy output.
     """
-    hours, rem = divmod(total, 3600)
-    mins, secs = divmod(rem, 60)
+    hours, mins, secs = convert_to_hms(total)
     ret = "%.3fs" % (secs,)
     if mins:
         ret = "%im%s" % (mins, ret)
@@ -46,6 +58,24 @@ def duration_str(total):
     return ret
 
 
+def elapsed_str(total):
+    """Returns seconds in the format [H:]MM:SS.
+
+    Does not display a leading zero for minutes if under 10 minutes. This should
+    be used when displaying elapsed time in a progress indicator.
+    """
+    hours, mins, secs = convert_to_hms(total)
+    ret = f"{int(secs):>02d}"
+    if total >= 3600:
+        # Show leading zeroes if over an hour.
+        ret = f"{mins:>02d}:{ret}"
+    else:
+        ret = f"{mins}:{ret}"
+    if hours:
+        ret = f"{hours}:{ret}"
+    return ret
+
+
 class Progress(object):
     def __init__(
         self,
@@ -55,11 +85,12 @@ class Progress(object):
         print_newline=False,
         delay=True,
         quiet=False,
+        show_elapsed=False,
     ):
         self._title = title
         self._total = total
         self._done = 0
-        self._start = time()
+        self._start = time.time()
         self._show = not delay
         self._units = units
         self._print_newline = print_newline
@@ -67,12 +98,30 @@ class Progress(object):
         self._show_jobs = False
         self._active = 0
 
+        # Save the last message for displaying on refresh.
+        self._last_msg = None
+        self._show_elapsed = show_elapsed
+        self._update_event = _threading.Event()
+        self._update_thread = _threading.Thread(
+            target=self._update_loop,
+        )
+        self._update_thread.daemon = True
+
         # When quiet, never show any output.  It's a bit hacky, but reusing the
         # existing logic that delays initial output keeps the rest of the class
         # clean.  Basically we set the start time to years in the future.
         if quiet:
             self._show = False
             self._start += 2**32
+        elif show_elapsed:
+            self._update_thread.start()
+
+    def _update_loop(self):
+        while True:
+            if self._update_event.is_set():
+                return
+            self.update(inc=0, msg=self._last_msg)
+            time.sleep(1)
 
     def start(self, name):
         self._active += 1
@@ -86,12 +135,14 @@ class Progress(object):
 
     def update(self, inc=1, msg=""):
         self._done += inc
+        self._last_msg = msg
 
         if _NOT_TTY or IsTraceToStderr():
             return
 
+        elapsed_sec = time.time() - self._start
         if not self._show:
-            if 0.5 <= time() - self._start:
+            if 0.5 <= elapsed_sec:
                 self._show = True
             else:
                 return
@@ -110,6 +161,10 @@ class Progress(object):
                 )
             else:
                 jobs = ""
+            if self._show_elapsed:
+                elapsed = f" {elapsed_str(elapsed_sec)} |"
+            else:
+                elapsed = ""
             sys.stderr.write(
                 "\r%s: %2d%% %s(%d%s/%d%s)%s %s%s%s"
                 % (
@@ -120,7 +175,7 @@ class Progress(object):
                     self._units,
                     self._total,
                     self._units,
-                    " " if msg else "",
+                    elapsed,
                     msg,
                     CSI_ERASE_LINE_AFTER,
                     "\n" if self._print_newline else "",
@@ -129,10 +184,11 @@ class Progress(object):
             sys.stderr.flush()
 
     def end(self):
+        self._update_event.set()
         if _NOT_TTY or IsTraceToStderr() or not self._show:
             return
 
-        duration = duration_str(time() - self._start)
+        duration = duration_str(time.time() - self._start)
         if self._total <= 0:
             sys.stderr.write(
                 "\r%s: %d, done in %s%s\n"

subcmds/sync.py

@@ -675,7 +675,13 @@ later is required to fix a server side protocol bug.
         jobs = opt.jobs_network
         fetched = set()
         remote_fetched = set()
-        pm = Progress("Fetching", len(projects), delay=False, quiet=opt.quiet)
+        pm = Progress(
+            "Fetching",
+            len(projects),
+            delay=False,
+            quiet=opt.quiet,
+            show_elapsed=True,
+        )
 
         objdir_project_map = dict()
         for project in projects: