diff --git a/samples/boards/nrf/coresight_stm/README.rst b/samples/boards/nrf/coresight_stm/README.rst new file mode 100644 index 00000000000..09a34f74856 --- /dev/null +++ b/samples/boards/nrf/coresight_stm/README.rst @@ -0,0 +1,224 @@ +.. _nrf-coresight-stm-sample: + +Coresight STM demo +################## + +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. + +Sample has three configurations: +#. '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 and Radio cores send logs to 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 and Radio cores +send logs to ETR buffer. Proxy (Application core) forwards data from ETR to +the host using UART. Host tool is needed to decode the logs. + +Requirements +************ + +This application uses nRF54H20 DK board for the demo. + +Building and running +******************** + +To build the sample, use configuration setups from :file:`sample.yaml` using the ``-T`` option. +See the following examples: + +nRF54H20 DK + You can build the test for application and radio cores as follows: + + .. 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.385,817] rad/app: test with one argument 100 + [00:00:00.385,827] rad/app: test with one argument 100 + [00:00:00.385,832] rad/app: test with one argument 100 + [00:00:00.385,836] rad/app: test with one argument 100 + [00:00:00.385,841] rad/app: test with one argument 100 + [00:00:00.385,846] rad/app: test with one argument 100 + [00:00:00.385,851] rad/app: test with one argument 100 + [00:00:00.385,856] rad/app: test with one argument 100 + [00:00:00.385,860] rad/app: test with one argument 100 + [00:00:00.385,865] rad/app: test with one argument 100 + [00:00:00.424,091] app/app: test with one argument 100 + [00:00:00.424,094] app/app: test with one argument 100 + [00:00:00.424,096] app/app: test with one argument 100 + [00:00:00.424,097] app/app: test with one argument 100 + [00:00:00.424,099] app/app: test with one argument 100 + [00:00:00.424,100] app/app: test with one argument 100 + [00:00:00.424,102] app/app: test with one argument 100 + [00:00:00.424,104] app/app: test with one argument 100 + [00:00:00.424,105] app/app: test with one argument 100 + [00:00:00.424,108] app/app: test with one argument 100 + [00:00:00.585,056] rad/app: test with two arguments 100 10 + [00:00:00.585,065] rad/app: test with two arguments 100 10 + [00:00:00.585,070] rad/app: test with two arguments 100 10 + [00:00:00.585,075] rad/app: test with two arguments 100 10 + [00:00:00.585,080] rad/app: test with two arguments 100 10 + [00:00:00.585,086] rad/app: test with two arguments 100 10 + [00:00:00.585,091] rad/app: test with two arguments 100 10 + [00:00:00.585,096] rad/app: test with two arguments 100 10 + [00:00:00.585,100] rad/app: test with two arguments 100 10 + [00:00:00.585,105] rad/app: test with two arguments 100 10 + [00:00:00.623,262] app/app: test with two arguments 100 10 + [00:00:00.623,265] app/app: test with two arguments 100 10 + [00:00:00.623,267] app/app: test with two arguments 100 10 + [00:00:00.623,268] app/app: test with two arguments 100 10 + [00:00:00.623,272] app/app: test with two arguments 100 10 + [00:00:00.623,273] app/app: test with two arguments 100 10 + [00:00:00.623,275] app/app: test with two arguments 100 10 + [00:00:00.623,276] app/app: test with two arguments 100 10 + [00:00:00.623,278] app/app: test with two arguments 100 10 + [00:00:00.623,280] app/app: test with two arguments 100 10 + [00:00:00.784,382] rad/app: test with three arguments 100 10 1 + [00:00:00.784,392] rad/app: test with three arguments 100 10 1 + [00:00:00.784,398] rad/app: test with three arguments 100 10 1 + [00:00:00.784,403] rad/app: test with three arguments 100 10 1 + [00:00:00.784,409] rad/app: test with three arguments 100 10 1 + [00:00:00.784,414] rad/app: test with three arguments 100 10 1 + [00:00:00.784,419] rad/app: test with three arguments 100 10 1 + [00:00:00.784,425] rad/app: test with three arguments 100 10 1 + [00:00:00.784,430] rad/app: test with three arguments 100 10 1 + [00:00:00.784,436] rad/app: test with three arguments 100 10 1 + [00:00:00.822,484] app/app: test with three arguments 100 10 1 + [00:00:00.822,488] app/app: test with three arguments 100 10 1 + [00:00:00.822,489] app/app: test with three arguments 100 10 1 + [00:00:00.822,491] app/app: test with three arguments 100 10 1 + [00:00:00.822,492] app/app: test with three arguments 100 10 1 + [00:00:00.822,494] app/app: test with three arguments 100 10 1 + [00:00:00.822,497] app/app: test with three arguments 100 10 1 + [00:00:00.822,499] app/app: test with three arguments 100 10 1 + [00:00:00.822,500] app/app: test with three arguments 100 10 1 + [00:00:00.822,502] app/app: test with three arguments 100 10 1 + [00:00:00.983,660] rad/app: test with string test string + [00:00:00.983,673] rad/app: test with string test string + [00:00:00.983,678] rad/app: test with string test string + [00:00:00.983,684] rad/app: test with string test string + [00:00:00.983,691] rad/app: test with string test string + [00:00:00.983,697] rad/app: test with string test string + [00:00:00.983,702] rad/app: test with string test string + [00:00:00.983,708] rad/app: test with string test string + [00:00:00.983,715] rad/app: test with string test string + [00:00:00.983,720] rad/app: test with string test string + [00:00:01.021,668] app/app: test with string test string + [00:00:01.021,678] app/app: test with string test string + [00:00:01.021,681] app/app: test with string test string + [00:00:01.021,684] app/app: test with string test string + [00:00:01.021,688] app/app: test with string test string + [00:00:01.021,692] app/app: test with string test string + [00:00:01.021,696] app/app: test with string test string + [00:00:01.021,699] app/app: test with string test string + [00:00:01.021,702] app/app: test with string test string + [00:00:01.021,707] app/app: test with string test string + [00:00:01.182,876] rad/tp: 5 + [00:00:01.182,876] rad/tp: 5 + [00:00:01.182,876] rad/tp: 5 + [00:00:01.182,876] rad/tp: 5 + [00:00:01.182,876] rad/tp: 5 + [00:00:01.182,878] rad/tp: 5 + [00:00:01.182,878] rad/tp: 5 + [00:00:01.182,878] rad/tp: 5 + [00:00:01.182,878] rad/tp: 5 + [00:00:01.182,878] rad/tp: 5 + [00:00:01.182,878] rad/tp: 5 + [00:00:01.182,878] rad/tp: 5 + [00:00:01.182,878] rad/tp: 5 + [00:00:01.182,878] rad/tp: 5 + [00:00:01.182,878] rad/tp: 5 + [00:00:01.182,878] rad/tp: 5 + [00:00:01.182,878] rad/tp: 5 + [00:00:01.182,878] rad/tp: 5 + [00:00:01.182,878] rad/tp: 5 + [00:00:01.182,878] rad/tp: 5 + [00:00:01.220,788] app/tp: 5 + [00:00:01.220,788] app/tp: 5 + [00:00:01.220,788] app/tp: 5 + [00:00:01.220,788] app/tp: 5 + [00:00:01.220,788] app/tp: 5 + [00:00:01.220,788] app/tp: 5 + [00:00:01.220,788] app/tp: 5 + [00:00:01.220,788] app/tp: 5 + [00:00:01.220,788] app/tp: 5 + [00:00:01.220,788] app/tp: 5 + [00:00:01.220,790] app/tp: 5 + [00:00:01.220,790] app/tp: 5 + [00:00:01.220,790] app/tp: 5 + [00:00:01.220,790] app/tp: 5 + [00:00:01.220,790] app/tp: 5 + [00:00:01.220,790] app/tp: 5 + [00:00:01.220,790] app/tp: 5 + [00:00:01.220,790] app/tp: 5 + [00:00:01.220,790] app/tp: 5 + [00:00:01.220,790] app/tp: 5 + [00:00:01.382,048] rad/tp: 6 0000000a + [00:00:01.382,048] rad/tp: 6 0000000a + [00:00:01.382,048] rad/tp: 6 0000000a + [00:00:01.382,048] rad/tp: 6 0000000a + [00:00:01.382,048] rad/tp: 6 0000000a + [00:00:01.382,048] rad/tp: 6 0000000a + [00:00:01.382,048] rad/tp: 6 0000000a + [00:00:01.382,048] rad/tp: 6 0000000a + [00:00:01.382,048] rad/tp: 6 0000000a + [00:00:01.382,048] rad/tp: 6 0000000a + [00:00:01.382,049] rad/tp: 6 0000000a + [00:00:01.382,049] rad/tp: 6 0000000a + [00:00:01.382,049] rad/tp: 6 0000000a + [00:00:01.382,049] rad/tp: 6 0000000a + [00:00:01.382,049] rad/tp: 6 0000000a + [00:00:01.382,049] rad/tp: 6 0000000a + [00:00:01.382,049] rad/tp: 6 0000000a + [00:00:01.382,049] rad/tp: 6 0000000a + [00:00:01.382,049] rad/tp: 6 0000000a + [00:00:01.382,049] rad/tp: 6 0000000a + [00:00:01.419,950] app/tp: 6 0000000a + [00:00:01.419,950] app/tp: 6 0000000a + [00:00:01.419,950] app/tp: 6 0000000a + [00:00:01.419,950] app/tp: 6 0000000a + [00:00:01.419,950] app/tp: 6 0000000a + [00:00:01.419,952] app/tp: 6 0000000a + [00:00:01.419,952] app/tp: 6 0000000a + [00:00:01.419,952] app/tp: 6 0000000a + [00:00:01.419,952] app/tp: 6 0000000a + [00:00:01.419,952] app/tp: 6 0000000a + [00:00:01.419,952] app/tp: 6 0000000a + [00:00:01.419,952] app/tp: 6 0000000a + [00:00:01.419,952] app/tp: 6 0000000a + [00:00:01.419,952] app/tp: 6 0000000a + [00:00:01.419,952] app/tp: 6 0000000a + [00:00:01.419,952] app/tp: 6 0000000a + [00:00:01.419,952] app/tp: 6 0000000a + [00:00:01.419,952] app/tp: 6 0000000a + [00:00:01.419,952] app/tp: 6 0000000a + [00:00:01.419,952] app/tp: 6 0000000a + rad: Timing for log message with 0 arguments: 6.60us + rad: Timing for log message with 1 argument: 5.80us + 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 + app: Timing for log message with 0 arguments: 3.20us + app: Timing for log message with 1 argument: 2.10us + app: Timing for log message with 2 arguments: 2.10us + app: Timing for log message with 3 arguments: 2.0us + app: Timing for log_message with string: 4.50us + app: Timing for tracepoint: 0.10us + app: Timing for tracepoint_d32: 0.10us + +See OS Services » Logging » Multi-domain logging using ARM Coresight STM` for details. diff --git a/samples/boards/nrf/coresight_stm/pytest/test_stm.py b/samples/boards/nrf/coresight_stm/pytest/test_stm.py new file mode 100644 index 00000000000..4155acfcd98 --- /dev/null +++ b/samples/boards/nrf/coresight_stm/pytest/test_stm.py @@ -0,0 +1,194 @@ +# +# 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__) + + +# 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) -> 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/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. + """ + + # 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', + ) + + # check results on Radio core + _check_benchmark_results( + output=output, + core='rad', + ) + +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" + COLLECT_TIMEOUT = 10.0 + + # 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 logs from Application core + _check_benchmark_results( + output=decoded_file_content, + core='app', + ) + + # check logs from Radio core + _check_benchmark_results( + output=decoded_file_content, + core='rad', + ) diff --git a/samples/boards/nrf/coresight_stm/sample.yaml b/samples/boards/nrf/coresight_stm/sample.yaml index eb3971a2f4e..25546c7a49a 100644 --- a/samples/boards/nrf/coresight_stm/sample.yaml +++ b/samples/boards/nrf/coresight_stm/sample.yaml @@ -1,44 +1,42 @@ 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 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 + filter: not CONFIG_COVERAGE + 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