Instrument installer to profile steps

Installer now prints runtime of each step / part to install log.

Signed-off-by: Christian Heimes <cheimes@redhat.com>
Reviewed-By: Rob Crittenden <rcritten@redhat.com>

ipaserver/install/ldapupdate.py

@@ -928,7 +928,6 @@ class LDAPUpdate(object):
         returns True if anything was changed, otherwise False
         """
         self.modified = False
-        all_updates = []
         try:
             self.create_connection()
 
@@ -937,6 +936,7 @@ class LDAPUpdate(object):
                 upgrade_files = sorted(files)
 
             for f in upgrade_files:
+                start = time.time()
                 try:
                     logger.debug("Parsing update file '%s'", f)
                     data = self.read_file(f)
@@ -944,9 +944,14 @@ class LDAPUpdate(object):
                     logger.error("error reading update file '%s'", f)
                     raise RuntimeError(e)
 
+                all_updates = []
                 self.parse_update_file(f, data, all_updates)
                 self._run_updates(all_updates)
-                all_updates = []
+                dur = time.time() - start
+                logger.debug(
+                    "LDAP update duration: %s %.03f sec", f, dur,
+                    extra={'timing': ('ldapupdate', f, None, dur)}
+                )
         finally:
             self.close_connection()
 

ipaserver/install/server/install.py

@@ -10,6 +10,7 @@ import os
 import pickle
 import shutil
 import sys
+import time
 import tempfile
 import textwrap
 
@@ -925,7 +926,11 @@ def install(installer):
             args.append("--no-sshd")
         if options.mkhomedir:
             args.append("--mkhomedir")
+        start = time.time()
         run(args, redirect_output=True)
+        dur = time.time() - start
+        logger.debug("Client install duration: %0.3f", dur,
+                     extra={'timing': ('clientinstall', None, None, dur)})
         print()
     except Exception:
         raise ScriptError("Configuration of client side components failed!")

ipaserver/install/service.py

@@ -24,7 +24,7 @@ import sys
 import os
 import pwd
 import socket
-import datetime
+import time
 import traceback
 import tempfile
 
@@ -492,6 +492,7 @@ class Service(object):
 
         Use show_service_name to include service name in generated descriptions.
         """
+        creation_start = time.time()
 
         if start_message is None:
             # no other info than mandatory service_name provided, use that
@@ -525,11 +526,15 @@ class Service(object):
 
         def run_step(message, method):
             self.print_msg(message)
-            s = datetime.datetime.now()
+            start = time.time()
             method()
-            e = datetime.datetime.now()
-            d = e - s
-            logger.debug("  duration: %d seconds", d.seconds)
+            dur = time.time() - start
+            name = method.__name__
+            logger.debug(
+                "step duration: %s %s %.02f sec",
+                self.service_name, name, dur,
+                extra={'timing': ('step', self.service_name, name, dur)},
+            )
 
         step = 0
         steps_iter = iter(self.steps)
@@ -553,7 +558,12 @@ class Service(object):
             raise
 
         self.print_msg(end_message)
-
+        dur = time.time() - creation_start
+        logger.debug(
+            "service duration: %s %.02f sec",
+            self.service_name, dur,
+            extra={'timing': ('service', self.service_name, None, dur)},
+        )
         self.steps = []
 
     def ldap_enable(self, name, fqdn, dm_password=None, ldap_suffix='',