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.

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?