add bpftrace scripts to track performance and behavior of SOF functions in the kernel

.gitignore

@@ -1,2 +1,3 @@
 logs/
 tools/__pycache__/
+kernel_tracing/metric_evaluation/__pycache__/

kernel_tracing/bpftrace_scripts/hda_irq_source_counts.bt

@@ -0,0 +1,12 @@
+// SPDX-License-Identifier: BSD-3-Clause
+// Copyright(c) 2022 Intel Corporation. All rights reserved.
+
+// This keeps count of the irqs from each source
+
+kprobe:hda_dsp_interrupt_thread {
+  @total = count();
+}
+
+tracepoint:sof_intel:sof_intel_hda_irq {
+  @counts[str(args->source)] = count();
+}

kernel_tracing/bpftrace_scripts/hda_irq_source_deltas.bt

@@ -0,0 +1,15 @@
+// SPDX-License-Identifier: BSD-3-Clause
+// Copyright(c) 2022 Intel Corporation. All rights reserved.
+
+// This collects the deltas between irqs from each source
+
+tracepoint:sof_intel:sof_intel_hda_irq {
+  if (@times[str(args->source)]) {
+    @delta_usecs[str(args->source)] = hist((nsecs - @times[str(args->source)]) / 1000);
+  }
+  @times[str(args->source)] = nsecs;
+}
+
+END {
+  clear(@times)
+}

kernel_tracing/bpftrace_scripts/ipc_tx_time.bt

@@ -0,0 +1,30 @@
+// SPDX-License-Identifier: BSD-3-Clause
+// Copyright(c) 2022 Intel Corporation. All rights reserved.
+
+// This tracks the time it takes for ipc communications (sof_ipc_tx_message execution time)
+// It prints out timings as they happen, and will generate a histogram
+// when you stop the script with ctrl-c
+
+kprobe:sof_ipc_tx_message {
+  if (@start != 0 ) {
+    printf("ERROR: overlapping tx");
+    exit();
+  }
+  @start = nsecs;
+  // We could get also the name of the device and other properties from the args,
+  // but we'd need to enable DEBUG_INFO and DEBUG_INFO_BTF to get the types
+  // It would allow us to sort timings by device for example
+  printf("tx started\n");
+}
+
+kretprobe:sof_ipc_tx_message {
+  printf("tx finished, took %d nsecs\n", nsecs - @start);
+  @usecs = hist((nsecs - @start) / 1000);
+  @avg = avg((nsecs - @start) / 1000);
+  @start = 0;
+}
+
+END {
+  // Clean up variables that shouldn't be printed
+  delete(@start);
+}

kernel_tracing/bpftrace_scripts/suspend_resume_time.bt

@@ -0,0 +1,29 @@
+// SPDX-License-Identifier: BSD-3-Clause
+// Copyright(c) 2022 Intel Corporation. All rights reserved.
+
+
+// This tracks the time it takes for runtime and system suspend/resume
+// It prints out timings as they happen, and will generate a histogram
+// when you stop the script with ctrl-c
+
+// Use the `test-case/check-suspend-resume.sh` script to try this out
+
+kprobe:sof_resume, kprobe:sof_suspend {
+  // When the function enters, we record a timestamp and the type
+  @start = nsecs;
+  @type = arg1 ? "runtime" : "system";
+  printf("%s (%s) started\n", probe, @type);
+}
+
+kretprobe:sof_resume, kretprobe:sof_suspend {
+  // When the function returns, we use the saved timestamp to determine execution time
+  printf("%s (%s) finished, took %d nsecs\n", probe, @type, nsecs - @start);
+  @usecs[probe, @type] = hist((nsecs - @start) / 1000);
+  @avg[probe, @type] = avg((nsecs - @start) / 1000);
+}
+
+END {
+  // Clean up variables that shouldn't be printed
+  delete(@start);
+  delete(@type);
+}

kernel_tracing/metric_evaluation/conftest.py

