arm/oeqa: Enable pexpect profiling for testcase debugging

This patch enables logging with timestamps for individual pexpect
assertions to ease the debugging of failed tests and the tuning of
timeouts. It measures the execution time of all pexpect calls and logs
the actual duration for each.

Only "callable" pexpect calls are timed (e.g. expect, sendline, but not
before or after).

Signed-off-by: Divin Raj <divin.raj@arm.com>
Signed-off-by: Ziad Elhanafy <ziad.elhanafy@arm.com>
Signed-off-by: Peter Hoyes <peter.hoyes@arm.com>
Signed-off-by: Jon Mason <jon.mason@arm.com>

meta-arm/lib/oeqa/controllers/fvp.py

@@ -3,6 +3,7 @@ import enum
 import pathlib
 import pexpect
 import os
+import time
 
 from oeqa.core.target.ssh import OESSHTarget
 from fvp import runner
@@ -127,9 +128,19 @@ class OEFVPTarget(OESSHTarget):
         def call_pexpect(terminal, *args, **kwargs):
             attr = getattr(self.terminals[terminal], name)
             if callable(attr):
-                return attr(*args, **kwargs)
+                self.logger.debug(f"Calling {name} on {terminal} : with arguments -> {args}  :  {kwargs}")
+                start_time = time.monotonic()  # Record the start time
+
+                attr = getattr(self.terminals[terminal], name)
+                result = attr(*args, **kwargs)
+
+                end_time = time.monotonic()  # Record the end time
+                elapsed_time = end_time - start_time
+                self.logger.debug(f"Execution time for result: [ {result} ] - elapsed_time: {elapsed_time} seconds")
             else:
-                return attr
+                result = attr
+
+            return result
 
         return call_pexpect