From 91ad5b6ef7c1fbb18d01123c96b554f31be3f966 Mon Sep 17 00:00:00 2001
From: Noah Klayman <noah.klayman@intel.com>
Date: Thu, 10 Mar 2022 18:49:47 -0500
Subject: [PATCH 1/2] tracing: add various bpftrace scripts to trace SOF events
 in the kernel

Adds scripts to track sof_resume/suspend and ipc tx time, and count hda
irq interrupt sources and calculate timestamp deltas per-source.

Signed-off-by: Noah Klayman <noah.klayman@intel.com>
---
 .../bpftrace_scripts/hda_irq_source_counts.bt | 12 ++++++++
 .../bpftrace_scripts/hda_irq_source_deltas.bt | 15 ++++++++++
 .../bpftrace_scripts/ipc_tx_time.bt           | 30 +++++++++++++++++++
 .../bpftrace_scripts/suspend_resume_time.bt   | 29 ++++++++++++++++++
 kernel_tracing/readme.md                      | 12 ++++++++
 5 files changed, 98 insertions(+)
 create mode 100644 kernel_tracing/bpftrace_scripts/hda_irq_source_counts.bt
 create mode 100644 kernel_tracing/bpftrace_scripts/hda_irq_source_deltas.bt
 create mode 100644 kernel_tracing/bpftrace_scripts/ipc_tx_time.bt
 create mode 100644 kernel_tracing/bpftrace_scripts/suspend_resume_time.bt
 create mode 100644 kernel_tracing/readme.md

diff --git a/kernel_tracing/bpftrace_scripts/hda_irq_source_counts.bt b/kernel_tracing/bpftrace_scripts/hda_irq_source_counts.bt
new file mode 100644
index 00000000..8ae5ebfd
--- /dev/null
+++ b/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();
+}
diff --git a/kernel_tracing/bpftrace_scripts/hda_irq_source_deltas.bt b/kernel_tracing/bpftrace_scripts/hda_irq_source_deltas.bt
new file mode 100644
index 00000000..19114e3e
--- /dev/null
+++ b/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)
+}
diff --git a/kernel_tracing/bpftrace_scripts/ipc_tx_time.bt b/kernel_tracing/bpftrace_scripts/ipc_tx_time.bt
new file mode 100644
index 00000000..21f2ac88
--- /dev/null
+++ b/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);
+}
diff --git a/kernel_tracing/bpftrace_scripts/suspend_resume_time.bt b/kernel_tracing/bpftrace_scripts/suspend_resume_time.bt
new file mode 100644
index 00000000..f21db351
--- /dev/null
+++ b/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);
+}
diff --git a/kernel_tracing/readme.md b/kernel_tracing/readme.md
new file mode 100644
index 00000000..cbda2e18
--- /dev/null
+++ b/kernel_tracing/readme.md
@@ -0,0 +1,12 @@
+# 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 using tools that allow for collection and evaluation of BPF programs' output.

From e289f80c612abf713a7c8a9cd18e06a2ed0b07d1 Mon Sep 17 00:00:00 2001
From: Noah Klayman <noah.klayman@intel.com>
Date: Thu, 7 Oct 2021 21:02:27 -0400
Subject: [PATCH 2/2] tracing: add python script to evaluate performance
 metrics for CI

Takes a test specification from a JSON file, which contains a bpftrace
script, shell commands, and test conditions. It runs the bpftrace script
while executing shell commands, and collects all variables from
bpftrace. These are then injected into the conditions which are
evaluated with python's eval. Case execution and output formatting is
handled by pytest.

Signed-off-by: Noah Klayman <noah.klayman@intel.com>
---
 .gitignore                                    |  1 +
 kernel_tracing/metric_evaluation/conftest.py  | 91 +++++++++++++++++++
 .../metric_evaluation/no_dependencies.json    | 12 +++
 kernel_tracing/metric_evaluation/readme.md    | 34 +++++++
 .../metric_evaluation/sample_shell.sh         |  3 +
 .../metric_evaluation/sample_spec.json        | 23 +++++
 .../metric_evaluation/simple_bpftrace.bt      |  7 ++
 kernel_tracing/metric_evaluation/test.py      | 50 ++++++++++
 kernel_tracing/readme.md                      |  4 +-
 python-deps.txt                               |  1 +
 10 files changed, 225 insertions(+), 1 deletion(-)
 create mode 100644 kernel_tracing/metric_evaluation/conftest.py
 create mode 100644 kernel_tracing/metric_evaluation/no_dependencies.json
 create mode 100644 kernel_tracing/metric_evaluation/readme.md
 create mode 100755 kernel_tracing/metric_evaluation/sample_shell.sh
 create mode 100644 kernel_tracing/metric_evaluation/sample_spec.json
 create mode 100644 kernel_tracing/metric_evaluation/simple_bpftrace.bt
 create mode 100755 kernel_tracing/metric_evaluation/test.py

diff --git a/.gitignore b/.gitignore
index 946cfc75..c47cf4aa 100644
--- a/.gitignore
+++ b/.gitignore
@@ -1,2 +1,3 @@
 logs/
 tools/__pycache__/
+kernel_tracing/metric_evaluation/__pycache__/
diff --git a/kernel_tracing/metric_evaluation/conftest.py b/kernel_tracing/metric_evaluation/conftest.py
new file mode 100644
index 00000000..85fcf889
--- /dev/null
+++ b/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))
diff --git a/kernel_tracing/metric_evaluation/no_dependencies.json b/kernel_tracing/metric_evaluation/no_dependencies.json
new file mode 100644
index 00000000..6cf70cbe
--- /dev/null
+++ b/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"
+        ]
+      }
+    ]
+  }
diff --git a/kernel_tracing/metric_evaluation/readme.md b/kernel_tracing/metric_evaluation/readme.md
new file mode 100644
index 00000000..dfde8a4a
--- /dev/null
+++ b/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.
\ No newline at end of file
diff --git a/kernel_tracing/metric_evaluation/sample_shell.sh b/kernel_tracing/metric_evaluation/sample_shell.sh
new file mode 100755
index 00000000..49e14cca
--- /dev/null
+++ b/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
diff --git a/kernel_tracing/metric_evaluation/sample_spec.json b/kernel_tracing/metric_evaluation/sample_spec.json
new file mode 100644
index 00000000..adabe71b
--- /dev/null
+++ b/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"
+      ]
+    }
+  ]
+}
diff --git a/kernel_tracing/metric_evaluation/simple_bpftrace.bt b/kernel_tracing/metric_evaluation/simple_bpftrace.bt
new file mode 100644
index 00000000..8e894b22
--- /dev/null
+++ b/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;
+}
diff --git a/kernel_tracing/metric_evaluation/test.py b/kernel_tracing/metric_evaluation/test.py
new file mode 100755
index 00000000..d2eb894b
--- /dev/null
+++ b/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()
diff --git a/kernel_tracing/readme.md b/kernel_tracing/readme.md
index cbda2e18..76b53237 100644
--- a/kernel_tracing/readme.md
+++ b/kernel_tracing/readme.md
@@ -9,4 +9,6 @@ output data either as they run or when stopped with ctrl-c. To use them, you'll
 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 using tools that allow for collection and evaluation of BPF programs' output.
+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.
diff --git a/python-deps.txt b/python-deps.txt
index 75dffa26..56b941a4 100644
--- a/python-deps.txt
+++ b/python-deps.txt
@@ -3,3 +3,4 @@ python3-scipy
 pylint
 python3-graphviz
 python3-construct=2.8.*
+python3-pytest