[nrf fromlist] samples: boards: nordic: coresight_stm: Test STM dictionary mode

Extend STM logger test.
Use nrfutil trace to decode STM logs in dictionary mode.
Add check if timing for a log message is below a threshold.
Set thresholds experimentally.

Upstream PR: zephyrproject-rtos/zephyr#78947

Signed-off-by: Sebastian Głąb <[email protected]>

Author: nordic-segl

.github/test-spec.yml

@@ -363,6 +363,8 @@
   - "samples/drivers/adc/**/*"
   - "samples/basic/fade_led/**/*"
   - "samples/basic/blinky_pwm/**/*"
+  - "samples/boards/nrf/coresight_stm/**/*"
+  - "samples/boards/nordic/coresight_stm/**/*"
   - "samples/subsys/usb/mass/**/*"
   - "samples/subsys/usb/cdc_acm/**/*"
   - "modules/hal_nordic/**/*"

samples/boards/nrf/coresight_stm/pytest/test_stm.py

@@ -0,0 +1,304 @@
+#
+# Copyright (c) 2024 Nordic Semiconductor ASA
+#
+# SPDX-License-Identifier: Apache-2.0
+#
+
+import logging
+import re
+import subprocess
+from dataclasses import dataclass
+from pathlib import Path
+from time import sleep
+from typing import Optional
+
+import psutil
+from twister_harness import DeviceAdapter
+
+logger = logging.getLogger(__name__)
+
+
+@dataclass
+class STMLimits:
+    log_0_arg: Optional[float]
+    log_1_arg: Optional[float]
+    log_2_arg: Optional[float]
+    log_3_arg: Optional[float]
+    log_str: Optional[float]
+    tracepoint: Optional[float]
+    tracepoint_d32: Optional[float]
+    tolerance: Optional[float]
+
+
+# https://github.com/zephyrproject-rtos/zephyr/blob/main/drivers/misc/coresight/nrf_etr.c#L102
+STM_M_ID = {
+    "sec": 33,
+    "app": 34,
+    "rad": 35,
+    "mod": 36,
+    "sys": 44,
+    "flpr": 45,
+    "ppr": 46,
+    "hw": 128,
+}
+
+
+def _check_benchmark_results(output: str, core: str, constraints: STMLimits) -> None:
+    """
+    Use regular expressions to parse 'output' string.
+    Search for benchmark results related to 'core' coprocessor.
+    Check that benchamrk results are lower than limits provided in 'constraints'.
+    """
+
+    latency_msg_0_str = re.search(
+        rf"{core}: Timing for log message with 0 arguments: (.+)us", output
+    ).group(1)
+    assert latency_msg_0_str is not None, "Timing for log message with 0 arguments NOT found"
+    # check value
+    latency_msg_0 = float(latency_msg_0_str)
+    threshold = (constraints.log_0_arg) * (1 + constraints.tolerance)
+    assert (
+        latency_msg_0 < threshold
+    ), f"Timing for log message with 0 arguments {latency_msg_0} us exceeds threshold {threshold} us"
+
+
+    latency_msg_1_str = re.search(
+        rf"{core}: Timing for log message with 1 argument: (.+)us", output
+    ).group(1)
+    assert latency_msg_1_str is not None, "Timing for log message with 1 argument NOT found"
+    # check value
+    latency_msg_1 = float(latency_msg_1_str)
+    threshold = (constraints.log_1_arg) * (1 + constraints.tolerance)
+    assert (
+        latency_msg_1 < threshold
+    ), f"Timing for log message with 1 argument {latency_msg_1} us exceeds threshold {threshold} us"
+
+
+    latency_msg_2_str = re.search(
+        rf"{core}: Timing for log message with 2 arguments: (.+)us", output
+    ).group(1)
+    assert latency_msg_2_str is not None, "Timing for log message with 2 arguments NOT found"
+    # check value
+    latency_msg_2 = float(latency_msg_2_str)
+    threshold = (constraints.log_2_arg) * (1 + constraints.tolerance)
+    assert (
+        latency_msg_2 < threshold
+    ), f"Timing for log message with 2 arguments {latency_msg_2} us exceeds threshold {threshold} us"
+
+
+    latency_msg_3_str = re.search(
+        rf"{core}: Timing for log message with 3 arguments: (.+)us", output
+    ).group(1)
+    assert latency_msg_3_str is not None, "Timing for log message with 3 arguments NOT found"
+    # check value
+    latency_msg_3 = float(latency_msg_3_str)
+    threshold = (constraints.log_3_arg) * (1 + constraints.tolerance)
+    assert (
+        latency_msg_3 < threshold
+    ), f"Timing for log message with 3 arguments {latency_msg_3} us exceeds threshold {threshold} us"
+
+
+    latency_msg_string_str = re.search(
+        rf"{core}: Timing for log_message with string: (.+)us", output
+    ).group(1)
+    assert latency_msg_string_str is not None, "Timing for log_message with string NOT found"
+    # check value
+    latency_msg_string = float(latency_msg_string_str)
+    threshold = (constraints.log_str) * (1 + constraints.tolerance)
+    assert (
+        latency_msg_string < threshold
+    ), f"Timing for log message with string {latency_msg_string} us exceeds threshold {threshold} us"
+
+
+    latency_tracepoint_str = re.search(
+        rf"{core}: Timing for tracepoint: (.+)us", output
+    ).group(1)
+    assert latency_tracepoint_str is not None, "Timing for tracepoint NOT found"
+    # check value
+    latency_tracepoint = float(latency_tracepoint_str)
+    threshold = (constraints.tracepoint) * (1 + constraints.tolerance)
+    assert (
+        latency_tracepoint < threshold
+    ), f"Timing for tracepoint {latency_tracepoint} us exceeds threshold {threshold} us"
+
+
+    latency_tracepoint_d32_str = re.search(
+        rf"{core}: Timing for tracepoint_d32: (.+)us", output
+    ).group(1)
+    assert latency_tracepoint_d32_str is not None, "Timing for tracepoint_d32 NOT found"
+    # check value
+    latency_tracepoint_d32 = float(latency_tracepoint_d32_str)
+    threshold = (constraints.tracepoint_d32) * (1 + constraints.tolerance)
+    assert (
+        latency_tracepoint_d32 < threshold
+    ), f"Timing for tracepoint_d32 {latency_tracepoint_d32} us exceeds threshold {threshold} us"
+
+
+# nrfutil starts children processes
+# when subprocess.terminate(nrfutil_process) is executed, only the parent terminates
+# this blocks serial port for other uses
+def _kill(proc):
+    try:
+        for child in psutil.Process(proc.pid).children(recursive=True):
+            child.kill()
+        proc.kill()
+    except Exception as e:
+        logger.exception(f'Could not kill nrfutil - {e}')
+
+
+def _nrfutil_dictionary_from_serial(
+    dut: DeviceAdapter,
+    decoded_file_name: str = "output.txt",
+    collect_time: float = 60.0,
+) -> None:
+    UART_PATH = dut.device_config.serial
+    UART_BAUDRATE = dut.device_config.baud
+    dut.close()
+
+    logger.debug(f"Using serial: {UART_PATH}")
+
+    if Path(f"{decoded_file_name}").exists():
+        logger.warning("Output file already exists!")
+
+    # prepare database config string
+    BUILD_DIR = str(dut.device_config.build_dir)
+    logger.debug(f"{BUILD_DIR=}")
+    config_str = f"{STM_M_ID['app']}:{BUILD_DIR}/coresight_stm/zephyr/log_dictionary.json"
+    config_str = config_str + f",{STM_M_ID['rad']}:{BUILD_DIR}/remote/zephyr/log_dictionary.json"
+    logger.debug(f"{config_str=}")
+
+    cmd = (
+        "nrfutil trace stm --database-config "
+        f"{config_str} "
+        f"--input-serialport {UART_PATH} --baudrate {UART_BAUDRATE} "
+        f"--output-ascii {decoded_file_name}"
+    )
+    try:
+        # run nrfutil trace in background non-blocking
+        logger.info(f"Executing:\n{cmd}")
+        proc = subprocess.Popen(cmd.split(), stdout=subprocess.DEVNULL)
+    except OSError as exc:
+        logger.error(f"Unable to start nrfutil trace:\n{cmd}\n{exc}")
+    try:
+        proc.wait(collect_time)
+    except subprocess.TimeoutExpired:
+        pass
+    finally:
+        _kill(proc)
+
+
+def test_STM_decoded(dut: DeviceAdapter):
+    """
+    Run sample.boards.nrf.coresight_stm from samples/boards/nrf/coresight_stm sample.
+    Both Application and Radio cores use STM for logging.
+    STM proxy (Application core) decodes logs from all domains.
+    After reset, coprocessors execute code in expected way and Application core
+    outputs STM traces on UART port.
+    """
+    app_constraints = STMLimits(
+        # all values in us
+        log_0_arg=3.3,
+        log_1_arg=2.4,
+        log_2_arg=2.1,
+        log_3_arg=2.1,
+        log_str=4.6,
+        tracepoint=0.5,
+        tracepoint_d32=0.5,
+        tolerance=0.5,
+    )
+    rad_constraints = STMLimits(
+        # all values in us
+        log_0_arg=6.6,
+        log_1_arg=5.8,
+        log_2_arg=6.0,
+        log_3_arg=6.4,
+        log_str=7.1,
+        tracepoint=0.5,
+        tracepoint_d32=0.5,
+        tolerance=0.5,
+    )
+    # nrf54h20 prints immediately after it is flashed.
+    # Wait a bit to skipp logs from previous test.
+    sleep(3)
+
+    # Get output from serial port
+    output = "\n".join(dut.readlines())
+
+    # check results on Application core
+    _check_benchmark_results(
+        output=output,
+        core='app',
+        constraints=app_constraints
+    )
+
+    # check results on Radio core
+    _check_benchmark_results(
+        output=output,
+        core='rad',
+        constraints=rad_constraints
+    )
+
+def test_STM_dictionary_mode(dut: DeviceAdapter):
+    """
+    Run sample.boards.nrf.coresight_stm.dict from samples/boards/nrf/coresight_stm sample.
+    Both Application and Radio cores use STM for logging.
+    STM proxy (Application core) prints on serial port raw logs from all domains.
+    Nrfutil trace is used to decode STM logs.
+    After reset, coprocessors execute code in expected way and Application core
+    outputs STM traces on UART port.
+    """
+    BUILD_DIR = str(dut.device_config.build_dir)
+    test_filename = f"{BUILD_DIR}/stm_benchmark_dictionary_from_serial.txt"
+    COLLECT_TIMEOUT = 10.0
+    app_constraints = STMLimits(
+        # all values in us
+        log_0_arg=1.8,
+        log_1_arg=0.7,
+        log_2_arg=0.7,
+        log_3_arg=1.5,
+        log_str=3.4,
+        tracepoint=0.5,
+        tracepoint_d32=0.5,
+        tolerance=0.5,
+    )
+    rad_constraints = STMLimits(
+        # all values in us
+        log_0_arg=2.0,
+        log_1_arg=0.8,
+        log_2_arg=0.9,
+        log_3_arg=1.7,
+        log_str=4.0,
+        tracepoint=0.5,
+        tracepoint_d32=0.5,
+        tolerance=0.5,
+    )
+
+    # use nrfutil trace to decode logs
+    _nrfutil_dictionary_from_serial(
+        dut=dut,
+        decoded_file_name=f"{test_filename}",
+        collect_time=COLLECT_TIMEOUT,
+    )
+
+    # read decoded logs
+    with open(f"{test_filename}", errors="ignore") as decoded_file:
+        decoded_file_content = decoded_file.read()
+
+    # if nothing in decoded_file, stop test
+    assert(
+        len(decoded_file_content) > 0
+    ), f"File {test_filename} is empty"
+
+    # check results on Application core
+    _check_benchmark_results(
+        output=decoded_file_content,
+        core='app',
+        constraints=app_constraints
+    )
+
+    # check results on Radio core
+    _check_benchmark_results(
+        output=decoded_file_content,
+        core='rad',
+        constraints=rad_constraints
+    )

