mirrors/poky
1
0
Fork 0
mirror of https://git.yoctoproject.org/poky synced 2026-06-05 14:29:48 +00:00
Code Issues Projects Releases Wiki Activity

utils: qemurunner.py: Add wall clock to 'timeout' logging

Browse Source 
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'.

(From OE-Core rev: 4a6364309547d77d1d7a94c48f7c51ceee2b5d1a)

Signed-off-by: Mark Asselstine <mark.asselstine@windriver.com>
Signed-off-by: Ross Burton <ross.burton@intel.com>
Signed-off-by: Richard Purdie <richard.purdie@linuxfoundation.org>
This commit is contained in:
Mark Asselstine
2017-12-01 11:30:11 -05:00
committed by Richard Purdie
parent 5719b37bcd
commit 6fca24f499
1 changed files with 14 additions and 6 deletions
Download Patch File Download Diff File Expand all files Collapse all files
meta/lib/oeqa/utils/qemurunner.py
+14 -6
View File
@@ -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)