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:45:19 +0000
commit6fca24f4992bcfb7bee13b201a7b8416517e3f70 (patch)
treecee8173ee5efe0f5ecec731a6d44f7a010442d90
parent5719b37bcd25322b8d764b12b65e57877205cffb (diff)
downloadpoky-6fca24f4992bcfb7bee13b201a7b8416517e3f70.tar.gz
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'. (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>
-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:
194 sys.exit(0) 194 sys.exit(0)
195 195
196 self.logger.debug("runqemu started, pid is %s" % self.runqemu.pid) 196 self.logger.debug("runqemu started, pid is %s" % self.runqemu.pid)
197 self.logger.debug("waiting at most %s seconds for qemu pid" % self.runqemutime) 197 self.logger.debug("waiting at most %s seconds for qemu pid (%s)" %
198 (self.runqemutime, time.strftime("%D %H:%M:%S")))
198 endtime = time.time() + self.runqemutime 199 endtime = time.time() + self.runqemutime
199 while not self.is_alive() and time.time() < endtime: 200 while not self.is_alive() and time.time() < endtime:
200 if self.runqemu.poll(): 201 if self.runqemu.poll():
@@ -208,7 +209,8 @@ class QemuRunner:
208 time.sleep(0.5) 209 time.sleep(0.5)
209 210
210 if not self.is_alive(): 211 if not self.is_alive():
211 self.logger.error("Qemu pid didn't appear in %s seconds" % self.runqemutime) 212 self.logger.error("Qemu pid didn't appear in %s seconds (%s)" %
213 (self.runqemutime, time.strftime("%D %H:%M:%S")))
212 # Dump all processes to help us to figure out what is going on... 214 # Dump all processes to help us to figure out what is going on...
213 ps = subprocess.Popen(['ps', 'axww', '-o', 'pid,ppid,command '], stdout=subprocess.PIPE).communicate()[0] 215 ps = subprocess.Popen(['ps', 'axww', '-o', 'pid,ppid,command '], stdout=subprocess.PIPE).communicate()[0]
214 processes = ps.decode("utf-8") 216 processes = ps.decode("utf-8")
@@ -225,7 +227,9 @@ class QemuRunner:
225 # We are alive: qemu is running 227 # We are alive: qemu is running
226 out = self.getOutput(output) 228 out = self.getOutput(output)
227 netconf = False # network configuration is not required by default 229 netconf = False # network configuration is not required by default
228 self.logger.debug("qemu started in %s seconds - qemu procces pid is %s" % (time.time() - (endtime - self.runqemutime), self.qemupid)) 230 self.logger.debug("qemu started in %s seconds - qemu procces pid is %s (%s)" %
231 (time.time() - (endtime - self.runqemutime),
232 self.qemupid, time.strftime("%D %H:%M:%S")))
229 if get_ip: 233 if get_ip:
230 cmdline = '' 234 cmdline = ''
231 with open('/proc/%s/cmdline' % self.qemupid) as p: 235 with open('/proc/%s/cmdline' % self.qemupid) as p:
@@ -269,7 +273,8 @@ class QemuRunner:
269 return False 273 return False
270 274
271 self.logger.debug("Output from runqemu:\n%s", out) 275 self.logger.debug("Output from runqemu:\n%s", out)
272 self.logger.debug("Waiting at most %d seconds for login banner" % self.boottime) 276 self.logger.debug("Waiting at most %d seconds for login banner (%s)" %
277 (self.boottime, time.strftime("%D %H:%M:%S")))
273 endtime = time.time() + self.boottime 278 endtime = time.time() + self.boottime
274 socklist = [self.server_socket] 279 socklist = [self.server_socket]
275 reachedlogin = False 280 reachedlogin = False
@@ -298,7 +303,9 @@ class QemuRunner:
298 self.server_socket = qemusock 303 self.server_socket = qemusock
299 stopread = True 304 stopread = True
300 reachedlogin = True 305 reachedlogin = True
301 self.logger.debug("Reached login banner") 306 self.logger.debug("Reached login banner in %s seconds (%s)" %
307 (time.time() - (endtime - self.boottime),
308 time.strftime("%D %H:%M:%S")))
302 else: 309 else:
303 socklist.remove(sock) 310 socklist.remove(sock)
304 sock.close() 311 sock.close()
@@ -306,7 +313,8 @@ class QemuRunner:
306 313
307 314
308 if not reachedlogin: 315 if not reachedlogin:
309 self.logger.debug("Target didn't reached login boot in %d seconds" % self.boottime) 316 self.logger.debug("Target didn't reached login boot in %d seconds (%s)" %
317 (self.boottime, time.strftime("%D %H:%M:%S")))
310 tail = lambda l: "\n".join(l.splitlines()[-25:]) 318 tail = lambda l: "\n".join(l.splitlines()[-25:])
311 # in case bootlog is empty, use tail qemu log store at self.msg 319 # in case bootlog is empty, use tail qemu log store at self.msg
312 lines = tail(bootlog if bootlog else self.msg) 320 lines = tail(bootlog if bootlog else self.msg)