cloud-init-dev team mailing list archive
-
cloud-init-dev team
-
Mailing list archive
-
Message #00295
[Merge] lp:~smoser/cloud-init/log_time into lp:cloud-init
Scott Moser has proposed merging lp:~smoser/cloud-init/log_time into lp:cloud-init.
Requested reviews:
cloud init development team (cloud-init-dev)
For more details, see:
https://code.launchpad.net/~smoser/cloud-init/log_time/+merge/177666
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.
--
https://code.launchpad.net/~smoser/cloud-init/log_time/+merge/177666
Your team cloud init development team is requested to review the proposed merge of lp:~smoser/cloud-init/log_time into lp:cloud-init.
=== modified file 'ChangeLog'
--- ChangeLog 2013-07-29 16:33:42 +0000
+++ ChangeLog 2013-07-30 18:35:32 +0000
@@ -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)
=== modified file 'bin/cloud-init'
--- bin/cloud-init 2012-09-20 01:19:43 +0000
+++ bin/cloud-init 2013-07-30 18:35:32 +0000
@@ -502,7 +502,9 @@
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__':
=== modified file 'cloudinit/config/cc_growpart.py'
--- cloudinit/config/cc_growpart.py 2013-06-19 06:44:00 +0000
+++ cloudinit/config/cc_growpart.py 2013-07-30 18:35:32 +0000
@@ -264,7 +264,8 @@
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))
=== modified file 'cloudinit/config/cc_resizefs.py'
--- cloudinit/config/cc_resizefs.py 2013-03-26 19:50:25 +0000
+++ cloudinit/config/cc_resizefs.py 2013-07-30 18:35:32 +0000
@@ -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 @@
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 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?
=== modified file 'cloudinit/sources/DataSourceAzure.py'
--- cloudinit/sources/DataSourceAzure.py 2013-07-29 16:02:03 +0000
+++ cloudinit/sources/DataSourceAzure.py 2013-07-30 18:35:32 +0000
@@ -138,13 +138,11 @@
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 @@
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):
=== modified file 'cloudinit/util.py'
--- cloudinit/util.py 2013-07-24 14:37:36 +0000
+++ cloudinit/util.py 2013-07-30 18:35:32 +0000
@@ -1770,3 +1770,38 @@
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