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

4 files changed, 32 insertions, 8 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)
diff --git a/rumba/prototypes/irati.py b/rumba/prototypes/irati.py
index 82e56b9..e8da727 100644
--- a/rumba/prototypes/irati.py
+++ b/rumba/prototypes/irati.py
@@ -115,12 +115,12 @@ class Experiment(mod.Experiment):
             self.process_node(node)
         self.enroll_nodes()
 
-    def install_prototype(self):
+    def _install_prototype(self):
         logger.info("installing IRATI on all the nodes")
         self.install()
         logger.info("installation complete")
 
-    def bootstrap_prototype(self):
+    def _bootstrap_prototype(self):
         logger.info("setting up")
         self.conf_files = self.write_conf()
         logger.info("configuration files generated for all nodes")
diff --git a/rumba/prototypes/ouroboros.py b/rumba/prototypes/ouroboros.py
index 055ed43..6d5d184 100644
--- a/rumba/prototypes/ouroboros.py
+++ b/rumba/prototypes/ouroboros.py
@@ -153,12 +153,12 @@ class Experiment(mod.Experiment):
                                 ipcp.node.ssh_config,
                                 cmd, time_out=None)
 
-    def install_prototype(self):
+    def _install_prototype(self):
         logger.info("Installing Ouroboros...")
         self.install_ouroboros()
         logger.info("Installed on all nodes...")
 
-    def bootstrap_prototype(self):
+    def _bootstrap_prototype(self):
         logger.info("Starting IRMd on all nodes...")
         self.setup_ouroboros()
         logger.info("Creating IPCPs")
diff --git a/rumba/prototypes/rlite.py b/rumba/prototypes/rlite.py
index 0579e3a..d55b253 100644
--- a/rumba/prototypes/rlite.py
+++ b/rumba/prototypes/rlite.py
@@ -140,7 +140,7 @@ class Experiment(mod.Experiment):
                 self.execute_commands(e['enrollee'].node, cmds)
                 time.sleep(1)
 
-    def install_prototype(self):
+    def _install_prototype(self):
         logger.info("installing rlite on all nodes")
 
         packages = ["g++", "gcc", "cmake", "linux-headers-$(uname -r)",
@@ -163,7 +163,7 @@ class Experiment(mod.Experiment):
         m_processing.call_in_parallel(names, args, executors)
         logger.info("installation complete")
 
-    def bootstrap_prototype(self):
+    def _bootstrap_prototype(self):
         logger.info("setting up")
         self.init_nodes()
         logger.info("software initialized on all nodes")