Selftest for cpuidle latency measurement

Fire directed smp_call_function_single IPIs from a specified source CPU to the specified target CPU to reduce the noise we have to wade through in the trace log.
The module is based on the idea written by Srivatsa Bhat and maintained by Vaidyanathan Srinivasan internally.

Queue HR timer and measure jitter. Wakeup latency measurement for idle states using hrtimer. Echo a value in ns to timer_test_function and watch trace. A HRtimer will be queued and when it fires the expected wakeup vs actual wakeup is computes and delay printed in ns.

Implemented as a module which utilizes debugfs so that it can be integrated with selftests.

To include the module, check option and include as module kernel hacking -> Cpuidle latency selftests

[[email protected]: Initial implementation in
cpidle/sysfs]

[[email protected]: wakeup latency measurements using hrtimer
and fix some of the time calculation]

[[email protected]: Fix some whitespace and tab errors and
increase the resolution of IPI wakeup]

Signed-off-by Pratik Rajesh Sampat <[email protected]>

---
 drivers/cpuidle/Makefile               |   1 +
 drivers/cpuidle/test-cpuidle_latency.c | 150 +++++++++++++++++++++++++
 lib/Kconfig.debug                      |  10 ++
 3 files changed, 161 insertions(+)
 create mode 100644 drivers/cpuidle/test-cpuidle_latency.c

drivers/cpuidle/Makefile +1 -0

index f07800cbb43f..2ae05968078c 100644
@@ -8,6 +8,7 @@ obj-$(CONFIG_ARCH_NEEDS_CPU_IDLE_COUPLED) += coupled.o
 obj-$(CONFIG_DT_IDLE_STATES)		  += dt_idle_states.o
 obj-$(CONFIG_ARCH_HAS_CPU_RELAX)	  += poll_state.o
 obj-$(CONFIG_HALTPOLL_CPUIDLE)		  += cpuidle-haltpoll.o
+obj-$(CONFIG_IDLE_LATENCY_SELFTEST)	  += test-cpuidle_latency.o
 
 ##################################################################################
 # ARM SoC drivers

drivers/cpuidle/test-cpuidle_latency.c new file +150 -0

