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/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/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 new file mode 100644 index 00000000..76b53237 --- /dev/null +++ b/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. 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