diff mbox series

arm/oeqa: Enable pexpect profiling for testcase debugging

Message ID 20240627125700.2406122-1-peter.hoyes@arm.com
State New
Headers show
Series arm/oeqa: Enable pexpect profiling for testcase debugging | expand

Commit Message

Peter Hoyes June 27, 2024, 12:57 p.m. UTC 
From: Ziad Elhanafy <ziad.elhanafy@arm.com>

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>
---
 meta-arm/lib/oeqa/controllers/fvp.py | 15 +++++++++++++--
 1 file changed, 13 insertions(+), 2 deletions(-)

Comments

Jon Mason June 30, 2024, 10:23 p.m. UTC | #1 
On Thu, 27 Jun 2024 13:57:00 +0100, Peter Hoyes wrote:
> 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).
> 
> [...]

Applied, thanks!

[1/1] arm/oeqa: Enable pexpect profiling for testcase debugging
      commit: 5f647901524c945058a7495a9ff999d191718334

Best regards,
diff mbox series

Patch

diff --git a/meta-arm/lib/oeqa/controllers/fvp.py b/meta-arm/lib/oeqa/controllers/fvp.py
index 80f72aab..dddc10ee 100644
--- a/meta-arm/lib/oeqa/controllers/fvp.py
+++ b/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