qemurunner: Add info log for qemu startup

Add a couple of logging info to track time between activities, first
is from after the Popen(launch_cmd) to after qmp.connect(), second is
from qmp.connect() to the release of the qemu via the qmp("cont") command
this includes the mmap() activity.

Example output:
QMP connected to QEMU at 06/24/21 11:11:56 and took 0.9556229114532471 seconds from launch
QMP released QEMU at 06/24/21 11:11:56 and took 0.26789021492004395 seconds from connect

(From OE-Core rev: 547f49230ba4ebeefe5b696e0460ebaffa8e91e6)

Signed-off-by: Saul Wold <saul.wold@windriver.com>
Signed-off-by: Alexandre Belloni <alexandre.belloni@bootlin.com>
Signed-off-by: Richard Purdie <richard.purdie@linuxfoundation.org>

1 files changed, 8 insertions, 0 deletions

diff --git a/meta/lib/oeqa/utils/qemurunner.py b/meta/lib/oeqa/utils/qemurunner.py
index abbc7f7d1f..c7f7860317 100644
--- a/meta/lib/oeqa/utils/qemurunner.py
+++ b/meta/lib/oeqa/utils/qemurunner.py
@@ -236,6 +236,7 @@ class QemuRunner:
         # to be a proper fix but this will suffice for now.
         self.runqemu = subprocess.Popen(launch_cmd, shell=True, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, stdin=subprocess.PIPE, preexec_fn=os.setpgrp, env=env, cwd=self.tmpdir)
         output = self.runqemu.stdout
+        launch_time = time.time()
 
         #
         # We need the preexec_fn above so that all runqemu processes can easily be killed
@@ -339,6 +340,10 @@ class QemuRunner:
 
             try:
                 self.qmp.connect()
+                connect_time = time.time()
+                self.logger.info("QMP connected to QEMU at %s and took %s seconds" %
+                                  (time.strftime("%D %H:%M:%S"),
+                                   time.time() - launch_time))
             except OSError as msg:
                 self.logger.warning("Failed to connect qemu monitor socket: %s File: %s" % (msg, msg.filename))
                 return False
@@ -367,6 +372,9 @@ class QemuRunner:
 
         # Release the qemu process to continue running
         self.run_monitor('cont')
+        self.logger.info("QMP released QEMU at %s and took %s seconds from connect" %
+                          (time.strftime("%D %H:%M:%S"),
+                           time.time() - connect_time))
 
         # We are alive: qemu is running
         out = self.getOutput(output)