summaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorMark Asselstine <mark.asselstine@windriver.com>2017-12-01 11:30:11 -0500
committerRichard Purdie <richard.purdie@linuxfoundation.org>2017-12-10 22:41:41 +0000
commit4a6364309547d77d1d7a94c48f7c51ceee2b5d1a (patch)
treeff188c644866c323bd7501d9e428f3d686a24b8a
parentebdd054ad85b19d47dd20eab0ba3f31ef5141140 (diff)
downloadopenembedded-core-contrib-4a6364309547d77d1d7a94c48f7c51ceee2b5d1a.tar.gz
openembedded-core-contrib-4a6364309547d77d1d7a94c48f7c51ceee2b5d1a.tar.bz2
openembedded-core-contrib-4a6364309547d77d1d7a94c48f7c51ceee2b5d1a.zip
utils: qemurunner.py: Add wall clock to 'timeout' logging
When debugging issues when timeouts are involved it is always best to have wall clock times included. This helps give confidence that the timeout is in fact run down at the right rate and that no unexpected events were the true cause of a premature running down of the timeout. Having these times in old logs also helps when debugging issues as we have a historic record as to what is a 'typical' time to complete an action. In addition to adding the wall clock times the time to 'login' is now printed making it consistent with the time to 'qemu pid'. Signed-off-by: Mark Asselstine <mark.asselstine@windriver.com> Signed-off-by: Ross Burton <ross.burton@intel.com>
-rw-r--r--meta/lib/oeqa/utils/qemurunner.py20
1 files changed, 14 insertions, 6 deletions
diff --git a/meta/lib/oeqa/utils/qemurunner.py b/meta/lib/oeqa/utils/qemurunner.py
index 0631d43218..8296e989b1 100644
--- a/meta/lib/oeqa/utils/qemurunner.py
+++ b/meta/lib/oeqa/utils/qemurunner.py
@@ -194,7 +194,8 @@ class QemuRunner:
sys.exit(0)
self.logger.debug("runqemu started, pid is %s" % self.runqemu.pid)
- self.logger.debug("waiting at most %s seconds for qemu pid" % self.runqemutime)
+ self.logger.debug("waiting at most %s seconds for qemu pid (%s)" %
+ (self.runqemutime, time.strftime("%D %H:%M:%S")))
endtime = time.time() + self.runqemutime
while not self.is_alive() and time.time() < endtime:
if self.runqemu.poll():
@@ -208,7 +209,8 @@ class QemuRunner:
time.sleep(0.5)
if not self.is_alive():
- self.logger.error("Qemu pid didn't appear in %s seconds" % self.runqemutime)
+ self.logger.error("Qemu pid didn't appear in %s seconds (%s)" %
+ (self.runqemutime, time.strftime("%D %H:%M:%S")))
# Dump all processes to help us to figure out what is going on...
ps = subprocess.Popen(['ps', 'axww', '-o', 'pid,ppid,command '], stdout=subprocess.PIPE).communicate()[0]
processes = ps.decode("utf-8")
@@ -225,7 +227,9 @@ class QemuRunner:
# We are alive: qemu is running
out = self.getOutput(output)
netconf = False # network configuration is not required by default
- self.logger.debug("qemu started in %s seconds - qemu procces pid is %s" % (time.time() - (endtime - self.runqemutime), self.qemupid))
+ self.logger.debug("qemu started in %s seconds - qemu procces pid is %s (%s)" %
+ (time.time() - (endtime - self.runqemutime),
+ self.qemupid, time.strftime("%D %H:%M:%S")))
if get_ip:
cmdline = ''
with open('/proc/%s/cmdline' % self.qemupid) as p:
@@ -269,7 +273,8 @@ class QemuRunner:
return False
self.logger.debug("Output from runqemu:\n%s", out)
- self.logger.debug("Waiting at most %d seconds for login banner" % self.boottime)
+ self.logger.debug("Waiting at most %d seconds for login banner (%s)" %
+ (self.boottime, time.strftime("%D %H:%M:%S")))
endtime = time.time() + self.boottime
socklist = [self.server_socket]
reachedlogin = False
@@ -298,7 +303,9 @@ class QemuRunner:
self.server_socket = qemusock
stopread = True
reachedlogin = True
- self.logger.debug("Reached login banner")
+ self.logger.debug("Reached login banner in %s seconds (%s)" %
+ (time.time() - (endtime - self.boottime),
+ time.strftime("%D %H:%M:%S")))
else:
socklist.remove(sock)
sock.close()
@@ -306,7 +313,8 @@ class QemuRunner:
if not reachedlogin:
- self.logger.debug("Target didn't reached login boot in %d seconds" % self.boottime)
+ self.logger.debug("Target didn't reached login boot in %d seconds (%s)" %
+ (self.boottime, time.strftime("%D %H:%M:%S")))
tail = lambda l: "\n".join(l.splitlines()[-25:])
# in case bootlog is empty, use tail qemu log store at self.msg
lines = tail(bootlog if bootlog else self.msg)