Merge branch 'timings' into 'master'

Improve progress output and timings

See merge request larswirzenius/contractor!6

1 files changed, 111 insertions, 123 deletions

diff --git a/contractor b/contractor
index 58625af..e8d0a3d 100755
--- a/contractor
+++ b/contractor
@@ -57,98 +57,85 @@ class ContractorApplication(cliapp.Application):
         self.output.write('{}\n'.format(json.dumps(bs.as_dict(), indent=4)))
 
     def cmd_build(self, args):
-        timer = Timer(self.verbose)
-        overall = Timer(self.verbose)
+        self.verbose('building according to {}'.format(args[0]))
+        bs = self.load_build_spec(args[0])
         dest = self.manager_destination()
         manager = RemoteServer(dest, verbose=self.verbose)
+        self.verbose('manager is at {}'.format(dest))
+
+        with Timer(self.verbose, 'complete-run'):
+            with Timer(self.verbose, 'upload-worker-image'):
+                self.upload_worker_image(bs.worker_image(), dest)
+
+            # Do the minimum needed to start worker VM. The VM takes a
+            # while to boot and we can do other things while that
+            # happens.
+            with Timer(self.verbose, 'start-worker'):
+                execs = [
+                    DestroyWorkerVM(),
+                    UndefineWorkerVM(),
+                    CopyWorkerImage(),
+                    StartGuestNetworking(),
+                    CreateWorkerVM(),
+                    TryUnmountWS(),
+                    MountWS(),
+                    ChownWS(),
+                ]
+                self.exec_quietly(manager, *execs)
+
+            with Timer(self.verbose, 'upload-saved-workspace'):
+                ws = bs.workspace()
+                if os.path.exists(ws):
+                    self.sync_to_workspace(ws, dest, '.')
+
+            with Timer(self.verbose, 'upload-source'):
+                self.exec_quietly(
+                    manager, Mkdir(
+                        '/mnt/src', owner=WORKER_UID, group=WORKER_GID))
+                src = bs.source()
+                self.sync_to_workspace(src, dest, 'src')
+
+            with Timer(self.verbose, 'wait-for-worker-to-be-available'):
+                execs = [
+                    UnmountWS(),
+                    WorkerIP(),
+                    AttachWS(),
+                ]
+                er = self.exec_quietly(manager, *execs)
+                worker_ip = er.stdout.decode('UTF8').strip()
+
+            with Timer(self.verbose, 'prepare-workspace-worker'):
+                worker_dest = 'worker@{}'.format(worker_ip)
+                self.verbose(
+                    'worker is at {} (via manager)'.format(worker_dest))
+                worker = OnWorker(dest, worker_dest, verbose=self.verbose)
+                self.exec_quietly(
+                    worker, Mkdir('/workspace'), MountWSonWorker())
+
+            with Timer(self.verbose, 'prepare-worker-with-ansible'):
+                ansible = bs.ansible()
+                if ansible:
+                    self.exec_verbosely(manager, Ansible(ansible, worker_ip))
+
+            with Timer(self.verbose, 'build'):
+                execs = [
+                    Chdir('/workspace/src'),
+                    Build(bs.build()),
+                ]
+                self.exec_verbosely(worker, *execs)
+
+            with Timer(self.verbose, 'shutdown-worker'):
+                execs = [
+                    ShutdownWorkerVM(),
+                    MountWS(),
+                ]
+                self.exec_quietly(manager, *execs)
+
+            with Timer(self.verbose, 'save-workspace'):
+                if ws:
+                    self.verbose('saving workspace to {}'.format(ws))
+                    self.sync_from_workspace(dest, ws)
 
-        self.verbose('building using spec at {}'.format(args[0]))
-        bs = self.load_build_spec(args[0])
-
-        self.upload_worker_image(bs.worker_image(), dest)
-        timer.report('upload-worker-image')
-
-        # Do the minimum needed to start worker VM. The VM takes a
-        # while to boot and we can do other things while that happens.
-        execs = [
-            GetCPUCount(),
-        ]
-        er = self.exec_quietly(manager, *execs)
-        timer.report('setup')
-
-        # Find number of CPUs.
-        cpus = 1
-        for line in er.stdout.decode('UTF8').splitlines():
-            if line.startswith('CPU(s):'):
-                cpus = int(line.split()[-1])
-
-        execs = [
-            DestroyWorkerVM(),
-            UndefineWorkerVM(),
-            CopyWorkerImage(),
-            StartGuestNetworking(),
-            CreateWorkerVM(cpus),
-            TryUnmountWS(),
-            MountWS(),
-            ChownWS(),
-        ]
-        self.exec_quietly(manager, *execs)
-        timer.report('setup')
-
-        self.verbose('setting up workspace on worker')
-
-        ws = bs.workspace()
-        if os.path.exists(ws):
-            self.sync_to_workspace(ws, dest, '.')
-            timer.report('upload-saved-workspace')
-
-        execs = [
-            Mkdir('/mnt/src', owner=WORKER_UID, group=WORKER_GID),
-        ]
-        self.exec_quietly(manager, *execs)
-        src = bs.source()
-        self.sync_to_workspace(src, dest, 'src')
-        timer.report('upload-source')
-
-        execs = [
-            UnmountWS(),
-            WorkerIP(),
-        ]
-        er = self.exec_quietly(manager, *execs)
-        worker_ip = er.stdout.decode('UTF8').strip()
-        timer.report('wait-for-worker')
-
-        self.exec_quietly(manager, AttachWS())
-        self.verbose('attached')
-
-        worker = OnWorker(
-            dest, 'worker@{}'.format(worker_ip), verbose=self.verbose)
-        self.exec_quietly(worker, Mkdir('/workspace'), MountWSonWorker())
-
-        ansible = bs.ansible()
-        if ansible:
-            self.exec_verbosely(manager, Ansible(ansible, worker_ip))
-
-        execs = [
-            Chdir('/workspace/src'),
-            Build(bs.build()),
-        ]
-        self.exec_verbosely(worker, *execs)
-        timer.report('build')
-
-        execs = [
-            ShutdownWorkerVM(),
-            MountWS(),
-        ]
-        self.exec_quietly(manager, *execs)
-        timer.report('shutdown-worker')
-
-        if ws:
-            self.verbose('saving workspace to {}'.format(ws))
-            self.sync_from_workspace(dest, ws)
-            timer.report('save-workspace')
-
-        overall.report('complete-run')
         self.verbose('build finished OK')
 
     def load_build_spec(self, filename):
