tools: Add a new script for firmware boot stress testing

This requires the kernel changes that expose the debugfs entries for
executing the different DSP ops and reading the current DSP firmware and
power states.

The script takes the firmware name and the path as inputs along with the
number of iterations of firmware boot. It takes care of putting the DSP
in the D3 state and unloading any existing firmware before starting
firmware boot.

Signed-off-by: Ranjani Sridharan <[email protected]>

tools/sof-fw-boot-test.py

@@ -0,0 +1,167 @@
+#!/usr/bin/env python3
+
+"""Module to stress test firmware boot"""
+
+import argparse
+import logging
+import sys
+from datetime import datetime
+from systemd import journal
+
+logging.basicConfig(level=logging.INFO, format="%(message)s")
+
+# set path to the depbugfs entries
+DEBUGFS_PATH = "/sys/kernel/debug/sof/fw_debug_ops"
+
+def read_jctl_logs(start_time):
+    """Reads journalctl logs from a given start time and extracts the timestamp and log"""
+    journal_reader = journal.Reader()
+    journal_reader.this_boot()
+    journal_reader.seek_realtime(datetime.strptime(start_time, '%Y-%m-%d %H:%M:%S'))
+
+    entries = []
+    for entry in journal_reader:
+        timestamp = entry['__REALTIME_TIMESTAMP']
+        message = entry.get('MESSAGE', '')
+        if isinstance(message, bytes):
+            message = message.decode('utf-8', errors='replace')
+        entries.append((timestamp, message))
+
+    return entries
+
+# define command line arguments
+def parse_cmdline():
+    """Function to parse the command line arguments"""
+    parser = argparse.ArgumentParser(
+        add_help=True,
+        formatter_class=argparse.RawTextHelpFormatter,
+        description="A script for stress testing firmware boot",
+    )
+    parser.add_argument(
+        "-i", "--iter", type=int, default=100, help="number of firmware boot iterations"
+    )
+    parser.add_argument(
+        "-f", "--firmware", type=str,
+        help="firmware filename. If this is not set, the kernel will boot the default firmware"
+    )
+    parser.add_argument(
+        "-p",
+        "--fw_path",
+        type=str,
+        help="""path to the firmware file. If the path is not relative to /lib/firmware,
+             use echo -n /path/to/fw_file > /sys/module/firmware_class/parameters/path""",
+    )
+    return parser.parse_args()
+
+def dsp_set(node, value):
+    """Set the debugfs node"""
+    open(f"{DEBUGFS_PATH}/{node}", "w").write(f"{value}\n")
+
+def dsp_get(node):
+    """Get the value from a debugfs node"""
+    return open(f"{DEBUGFS_PATH}/{node}").read().rstrip()
+
+def boot_fw():
+    """Power down the DSP and boot firmware using previously set firmware path and filename"""
+    # put the DSP in D3
+    dsp_set("dsp_power_state", "D3")
+
+    # check if the DSP is in D3
+    power_state = dsp_get("dsp_power_state")
+    if power_state != "D3":
+        sys.exit("Failed booting firmware. DSP is not in D3")
+
+    # unload current firmware
+    dsp_set("unload_fw", "1")
+
+    # get current fw_state and continue to boot only if the current state is 'PREPARE'
+    fw_state = dsp_get("fw_state")
+    if "PREPARE" not in fw_state:
+        sys.exit(f"Cannot boot firmware from current state {fw_state}")
+
+    # load and boot firmware
+    dsp_set("boot_fw", "1")
+
+    # get current fw_state
+    fw_state = dsp_get("fw_state")
+
+    return fw_state
+
+def calculate_boot_time(journalctl_output):
+    """Calculate boot time from the journal ctl log entries"""
+    boot_start_time = 0
+    boot_end_time = 0
+    for timestamp, message in journalctl_output:
+        if 'booting DSP firmware' in message:
+            boot_start_time = timestamp
+        if 'firmware boot complete' in message:
+            boot_end_time = timestamp
+    if boot_start_time == 0 or boot_end_time == 0:
+        sys.exit("Failed to calculate boot time")
+    time_diff = boot_end_time - boot_start_time
+    boot_time_ms = round(time_diff.total_seconds() * 1000, 2)
+
+    return boot_time_ms
+
+def main():
+    """Main function for stress testing"""
+    cmd_args = parse_cmdline()
+
+   # clear firmware filename/path
+    dsp_set("fw_filename", "")
+    dsp_set("fw_path", "")
+
+    # Get firmware file path if set
+    if cmd_args.fw_path:
+        fw_path = cmd_args.fw_path
+        dsp_set("fw_path", fw_path)
+    else:
+        fw_path = "default"
+
+    # Get firmware file name if set
+    if cmd_args.firmware:
+        fw_filename = cmd_args.firmware
+        dsp_set("fw_filename", fw_filename)
+    else:
+        fw_filename = "default"
+
+    num_iter = cmd_args.iter
+    output = f"""==============================================================================
+	Starting boot stress test with:
+	Firmware filename: {fw_filename}
+	Path to firmware file: {fw_path}
+	Number of Iterations: {num_iter}
+=============================================================================="""
+    logging.info(output)
+
+    total_boot_time_ms = 0
+    min_boot_time_ms = sys.maxsize
+    max_boot_time_ms = 0
+
+    for i in range(num_iter):
+        start_time = datetime.now().strftime('%Y-%m-%d %H:%M:%S')
+        fw_state = boot_fw()
+        # check if fw_state is COMPLETE
+        if "COMPLETE" not in fw_state:
+            sys.exit(f"Firmware boot failed at iteration {i}")
+
+        journalctl_output = read_jctl_logs(start_time)
+
+        boot_time_ms = calculate_boot_time(journalctl_output)
+        total_boot_time_ms += boot_time_ms
+        min_boot_time_ms = min(min_boot_time_ms, boot_time_ms)
+        max_boot_time_ms = max(max_boot_time_ms, boot_time_ms)
+
+        logging.info("Firmware boot iteration %d completed in %0.2f ms", i, boot_time_ms)
+
+    # print firmware boot stats
+    avg_boot_time_ms = round(total_boot_time_ms / num_iter, 2)
+    output = f"""==============================================================================
+	Average firmware boot time {avg_boot_time_ms} ms
+	Maximum firmware boot time {max_boot_time_ms} ms
+	Minimum firmware boot time {min_boot_time_ms} ms
+=============================================================================="""
+    logging.info(output)
+
+if __name__ == "__main__":
+    main()