From: Thomas Weißschuh thomas.weissschuh@linutronix.de
The KUnit test validates the correct operation of the ringbuffer. A separate dedicated ringbuffer is used so that the global printk ringbuffer is not touched.
Co-developed-by: John Ogness john.ogness@linutronix.de Signed-off-by: John Ogness john.ogness@linutronix.de Signed-off-by: Thomas Weißschuh thomas.weissschuh@linutronix.de --- For those not familiar with KUnit, you can easily run this test doing something like this:
$ ./tools/testing/kunit/kunit.py run \ --arch=x86_64 \ --qemu_args "-enable-kvm -smp 8" \ --kunitconfig kernel/printk
init/Kconfig | 12 + kernel/printk/.kunitconfig | 3 + kernel/printk/Makefile | 2 + kernel/printk/printk_ringbuffer.c | 4 + kernel/printk/printk_ringbuffer_test.c | 350 +++++++++++++++++++++++++ 5 files changed, 371 insertions(+) create mode 100644 kernel/printk/.kunitconfig create mode 100644 kernel/printk/printk_ringbuffer_test.c
diff --git a/init/Kconfig b/init/Kconfig index 3b6ca7cce03b..46d144908191 100644 --- a/init/Kconfig +++ b/init/Kconfig @@ -1576,6 +1576,18 @@ config PRINTK very difficult to diagnose system problems, saying N here is strongly discouraged.
+config PRINTK_RINGBUFFER_TEST + tristate "Test for the printk ringbuffer" if !KUNIT_ALL_TESTS + depends on PRINTK && KUNIT + default KUNIT_ALL_TESTS + help + This builds the printk ringbuffer KUnit test suite. + + For more information on KUnit and unit tests in general, please refer + to the KUnit documentation. + + If unsure, say N. + config BUG bool "BUG() support" if EXPERT default y diff --git a/kernel/printk/.kunitconfig b/kernel/printk/.kunitconfig new file mode 100644 index 000000000000..8d31a5c19053 --- /dev/null +++ b/kernel/printk/.kunitconfig @@ -0,0 +1,3 @@ +CONFIG_KUNIT=y +CONFIG_SMP=y +CONFIG_PRINTK_RINGBUFFER_TEST=y diff --git a/kernel/printk/Makefile b/kernel/printk/Makefile index 39a2b61c7232..edb5a4cacf67 100644 --- a/kernel/printk/Makefile +++ b/kernel/printk/Makefile @@ -7,3 +7,5 @@ obj-$(CONFIG_PRINTK_INDEX) += index.o obj-$(CONFIG_PRINTK) += printk_support.o printk_support-y := printk_ringbuffer.o printk_support-$(CONFIG_SYSCTL) += sysctl.o + +obj-$(CONFIG_PRINTK_RINGBUFFER_TEST) += printk_ringbuffer_test.o diff --git a/kernel/printk/printk_ringbuffer.c b/kernel/printk/printk_ringbuffer.c index 88e8f3a61922..57b80d262cb7 100644 --- a/kernel/printk/printk_ringbuffer.c +++ b/kernel/printk/printk_ringbuffer.c @@ -1,5 +1,6 @@ // SPDX-License-Identifier: GPL-2.0
+#include <kunit/visibility.h> #include <linux/kernel.h> #include <linux/irqflags.h> #include <linux/string.h> @@ -1685,6 +1686,7 @@ bool prb_reserve(struct prb_reserved_entry *e, struct printk_ringbuffer *rb, memset(r, 0, sizeof(*r)); return false; } +EXPORT_SYMBOL_IF_KUNIT(prb_reserve);
/* Commit the data (possibly finalizing it) and restore interrupts. */ static void _prb_commit(struct prb_reserved_entry *e, unsigned long state_val) @@ -1759,6 +1761,7 @@ void prb_commit(struct prb_reserved_entry *e) if (head_id != e->id) desc_make_final(e->rb, e->id); } +EXPORT_SYMBOL_IF_KUNIT(prb_commit);
/** * prb_final_commit() - Commit and finalize (previously reserved) data to @@ -2181,6 +2184,7 @@ bool prb_read_valid(struct printk_ringbuffer *rb, u64 seq, { return _prb_read_valid(rb, &seq, r, NULL); } +EXPORT_SYMBOL_IF_KUNIT(prb_read_valid);
/** * prb_read_valid_info() - Non-blocking read of meta data for a requested diff --git a/kernel/printk/printk_ringbuffer_test.c b/kernel/printk/printk_ringbuffer_test.c new file mode 100644 index 000000000000..79331ea2b739 --- /dev/null +++ b/kernel/printk/printk_ringbuffer_test.c @@ -0,0 +1,350 @@ +// SPDX-License-Identifier: GPL-2.0 + +#include <linux/delay.h> +#include <linux/init.h> +#include <linux/kthread.h> +#include <linux/module.h> +#include <linux/moduleparam.h> +#include <linux/random.h> +#include <linux/sched/clock.h> +#include <linux/slab.h> +#include <linux/wait.h> + +#include <kunit/test.h> + +#include "printk_ringbuffer.h" + +/* + * This KUnit tests the data integrity of the lockless printk_ringbuffer. + * From multiple CPUs it writes messages of varying length and content while + * a reader validates the correctness of the messages. + * + * IMPORTANT: The more CPUs you can use for this KUnit, the better! + * + * The test works by starting "num_online_cpus() - 1" writer threads, each + * pinned to their own CPU. Each writer thread loops, writing data of varying + * length into a printk_ringbuffer as fast as possible. The data content is + * an embedded data struct followed by string content repeating the byte: + * + * 'A' + CPUID + * + * A reader thread is started on the remaining online CPU and ensures that + * embedded struct content is consistent with the string and that the string + * is terminated and is composed of the same repeating byte as its first byte. + * + * Because the threads are running in such tight loops, they will call + * schedule() from time to time so the system stays functional. + * + * If the reader encounters an error, the test is aborted and some + * information about the error is provided via printk. The runtime of + * the test can be configured with the runtime_ms module parameter. + * + * Note that the test is performed on a separate printk_ringbuffer instance + * and not the instance used by printk(). + */ + +static unsigned long runtime_ms = 10000; +module_param(runtime_ms, ulong, 0400); + +/* used by writers to signal reader of new records */ +static DECLARE_WAIT_QUEUE_HEAD(test_wait); + +/* test data structure */ +struct rbdata { + unsigned int len; + char text[] __counted_by(len); +}; + +#define MAX_RBDATA_LEN (0x7f + 1) +#define MAX_RECORD_SIZE (sizeof(struct rbdata) + MAX_RBDATA_LEN + 1) + +static struct test_running { + int runstate; + unsigned long num; + struct kunit *test; +} *test_running; +static int halt_test; + +static void fail_record(struct kunit *test, struct rbdata *dat, u64 seq) +{ + char buf[MAX_RBDATA_LEN + 1]; + + snprintf(buf, sizeof(buf), "%s", dat->text); + buf[sizeof(buf) - 1] = 0; + + KUNIT_FAIL(test, "BAD RECORD: seq=%llu len=%u text=%s\n", + seq, dat->len, dat->len < sizeof(buf) ? buf : "<invalid>"); +} + +static bool check_data(struct rbdata *dat) +{ + unsigned int len; + + len = strnlen(dat->text, MAX_RBDATA_LEN + 1); + + /* Sane length? */ + if (len != dat->len || !len || len > MAX_RBDATA_LEN) + return false; + + /* String repeats with the same character? */ + while (len) { + len--; + if (dat->text[len] != dat->text[0]) + return false; + } + + return true; +} + +/* Equivalent to CONFIG_LOG_BUF_SHIFT=13 */ +DEFINE_PRINTKRB(test_rb, 8, 5); + +static int prbtest_writer(void *data) +{ + struct test_running *tr = data; + char text_id = 'A' + tr->num; + struct prb_reserved_entry e; + unsigned long count = 0; + struct printk_record r; + u64 min_ns = (u64)-1; + struct rbdata *dat; + u64 total_ns = 0; + u64 max_ns = 0; + u64 post_ns; + u64 pre_ns; + int len; + + set_cpus_allowed_ptr(current, cpumask_of(tr->num)); + + kunit_info(tr->test, "start thread %03lu (writer)\n", tr->num); + + tr->runstate = 1; + + for (;;) { + /* +2 to ensure at least 1 character + terminator. */ + len = sizeof(struct rbdata) + (get_random_u32() & 0x7f) + 2; + + /* specify the text sizes for reservation */ + prb_rec_init_wr(&r, len); + + pre_ns = local_clock(); + + if (prb_reserve(&e, &test_rb, &r)) { + r.info->text_len = len; + + len -= sizeof(struct rbdata) + 1; + + dat = (struct rbdata *)&r.text_buf[0]; + dat->len = len; + memset(&dat->text[0], text_id, len); + dat->text[len] = 0; + + prb_commit(&e); + + post_ns = local_clock(); + + wake_up_interruptible(&test_wait); + + post_ns -= pre_ns; + if (post_ns < min_ns) + min_ns = post_ns; + if (post_ns > max_ns) + max_ns = post_ns; + total_ns += post_ns; + } + + if ((count++ & 0x3fff) == 0) + schedule(); + + if (READ_ONCE(halt_test) == 1) + break; + } + + kunit_info(tr->test, "end thread %03lu: wrote=%lu min_ns=%llu avg_ns=%llu max_ns=%llu\n", + tr->num, count, min_ns, total_ns / (u64)count, max_ns); + + tr->runstate = 2; + + return 0; +} + +static int prbtest_reader(void *data) +{ + struct test_running *tr = data; + char text_buf[MAX_RECORD_SIZE]; + unsigned long total_lost = 0; + unsigned long max_lost = 0; + unsigned long count = 0; + struct printk_info info; + struct printk_record r; + int did_sched = 1; + u64 seq = 0; + + set_cpus_allowed_ptr(current, cpumask_of(tr->num)); + + prb_rec_init_rd(&r, &info, &text_buf[0], sizeof(text_buf)); + + kunit_info(tr->test, "start thread %03lu (reader)\n", tr->num); + + tr->runstate = 1; + + while (!wait_event_interruptible(test_wait, + kthread_should_stop() || + prb_read_valid(&test_rb, seq, &r))) { + bool error = false; + + if (kthread_should_stop()) + break; + /* check/track the sequence */ + if (info.seq < seq) { + KUNIT_FAIL(tr->test, "BAD SEQ READ: request=%llu read=%llu\n", + seq, info.seq); + error = true; + } else if (info.seq != seq && !did_sched) { + total_lost += info.seq - seq; + if (max_lost < info.seq - seq) + max_lost = info.seq - seq; + } + + if (!check_data((struct rbdata *)&r.text_buf[0])) { + fail_record(tr->test, (struct rbdata *)&r.text_buf[0], info.seq); + error = true; + } + + if (error) + WRITE_ONCE(halt_test, 1); + + did_sched = 0; + if ((count++ & 0x3fff) == 0) { + did_sched = 1; + schedule(); + } + + if (READ_ONCE(halt_test) == 1) + break; + + seq = info.seq + 1; + } + + kunit_info(tr->test, + "end thread %03lu: read=%lu seq=%llu total_lost=%lu max_lost=%lu\n", + tr->num, count, info.seq, total_lost, max_lost); + + while (!kthread_should_stop()) + msleep(1000); + tr->runstate = 2; + + return 0; +} + +static int module_test_running; +static struct task_struct *reader_thread; + +static int start_test(void *arg) +{ + struct kunit *test = arg; + struct task_struct *thread; + unsigned long i; + int num_cpus; + + num_cpus = num_online_cpus(); + if (num_cpus == 1) + kunit_skip(test, "need >1 CPUs for at least one reader and writer"); + + test_running = kcalloc(num_cpus, sizeof(*test_running), GFP_KERNEL); + KUNIT_ASSERT_NOT_NULL(test, test_running); + + module_test_running = 1; + + kunit_info(test, "starting test\n"); + + for (i = 0; i < num_cpus; i++) { + test_running[i].test = test; + test_running[i].num = i; + if (i < num_cpus - 1) { + thread = kthread_run(prbtest_writer, &test_running[i], + "prbtest writer"); + } else { + thread = kthread_run(prbtest_reader, &test_running[i], + "prbtest reader"); + reader_thread = thread; + } + if (IS_ERR(thread)) { + kunit_err(test, "unable to create thread %lu\n", i); + test_running[i].runstate = 2; + } + } + + /* wait until all threads finish */ + for (;;) { + msleep(1000); + + for (i = 0; i < num_cpus; i++) { + if (test_running[i].runstate < 2) + break; + } + if (i == num_cpus) + break; + } + + kunit_info(test, "completed test\n"); + + module_test_running = 0; + + return 0; +} + +static void test_readerwriter(struct kunit *test) +{ + static bool already_run; + int num_cpus; + int i; + + if (already_run) + KUNIT_FAIL_AND_ABORT(test, "test can only be run once"); + already_run = true; + + kunit_info(test, "running for %lu ms\n", runtime_ms); + + kthread_run(start_test, test, "prbtest"); + + /* wait until all threads active */ + num_cpus = num_online_cpus(); + for (;;) { + msleep(1000); + + for (i = 0; i < num_cpus; i++) { + if (test_running[i].runstate == 0) + break; + } + if (i == num_cpus) + break; + } + + msleep(runtime_ms); + + if (reader_thread && !IS_ERR(reader_thread)) + kthread_stop(reader_thread); + + WRITE_ONCE(halt_test, 1); + + while (module_test_running) + msleep(1000); + kfree(test_running); +} + +static struct kunit_case prb_test_cases[] = { + KUNIT_CASE_SLOW(test_readerwriter), + {} +}; + +static struct kunit_suite prb_test_suite = { + .name = "printk-ringbuffer", + .test_cases = prb_test_cases, +}; +kunit_test_suite(prb_test_suite); + +MODULE_IMPORT_NS(EXPORTED_FOR_KUNIT_TESTING); +MODULE_AUTHOR("John Ogness john.ogness@linutronix.de"); +MODULE_DESCRIPTION("printk_ringbuffer test"); +MODULE_LICENSE("GPL");
base-commit: 4022ef25504db2fb79a2acac0afe9bac934f8dd6