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

Extend STM logger test.
Use nrfutil trace to decode STM logs in dictionary mode.

Signed-off-by: Sebastian Głąb <[email protected]>
(cherry picked from commit f0eba33)
(cherry picked from commit 4ba4768)

Author: nordic-segl

samples/boards/nordic/coresight_stm/README.rst

@@ -0,0 +1,102 @@
+.. zephyr:code-sample:: coresight_stm_sample
+   :name: Coresight STM benchmark
+   :relevant-api: log_api
+
+Overview
+********
+
+This sample presents how to enable STM logging on nRF54H20 platform.
+
+Also, it prints timing for different log messages.
+Thus, performance of different loggers can be compared.
+
+There are three sample configurations in the :file:`sample.yaml`.
+
+* **sample.boards.nrf.coresight_stm.local_uart**
+
+  This configuration doesn't use STM.
+  Logs are printed on local console.
+
+* **sample.boards.nrf.coresight_stm**
+
+  This configuration use STM.
+  Application, Radio, PPR and FLPR cores send logs to an ETR buffer.
+  Proxy (Application core) gets logs from the ETR buffer, decodes STPv2 data
+  and prints human readable logs on UART.
+
+* **sample.boards.nrf.coresight_stm.dict**
+
+  This sample uses STM logging in dictionary mode.
+  Application, Radio, PPR and FLPR cores send logs to the ETR buffer.
+  Proxy (Application core) forwards data from the ETR to the host using UART.
+  Host tool is needed to decode the logs.
+
+Requirements
+************
+
+This application uses nRF54H20 DK board for the demo.
+
+**sample.boards.nrf.coresight_stm.dict** requires host tool like ``nrfutil trace``
+to decode the traces.
+
+Building and running
+********************
+
+To build the sample, use configuration setups from the :file:`sample.yaml` using the ``-T`` option.
+See the example:
+
+nRF54H20 DK
+
+  .. code-block:: console
+
+     west build -p -b nrf54h20dk/nrf54h20/cpuapp -T sample.boards.nrf.coresight_stm .
+
+Sample Output
+=============
+
+.. code-block:: console
+
+   *** Using Zephyr OS v3.6.99-5bb7bb0af17c ***
+   (...)
+   [00:00:00.227,264] <inf> app/app: test with one argument 100
+   [00:00:00.227,265] <inf> app/app: test with one argument 100
+   (...)
+   [00:00:00.585,558] <inf> rad/app: test with one argument 100
+   [00:00:00.585,569] <inf> rad/app: test with one argument 100
+   (...)
+   [00:00:00.624,408] <inf> ppr/app: test with one argument 100
+   [00:00:00.624,433] <inf> ppr/app: test with one argument 100
+   (...)
+   [00:00:00.625,249] <inf> flpr/app: test with one argument 100
+   [00:00:00.625,251] <inf> flpr/app: test with one argument 100
+   (...)
+   rad: Timing for log message with 0 arguments: 5.10us
+   rad: Timing for log message with 1 argument: 6.10us
+   rad: Timing for log message with 2 arguments: 6.0us
+   rad: Timing for log message with 3 arguments: 6.40us
+   rad: Timing for log_message with string: 7.10us
+   rad: Timing for tracepoint: 0.5us
+   rad: Timing for tracepoint_d32: 0.5us
+   flpr: Timing for log message with 0 arguments: 1.20us
+   flpr: Timing for log message with 1 argument: 1.20us
+   flpr: Timing for log message with 2 arguments: 1.20us
+   flpr: Timing for log message with 3 arguments: 1.30us
+   flpr: Timing for log_message with string: 3.0us
+   flpr: Timing for tracepoint: 0.0us
+   flpr: Timing for tracepoint_d32: 0.0us
+   app: Timing for log message with 0 arguments: 1.80us
+   app: Timing for log message with 1 argument: 2.0us
+   app: Timing for log message with 2 arguments: 2.0us
+   app: Timing for log message with 3 arguments: 2.10us
+   app: Timing for log_message with string: 4.40us
+   app: Timing for tracepoint: 0.10us
+   app: Timing for tracepoint_d32: 0.10us
+   ppr: Timing for log message with 0 arguments: 25.20us
+   ppr: Timing for log message with 1 argument: 26.20us
+   ppr: Timing for log message with 2 arguments: 26.90us
+   ppr: Timing for log message with 3 arguments: 27.40us
+   ppr: Timing for log_message with string: 64.80us
+   ppr: Timing for tracepoint: 0.30us
+   ppr: Timing for tracepoint_d32: 0.25us
+
+For logging on NRF54H20 using ARM Coresight STM see :ref:`logging_cs_stm`.

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