new file mode 100644
index 000000000000..61574665e972
@@ -0,0 +1,150 @@
+// SPDX-License-Identifier: GPL-2.0-or-later
+/*
+ * Module-based API test facility for cpuidle latency using IPIs and timers
+ */
+
+#include <linux/debugfs.h>
+#include <linux/kernel.h>
+#include <linux/module.h>
+
+/* IPI based wakeup latencies */
+struct latency {
+	unsigned int src_cpu;
+	unsigned int dest_cpu;
+	ktime_t time_start;
+	ktime_t time_end;
+	u64 latency_ns;
+} ipi_wakeup;
+
+static void measure_latency(void *info)
+{
+	struct latency *v;
+	ktime_t time_diff;
+
+	v = (struct latency *)info;
+	v->time_end = ktime_get();
+	time_diff = ktime_sub(v->time_end, v->time_start);
+	v->latency_ns = ktime_to_ns(time_diff);
+}
+
+void run_smp_call_function_test(unsigned int cpu)
+{
+	ipi_wakeup.src_cpu = smp_processor_id();
+	ipi_wakeup.dest_cpu = cpu;
+	ipi_wakeup.time_start = ktime_get();
+	smp_call_function_single(cpu, measure_latency, &ipi_wakeup, 1);
+}
+
+/* Timer based wakeup latencies */
+struct timer_data {
+	unsigned int src_cpu;
+	u64 timeout;
+	ktime_t time_start;
+	ktime_t time_end;
+	struct hrtimer timer;
+	u64 timeout_diff_ns;
+} timer_wakeup;
+
+static enum hrtimer_restart timer_called(struct hrtimer *hrtimer)
+{
+	struct timer_data *w;
+	ktime_t time_diff;
+
+	w = container_of(hrtimer, struct timer_data, timer);
+	w->time_end = ktime_get();
+
+	time_diff = ktime_sub(w->time_end, w->time_start);
+	time_diff = ktime_sub(time_diff, ns_to_ktime(w->timeout));
+	w->timeout_diff_ns = ktime_to_ns(time_diff);
+	return HRTIMER_NORESTART;
+}
+
+static void run_timer_test(unsigned int ns)
+{
+	hrtimer_init(&timer_wakeup.timer, CLOCK_MONOTONIC,
+		     HRTIMER_MODE_REL);
+	timer_wakeup.timer.function = timer_called;
+	timer_wakeup.time_start = ktime_get();
+	timer_wakeup.src_cpu = smp_processor_id();
+	timer_wakeup.timeout = ns;
+
+	hrtimer_start(&timer_wakeup.timer, ns_to_ktime(ns),
+		      HRTIMER_MODE_REL_PINNED);
+}
+
+static struct dentry *dir;
+
+static int cpu_read_op(void *data, u64 *value)
+{
+	*value = ipi_wakeup.dest_cpu;
+	return 0;
+}
+
+static int cpu_write_op(void *data, u64 value)
+{
+	run_smp_call_function_test(value);
+	return 0;
+}
+DEFINE_SIMPLE_ATTRIBUTE(ipi_ops, cpu_read_op, cpu_write_op, "%llu\n");
+
+static int timeout_read_op(void *data, u64 *value)
+{
+	*value = timer_wakeup.timeout;
+	return 0;
+}
+
+static int timeout_write_op(void *data, u64 value)
+{
+	run_timer_test(value);
+	return 0;
+}
+DEFINE_SIMPLE_ATTRIBUTE(timeout_ops, timeout_read_op, timeout_write_op, "%llu\n");
+
+static int __init latency_init(void)
+{
+	struct dentry *temp;
+
+	dir = debugfs_create_dir("latency_test", 0);
+	if (!dir) {
+		pr_alert("latency_test: failed to create /sys/kernel/debug/latency_test\n");
+		return -1;
+	}
+	temp = debugfs_create_file("ipi_cpu_dest",
+				   0666,
+				   dir,
+				   NULL,
+				   &ipi_ops);
+	if (!temp) {
+		pr_alert("latency_test: failed to create /sys/kernel/debug/ipi_cpu_dest\n");
+		return -1;
+	}
+	debugfs_create_u64("ipi_latency_ns", 0444, dir, &ipi_wakeup.latency_ns);
+	debugfs_create_u32("ipi_cpu_src", 0444, dir, &ipi_wakeup.src_cpu);
+
+	temp = debugfs_create_file("timeout_expected_ns",
+				   0666,
+				   dir,
+				   NULL,
+				   &timeout_ops);
+	if (!temp) {
+		pr_alert("latency_test: failed to create /sys/kernel/debug/timeout_expected_ns\n");
+		return -1;
+	}
+	debugfs_create_u64("timeout_diff_ns", 0444, dir, &timer_wakeup.timeout_diff_ns);
+	debugfs_create_u32("timeout_cpu_src", 0444, dir, &timer_wakeup.src_cpu);
+	pr_info("Latency Test module loaded\n");
+	return 0;
+}
+
+static void __exit latency_cleanup(void)
+{
+	pr_info("Cleaning up Latency Test module.\n");
+	debugfs_remove_recursive(dir);
+}
+
+module_init(latency_init);
+module_exit(latency_cleanup);
+
+MODULE_LICENSE("GPL");
+MODULE_AUTHOR("IBM Corporation");
+MODULE_DESCRIPTION("Measuring idle latency for IPIs and Timers");

lib/Kconfig.debug +10 -0

index d74ac0fd6b2d..e2283790245a 100644
@@ -1375,6 +1375,16 @@ config DEBUG_KOBJECT
 	  If you say Y here, some extra kobject debugging messages will be sent
 	  to the syslog.
 
+config IDLE_LATENCY_SELFTEST
+	tristate "Cpuidle latency selftests"
+	depends on CPU_IDLE
+	help
+	  This option provides a kernel module that runs tests using the IPI and
+	  timers to measure latency.
+
+	  Say M if you want these self tests to build as a module.
+	  Say N if you are unsure.
+
 config DEBUG_KOBJECT_RELEASE
 	bool "kobject release debugging"
 	depends on DEBUG_OBJECTS_TIMERS

