git_cache: add more diagnostic logging wrt bootstrapping.

This is short of sending this metrics to ts_mon, but is still useful
for diagnose and then claim improvements in git cache performance on
bots.

This change has been tested for realz with led, particularly on windows
https://ci.chromium.org/swarming/task/3a01358af14a7d10

Bug: 749709
Change-Id: I2b3589079d2caa7f70007f90fcbce85a0205d24b
Reviewed-on: https://chromium-review.googlesource.com/787173Reviewed-by: Takuto Ikuta <tikuta@google.com>
Reviewed-by: Sergiy Byelozyorov <sergiyb@chromium.org>
Reviewed-by: Michael Achenbach <machenbach@chromium.org>
Commit-Queue: Andrii Shyshkalov <tandrii@chromium.org>

git_cache.py

@@ -6,6 +6,7 @@
 """A git command for managing a local cache of git repositories."""
 
 from __future__ import print_function
+import contextlib
 import errno
 import logging
 import optparse
@@ -223,6 +224,14 @@ class Mirror(object):
   def print_without_file(self, message, **_kwargs):
     self.print_func(message)
 
+  @contextlib.contextmanager
+  def print_duration_of(self, what):
+    start = time.time()
+    try:
+      yield
+    finally:
+      self.print('%s took %.1f minutes' % (what, (time.time() - start) / 60.0))
+
   @property
   def bootstrap_bucket(self):
     u = urlparse.urlparse(self.url)
@@ -324,11 +333,10 @@ class Mirror(object):
           cwd=cwd)
 
   def bootstrap_repo(self, directory):
-    """Bootstrap the repo from Google Stroage if possible.
+    """Bootstrap the repo from Google Storage if possible.
 
     More apt-ly named bootstrap_repo_from_cloud_if_possible_else_do_nothing().
     """
-
     if not self.bootstrap_bucket:
       return False
     python_fallback = False
@@ -344,10 +352,13 @@ class Mirror(object):
     gs_folder = 'gs://%s/%s' % (self.bootstrap_bucket, self.basedir)
     gsutil = Gsutil(self.gsutil_exe, boto_path=None)
     # Get the most recent version of the zipfile.
-    _, ls_out, _ = gsutil.check_call('ls', gs_folder)
+    _, ls_out, ls_err = gsutil.check_call('ls', gs_folder)
     ls_out_sorted = sorted(ls_out.splitlines())
     if not ls_out_sorted:
       # This repo is not on Google Storage.
+      self.print('No bootstrap file for %s found in %s, stderr:\n  %s' %
+                 (self.mirror_path, self.bootstrap_bucket,
+                  '  '.join((ls_err or '').splitlines(True))))
       return False
     latest_checkout = ls_out_sorted[-1]
 
@@ -355,28 +366,30 @@ class Mirror(object):
     try:
       tempdir = tempfile.mkdtemp(prefix='_cache_tmp', dir=self.GetCachePath())
       self.print('Downloading %s' % latest_checkout)
-      code = gsutil.call('cp', latest_checkout, tempdir)
+      with self.print_duration_of('download'):
+        code = gsutil.call('cp', latest_checkout, tempdir)
       if code:
         return False
       filename = os.path.join(tempdir, latest_checkout.split('/')[-1])
 
       # Unpack the file with 7z on Windows, unzip on linux, or fallback.
-      if not python_fallback:
-        if sys.platform.startswith('win'):
-          cmd = ['7z', 'x', '-o%s' % directory, '-tzip', filename]
-        else:
-          cmd = ['unzip', filename, '-d', directory]
-        retcode = subprocess.call(cmd)
-      else:
-        try:
-          with zipfile.ZipFile(filename, 'r') as f:
-            f.printdir()
-            f.extractall(directory)
-        except Exception as e:
-          self.print('Encountered error: %s' % str(e), file=sys.stderr)
-          retcode = 1
+      with self.print_duration_of('unzip'):
+        if not python_fallback:
+          if sys.platform.startswith('win'):
+            cmd = ['7z', 'x', '-o%s' % directory, '-tzip', filename]
+          else:
+            cmd = ['unzip', filename, '-d', directory]
+          retcode = subprocess.call(cmd)
         else:
-          retcode = 0
+          try:
+            with zipfile.ZipFile(filename, 'r') as f:
+              f.printdir()
+              f.extractall(directory)
+          except Exception as e:
+            self.print('Encountered error: %s' % str(e), file=sys.stderr)
+            retcode = 1
+          else:
+            retcode = 0
     finally:
       # Clean up the downloaded zipfile.
       #
@@ -432,6 +445,8 @@ class Mirror(object):
 
     if os.path.isdir(pack_dir):
       pack_files = [f for f in os.listdir(pack_dir) if f.endswith('.pack')]
+      self.print('%s has %d .pack files, re-bootstrapping if >%d' %
+                 (self.mirror_path, len(pack_files), GC_AUTOPACKLIMIT))
 
     should_bootstrap = (force or
                         not self.exists() or
@@ -455,8 +470,8 @@ class Mirror(object):
       else:
         # Bootstrap failed, previous cache exists; warn and continue.
         logging.warn(
-            'Git cache has a lot of pack files (%d).  Tried to re-bootstrap '
-            'but failed.  Continuing with non-optimized repository.'
+            'Git cache has a lot of pack files (%d). Tried to re-bootstrap '
+            'but failed. Continuing with non-optimized repository.'
             % len(pack_files))
         gclient_utils.rmtree(tempdir)
         tempdir = None
@@ -481,7 +496,8 @@ class Mirror(object):
     for spec in fetch_specs:
       try:
         self.print('Fetching %s' % spec)
-        self.RunGit(fetch_cmd + [spec], cwd=rundir, retry=True)
+        with self.print_duration_of('fetch %s' % spec):
+          self.RunGit(fetch_cmd + [spec], cwd=rundir, retry=True)
       except subprocess.CalledProcessError:
         if spec == '+refs/heads/*:refs/heads/*':
           raise ClobberNeeded()  # Corrupted cache.