@@ -0,0 +1,91 @@
+import argparse
+import os
+import json
+import subprocess
+import re
+
+# This file does all the setup for the "test_bpftrace_conditions" function in test.py
+# It loads the test cases from the json file, and runs the bpftrace script and shell commands
+# It collects the variables from the bpftrace script through stdout,
+# and then uses Pytest Parameterization to run the test function for each condition
+
+
+def pytest_addoption(parser):
+    parser.addoption("--spec_file", type=argparse.FileType('r'),
+                     help="json file with test cases", required=True)
+
+
+def pytest_itemcollected(item):
+    """ Overwrite test name with name defined in json file """
+    item.name = item.name.split('[', 1)[1][:-1]
+    # pylint: disable=protected-access
+    item._nodeid = item.name
+
+
+class BPFTrace:
+    def __init__(self, bpftrace_script):
+        self.script = bpftrace_script
+        self.process = None
+
+    def start(self):
+        self.process = subprocess.Popen(
+            ["bpftrace", self.script], stdout=subprocess.PIPE, encoding="utf-8")
+        # Wait for bpftrace script to load
+        while True:
+            line = self.process.stdout.readline()
+            if "Attaching" in line:
+                break
+
+    def stop(self):
+        # Send ctrl-c
+        self.process.send_signal(subprocess.signal.SIGINT)
+        self.process.wait(10)
+
+        # Collect printed variables for condition evaluation
+        lines = self.process.stdout.read().split("\n")
+        bpftrace_vars = {}
+        for line in lines:
+            # Check if line is outputting a variable from the script
+            # bpftrace output format is `@name[key1, key2, ...]: val` (keys are optional)
+            if re.match("@.*: .*", line):
+                key, val = line.split(": ", 1)
+                bpftrace_vars[key] = val
+        return bpftrace_vars
+
+
+def collect_test_results(test_case, working_dir):
+    """ This runs the bpftrace script and the shell command, and collects the trace output from stdout """
+    # Start bpftrace collection
+    bpftrace_script = os.path.join(working_dir, test_case['bpftrace'])
+    bpf = BPFTrace(bpftrace_script)
+    bpf.start()
+
+    # Execute shell command
+    shell_cmd = test_case['shell']
+    print("$", shell_cmd)
+    subprocess.run(shell_cmd, cwd=working_dir, shell=False, check=True)
+
+    # Stop tracing and return collected output vairables
+    print("BPF tracing finished")
+    bpf_vars = bpf.stop()
+    return bpf_vars
+
+
+def pytest_generate_tests(metafunc):
+    """ Parametrize each JSON test case, once for each of its conditions """
+    if not "bpftrace_condition" in metafunc.fixturenames:
+        raise RuntimeError("Invalid test case.")
+    spec_file = metafunc.config.option.spec_file
+    spec_dir = os.path.dirname(os.path.realpath(spec_file.name))
+    spec = json.load(spec_file)
+    conditions = []
+    # Generate a list of conditions to evaluate
+    for test_case in spec['cases']:
+        bpftrace_vars = collect_test_results(test_case, spec_dir)
+        for condition in test_case['conditions']:
+            conditions.append((test_case['name'], condition, bpftrace_vars))
+
+    # Parameterize the conditions so that the test function gets run for each condition
+    # We also set the ids of the functions to be "name: condition" for better reporting
+    metafunc.parametrize("bpftrace_condition", conditions, ids=map(
+        lambda c: f"{c[0]}: {c[1]}", conditions))

kernel_tracing/metric_evaluation/no_dependencies.json

@@ -0,0 +1,12 @@
+{
+    "cases": [
+      {
+        "name": "Demo test",
+        "bpftrace": "./simple_bpftrace.bt",
+        "shell": ["sleep", "1"],
+        "conditions": [
+          "@demo_value == 42"
+        ]
+      }
+    ]
+  }

kernel_tracing/metric_evaluation/readme.md

@@ -0,0 +1,34 @@
+# Metric Evaluation
+
+The `test.py` script in this directory executes tests specified in a JSON file.
+The JSON file is formatted as such:
+
+```json
+{
+  "cases": [
+    {
+      "name": "Name to be displayed in output",
+      "bpftrace": "path to the bpftrace script used to collect metrics, relative to spec file",
+      "shell": "shell command to be run alongside bpftrace script, relative to spec file",
+      "conditions": [
+        "list of conditions that will be evaluated against bpftrace output",
+        "these are python expressions",
+        "bpftrace vars can be referenced with @{var name}, ie @avg",
+        "maps are referenced by @{var name}[{key name(s)}], ie @avg[ipc_time]"
+      ]
+    }
+  ]
+}
+```
+See `sample_spec.json` for an example. `no_dependencies.json` is an alternative
+spec file that should be able to run without any special kernel config.
+
+
+To run a test file, pass it as an argument to the `test.py` script:
+
+```bash
+./test.py my_tests.json
+```
+
+If any of the tests fail, the script will exit with code 1. Individual test
+output will also be printed.

kernel_tracing/metric_evaluation/sample_shell.sh

