model: Add timings for every public Experiment call

This measures the time for every public function of the Experiment
class and logs them.

Fixes #40

1 files changed, 26 insertions, 2 deletions

diff --git a/rumba/model.py b/rumba/model.py
index 7573df2..30bc70f 100644
--- a/rumba/model.py
+++ b/rumba/model.py
@@ -27,6 +27,7 @@
 import abc
 import os
 import stat
+import time
 
 import rumba.log as log
 from rumba import ssh_support
@@ -518,6 +519,8 @@ class Policy(object):
 # @nodes: Nodes in the experiment
 #
 class Experiment:
+    __metaclass__ = abc.ABCMeta
+
     def __init__(self, testbed, nodes=None):
         if nodes is None:
             nodes = list()
@@ -799,19 +802,34 @@ class Experiment:
     # Examine the nodes and DIFs, compute the registration and enrollment
     # order, the list of IPCPs to create, registrations, ...
     def generate(self):
+        start = time.time()
         self.compute_dif_ordering()
         self.compute_ipcps()
         self.compute_enrollments()
         self.compute_bootstrappers()
         for node in self.nodes:
             logger.info("IPCPs for node %s: %s", node.name, node.ipcps)
+        end = time.time()
+        logger.info("Layer ordering computation took %.2f seconds", end - start)
 
-    @abc.abstractmethod
     def install_prototype(self):
+        start = time.time()
+        self._install_prototype()
+        end = time.time()
+        logger.info("Install took %.2f seconds", end - start)
+
+    def bootstrap_prototype(self):
+        start = time.time()
+        self._bootstrap_prototype()
+        end = time.time()
+        logger.info("Bootstrap took %.2f seconds", end - start)
+
+    @abc.abstractmethod
+    def _install_prototype(self):
         raise Exception('install_prototype() method not implemented')
 
     @abc.abstractmethod
-    def bootstrap_prototype(self):
+    def _bootstrap_prototype(self):
         raise Exception('bootstrap_prototype() method not implemented')
 
     @abc.abstractmethod
@@ -820,10 +838,14 @@ class Experiment:
 
     def swap_in(self):
         # Realize the experiment testbed (testbed-specific)
+        start = time.time()
         self.testbed.swap_in(self)
         self.dump_ssh_info()
+        end = time.time()
+        logger.info("Swap-in took %.2f seconds", end - start)
 
     def swap_out(self):
+        start = time.time()
         for node in self.nodes:
             if node.ssh_config.client is not None:
                 node.ssh_config.client.close()
@@ -831,3 +853,5 @@ class Experiment:
                 node.ssh_config.proxy_client.close()
         # Undo the testbed (testbed-specific)
         self.testbed.swap_out(self)
+        end = time.time()
+        logger.info("Swap-out took %.2f seconds", end - start)