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.

2 files changed, 7 insertions, 7 deletions

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?