Message-Id: <20240725110622.96301-2-laura.nao@collabora.com>
Date: Thu, 25 Jul 2024 13:06:22 +0200
From: Laura Nao <laura.nao@...labora.com>
To: shuah@...nel.org
Cc: linux-kernel@...r.kernel.org,
	linux-kselftest@...r.kernel.org,
	kernel@...labora.com,
	kernelci@...ts.linux.dev,
	tim.bird@...y.com,
	mhiramat@...nel.org,
	Laura Nao <laura.nao@...labora.com>
Subject: [RFC PATCH 1/1] kselftests: Add test to detect boot event slowdowns

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@...labora.com>
---
 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

Powered by blists - more mailing lists