Add: more detailed timings for slowest steps

1 files changed, 27 insertions, 15 deletions

diff --git a/contractor b/contractor
index 3653466..89bb98f 100755
--- a/contractor
+++ b/contractor
@@ -61,20 +61,18 @@ class ContractorApplication(cliapp.Application):
 
         self.verbose('building using spec at {}'.format(args[0]))
         bs = self.load_build_spec(args[0])
-        m = self.manager()
+        m = self.manager(timer)
         timer.report('load-build-spec')
 
         # This might fail. We ignore the failure.
         self.verbose('stopping worker')
         m.kill_worker()
-        timer.report('kill-worker')
 
         self.verbose(
             'uploading image to worker: {}'.format(bs.worker_image()))
         if m.upload_worker_image(bs.worker_image()).failed():
             self.error('could not upload image to worker')
             sys.exit(1)
-        timer.report('upload-image')
 
         self.verbose('setting up workspace on worker')
         ws = bs.workspace()
@@ -82,14 +80,12 @@ class ContractorApplication(cliapp.Application):
         if m.setup_workspace(ws, source).failed():
             self.error('could not set up workspace')
             sys.exit(1)
-        timer.report('setup-workspace')
 
         self.verbose('starting worker')
         w = m.start_worker()
         if not w:
             self.error('could not start worker')
             sys.exit(1)
-        timer.report('start-worker')
 
         install = bs.install()
         if install:
@@ -100,7 +96,6 @@ class ContractorApplication(cliapp.Application):
                 sys.exit(1)
         else:
             self.verbose('no packages to install')
-        timer.report('install-packages')
 
         self.verbose('building')
         if w.build(bs.build()).failed():
@@ -111,12 +106,10 @@ class ContractorApplication(cliapp.Application):
         # This might fail. We ignore the failure.
         self.verbose('stopping worker')
         m.stop_worker()
-        timer.report('stop-worker')
 
         if ws:
             self.verbose('saving workspace to {}'.format(ws))
             m.save_workspace(ws)
-            timer.report('save-workspace')
 
         self.verbose('build finished OK')
 
@@ -131,10 +124,10 @@ class ContractorApplication(cliapp.Application):
             sys.exit(1)
         self.verbose('Manager VM is available')
 
-    def manager(self):
+    def manager(self, timer):
         user = self.settings['manager-user']
         addr = self.settings['manager-address']
-        return Manager(user, addr)
+        return Manager(user, addr, timer)
 
     def error(self, msg):
         sys.stderr.write('ERROR: {}\n'.format(msg))
@@ -233,17 +226,20 @@ class SpecMissingKey(Exception):
 
 class Manager:
 
-    def __init__(self, user, addr):
+    def __init__(self, user, addr, timer):
         self._target = '{}@{}'.format(user, addr)
+        self._timer = timer
 
     def ssh(self, argv, quiet=False):
         return ssh(self._target, argv, quiet=quiet)
 
     def virsh(self, argv):
-        return ssh(
+        ret = ssh(
             self._target,
             ['virsh', '-c', 'qemu:///system'] + argv,
             quiet=True)
+        self._timer.report('virsh {}'.format(' '.join(argv)))
+        return ret
 
     def kill_worker(self):
         self.virsh(['destroy', 'worker'])
@@ -260,7 +256,9 @@ class Manager:
             time.sleep(2)
 
     def upload_worker_image(self, filename):
-        return rsync(filename, '{}:{}'.format(self._target, WORKER_IMG))
+        ret = rsync(filename, '{}:{}'.format(self._target, WORKER_IMG))
+        self._timer.report('upload-worker-image')
+        return ret
 
     def start_worker(self):
         if self.copy_worker_image().failed():
@@ -275,6 +273,7 @@ class Manager:
         if not isinstance(n, int):
             logging.error('Could not start worker due to missing CPU count')
             return None
+        self._timer.report('get-cpu-count')
 
         er = self.ssh([
             'virt-install',
@@ -296,11 +295,14 @@ class Manager:
             logging.error('Could not create worker VM')
             return None
 
+        self._timer.report('virt-install')
         return self.wait_for_worker()
 
     def copy_worker_image(self):
         self.ssh(['rm', '-f', TEMP_IMG])
-        return self.ssh(['cp', WORKER_IMG, TEMP_IMG])
+        ret = self.ssh(['cp', WORKER_IMG, TEMP_IMG])
+        self._timer.report('copy-worker-image')
+        return ret
 
     def get_cpu_count(self):
         er = self.ssh(['lscpu'], quiet=True)
@@ -330,6 +332,7 @@ class Manager:
             return None
 
         status.sort(key=lambda e: e['expiry-time'])
+        self._timer.report('worker-ip')
         return status[-1]['ip-address']
 
     def wait_for_worker(self):
@@ -341,6 +344,7 @@ class Manager:
                 continue
             w = Worker(self, ip)
             if not w.ssh(['true'], quiet=True).failed():
+                self._timer.report('wait-for-worker')
                 return w
             time.sleep(2)
 
@@ -355,18 +359,21 @@ class Manager:
         er = self.mount(WS_DEV)
         if er.failed():
             return er
+        self._timer.report('mount-workspace')
 
         er = self.ssh(
             ['sudo', 'chown', '{}:{}'.format(WORKER_UID, WORKER_GID),
              '/mnt'])
         if er.failed():
             return er
+        self._timer.report('chown-workspace')
 
         er = self.ssh(
             ['sudo', 'install', '-d', '--owner={}'.format(WORKER_UID),
              '--group={}'.format(WORKER_GID), '/mnt/src'])
         if er.failed():
             return er
+        self._timer.report('create-workspace-src')
 
         if os.path.exists(saved_workspace):
             er = rsync(
@@ -374,12 +381,14 @@ class Manager:
                 '{}:/mnt/.'.format(self._target))
             if er.failed():
                 return er
+            self._timer.report('upload-saved-workspace')
 
         er = rsync(
             '{}/.'.format(source),
             '{}:/mnt/src/.'.format(self._target))
         if er.failed():
             return er
+        self._timer.report('upload-source')
 
         return er
 
@@ -394,13 +403,16 @@ class Manager:
         er = self.mount(WS_DEV)
         if er.failed():
             return er
+        self._timer.report('mount-workspace')
 
         if not os.path.exists(saved_workspace):
             os.makedirs(saved_workspace)
 
-        return rsync(
+        ret = rsync(
                 '{}:/mnt/.'.format(self._target),
                 '{}/.'.format(saved_workspace))
+        self._timer.report('save-workspace')
+        return ret
 
     def kpartx(self, options):
         er = self.ssh(['sudo', 'kpartx', options, TEMP_IMG])