samples/boards/nrf/coresight_stm/sample.yaml

@@ -1,21 +1,36 @@
 sample:
   name: Logging using Coresight STM on nrf54h20
+
 common:
+  tags: stm
   sysbuild: true
+  platform_allow:
+    - nrf54h20dk/nrf54h20/cpuapp
+  integration_platforms:
+    - nrf54h20dk/nrf54h20/cpuapp
+
 tests:
   sample.boards.nrf.coresight_stm.dict:
-    platform_allow:
-      - nrf54h20dk/nrf54h20/cpuapp
-    integration_platforms:
-      - nrf54h20dk/nrf54h20/cpuapp
-    build_only: true
+    filter: not CONFIG_COVERAGE
+    harness: pytest
+    harness_config:
+      pytest_dut_scope: session
+      pytest_root:
+        - "pytest/test_stm.py::test_STM_dictionary_mode"
     required_snippets:
       - nordic-log-stm-dict
+
   sample.boards.nrf.coresight_stm:
-    platform_allow:
-      - nrf54h20dk/nrf54h20/cpuapp
-    integration_platforms:
-      - nrf54h20dk/nrf54h20/cpuapp
+    filter: not CONFIG_COVERAGE
+    harness: pytest
+    harness_config:
+      pytest_dut_scope: session
+      pytest_root:
+        - "pytest/test_stm.py::test_STM_decoded"
+    required_snippets:
+      - nordic-log-stm
+
+  sample.boards.nrf.coresight_stm.local_uart:
     harness: console
     harness_config:
       type: multi_line
