Add Stopwatch class, write build times to $cache_prefix.meta.

The Stopwatch class does not have unit tests yet and the build times
stored in the cache for system images may be a little too fine-grained
at the moment.

3 files changed, 118 insertions, 0 deletions

diff --git a/morphlib/__init__.py b/morphlib/__init__.py
index 6ec0f7fe..c4a1992d 100644
--- a/morphlib/__init__.py
+++ b/morphlib/__init__.py
@@ -26,5 +26,6 @@ import cachedir
 import execute
 import git
 import morphology
+import stopwatch
 import tempdir
 import util
diff --git a/morphlib/builder.py b/morphlib/builder.py
index 0323cbbc..85fecc1e 100644
--- a/morphlib/builder.py
+++ b/morphlib/builder.py
@@ -42,6 +42,9 @@ class BinaryBlob(object):
         self.tempdir = None
         self.built = None
 
+        # Stopwatch to measure build times
+        self.build_watch = morphlib.stopwatch.Stopwatch()
+
     def dict_key(self):
         return {}
     
@@ -77,6 +80,25 @@ class BinaryBlob(object):
             json.dump(meta, f, indent=4)
             f.write('\n')
 
+    def write_cache_metadata(self, meta):
+        self.msg('Writing metadata to the cache')
+        filename = '%s.meta' % self.cache_prefix
+        with open(filename, 'w') as f:
+            json.dump(meta, f, indent=4)
+            f.write('\n')
+
+    def save_build_times(self):
+        meta = {
+            'build-times': {}
+        }
+        for stage in self.build_watch.ticks.iterkeys():
+            meta['build-times'][stage] = {
+                'start': '%s' % self.build_watch.start(stage),
+                'stop': '%s' % self.build_watch.stop(stage),
+                'delta': self.build_watch.delta(stage).total_seconds()
+            }
+        self.write_cache_metadata(meta)
+
 
 class Chunk(BinaryBlob):
 
@@ -113,6 +135,8 @@ class Chunk(BinaryBlob):
     def build(self):
         logging.debug('Creating build tree at %s' % self.builddir)
 
+        self.build_watch.enter('overall-build')
+
         self.ex = morphlib.execute.Execute(self.builddir, self.msg)
         self.setup_env()
 
@@ -205,19 +229,24 @@ class Chunk(BinaryBlob):
 
     def run_in_parallel(self, what, commands):
         self.msg('commands: %s' % what)
+        self.build_watch.enter(what)
         self.ex.run(commands)
+        self.build_watch.leave(what)
 
     def run_sequentially(self, what, commands, as_fakeroot=False):
         self.msg ('commands: %s' % what)
+        self.build_watch.enter(what)
         flags = self.ex.env['MAKEFLAGS']
         self.ex.env['MAKEFLAGS'] = '-j1'
         logging.debug('Setting MAKEFLAGS=%s' % self.ex.env['MAKEFLAGS'])
         self.ex.run(commands, as_fakeroot=as_fakeroot)
         self.ex.env['MAKEFLAGS'] = flags
         logging.debug('Restore MAKEFLAGS=%s' % self.ex.env['MAKEFLAGS'])
+        self.build_watch.leave(what)
 
     def create_chunks(self, chunks):
         ret = {}
+        self.build_watch.enter('create-chunks')
         for chunk_name in chunks:
             self.msg('Creating chunk %s' % chunk_name)
             self.prepare_binary_metadata(chunk_name)
@@ -227,6 +256,9 @@ class Chunk(BinaryBlob):
             self.msg('Creating binary for %s' % chunk_name)
             morphlib.bins.create_chunk(self.destdir, filename, patterns)
             ret[chunk_name] = filename