@@ -0,0 +1,3 @@
+#!/bin/sh
+SOF_LOGGING=none TPLG=/lib/firmware/intel/sof-tplg/sof-hda-generic-4ch.tplg ../../test-case/check-playback.sh -l1
+sleep 5

kernel_tracing/metric_evaluation/sample_spec.json

@@ -0,0 +1,23 @@
+{
+  "cases": [
+    {
+      "name": "IPC TX Time",
+      "bpftrace": "../bpftrace_scripts/ipc_tx_time.bt",
+      "shell": "./sample_shell.sh",
+      "conditions": [
+        "@avg < 500"
+      ]
+    },
+    {
+      "name": "Suspend/Resume Time",
+      "bpftrace": "../bpftrace_scripts/suspend_resume_time.bt",
+      "shell": "../../test-case/check-suspend-resume.sh",
+      "conditions": [
+        "@avg[kretprobe:sof_resume, runtime] < 150000",
+        "@avg[kretprobe:sof_resume, system] < 200000",
+        "@avg[kretprobe:sof_suspend, runtime] < 50000",
+        "@avg[kretprobe:sof_suspend, system] < 1000"
+      ]
+    }
+  ]
+}

kernel_tracing/metric_evaluation/simple_bpftrace.bt

@@ -0,0 +1,7 @@
+// This is used to demo the metric evaluation script without requiring any
+// dependencies. Run `./test.py no_dependencies.json` to try it, and change
+// demo_value to see the failure output.
+
+BEGIN {
+    @demo_value = 42;
+}

kernel_tracing/metric_evaluation/test.py

@@ -0,0 +1,50 @@
+#!/usr/bin/env python3
+
+# SPDX-License-Identifier: BSD-3-Clause
+# Copyright(c) 2022 Intel Corporation. All rights reserved.
+
+# Run with --help for a description of this script
+
+import argparse
+import pytest
+import os
+
+
+def test_bpftrace_conditions(bpftrace_condition):
+    """ This is the test function that is called by pytest """
+    (_name, condition, bpftrace_vars) = bpftrace_condition
+    condition_with_vars = condition
+    for key, val in bpftrace_vars.items():
+        condition_with_vars = condition_with_vars.replace(key, val)
+    has_syntax_error = False
+    try:
+        # Eval does not decrease security as the spec file already embeds shell commands anyway
+        # pylint: disable=eval-used
+        if not eval(condition_with_vars):
+            pytest.fail(
+                f"Failed condition: {condition}. Evaluated to {condition_with_vars}.", pytrace=False)
+    except SyntaxError:
+        has_syntax_error = True
+    # We need pytest.fail to be called outside of the try/except block so the unneeded stack trace is not included
+    if has_syntax_error:
+        pytest.fail(
+            f"Invalid condition: {condition}. Are you sure the bpftrace script outputs necessary variables?", pytrace=False)
+
+
+def main():
+    """ This calls pytest, which runs the test above """
+    parser = argparse.ArgumentParser(
+        description="""
+This script takes as an argument a path to a json file that contains test cases.
+See readme.md for more details.
+"""
+    )
+    parser.add_argument("spec_file", type=argparse.FileType('r'))
+    args = parser.parse_args()
+    os.chdir(os.path.dirname(os.path.abspath(args.spec_file.name)))
+    pytest.main([parser.prog, "-s", "-v", "-rA",
+                "--spec_file", os.path.basename(args.spec_file.name)])
+
+
+if __name__ == "__main__":
+    main()

kernel_tracing/readme.md

@@ -0,0 +1,14 @@
+# Kernel Tracing
+
+This hosts a WIP effort to use kernel tracing to evaluate performance and validate the execution
+context of various functions and operations. The `bpftrace_scripts` folder contains short scripts
+that you can run via the command line. They'll collect traces from the kernel via
+[kprobes](https://lwn.net/Articles/132196) and
+[tracepoints](https://blogs.oracle.com/linux/post/taming-tracepoints-in-the-linux-kernel), and
+output data either as they run or when stopped with ctrl-c. To use them, you'll need to include the
+kconfig/bpf-defconfig in your kernel config, and install `bpftrace` via your package manager. Then,
+just run them with `bpftrace [path to script]`.
+
+Soon, kernel tracing will be integrated into the CI process to detect performance regressions. The
+`kernel_tracing/metric_evaluation` folder contains a script that collects bpftrace data and
+evaluates conditions with pytest, which would be a good candidate for CI integration.

python-deps.txt

@@ -3,3 +3,4 @@ python3-scipy
 pylint
 python3-graphviz
 python3-construct=2.8.*
+python3-pytest