@@ -26,20 +41,23 @@ tests:
         - "Timing for log message with 2 arguments:"
         - "Timing for log message with 3 arguments:"
         - "Timing for log_message with string:"
+
+  sample.boards.nrf.coresight_stm.coverage:
+    filter: CONFIG_COVERAGE
+    harness: console
+    harness_config:
+      type: one_line
+      regex:
+        - "GCOV_COVERAGE_DUMP_END"
     required_snippets:
       - nordic-log-stm
-  sample.boards.nrf.coresight_stm.local_uart:
-    platform_allow:
-      - nrf54h20dk/nrf54h20/cpuapp
-    integration_platforms:
-      - nrf54h20dk/nrf54h20/cpuapp
+
+  sample.boards.nrf.coresight_stm.dict.coverage:
+    filter: CONFIG_COVERAGE
     harness: console
     harness_config:
-      type: multi_line
-      ordered: true
+      type: one_line
       regex:
-        - "Timing for log message with 0 arguments:"
-        - "Timing for log message with 1 argument:"
-        - "Timing for log message with 2 arguments:"
-        - "Timing for log message with 3 arguments:"
-        - "Timing for log_message with string:"
+        - "GCOV_COVERAGE_DUMP_END"
+    required_snippets:
+      - nordic-log-stm-dict