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 from /proc/uptime as the timing mechanism.

While reading /proc/uptime 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.

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..b4f9fd07 100755
--- a/bin/cloud-init
+++ b/bin/cloud-init
@@ -502,7 +502,9 @@ 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,
+                         get_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..1a74de21 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,12 @@ 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",
+        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 8542fe27..4a74ba57 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=False):
+    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