Signature · 1 line

2.25.4

This patch adds support to trace IPI based and timer based wakeup latency from idle states

Latches onto the test-cpuidle_latency kernel module using the debugfs interface to send IPIs or schedule a timer based event, which in-turn populates the debugfs with the latency measurements.

Currently for the IPI and timer tests; first disable all idle states and then test for latency measurements incrementally enabling each state

Signed-off-by Pratik Rajesh Sampat <[email protected]>

---
 tools/testing/selftests/Makefile           |   1 +
 tools/testing/selftests/cpuidle/Makefile   |   6 +
 tools/testing/selftests/cpuidle/cpuidle.sh | 257 +++++++++++++++++++++
 tools/testing/selftests/cpuidle/settings   |   1 +
 4 files changed, 265 insertions(+)
 create mode 100644 tools/testing/selftests/cpuidle/Makefile
 create mode 100755 tools/testing/selftests/cpuidle/cpuidle.sh
 create mode 100644 tools/testing/selftests/cpuidle/settings

tools/testing/selftests/cpuidle/cpuidle.sh new file +10 -0

+		exit $ksft_skip
+	fi
+	printf "Inserting $MODULE module\n\n"
+	insmod $MODULE
+	if [ $? != 0 ]; then
+		printf "Insmod $MODULE failed\n"
+		exit $ksft_skip
+	fi
+}
+

+

tools/testing/selftests/cpuidle/cpuidle.sh new file +16 -0

+run_ipi_tests()
+{
+        extract_latency
+        disable_idle
+        declare -a avg_arr
+        echo -e "--IPI Latency Test---" >> $LOG
+
+		echo -e "--Baseline IPI Latency measurement: CPU Busy--" >> $LOG
+		printf "%s %10s %12s\n" "SRC_CPU" "DEST_CPU" "IPI_Latency(ns)" >> $LOG
+		for ((cpu=0; cpu<NUM_CPUS; cpu++))
+		do
+			ipi_test_once "baseline" $cpu
+			printf "%-3s %10s %12s\n" $src_cpu $cpu $ipi_latency >> $LOG
+			avg_arr+=($ipi_latency)
+		done
+		compute_average "${avg_arr[@]}"

tools/testing/selftests/cpuidle/cpuidle.sh new file +50 -0

+				# Running IPI test and logging results
+				sleep 1
+				ipi_test_once "test" $cpu
+				printf "%-3s %10s %12s\n" $src_cpu $cpu $ipi_latency >> $LOG
+				avg_arr+=($ipi_latency)
+			done
+			compute_average "${avg_arr[@]}"
+			echo -e "Expected IPI latency(ns): ${latency_arr[$state]}" >> $LOG
+			echo -e "Observed Average IPI latency(ns): $avg" >> $LOG
+			op_state 1 $state
+        done
+}
+
+# Extract the residency in microseconds and convert to nanoseconds.
+# Add 100 ns so that the timer stays for a little longer than the residency
+extract_residency()
+{
+	for ((state=0; state<NUM_STATES; state++))
+	do
+		residency=$(($(cat /sys/devices/system/cpu/cpu0/cpuidle/state$state/residency) * 1000 + 200))
+		residency_arr+=($residency)
+	done
+}
+
+# Run the Timeout test
+# $1 run for baseline - busy cpu or regular environment
+# $2 destination cpu
+# $3 timeout
+timeout_test_once()
+{
+	dest_cpu=$2
+	if [ "$1" = "baseline" ]; then
+		# Keep the CPU busy
+		taskset -c $dest_cpu cat /dev/random > /dev/null &
+		task_pid=$!
+		# Wait for the workload to achieve 100% CPU usage
+		sleep 1
+	fi
+	taskset -c $dest_cpu echo $3 > /sys/kernel/debug/latency_test/timeout_expected_ns
+	# Wait for the result to populate
+	sleep 0.1
+	timeout_diff=$(cat /sys/kernel/debug/latency_test/timeout_diff_ns)
+	src_cpu=$(cat /sys/kernel/debug/latency_test/timeout_cpu_src)
+	if [ "$1" = "baseline" ]; then
+		kill $task_pid
+		wait $task_pid 2>/dev/null
+	fi
+}
+
+run_timeout_tests()

