Introduce a new kselftest to identify slowdowns in key boot events.
The test uses ftrace to track timings for specific boot events.
The kprobe_timestamps_to_yaml.py script can be run once to generate a
YAML file with the initial reference timestamps for these events.
The test_boot_time.py script can then be run on subsequent boots to
compare current timings against the reference values and check for
significant slowdowns over time.
The test ships with a bootconfig file for ftrace setup and a config
fragment for the necessary kernel configurations.
Signed-off-by: Laura Nao <laura.nao@xxxxxxxxxxxxx>
---
tools/testing/selftests/Makefile | 1 +
tools/testing/selftests/boot-time/Makefile | 17 ++++
tools/testing/selftests/boot-time/bootconfig | 8 ++
tools/testing/selftests/boot-time/config | 4 +
.../boot-time/kprobe_timestamps_to_yaml.py | 55 +++++++++++
.../selftests/boot-time/test_boot_time.py | 94 +++++++++++++++++++
.../selftests/boot-time/trace_utils.py | 63 +++++++++++++
7 files changed, 242 insertions(+)
create mode 100644 tools/testing/selftests/boot-time/Makefile
create mode 100644 tools/testing/selftests/boot-time/bootconfig
create mode 100644 tools/testing/selftests/boot-time/config
create mode 100755 tools/testing/selftests/boot-time/kprobe_timestamps_to_yaml.py
create mode 100755 tools/testing/selftests/boot-time/test_boot_time.py
create mode 100644 tools/testing/selftests/boot-time/trace_utils.py
diff --git a/tools/testing/selftests/Makefile b/tools/testing/selftests/Makefile
index bc8fe9e8f7f2..1e675779322f 100644
--- a/tools/testing/selftests/Makefile
+++ b/tools/testing/selftests/Makefile
@@ -2,6 +2,7 @@
TARGETS += alsa
TARGETS += amd-pstate
TARGETS += arm64
+TARGETS += boot-time
TARGETS += bpf
TARGETS += breakpoints
TARGETS += cachestat
diff --git a/tools/testing/selftests/boot-time/Makefile b/tools/testing/selftests/boot-time/Makefile
new file mode 100644
index 000000000000..43ccd0a3b62e
--- /dev/null
+++ b/tools/testing/selftests/boot-time/Makefile
@@ -0,0 +1,17 @@
+PY3 = $(shell which python3 2>/dev/null)
+
+ifneq ($(PY3),)
+
+TEST_PROGS := test_boot_time.py
+TEST_FILES := trace_utils.py kprobe_timestamps_to_yaml.py
+
+include ../lib.mk
+
+else
+
+all: no_py3_warning
+
+no_py3_warning:
+ @echo "Missing python3. This test will be skipped."
+
+endif
\ No newline at end of file
diff --git a/tools/testing/selftests/boot-time/bootconfig b/tools/testing/selftests/boot-time/bootconfig
new file mode 100644
index 000000000000..2883f03e0766
--- /dev/null
+++ b/tools/testing/selftests/boot-time/bootconfig
@@ -0,0 +1,8 @@
+ftrace {
+ event.kprobes {
+ populate_rootfs_begin.probes = "populate_rootfs"
+ unpack_to_rootfs_begin.probes = "unpack_to_rootfs"
+ run_init_process_begin.probes = "run_init_process"
+ run_init_process_end.probes = "run_init_process%return"
+ }
+}
\ No newline at end of file
diff --git a/tools/testing/selftests/boot-time/config b/tools/testing/selftests/boot-time/config
new file mode 100644
index 000000000000..957b40b45bc0
--- /dev/null
+++ b/tools/testing/selftests/boot-time/config
@@ -0,0 +1,4 @@
+CONFIG_TRACING=y
+CONFIG_BOOTTIME_TRACING=y
+CONFIG_BOOT_CONFIG_EMBED=y
+CONFIG_BOOT_CONFIG_EMBED_FILE="tools/testing/selftests/boot-time/bootconfig"
\ No newline at end of file
diff --git a/tools/testing/selftests/boot-time/kprobe_timestamps_to_yaml.py b/tools/testing/selftests/boot-time/kprobe_timestamps_to_yaml.py
new file mode 100755
index 000000000000..43e742e0759d
--- /dev/null
+++ b/tools/testing/selftests/boot-time/kprobe_timestamps_to_yaml.py
@@ -0,0 +1,55 @@
+#!/usr/bin/env python3
+# SPDX-License-Identifier: GPL-2.0
+#
+# Copyright (c) 2024 Collabora Ltd
+#
+#
+# This script reads the /sys/kernel/debug/tracing/trace file, extracts kprobe
+# event names and timestamps, and saves them to a YAML file.
+#
+# Example of the YAML content generated:
+#
+# - event: populate_rootfs_begin
+# timestamp: 0.525161
+# - event: unpack_to_rootfs_begin
+# timestamp: 0.525169
+#
+# Usage:
+# ./kprobe_timestamps_to_yaml.py [output_file]
+#
+
+import sys
+import argparse
+import yaml
+
+from trace_utils import mount_debugfs, parse_kprobe_event_trace
+
+
+def write_trace_timestamps_to_yaml(output_file_path):
+ """
+ Parse /sys/kernel/debug/tracing/trace file to extract kprobe event
+ names and timestamps, and write them to a YAML file.
+ @output_file_path: the path for the output YAML file, defaults to
+ 'kprobe-timestamps.yaml'.
+ """
+ trace_entries = parse_kprobe_event_trace("/sys/kernel/debug/tracing/trace")
+ filtered_entries = {entry['event']: entry['timestamp'] for entry in trace_entries}
+
+ with open(output_file_path, 'w', encoding="utf-8") as yaml_file:
+ yaml.dump(filtered_entries, yaml_file)
+
+ print(f"Generated {output_file_path}")
+
+
+if __name__ == "__main__":
+ parser = argparse.ArgumentParser(
+ description="Extract kprobe event names and timestamps from the \
+ /sys/kernel/debug/tracing/trace file and save them to a YAML file.")
+ parser.add_argument('output_file_path', nargs='?', default='kprobe-timestamps.yaml',
+ help="path for the output YAML file")
+ args = parser.parse_args()
+
+ if not mount_debugfs("/sys/kernel/debug"):
+ sys.exit(1)
+
+ write_trace_timestamps_to_yaml(args.output_file_path)
diff --git a/tools/testing/selftests/boot-time/test_boot_time.py b/tools/testing/selftests/boot-time/test_boot_time.py
new file mode 100755
index 000000000000..8a8de28c485c
--- /dev/null
+++ b/tools/testing/selftests/boot-time/test_boot_time.py
@@ -0,0 +1,94 @@
+#!/usr/bin/env python3
+# SPDX-License-Identifier: GPL-2.0
+#
+# Copyright (c) 2024 Collabora Ltd
+#
+# This script reads the /sys/kernel/debug/tracing/trace file, extracts kprobe
+# event names and timestamps, and compares them against reference timestamps
+# provided in an input YAML file to identify significant slowdowns in
+# the reference kprobe events.
+#
+# Usage:
+# ./test_boot_time.py <kprobe_timestamps_file> <delta(seconds)>
+
+import os
+import sys
+import argparse
+import yaml
+from trace_utils import mount_debugfs, parse_kprobe_event_trace
+
+this_dir = os.path.dirname(os.path.realpath(__file__))
+sys.path.append(os.path.join(this_dir, "../kselftest/"))
+
+import ksft
+
+def load_kprobe_timestamps_from_yaml(file_path):
+ """
+ Load YAML file containing kprobe event timestamps. Return a dictionary
+ with event names as keys and the corresponding timestamps as values.
+ For example:
+ {'populate_rootfs_begin': 0.525161, 'unpack_to_rootfs_begin': 0.525169}
+ @file_path: path to a YAML file containing the kprobe event timestamps.
+ """
+ try:
+ with open(file_path, 'r', encoding="utf-8") as file:
+ return yaml.safe_load(file)
+ except FileNotFoundError:
+ ksft.print_msg(f"Error: File {file_path} not found.")
+ ksft.exit_fail()
+ except yaml.YAMLError as e:
+ ksft.print_msg(f"Error: Failed to parse YAML file {file_path}. Error: {e}")
+ ksft.exit_fail()
+
+
+def evaluate_kprobe_event_delays(ref_entries, delta):
+ """
+ Read the /sys/kernel/debug/tracing/trace file to extract kprobe event
+ names and timestamps, then compare these timestamps with the reference
+ values provided. Report a failure for each timestamp that deviates from
+ the reference by more than the specified delta.
+ @ref_entries: dictionary containing event names and their timestamps
+ @delta: maximum allowed difference in seconds between the current and
+ reference timestamps
+ """
+ ksft.set_plan(len(ref_entries))
+
+ trace_entries = {entry['event']: entry['timestamp']
+ for entry in parse_kprobe_event_trace("/sys/kernel/debug/tracing/trace")}
+
+ for ref_event, ref_timestamp in ref_entries.items():
+ if ref_event in trace_entries:
+ timestamp = trace_entries[ref_event]
+ if timestamp >= ref_timestamp and (timestamp - ref_timestamp) >= delta:
+ ksft.print_msg(f"'{ref_event}' differs by "
+ f"{(timestamp - ref_timestamp):.6f} seconds.")
+ ksft.test_result_fail(ref_event)
+ else:
+ ksft.test_result_pass(ref_event)
+ else:
+ ksft.print_msg(f"Reference event '{ref_event}' not found in trace.")
+ ksft.test_result_skip(ref_event)
+
+
+if __name__ == "__main__":
+ parser = argparse.ArgumentParser(
+ description="Read the /sys/kernel/debug/tracing/trace file, extract kprobe event names \
+ and timestamps, and compares them against reference timestamps provided in an input YAML \
+ file to report significant slowdowns in the reference kprobe events.")
+ parser.add_argument('kprobe_timestamps_file', help="path to YAML file containing \
+ kprobe timestamps")
+ parser.add_argument('delta', type=float, help="maximum allowed difference in seconds \
+ (float) between the current and reference timestamps")
+ args = parser.parse_args()
+
+ # Ensure debugfs is mounted
+ if not mount_debugfs("/sys/kernel/debug"):
+ ksft.exit_fail()
+
+ ksft.print_header()
+
+ ref_entries = load_kprobe_timestamps_from_yaml(args.kprobe_timestamps_file)
+
+ evaluate_kprobe_event_delays(ref_entries, args.delta)
+
+ ksft.finished()
diff --git a/tools/testing/selftests/boot-time/trace_utils.py b/tools/testing/selftests/boot-time/trace_utils.py
new file mode 100644
index 000000000000..c40cef2bf584
--- /dev/null
+++ b/tools/testing/selftests/boot-time/trace_utils.py
@@ -0,0 +1,63 @@
+#!/usr/bin/env python3
+# SPDX-License-Identifier: GPL-2.0
+#
+# Copyright (c) 2024 Collabora Ltd
+#
+# Utility functions for parsing trace files and mounting debugfs.
+#
+
+import re
+import subprocess
+
+
+def mount_debugfs(path):
+ """
+ Mount debugfs at the specified path if it is not already mounted.
+ @path: path where debugfs should be mounted
+ """
+ # Check if debugfs is already mounted
+ with open('/proc/mounts', 'r', encoding="utf-8") as mounts:
+ for line in mounts:
+ if 'debugfs' in line and path in line:
+ print(f"debugfs is already mounted at {path}")
+ return True
+
+ # Mount debugfs
+ try:
+ subprocess.run(['mount', '-t', 'debugfs', 'none', path], check=True)
+ return True
+ except subprocess.CalledProcessError as e:
+ print(f"Failed to mount debugfs: {e.stderr}")
+ return False
+
+
+def parse_kprobe_event_trace(trace_file_path):
+ """
+ Parse a trace file containing kprobe events and return a list of
+ dictionaries, each representing a trace entry.
+
+ Example of trace entry:
+ {'task_pid': 'sh-1', 'timestamp': 0.256527, 'event': \\
+ 'populate_rootfs_begin', 'function': 'populate_rootfs+0x4/0x50'}
+
+ @trace_file_path: path to the trace file
+ """
+ trace_pattern = r'^\s*(\S+)\s+\[.*\]\s+\S+\s+(\d+\.\d+):\s+(\S+):\s+\((.*)\)$'
+
+ trace_entries = []
+
+ # Read trace file and parse entries
+ with open(trace_file_path, 'r', encoding="utf-8") as trace_file:
+ for line in trace_file:
+ match = re.match(trace_pattern, line)
+ if match:
+ trace_entry = {
+ 'task_pid': match.group(1),
+ 'timestamp': float(match.group(2)),
+ 'event': match.group(3),
+ 'function': match.group(4)
+ }
+
+ trace_entries.append(trace_entry)
+
+ return trace_entries
--
2.30.2
