diff --git a/ipaserver/install/ldapupdate.py b/ipaserver/install/ldapupdate.py index 63bc80df8..c3a5e92f5 100644 --- a/ipaserver/install/ldapupdate.py +++ b/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() diff --git a/ipaserver/install/server/install.py b/ipaserver/install/server/install.py index cfa28737e..b35b9bc85 100644 --- a/ipaserver/install/server/install.py +++ b/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!") diff --git a/ipaserver/install/service.py b/ipaserver/install/service.py index dba10ac2e..327bbf1b2 100644 --- a/ipaserver/install/service.py +++ b/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='',