From 66490ebb92af59d148f79aae42a2eddc1ecedb7e Mon Sep 17 00:00:00 2001 From: Scott Moser Date: Tue, 30 Jul 2013 14:23:10 -0400 Subject: add util.log_time helper The reason for this is that more and more things I was wanting to be able to see how long they took. This puts that time logic into a single place. It also supports (by default) reading from /proc/uptime as the timing mechanism. While that is almost certainly slower than time.time(), it does give millisecond granularity and is not affected by 'ntpdate' having run in between the two events. --- ChangeLog | 3 +++ bin/cloud-init | 5 ++++- cloudinit/config/cc_growpart.py | 3 ++- cloudinit/config/cc_resizefs.py | 11 +++++------ cloudinit/sources/DataSourceAzure.py | 14 ++++++-------- cloudinit/util.py | 35 +++++++++++++++++++++++++++++++++++ 6 files changed, 55 insertions(+), 16 deletions(-) diff --git a/ChangeLog b/ChangeLog index a255d24a..68d03376 100644 --- a/ChangeLog +++ b/ChangeLog @@ -11,6 +11,9 @@ - always finalize handlers even if processing failed (LP: #1203368) - support merging into cloud-config via jsonp. (LP: #1200476) - add datasource 'SmartOS' for Joyent Cloud. Adds a dependency on serial. + - add 'log_time' helper to util for timing how long things take + which also reads from uptime. uptime is useful as clock may change during + boot due to ntp. 0.7.2: - add a debian watch file - add 'sudo' entry to ubuntu's default user (LP: #1080717) diff --git a/bin/cloud-init b/bin/cloud-init index c5a5b949..bd9ddc04 100755 --- a/bin/cloud-init +++ b/bin/cloud-init @@ -502,7 +502,10 @@ def main(): signal_handler.attach_handlers() (name, functor) = args.action - return functor(name, args) + + return util.log_time(logfunc=LOG.debug, + msg="cloud-init mode '%s'" % name, uptime=True, + func=functor, args=(name, args)) if __name__ == '__main__': diff --git a/cloudinit/config/cc_growpart.py b/cloudinit/config/cc_growpart.py index 4f8c8f80..ba6c58af 100644 --- a/cloudinit/config/cc_growpart.py +++ b/cloudinit/config/cc_growpart.py @@ -264,7 +264,8 @@ def handle(_name, cfg, _cloud, log, _args): raise e return - resized = resize_devices(resizer, devices) + resized = util.log_time(logfunc=log.debug, msg="resize_devices", + func=resize_devices, args=(resizer, devices)) for (entry, action, msg) in resized: if action == RESIZE.CHANGED: log.info("'%s' resized: %s" % (entry, msg)) diff --git a/cloudinit/config/cc_resizefs.py b/cloudinit/config/cc_resizefs.py index b4ee16b2..56040fdd 100644 --- a/cloudinit/config/cc_resizefs.py +++ b/cloudinit/config/cc_resizefs.py @@ -21,7 +21,6 @@ import errno import os import stat -import time from cloudinit.settings import PER_ALWAYS from cloudinit import util @@ -120,9 +119,12 @@ def handle(name, cfg, _cloud, log, args): if resize_root == NOBLOCK: # Fork to a child that will run # the resize command - util.fork_cb(do_resize, resize_cmd, log) + util.fork_cb( + util.log_time(logfunc=log.debug, msg="backgrounded Resizing", + func=do_resize, args=(resize_cmd, log))) else: - do_resize(resize_cmd, log) + util.log_time(logfunc=log.debug, msg="Resizing", + func=do_resize, args=(resize_cmd, log)) action = 'Resized' if resize_root == NOBLOCK: @@ -132,13 +134,10 @@ def handle(name, cfg, _cloud, log, args): def do_resize(resize_cmd, log): - start = time.time() try: util.subp(resize_cmd) except util.ProcessExecutionError: util.logexc(log, "Failed to resize filesystem (cmd=%s)", resize_cmd) raise - tot_time = time.time() - start - log.debug("Resizing took %.3f seconds", tot_time) # TODO(harlowja): Should we add a fsck check after this to make # sure we didn't corrupt anything? diff --git a/cloudinit/sources/DataSourceAzure.py b/cloudinit/sources/DataSourceAzure.py index 2f28702e..f906b8fa 100644 --- a/cloudinit/sources/DataSourceAzure.py +++ b/cloudinit/sources/DataSourceAzure.py @@ -138,13 +138,11 @@ class DataSourceAzureNet(sources.DataSource): bname = pk['fingerprint'] + ".crt" fp_files += [os.path.join(mycfg['data_dir'], bname)] - start = time.time() - missing = wait_for_files(wait_for + fp_files) + missing = util.log_time(logfunc=LOG.debug, msg="waiting for files", + func=wait_for_files, + args=(wait_for + fp_files,)) if len(missing): LOG.warn("Did not find files, but going on: %s", missing) - else: - LOG.debug("waited %.3f seconds for %d files to appear", - time.time() - start, len(wait_for)) if shcfgxml in missing: LOG.warn("SharedConfig.xml missing, using static instance-id") @@ -206,11 +204,11 @@ def apply_hostname_bounce(hostname, policy, interface, command, command = BOUNCE_COMMAND LOG.debug("pubhname: publishing hostname [%s]", msg) - start = time.time() shell = not isinstance(command, (list, tuple)) # capture=False, see comments in bug 1202758 and bug 1206164. - (output, err) = util.subp(command, shell=shell, capture=False, env=env) - LOG.debug("publishing hostname took %.3f seconds", time.time() - start) + util.log_time(logfunc=LOG.debug, msg="publishing hostname", + func=util.subp, kwargs={'command': command, 'shell': shell, + 'capture': False, 'env': env}) def crtfile_to_pubkey(fname): diff --git a/cloudinit/util.py b/cloudinit/util.py index 8542fe27..b0eb56e6 100644 --- a/cloudinit/util.py +++ b/cloudinit/util.py @@ -1770,3 +1770,38 @@ def which(program): return exe_file return None + + +def log_time(logfunc, msg, func, args=None, kwargs=None, get_uptime=True): + if args is None: + args = [] + if kwargs is None: + kwargs = {} + + start = time.time() + + ustart = None + if get_uptime: + try: + ustart = float(uptime()) + except ValueError: + pass + + try: + ret = func(*args, **kwargs) + finally: + delta = time.time() - start + if ustart is not None: + try: + udelta = float(uptime()) - ustart + except ValueError: + udelta = "N/A" + + tmsg = " took %0.3f seconds" % delta + if get_uptime: + tmsg += "(%0.2f)" % udelta + try: + logfunc(msg + tmsg) + except: + pass + return ret -- cgit v1.2.3 From 0ca150b08433fbc57e10d599a46e300142c955c5 Mon Sep 17 00:00:00 2001 From: Scott Moser Date: Tue, 30 Jul 2013 14:28:09 -0400 Subject: set reading /proc/uptime to false by default. reading /proc/uptime is going to be slower, and no reason to do it on most things. Better to only do it when you suspect maybe a need for it. --- bin/cloud-init | 5 ++--- cloudinit/sources/DataSourceAzure.py | 5 +++-- cloudinit/util.py | 2 +- 3 files changed, 6 insertions(+), 6 deletions(-) diff --git a/bin/cloud-init b/bin/cloud-init index bd9ddc04..b4f9fd07 100755 --- a/bin/cloud-init +++ b/bin/cloud-init @@ -503,9 +503,8 @@ def main(): (name, functor) = args.action - return util.log_time(logfunc=LOG.debug, - msg="cloud-init mode '%s'" % name, uptime=True, - func=functor, args=(name, args)) + return util.log_time(logfunc=LOG.debug, msg="cloud-init mode '%s'" % name, + get_uptime=True, func=functor, args=(name, args)) if __name__ == '__main__': diff --git a/cloudinit/sources/DataSourceAzure.py b/cloudinit/sources/DataSourceAzure.py index f906b8fa..1a74de21 100644 --- a/cloudinit/sources/DataSourceAzure.py +++ b/cloudinit/sources/DataSourceAzure.py @@ -207,8 +207,9 @@ def apply_hostname_bounce(hostname, policy, interface, command, shell = not isinstance(command, (list, tuple)) # capture=False, see comments in bug 1202758 and bug 1206164. util.log_time(logfunc=LOG.debug, msg="publishing hostname", - func=util.subp, kwargs={'command': command, 'shell': shell, - 'capture': False, 'env': env}) + get_uptime=True, func=util.subp, + kwargs={'command': command, 'shell': shell, 'capture': False, + 'env': env}) def crtfile_to_pubkey(fname): diff --git a/cloudinit/util.py b/cloudinit/util.py index b0eb56e6..4a74ba57 100644 --- a/cloudinit/util.py +++ b/cloudinit/util.py @@ -1772,7 +1772,7 @@ def which(program): return None -def log_time(logfunc, msg, func, args=None, kwargs=None, get_uptime=True): +def log_time(logfunc, msg, func, args=None, kwargs=None, get_uptime=False): if args is None: args = [] if kwargs is None: -- cgit v1.2.3