@@ -156,20 +143,24 @@ class ContractorApplication(cliapp.Application):
             return BuildSpec(f.read())
 
     def upload_worker_image(self, filename, dest):
-        self.verbose('uploading image to worker: {}'.format(filename))
+        self.verbose(
+            'uploading to manager local worker image {}'.format(filename))
         target = '{}:{}'.format(dest, WORKER_IMG)
         if rsync(filename, target).failed():
             self.error('could not upload image to worker')
             sys.exit(1)
 
     def sync_to_workspace(self, frm, dest, subdir):
+        destdir = '/mnt/{}'.format(subdir)
+        self.verbose('syncing local {} to manager {}'.format(frm, destdir))
         er = rsync(
-            '{}/.'.format(frm), '{}:/mnt/{}/.'.format(dest, subdir))
+            '{}/.'.format(frm), '{}:{}/.'.format(dest, destdir))
         if er.failed():
             self.error('Failed to rsync saved workspace to worker')
             sys.exit(1)
 
     def sync_from_workspace(self, dest, ws):
+        self.verbose('syncing manager /mnt to local {}'.format(ws))
         if not os.path.exists(ws):
             os.makedirs(ws)
         er = rsync('{}:/mnt/.'.format(dest), '{}/.'.format(ws))
@@ -254,6 +245,7 @@ class RemoteServer:
 
     def __init__(self, ssh_destination, verbose=None):
         self._dest = ssh_destination
+        self._where = 'manager: {}'.format(ssh_destination)
         self._verbose = verbose
 
     def quietly(self, *execs):
@@ -264,7 +256,7 @@ class RemoteServer:
 
     def _msg(self, execs):
         if self._verbose is not None:
-            self._verbose('Executing steps')
+            self._verbose('Executing steps on {}'.format(self._where))
             for e in execs:
                 m = e.msg() or e.__class__.__name__
                 self._verbose('  - ' + m)
@@ -283,6 +275,7 @@ class OnWorker(RemoteServer):
 
     def __init__(self, manager, worker, verbose=None):
         self._dest = manager
+        self._where = 'worker: {}'.format(worker)
         self._prefix = ['ssh', worker, '--']
         self._verbose = verbose
 
@@ -492,39 +485,29 @@ class Mkdir(RemoteExecution):
         return self._argv
 
 
-class GetCPUCount(RemoteExecution):
-
-    def msg(self):
-        return 'get CPU count'
-
-    def argv(self):
-        return ['lscpu']
-
-
 class CreateWorkerVM(RemoteExecution):
 
-    def __init__(self, manager_cpus):
-        self._worker_cpus = max(manager_cpus - 1, 1)
-
     def msg(self):
         return 'creating worker VM'
 
     def argv(self):
-        return [
-            'virt-install',
-            '--connect', 'qemu:///system',
-            '--quiet',
-            '--name=worker',
-            '--memory=4096',
-            '--vcpus={}'.format(self._worker_cpus),
-            '--cpu=host',
-            '--import',
-            '--os-variant=debian9',
-            '--disk=path={},cache=none'.format(TEMP_IMG),
-            '--network=network=default',
-            '--graphics=spice',
-            '--noautoconsole',
-        ]
+        return ['sh', '-euxc', '''
+n="$(grep -c '^processor' /proc/cpuinfo)"
+n="$(expr "$n" - 1)"
+virt-install \
+    --connect=qemu:///system \
+    --quiet \
+    --name=worker \
+    --memory=4096 \
+    --vcpus="$n" \
+    --cpu=host \
+    --import \
+    --os-variant=debian9 \
+    --disk=path={img} \
+    --network=network=default \
+    --graphics=spice \
+    --noautoconsole \
+'''.format(img=TEMP_IMG)]
 
 
 class AttachWS(RemoteExecution):
@@ -533,7 +516,7 @@ class AttachWS(RemoteExecution):
         return 'attach workspace disk to worker'
 
     def argv(self):
-        return virsh('attach-disk', 'worker', WS_DEV, 'vdb',
+        return virsh('--quiet', 'attach-disk', 'worker', WS_DEV, 'vdb',
                      '--targetbus', 'virtio', '--live')
 
 
@@ -617,15 +600,20 @@ class SpecMissingKey(Exception):
 
 class Timer:
 
-    def __init__(self, report):
+    def __init__(self, report, title):
         self._report = report
+        self._title = title
+        self._prev = None
+
+    def __enter__(self):
         self._prev = time.time()
 
-    def report(self, msg):
+    def __exit__(self, exctype, exc, tb):
         now = time.time()
         duration = now - self._prev
         self._prev = now
-        self._report('time: {:.1f} s {}'.format(duration, msg))
+        self._report('time: {:.1f} s {}\n'.format(duration, self._title))
+        return False
 
 
 ContractorApplication().run()