@@ -0,0 +1,258 @@
+#
+# Copyright (c) 2024 Nordic Semiconductor ASA
+#
+# SPDX-License-Identifier: Apache-2.0
+#
+
+import logging
+import re
+import subprocess
+from pathlib import Path
+from time import sleep
+
+import psutil
+from twister_harness import DeviceAdapter
+
+logger = logging.getLogger(__name__)
+
+SB_CONFIG_APP_CPUPPR_RUN = None
+SB_CONFIG_APP_CPUFLPR_RUN = None
+
+# 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 _analyse_autoconf(filepath: str) -> None:
+    global SB_CONFIG_APP_CPUPPR_RUN
+    global SB_CONFIG_APP_CPUFLPR_RUN
+
+    SB_CONFIG_APP_CPUPPR_RUN = False
+    SB_CONFIG_APP_CPUFLPR_RUN = False
+
+    # Parse contents of {BUILD_DIR}/_sysbuild/autoconf.h
+    with open(f"{filepath}", errors="ignore") as autoconf:
+        for line in autoconf:
+            if "SB_CONFIG_APP_CPUPPR_RUN 1" in line:
+                SB_CONFIG_APP_CPUPPR_RUN = True
+                continue
+            if "SB_CONFIG_APP_CPUFLPR_RUN 1" in line:
+                SB_CONFIG_APP_CPUFLPR_RUN = True
+    logger.debug(f"{SB_CONFIG_APP_CPUPPR_RUN=}")
+    logger.debug(f"{SB_CONFIG_APP_CPUFLPR_RUN=}")
+
+
+def _check_benchmark_results(output: str, core: str) -> None:
+    """
+    Use regular expressions to parse 'output' string.
+    Search for benchmark results related to 'core' coprocessor.
+    """
+
+    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"
+
+    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"
+
+    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"
+
+    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"
+
+    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"
+
+    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"
+
+    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"
+
+
+# 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 += f",{STM_M_ID['rad']}:{BUILD_DIR}/remote_rad/zephyr/log_dictionary.json"
+    if SB_CONFIG_APP_CPUPPR_RUN:
+        config_str += f",{STM_M_ID['ppr']}:{BUILD_DIR}/remote_ppr/zephyr/log_dictionary.json"
+    if SB_CONFIG_APP_CPUFLPR_RUN:
+        config_str += f",{STM_M_ID['flpr']}:{BUILD_DIR}/remote_flpr/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.
+    """
+    BUILD_DIR = str(dut.device_config.build_dir)
+    autoconf_file = f"{BUILD_DIR}/_sysbuild/autoconf.h"
+
+    # nrf54h20 prints immediately after it is flashed.
+    # Wait a bit to skipp logs from previous test.
+    sleep(4)
+
+    # Get output from serial port
+    output = "\n".join(dut.readlines())
+
+    # set SB_CONFIG_APP_CPUPPR_RUN, SB_CONFIG_APP_CPUFLPR_RUN
+    _analyse_autoconf(autoconf_file)
+
+    # check that LOGs from Application core are present
+    _check_benchmark_results(
+        output=output,
+        core='app',
+    )
+
+    # check that LOGs from Radio core are present
+    _check_benchmark_results(
+        output=output,
+        core='rad',
+    )
+
+    if SB_CONFIG_APP_CPUPPR_RUN:
+        # check that LOGs from PPR core are present
+        _check_benchmark_results(
+            output=output,
+            core='ppr',
+        )
+
+    if SB_CONFIG_APP_CPUFLPR_RUN:
+        # check that LOGs from FLPR core are present
+        _check_benchmark_results(
+            output=output,
+            core='flpr',
+        )
+
+
+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}/coresight_stm_dictionary.txt"
+    autoconf_file = f"{BUILD_DIR}/_sysbuild/autoconf.h"
+    COLLECT_TIMEOUT = 10.0
+
+    # set SB_CONFIG_APP_CPUPPR_RUN, SB_CONFIG_APP_CPUFLPR_RUN
+    # this information is needed to build nrfutil database-config
+    _analyse_autoconf(autoconf_file)
+
+    # 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 that LOGs from Application core are present
+    _check_benchmark_results(
+        output=decoded_file_content,
+        core='app',
+    )
+
+    # check that LOGs from Radio core are present
+    _check_benchmark_results(
+        output=decoded_file_content,
+        core='rad',
+    )
+
+    if SB_CONFIG_APP_CPUPPR_RUN:
+        # check that LOGs from PPR core are present
+        _check_benchmark_results(
+            output=decoded_file_content,
+            core='ppr',
+        )
+
+    if SB_CONFIG_APP_CPUFLPR_RUN:
+        # check that LOGs from FLPR core are present
+        _check_benchmark_results(
+            output=decoded_file_content,
+            core='flpr',
+        )