From 49ce733a30d29c819e2ab57dbe758f272e09da7a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Sebastian=20G=C5=82=C4=85b?= Date: Tue, 14 Jan 2025 13:40:39 +0100 Subject: [PATCH 1/2] Revert "[nrf fromtree] samples: boards: nordic: coresight_stm: Test STM dictionary mode" This reverts commit fa58e795d190daf173dbda0f61d195a49bd26a3a. --- .../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, 24 insertions(+), 380 deletions(-) delete mode 100644 samples/boards/nordic/coresight_stm/README.rst delete 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 deleted file mode 100644 index 370253cf41cc..000000000000 --- a/samples/boards/nordic/coresight_stm/README.rst +++ /dev/null @@ -1,102 +0,0 @@ -.. 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 deleted file mode 100644 index 2187805f15f1..000000000000 --- a/samples/boards/nordic/coresight_stm/pytest/test_stm.py +++ /dev/null @@ -1,258 +0,0 @@ -# -# 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', - ) diff --git a/samples/boards/nordic/coresight_stm/sample.yaml b/samples/boards/nordic/coresight_stm/sample.yaml index 4251c5d6df8c..eb3971a2f4eb 100644 --- a/samples/boards/nordic/coresight_stm/sample.yaml +++ b/samples/boards/nordic/coresight_stm/sample.yaml @@ -1,40 +1,44 @@ 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: - harness: pytest - harness_config: - pytest_dut_scope: session - pytest_root: - - "pytest/test_stm.py::test_STM_dictionary_mode" + platform_allow: + - nrf54h20dk/nrf54h20/cpuapp + integration_platforms: + - nrf54h20dk/nrf54h20/cpuapp + build_only: true 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: - harness: pytest + platform_allow: + - nrf54h20dk/nrf54h20/cpuapp + integration_platforms: + - nrf54h20dk/nrf54h20/cpuapp + harness: console harness_config: - pytest_dut_scope: session - pytest_root: - - "pytest/test_stm.py::test_STM_decoded" - required_snippets: - - nordic-log-stm + 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:" 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 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 2/2] [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 000000000000..370253cf41cc --- /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 000000000000..fb2203e809e5 --- /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 eb3971a2f4eb..4251c5d6df8c 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