Add prebuild metrics logging for CI system

Metric about the times various parts of the build take are great to
have. This change takes us a step in that direction by adding metrics to
the prebuild step of the build process. These metrics are off by
default; use the `--ci-build` option of `prebuild.py` to enable them.

prebuild.py

@@ -35,9 +35,50 @@ import re
 import tempfile
 import time
 import functools
+import subprocess
+import logging
+
+from uuid import uuid4
+from contextlib import contextmanager
 
 print = functools.partial(print, flush=True)
 
+class TrackableLogger(logging.Logger):
+    guid = str(uuid4())
+
+    def _log(self, msg, *args, **kwargs):
+        x = {'guid': self.guid}
+        if 'extra' in kwargs:
+            kwargs['extra'].update(x)
+        else:
+            kwargs['extra'] = x
+        super()._log(msg, *args, **kwargs)
+
+logging.setLoggerClass(TrackableLogger)
+logger = logging.getLogger('prebuild')
+
+def headSha():
+    repo_dir = os.path.dirname(os.path.abspath(__file__))
+    git = subprocess.Popen(
+        'git rev-parse --short HEAD',
+        stdout=subprocess.PIPE, stderr=subprocess.PIPE,
+        shell=True, cwd=repo_dir, universal_newlines=True,
+    )
+    stdout, _ = git.communicate()
+    sha = stdout.split('\n')[0]
+    if not sha:
+        raise RuntimeError("couldn't find git sha")
+    return sha
+
+@contextmanager
+def timer(name):
+    ''' Print the elapsed time a context's execution takes to execute '''
+    start = time.time()
+    yield
+    # Please take care when modifiying this print statement.
+    # Log parsing logic may depend on it.
+    logger.info('%s took %.3f secs' % (name, time.time() - start))
+
 def parse_args():
     # our custom ports, relative to the script location
     defaultPortsPath = hifi_utils.scriptRelative('cmake', 'ports')
@@ -50,6 +91,7 @@ def parse_args():
     parser.add_argument('--vcpkg-root', type=str, help='The location of the vcpkg distribution')
     parser.add_argument('--build-root', required=True, type=str, help='The location of the cmake build')
     parser.add_argument('--ports-path', type=str, default=defaultPortsPath)
+    parser.add_argument('--ci-build', action='store_true')
     if True:
         args = parser.parse_args()
     else:
@@ -66,11 +108,19 @@ def main():
             del os.environ[var]
 
     args = parse_args()
+
+    if args.ci_build:
+        logging.basicConfig(datefmt='%s', format='%(asctime)s %(guid)s %(message)s', level=logging.INFO)
+
+    logger.info('sha=%s' % headSha())
+    logger.info('start')
+
     # Only allow one instance of the program to run at a time
     pm = hifi_vcpkg.VcpkgRepo(args)
     with hifi_singleton.Singleton(pm.lockFile) as lock:
-        if not pm.upToDate():
-            pm.bootstrap()
+        with timer('Bootstraping'):
+            if not pm.upToDate():
+                pm.bootstrap()
 
         # Always write the tag, even if we changed nothing.  This 
         # allows vcpkg to reclaim disk space by identifying directories with
@@ -80,11 +130,13 @@ def main():
         # Grab our required dependencies:
         #  * build host tools, like spirv-cross and scribe
         #  * build client dependencies like openssl and nvtt
-        pm.setupDependencies()
+        with timer('Setting up dependencies'):
+            pm.setupDependencies()
 
         # wipe out the build directories (after writing the tag, since failure 
         # here shouldn't invalidte the vcpkg install)
-        pm.cleanBuilds()
+        with timer('Cleaning builds'):
+            pm.cleanBuilds()
 
         # If we're running in android mode, we also need to grab a bunch of additional binaries
         # (this logic is all migrated from the old setupDependencies tasks in gradle)
@@ -98,7 +150,10 @@ def main():
             hifi_android.QtPackager(appPath, qtPath).bundle()
 
         # Write the vcpkg config to the build directory last
-        pm.writeConfig()
+        with timer('Writing configuration'):
+            pm.writeConfig()
+
+    logger.info('end')
 
 print(sys.argv)
 main()