+        self.build_watch.leave('create-chunks')
+        self.build_watch.leave('overall-build')
+        self.save_build_times()
         files = os.listdir(self.destdir)
         if files:
             raise Exception('DESTDIR %s is not empty: %s' %
@@ -250,14 +282,21 @@ class Stratum(BinaryBlob):
         return { self.morph.name: filename }
 
     def build(self):
+        self.build_watch.enter('overall-build')
         os.mkdir(self.destdir)
+        self.build_watch.enter('unpack-chunks')
         for chunk_name, filename in self.built:
             self.msg('Unpacking chunk %s' % chunk_name)
             morphlib.bins.unpack_binary(filename, self.destdir)
+        self.build_watch.leave('unpack-chunks')
         self.prepare_binary_metadata(self.morph.name)
+        self.build_watch.enter('create-binary')
         self.msg('Creating binary for %s' % self.morph.name)
         filename = self.filename(self.morph.name)
         morphlib.bins.create_stratum(self.destdir, filename)
+        self.build_watch.leave('create-binary')
+        self.build_watch.leave('overall-build')
+        self.save_build_times()
         return { self.morph.name: filename }
 
 
@@ -272,55 +311,74 @@ class System(BinaryBlob):
         return { self.morph.name: filename }
 
     def build(self):
+        self.build_watch.enter('overall-build')
+
         self.ex = morphlib.execute.Execute(self.tempdir.dirname, self.msg)
         
         # Create image.
+        self.build_watch.enter('create-image')
         image_name = self.tempdir.join('%s.img' % self.morph.name)
         self.ex.runv(['qemu-img', 'create', '-f', 'raw', image_name,
                       self.morph.disk_size])
+        self.build_watch.leave('create-image')
 
         # Partition it.
+        self.build_watch.enter('partition-image')
         self.ex.runv(['parted', '-s', image_name, 'mklabel', 'msdos'],
                      as_root=True)
         self.ex.runv(['parted', '-s', image_name, 'mkpart', 'primary', 
                       '0%', '100%'], as_root=True)
         self.ex.runv(['parted', '-s', image_name, 'set', '1', 'boot', 'on'],
                      as_root=True)
+        self.build_watch.leave('partition-image')
 
         # Install first stage boot loader into MBR.
+        self.build_watch.enter('install-mbr')
         self.ex.runv(['install-mbr', image_name], as_root=True)
+        self.build_watch.leave('install-mbr')
 
         # Setup device mapper to access the partition.
+        self.build_watch.enter('setup-device-mapper')
         out = self.ex.runv(['kpartx', '-av', image_name], as_root=True)
         devices = [line.split()[2]
                    for line in out.splitlines()
                    if line.startswith('add map ')]
         partition = '/dev/mapper/%s' % devices[0]
+        self.build_watch.leave('setup-device-mapper')
 
         mount_point = None
         try:
             # Create filesystem.
+            self.build_watch.enter('create-filesystem')
             self.ex.runv(['mkfs', '-t', 'ext3', partition], as_root=True)
+            self.build_watch.leave('create-filesystem')
             
             # Mount it.
+            self.build_watch.enter('mount-filesystem')
             mount_point = self.tempdir.join('mnt')
             os.mkdir(mount_point)
             self.ex.runv(['mount', partition, mount_point], as_root=True)
+            self.build_watch.leave('mount-filesystem')
 
             # Unpack all strata into filesystem.
+            self.build_watch.enter('unpack-strata')
             for name, filename in self.built:
                 self.msg('unpack %s from %s' % (name, filename))
                 self.ex.runv(['tar', '-C', mount_point, '-xf', filename],
                              as_root=True)
+            self.build_watch.leave('unpack-strata')
 
             # Create fstab.
+            self.build_watch.enter('create-fstab')
             fstab = self.tempdir.join('mnt/etc/fstab')
             with open(fstab, 'w') as f:
                 f.write('proc /proc proc defaults 0 0\n')
                 f.write('sysfs /sys sysfs defaults 0 0\n')
                 f.write('/dev/sda1 / ext4 errors=remount-ro 0 1\n')
+            self.build_watch.leave('create-fstab')
 
             # Install extlinux bootloader.
+            self.build_watch.enter('install-bootloader')
             conf = os.path.join(mount_point, 'extlinux.conf')
             logging.debug('configure extlinux %s' % conf)
             f = open(conf, 'w')
@@ -339,9 +397,12 @@ append root=/dev/sda1 init=/bin/sh quiet rw
             # Weird hack that makes extlinux work. There is a bug somewhere.
             self.ex.runv(['sync'])
             import time; time.sleep(2)
+            self.build_watch.leave('install-bootloader')
 
             # Unmount.
+            self.build_watch.enter('unmount-filesystem')
             self.ex.runv(['umount', mount_point], as_root=True)
+            self.build_watch.leave('unmount-filesystem')
         except BaseException, e:
             # Unmount.
             if mount_point is not None:
@@ -358,11 +419,19 @@ append root=/dev/sda1 init=/bin/sh quiet rw
             raise
 
         # Undo device mapping.
+        self.build_watch.enter('undo-device-mapper')
         self.ex.runv(['kpartx', '-d', image_name], as_root=True)
+        self.build_watch.leave('undo-device-mapper')
 
         # Move image file to cache.
+        self.build_watch.enter('cache-image')
         filename = self.filename(self.morph.name)
         self.ex.runv(['mv', image_name, filename])
+        self.build_watch.leave('cache-image')
+
+        # Write build time information to the cache
+        self.build_watch.leave('overall-build')
+        self.save_build_times()
 
         return { self.morph.name: filename }
 
diff --git a/morphlib/stopwatch.py b/morphlib/stopwatch.py
new file mode 100644
index 00000000..5fb4c42d
--- /dev/null
+++ b/morphlib/stopwatch.py
@@ -0,0 +1,48 @@
+# Copyright (C) 2011  Codethink Limited
+# 
+# This program is free software; you can redistribute it and/or modify
+# it under the terms of the GNU General Public License as published by
+# the Free Software Foundation; version 2 of the License.
+# 
+# This program is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+# GNU General Public License for more details.
+# 
+# You should have received a copy of the GNU General Public License along
+# with this program; if not, write to the Free Software Foundation, Inc.,
+# 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
+
+
+from datetime import datetime
+
+
+class Stopwatch(object):
+
+    def __init__(self):
+        self.ticks = {}
+
+    def tick(self, reference_object, name):
+        if not self.ticks.has_key(reference_object):
+            self.ticks[reference_object] = {}
+        self.ticks[reference_object][name] = datetime.now()
+
+    def enter(self, reference_object):
+        # TODO raise error if start already exists
+        self.tick(reference_object, 'start')
+
+    def leave(self, reference_object):
+        # TODO raise error if stop already exists
+        self.tick(reference_object, 'stop')
+
+    def time(self, reference_object, name):
+        return self.ticks[reference_object][name]
+
+    def start(self, reference_object):
+        return self.ticks[reference_object]['start']
+
+    def stop(self, reference_object):
+        return self.ticks[reference_object]['stop']
+
+    def delta(self, reference_object):
+        return self.stop(reference_object) - self.start(reference_object)