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

@@ -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)

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__':

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))

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?

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):

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