samples: boards: nordic: coresight_stm: Test STM dictionary mode

.. 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`.

#

# 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 = config_str + f",{STM_M_ID['rad']}:{BUILD_DIR}/remote_rad/zephyr/log_dictionary.json"

    if SB_CONFIG_APP_CPUPPR_RUN:

        config_str = config_str + f",{STM_M_ID['ppr']}:{BUILD_DIR}/remote_ppr/zephyr/log_dictionary.json"

    if SB_CONFIG_APP_CPUFLPR_RUN:

        config_str = 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',

        )

sample:

  name: Logging using Coresight STM on nrf54h20

common:

  tags: stm

  sysbuild: true

tests:

  sample.boards.nrf.coresight_stm.dict:

  platform_allow:

    - nrf54h20dk/nrf54h20/cpuapp

  integration_platforms:

    - nrf54h20dk/nrf54h20/cpuapp

    build_only: true

tests:

  sample.boards.nrf.coresight_stm.dict:

    harness: pytest

    harness_config:

      pytest_dut_scope: session

      pytest_root:

        - "pytest/test_stm.py::test_STM_dictionary_mode"

    required_snippets:

      - nordic-log-stm-dict

    extra_args:

      - SB_CONFIG_APP_CPUPPR_RUN=y

      - SB_CONFIG_APP_CPUFLPR_RUN=y

  sample.boards.nrf.coresight_stm:

    platform_allow:

      - nrf54h20dk/nrf54h20/cpuapp

    integration_platforms:

      - nrf54h20dk/nrf54h20/cpuapp

    harness: console

    harness: pytest

    harness_config:

      type: multi_line

      ordered: true

      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:"

      pytest_dut_scope: session

      pytest_root:

        - "pytest/test_stm.py::test_STM_decoded"

    required_snippets:

      - nordic-log-stm

    extra_args:

      - SB_CONFIG_APP_CPUPPR_RUN=y

      - SB_CONFIG_APP_CPUFLPR_RUN=y

    required_snippets:

      - nordic-log-stm

  sample.boards.nrf.coresight_stm.local_uart:

    platform_allow:

      - nrf54h20dk/nrf54h20/cpuapp

    integration_platforms:

      - nrf54h20dk/nrf54h20/cpuapp

    harness: console

    harness_config:

      type: multi_line