From 4f39e0dcd9bc007ba2ae981c59c67bfeb6ee1955 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Sebastian=20G=C5=82=C4=85b?= Date: Wed, 25 Sep 2024 07:28:55 +0200 Subject: [PATCH] [nrf fromtree] samples: boards: nordic: coresight_stm: Test STM dictionary mode MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Extend STM logger test. Use nrfutil trace to decode STM logs in dictionary mode. Signed-off-by: Sebastian Głąb (cherry picked from commit f0eba332588be7aff3adf479c23c836cb81c9f61) (cherry picked from commit 4ba47686ab416ed3a01b5dbac1c0b6f4a478e1fb) --- .../boards/nordic/coresight_stm/README.rst | 102 +++++++ .../nordic/coresight_stm/pytest/test_stm.py | 258 ++++++++++++++++++ .../boards/nordic/coresight_stm/sample.yaml | 44 ++- 3 files changed, 380 insertions(+), 24 deletions(-) create mode 100644 samples/boards/nordic/coresight_stm/README.rst create mode 100644 samples/boards/nordic/coresight_stm/pytest/test_stm.py diff --git a/samples/boards/nordic/coresight_stm/README.rst b/samples/boards/nordic/coresight_stm/README.rst new file mode 100644 index 00000000000..370253cf41c --- /dev/null +++ b/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] app/app: test with one argument 100 + [00:00:00.227,265] app/app: test with one argument 100 + (...) + [00:00:00.585,558] rad/app: test with one argument 100 + [00:00:00.585,569] rad/app: test with one argument 100 + (...) + [00:00:00.624,408] ppr/app: test with one argument 100 + [00:00:00.624,433] ppr/app: test with one argument 100 + (...) + [00:00:00.625,249] flpr/app: test with one argument 100 + [00:00:00.625,251] 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`. diff --git a/samples/boards/nordic/coresight_stm/pytest/test_stm.py b/samples/boards/nordic/coresight_stm/pytest/test_stm.py new file mode 100644 index 00000000000..fb2203e809e --- /dev/null +++ b/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', + ) diff --git a/samples/boards/nordic/coresight_stm/sample.yaml b/samples/boards/nordic/coresight_stm/sample.yaml index eb3971a2f4e..4251c5d6df8 100644 --- a/samples/boards/nordic/coresight_stm/sample.yaml +++ b/samples/boards/nordic/coresight_stm/sample.yaml @@ -1,44 +1,40 @@ 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 + 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