1#
2# Copyright (c) 2024 Nordic Semiconductor ASA
3#
4# SPDX-License-Identifier: Apache-2.0
5#
6
7import logging
8import re
9import subprocess
10from dataclasses import dataclass
11from pathlib import Path
12from time import sleep
13
14import psutil
15from twister_harness import DeviceAdapter
16
17logger = logging.getLogger(__name__)
18
19
20SB_CONFIG_APP_CPUPPR_RUN = None
21SB_CONFIG_APP_CPUFLPR_RUN = None
22
23# See definition of stm_m_id[] and stm_m_name[] in
24# https://github.com/zephyrproject-rtos/zephyr/blob/main/drivers/misc/coresight/nrf_etr.c
25STM_M_ID = {
26    "sec": 33,
27    "app": 34,
28    "rad": 35,
29    "mod": 36,
30    "sys": 44,
31    "flpr": 45,
32    "ppr": 46,
33    "hw": 128,
34}
35
36
37@dataclass
38class STMLimits:
39    log_0_arg: float | None
40    log_1_arg: float | None
41    log_2_arg: float | None
42    log_3_arg: float | None
43    log_str: float | None
44    tracepoint: float | None
45    tracepoint_d32: float | None
46    tolerance: float | None
47
48
49def _analyse_autoconf(filepath: str) -> None:
50    global SB_CONFIG_APP_CPUPPR_RUN
51    global SB_CONFIG_APP_CPUFLPR_RUN
52
53    SB_CONFIG_APP_CPUPPR_RUN = False
54    SB_CONFIG_APP_CPUFLPR_RUN = False
55
56    # Parse contents of {BUILD_DIR}/_sysbuild/autoconf.h
57    with open(f"{filepath}", errors="ignore") as autoconf:
58        for line in autoconf:
59            if "SB_CONFIG_APP_CPUPPR_RUN 1" in line:
60                SB_CONFIG_APP_CPUPPR_RUN = True
61                continue
62            if "SB_CONFIG_APP_CPUFLPR_RUN 1" in line:
63                SB_CONFIG_APP_CPUFLPR_RUN = True
64    logger.debug(f"{SB_CONFIG_APP_CPUPPR_RUN=}")
65    logger.debug(f"{SB_CONFIG_APP_CPUFLPR_RUN=}")
66
67
68def _check_benchmark_results(output: str, core: str, constraints: STMLimits) -> None:
69    """
70    Use regular expressions to parse 'output' string.
71    Search for benchmark results related to 'core' coprocessor.
72    Check that benchamrk results are lower than limits provided in 'constraints'.
73    """
74
75    cfg = {
76        "log message with 0 arguments": {
77            "regex": rf"{core}: Timing for log message with 0 arguments: (.+)us",
78            "expected": constraints.log_0_arg,
79        },
80        "log message with 1 argument": {
81            "regex": rf"{core}: Timing for log message with 1 argument: (.+)us",
82            "expected": constraints.log_1_arg,
83        },
84        "log message with 2 arguments": {
85            "regex": rf"{core}: Timing for log message with 2 arguments: (.+)us",
86            "expected": constraints.log_2_arg,
87        },
88        "log message with 3 arguments": {
89            "regex": rf"{core}: Timing for log message with 3 arguments: (.+)us",
90            "expected": constraints.log_3_arg,
91        },
92        "log message with string": {
93            "regex": rf"{core}: Timing for log_message with string: (.+)us",
94            "expected": constraints.log_str,
95        },
96        "tracepoint": {
97            "regex": rf"{core}: Timing for tracepoint: (.+)us",
98            "expected": constraints.tracepoint,
99        },
100        "tracepoint_d32": {
101            "regex": rf"{core}: Timing for tracepoint_d32: (.+)us",
102            "expected": constraints.tracepoint_d32,
103        },
104    }
105
106    for check in cfg:
107        observed_str = re.search(cfg[check]["regex"], output).group(1)
108        assert observed_str is not None, f"Timing for {check} NOT found"
109        # check value
110        observed = float(observed_str)
111        threshold = cfg[check]["expected"] * (1 + constraints.tolerance)
112        assert (
113            observed < threshold
114        ), f"{core}: Timing for {check} - {observed} us exceeds {threshold} us"
115
116
117# nrfutil starts children processes
118# when subprocess.terminate(nrfutil_process) is executed, only the parent terminates
119# this blocks serial port for other uses
120def _kill(proc):
121    try:
122        for child in psutil.Process(proc.pid).children(recursive=True):
123            child.kill()
124        proc.kill()
125    except Exception as e:
126        logger.exception(f'Could not kill nrfutil - {e}')
127
128
129def _nrfutil_dictionary_from_serial(
130    dut: DeviceAdapter,
131    decoded_file_name: str = "output.txt",
132    collect_time: float = 60.0,
133) -> None:
134    UART_PATH = dut.device_config.serial
135    UART_BAUDRATE = dut.device_config.baud
136    dut.close()
137
138    logger.debug(f"Using serial: {UART_PATH}")
139
140    if Path(f"{decoded_file_name}").exists():
141        logger.warning("Output file already exists!")
142
143    # prepare database config string
144    BUILD_DIR = str(dut.device_config.build_dir)
145    logger.debug(f"{BUILD_DIR=}")
146    config_str = f"{STM_M_ID['app']}:{BUILD_DIR}/coresight_stm/zephyr/log_dictionary.json"
147    config_str += f",{STM_M_ID['rad']}:{BUILD_DIR}/remote_rad/zephyr/log_dictionary.json"
148    if SB_CONFIG_APP_CPUPPR_RUN:
149        config_str += f",{STM_M_ID['ppr']}:{BUILD_DIR}/remote_ppr/zephyr/log_dictionary.json"
150    if SB_CONFIG_APP_CPUFLPR_RUN:
151        config_str += f",{STM_M_ID['flpr']}:{BUILD_DIR}/remote_flpr/zephyr/log_dictionary.json"
152    logger.debug(f"{config_str=}")
153
154    cmd = (
155        "nrfutil trace stm --database-config "
156        f"{config_str} "
157        f"--input-serialport {UART_PATH} --baudrate {UART_BAUDRATE} "
158        f"--output-ascii {decoded_file_name}"
159    )
160    try:
161        # run nrfutil trace in background non-blocking
162        logger.info(f"Executing:\n{cmd}")
163        proc = subprocess.Popen(cmd.split(), stdout=subprocess.DEVNULL)
164    except OSError as exc:
165        logger.error(f"Unable to start nrfutil trace:\n{cmd}\n{exc}")
166    try:
167        proc.wait(collect_time)
168    except subprocess.TimeoutExpired:
169        pass
170    finally:
171        _kill(proc)
172
173
174def test_STM_decoded(dut: DeviceAdapter):
175    """
176    Run sample.boards.nrf.coresight_stm from samples/boards/nrf/coresight_stm sample.
177    Both Application and Radio cores use STM for logging.
178    STM proxy (Application core) decodes logs from all domains.
179    After reset, coprocessors execute code in expected way and Application core
180    outputs STM traces on UART port.
181    """
182    BUILD_DIR = str(dut.device_config.build_dir)
183    autoconf_file = f"{BUILD_DIR}/_sysbuild/autoconf.h"
184
185    app_constraints = STMLimits(
186        # all values in us
187        log_0_arg=1.8,
188        log_1_arg=2.1,
189        log_2_arg=2.0,
190        log_3_arg=2.1,
191        log_str=4.5,
192        tracepoint=0.5,
193        tracepoint_d32=0.5,
194        tolerance=0.5,  # 50 %
195    )
196    rad_constraints = STMLimits(
197        # all values in us
198        log_0_arg=4.6,
199        log_1_arg=5.0,
200        log_2_arg=5.2,
201        log_3_arg=5.6,
202        log_str=6.3,
203        tracepoint=0.5,
204        tracepoint_d32=0.5,
205        tolerance=0.5,
206    )
207    ppr_constraints = STMLimits(
208        # all values in us
209        log_0_arg=25.7,
210        log_1_arg=27.1,
211        log_2_arg=27.3,
212        log_3_arg=30.4,
213        log_str=65.7,
214        tracepoint=0.55,
215        tracepoint_d32=0.25,
216        tolerance=0.5,
217    )
218    flpr_constraints = STMLimits(
219        # all values in us
220        log_0_arg=1.3,
221        log_1_arg=1.6,
222        log_2_arg=1.6,
223        log_3_arg=1.7,
224        log_str=3.0,
225        tracepoint=0.5,
226        tracepoint_d32=0.5,
227        tolerance=0.5,
228    )
229    # nrf54h20 prints immediately after it is flashed.
230    # Wait a bit to skipp logs from previous test.
231    sleep(6)
232
233    # Get output from serial port
234    output = "\n".join(dut.readlines())
235
236    # set SB_CONFIG_APP_CPUPPR_RUN, SB_CONFIG_APP_CPUFLPR_RUN
237    _analyse_autoconf(autoconf_file)
238
239    # check results on Application core
240    _check_benchmark_results(output=output, core='app', constraints=app_constraints)
241
242    # check results on Radio core
243    _check_benchmark_results(output=output, core='rad', constraints=rad_constraints)
244
245    if SB_CONFIG_APP_CPUPPR_RUN:
246        # check results on PPR core
247        _check_benchmark_results(output=output, core='ppr', constraints=ppr_constraints)
248
249    if SB_CONFIG_APP_CPUFLPR_RUN:
250        # check results on FLPR core
251        _check_benchmark_results(output=output, core='flpr', constraints=flpr_constraints)
252
253
254def test_STM_dictionary_mode(dut: DeviceAdapter):
255    """
256    Run sample.boards.nrf.coresight_stm.dict from samples/boards/nrf/coresight_stm sample.
257    Both Application and Radio cores use STM for logging.
258    STM proxy (Application core) prints on serial port raw logs from all domains.
259    Nrfutil trace is used to decode STM logs.
260    After reset, coprocessors execute code in expected way and Application core
261    outputs STM traces on UART port.
262    """
263    BUILD_DIR = str(dut.device_config.build_dir)
264    test_filename = f"{BUILD_DIR}/coresight_stm_dictionary.txt"
265    autoconf_file = f"{BUILD_DIR}/_sysbuild/autoconf.h"
266    COLLECT_TIMEOUT = 10.0
267
268    app_constraints = STMLimits(
269        # all values in us
270        log_0_arg=0.7,
271        log_1_arg=0.8,
272        log_2_arg=0.8,
273        log_3_arg=1.3,
274        log_str=3.2,
275        tracepoint=0.5,
276        tracepoint_d32=0.5,
277        tolerance=0.5,  # 50 %
278    )
279    rad_constraints = STMLimits(
280        # all values in us
281        log_0_arg=0.8,
282        log_1_arg=0.9,
283        log_2_arg=1.0,
284        log_3_arg=1.5,
285        log_str=3.6,
286        tracepoint=0.5,
287        tracepoint_d32=0.5,
288        tolerance=0.5,
289    )
290    ppr_constraints = STMLimits(
291        # all values in us
292        log_0_arg=7.5,
293        log_1_arg=8.5,
294        log_2_arg=8.6,
295        log_3_arg=17.4,
296        log_str=45.2,
297        tracepoint=0.5,
298        tracepoint_d32=0.5,
299        tolerance=0.5,
300    )
301    flpr_constraints = STMLimits(
302        # all values in us
303        log_0_arg=0.3,
304        log_1_arg=0.4,
305        log_2_arg=0.5,
306        log_3_arg=0.8,
307        log_str=2.6,
308        tracepoint=0.5,
309        tracepoint_d32=0.5,
310        tolerance=0.5,  # 50 %
311    )
312
313    # set SB_CONFIG_APP_CPUPPR_RUN, SB_CONFIG_APP_CPUFLPR_RUN
314    # this information is needed to build nrfutil database-config
315    _analyse_autoconf(autoconf_file)
316
317    # use nrfutil trace to decode logs
318    _nrfutil_dictionary_from_serial(
319        dut=dut,
320        decoded_file_name=f"{test_filename}",
321        collect_time=COLLECT_TIMEOUT,
322    )
323
324    # read decoded logs
325    with open(f"{test_filename}", errors="ignore") as decoded_file:
326        decoded_file_content = decoded_file.read()
327
328    # if nothing in decoded_file, stop test
329    assert len(decoded_file_content) > 0, f"File {test_filename} is empty"
330
331    # check results on Application core
332    _check_benchmark_results(output=decoded_file_content, core='app', constraints=app_constraints)
333
334    # check results on Radio core
335    _check_benchmark_results(output=decoded_file_content, core='rad', constraints=rad_constraints)
336
337    if SB_CONFIG_APP_CPUPPR_RUN:
338        # check results on PPR core
339        _check_benchmark_results(
340            output=decoded_file_content, core='ppr', constraints=ppr_constraints
341        )
342
343    if SB_CONFIG_APP_CPUFLPR_RUN:
344        # check results on FLPR core
345        _check_benchmark_results(
346            output=decoded_file_content, core='flpr', constraints=flpr_constraints
347        )
348