From patchwork Thu Jun 27 12:57:00 2024 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Peter Hoyes X-Patchwork-Id: 45695 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from aws-us-west-2-korg-lkml-1.web.codeaurora.org (localhost.localdomain [127.0.0.1]) by smtp.lore.kernel.org (Postfix) with ESMTP id 2D87AC2BD09 for ; Thu, 27 Jun 2024 12:57:53 +0000 (UTC) Received: from foss.arm.com (foss.arm.com [217.140.110.172]) by mx.groups.io with SMTP id smtpd.web10.7218.1719493068884316089 for ; Thu, 27 Jun 2024 05:57:49 -0700 Authentication-Results: mx.groups.io; dkim=none (message not signed); spf=pass (domain: arm.com, ip: 217.140.110.172, mailfrom: peter.hoyes@arm.com) Received: from usa-sjc-imap-foss1.foss.arm.com (unknown [10.121.207.14]) by usa-sjc-mx-foss1.foss.arm.com (Postfix) with ESMTP id 37F44367; Thu, 27 Jun 2024 05:58:13 -0700 (PDT) Received: from e133390.cambridge.arm.com (e133390.arm.com [10.1.36.164]) by usa-sjc-imap-foss1.foss.arm.com (Postfix) with ESMTPSA id 660AB3F766; Thu, 27 Jun 2024 05:57:47 -0700 (PDT) From: Peter Hoyes To: meta-arm@lists.yoctoproject.org Cc: Ziad Elhanafy , Divin Raj Subject: [PATCH] arm/oeqa: Enable pexpect profiling for testcase debugging Date: Thu, 27 Jun 2024 13:57:00 +0100 Message-Id: <20240627125700.2406122-1-peter.hoyes@arm.com> X-Mailer: git-send-email 2.34.1 MIME-Version: 1.0 List-Id: X-Webhook-Received: from li982-79.members.linode.com [45.33.32.79] by aws-us-west-2-korg-lkml-1.web.codeaurora.org with HTTPS for ; Thu, 27 Jun 2024 12:57:53 -0000 X-Groupsio-URL: https://lists.yoctoproject.org/g/meta-arm/message/5846 From: Ziad Elhanafy 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 Signed-off-by: Ziad Elhanafy Signed-off-by: Peter Hoyes --- meta-arm/lib/oeqa/controllers/fvp.py | 15 +++++++++++++-- 1 file changed, 13 insertions(+), 2 deletions(-) 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