tools/testing/selftests/cpuidle/cpuidle.sh new file +6 -0

+		timeout_test_once "baseline" $cpu ${residency_arr[0]}
+		printf "%-3s %13s\n" $src_cpu $timeout_diff >> $LOG
+		avg_arr+=($timeout_diff)
+	done
+	compute_average "${avg_arr[@]}"
+	echo -e "Baseline Average timeout diff(ns): $avg" >> $LOG

Hi Pratik,

Quoted 11 lines · Pratik Rajesh Sampat

This patch adds support to trace IPI based and timer based wakeup latency from idle states

Latches onto the test-cpuidle_latency kernel module using the debugfs interface to send IPIs or schedule a timer based event, which in-turn populates the debugfs with the latency measurements.

Currently for the IPI and timer tests; first disable all idle states and then test for latency measurements incrementally enabling each state

Signed-off-by Pratik Rajesh Sampat <[email protected]>

A few comments below.

Quoted 10 lines

---
  tools/testing/selftests/Makefile           |   1 +
  tools/testing/selftests/cpuidle/Makefile   |   6 +
  tools/testing/selftests/cpuidle/cpuidle.sh | 257 +++++++++++++++++++++
  tools/testing/selftests/cpuidle/settings   |   1 +
  4 files changed, 265 insertions(+)

create mode 100644 tools/testing/selftests/cpuidle/Makefile create mode 100755 tools/testing/selftests/cpuidle/cpuidle.sh create mode 100644 tools/testing/selftests/cpuidle/settings

[..skip..]

tools/testing/selftests/cpuidle/cpuidle.sh line 44

Quoted 5 lines

tools/testing/selftests/cpuidle/cpuidle.sh new file +5 -0

+
+ins_mod()
+{
+	if [ ! -f "$MODULE" ]; then
+		printf "$MODULE module does not exist. Exitting\n"

If the module has been compiled into the kernel (due to a localyesconfig, for instance), then it is unlikely that we will find it in /lib/modules. Perhaps you want to check if the debugfs directories created by the module exist, and if so, print a message saying that the modules is already loaded or some such?

Quoted 13 lines

tools/testing/selftests/cpuidle/cpuidle.sh new file +13 -0

+		exit $ksft_skip
+	fi
+	printf "Inserting $MODULE module\n\n"
+	insmod $MODULE
+	if [ $? != 0 ]; then
+		printf "Insmod $MODULE failed\n"
+		exit $ksft_skip
+	fi
+}
+
+compute_average()
+{
+	arr=("$@")

tools/testing/selftests/cpuidle/cpuidle.sh line 64

Quoted 7 lines

tools/testing/selftests/cpuidle/cpuidle.sh new file +7 -0

+	sum=0
+	size=${#arr[@]}
+	for i in "${arr[@]}"
+	do
+		sum=$((sum + i))
+	done
+	avg=$((sum/size))

It would be good to assert that "size" isn't 0 here.

Quoted 5 lines

tools/testing/selftests/cpuidle/cpuidle.sh new file +5 -0

+}
+
+# Disable all stop states
+disable_idle()
+{

tools/testing/selftests/cpuidle/cpuidle.sh line 74

Quoted 5 lines

tools/testing/selftests/cpuidle/cpuidle.sh new file +5 -0

+	for ((cpu=0; cpu<NUM_CPUS; cpu++))
+	do
+		for ((state=0; state<NUM_STATES; state++))
+		do
+			echo 1 > /sys/devices/system/cpu/cpu$cpu/cpuidle/state$state/disable

So, on offlined CPUs, we won't see /sys/devices/system/cpu/cpu$cpu/cpuidle/state$state directory. You should probably perform this operation only on online CPUs.