[RFC PATCH v5 3/3] printk-rb: add test module

From: John Ogness
Date: Wed Nov 27 2019 - 20:53:10 EST


This module does some heavy write stress testing on the ringbuffer
with a reader that is checking for integrity.

Signed-off-by: John Ogness <john.ogness@xxxxxxxxxxxxx>
---
kernel/printk/Makefile | 3 +
kernel/printk/test_prb.c | 347 +++++++++++++++++++++++++++++++++++++++
2 files changed, 350 insertions(+)
create mode 100644 kernel/printk/test_prb.c

diff --git a/kernel/printk/Makefile b/kernel/printk/Makefile
index 4d052fc6bcde..2aabbe561efc 100644
--- a/kernel/printk/Makefile
+++ b/kernel/printk/Makefile
@@ -2,3 +2,6 @@
obj-y = printk.o
obj-$(CONFIG_PRINTK) += printk_safe.o
obj-$(CONFIG_A11Y_BRAILLE_CONSOLE) += braille.o
+
+prbtest-y = printk_ringbuffer.o test_prb.o
+obj-m += prbtest.o
diff --git a/kernel/printk/test_prb.c b/kernel/printk/test_prb.c
new file mode 100644
index 000000000000..d038b16bf01b
--- /dev/null
+++ b/kernel/printk/test_prb.c
@@ -0,0 +1,347 @@
+// SPDX-License-Identifier: GPL-2.0
+
+#include <linux/init.h>
+#include <linux/module.h>
+#include <linux/kthread.h>
+#include <linux/delay.h>
+#include <linux/random.h>
+#include <linux/slab.h>
+#include <linux/wait.h>
+#include "printk_ringbuffer.h"
+
+/*
+ * This is a test module that starts "num_online_cpus()" writer threads
+ * that each write data of varying length. They do this as fast as
+ * they can.
+ *
+ * Dictionary data is stored in a separate data ring. The writers will
+ * only write dictionary data about half the time. This is to make the
+ * test more realistic with text and dict data rings containing
+ * different data blocks.
+ *
+ * Because the threads are running in such tight loops, they will call
+ * schedule() from time to time so the system stays alive.
+ *
+ * If the writers encounter an error, the test is aborted. Test results are
+ * recorded to the ftrace buffers, with some additional information also
+ * provided via printk. The test can be aborted manually by removing the
+ * module. (Ideally the test should never abort on its own.)
+ */
+
+/* not used right now */
+DECLARE_WAIT_QUEUE_HEAD(test_wait);
+
+/* test data structure */
+struct rbdata {
+ int len;
+ char text[0];
+};
+
+static char *test_running;
+static int halt_test;
+
+/* dump text or dictionary data to the trace buffers */
+static void print_record(const char *name, struct rbdata *dat, u64 seq)
+{
+ char buf[160];
+
+ snprintf(buf, sizeof(buf), "%s", dat->text);
+ buf[sizeof(buf) - 1] = 0;
+
+ trace_printk("seq=%llu len=%d %sval=%s\n",
+ seq, dat->len, name,
+ dat->len < sizeof(buf) ? buf : "<invalid>");
+}
+
+/*
+ * sequentially dump all the valid records in the ringbuffer
+ * (used to verify memory integrity)
+ *
+ * Since there is no reader interface, the internal members are
+ * directly accessed. This function is called after all writers
+ * are finished so there is no need for any memory barriers.
+ */
+static void dump_rb(struct printk_ringbuffer *rb)
+{
+ struct printk_info info;
+ struct printk_record r;
+ char text_buf[200];
+ char dict_buf[200];
+ u64 seq = 0;
+
+ r.info = &info;
+ r.text_buf = &text_buf[0];
+ r.dict_buf = &dict_buf[0];
+ r.text_buf_size = sizeof(text_buf);
+ r.dict_buf_size = sizeof(dict_buf);
+
+ trace_printk("BEGIN full dump\n");
+
+ while (prb_read_valid(rb, seq, &r)) {
+ /* check/track the sequence */
+ if (info.seq != seq)
+ trace_printk("DROPPED %llu\n", info.seq - seq);
+
+ print_record("TEXT", (struct rbdata *)&r.text_buf[0],
+ info.seq);
+ if (info.dict_len) {
+ print_record("DICT", (struct rbdata *)&r.dict_buf[0],
+ info.seq);
+ }
+
+ seq = info.seq + 1;
+ }
+
+ trace_printk("END full dump\n");
+}
+
+DECLARE_PRINTKRB(test_rb, 15, 5, 5);
+
+static int prbtest_writer(void *data)
+{
+ unsigned long num = (unsigned long)data;
+ struct prb_reserved_entry e;
+ char text_id = 'A' + num;
+ char dict_id = 'a' + num;
+ unsigned long count = 0;
+ struct printk_record r;
+ struct rbdata *dat;
+ int len;
+
+ pr_err("prbtest: start thread %03lu (writer)\n", num);
+
+ for (;;) {
+ len = sizeof(struct rbdata) + (prandom_u32() & 0x7f) + 2;
+
+ /* specify the text/dict sizes for reservation */
+ r.text_buf_size = len;
+ /* only add a dictionary on some records */
+ if (len % 2)
+ r.dict_buf_size = len;
+ else
+ r.dict_buf_size = 0;
+
+ if (prb_reserve(&e, &test_rb, &r)) {
+ 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;
+
+ /* dictionary reservation is allowed to fail */
+ if (r.dict_buf) {
+ dat = (struct rbdata *)&r.dict_buf[0];
+ dat->len = len;
+ memset(&dat->text[0], dict_id, len);
+ dat->text[len] = 0;
+ } else if (r.text_buf_size % 2) {
+ trace_printk(
+ "writer%lu (%c) dict dropped: seq=%llu\n",
+ num, text_id, r.info->seq);
+ }
+
+ prb_commit(&e);
+ wake_up_interruptible(&test_wait);
+ } else {
+ WRITE_ONCE(halt_test, 1);
+ trace_printk("writer%lu (%c) reserve failed\n",
+ num, text_id);
+ }
+
+ if ((count++ & 0x3fff) == 0)
+ schedule();
+
+ if (READ_ONCE(halt_test) == 1)
+ break;
+ }
+
+ pr_err("prbtest: end thread %03lu (writer, wrote %lu)\n", num, count);
+
+ test_running[num] = 0;
+
+ return 0;
+}
+
+static bool check_data(struct rbdata *dat, u64 seq, unsigned long num)
+{
+ int len;
+
+ len = strnlen(dat->text, 160);
+
+ if (len != dat->len || len >= 160) {
+ WRITE_ONCE(halt_test, 1);
+ trace_printk("reader%lu invalid len for %llu (%d<->%d)\n",
+ num, seq, len, dat->len);
+ return false;
+ }
+
+ while (len) {
+ len--;
+ if (dat->text[len] != dat->text[0]) {
+ WRITE_ONCE(halt_test, 1);
+ trace_printk("reader%lu bad data\n", num);
+ return false;
+ }
+ }
+
+ return true;
+}
+
+static int prbtest_reader(void *data)
+{
+ unsigned long num = (unsigned long)data;
+ unsigned long total_lost = 0;
+ unsigned long max_lost = 0;
+ unsigned long count = 0;
+ struct printk_info info;
+ struct printk_record r;
+ char text_buf[200];
+ char dict_buf[200];
+ int did_sched = 1;
+ u64 seq = 0;
+
+ r.info = &info;
+ r.text_buf = &text_buf[0];
+ r.dict_buf = &dict_buf[0];
+ r.text_buf_size = sizeof(text_buf);
+ r.dict_buf_size = sizeof(dict_buf);
+
+ pr_err("prbtest: start thread %03lu (reader)\n", num);
+
+ while (!wait_event_interruptible(test_wait,
+ kthread_should_stop() ||
+ prb_read_valid(&test_rb, seq, &r))) {
+ if (kthread_should_stop())
+ break;
+ /* check/track the sequence */
+ if (info.seq < seq) {
+ WRITE_ONCE(halt_test, 1);
+ trace_printk("reader%lu invalid seq %llu -> %llu\n",
+ num, seq, info.seq);
+ break;
+ } 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],
+ info.seq, num)) {
+ trace_printk("text error\n");
+ break;
+ }
+
+ if (info.dict_len) {
+ if (!check_data((struct rbdata *)&r.dict_buf[0],
+ info.seq, num)) {
+ trace_printk("dict error\n");
+ break;
+ }
+ } else if (info.text_len % 2) {
+ trace_printk("dict dropped: seq=%llu\n", info.seq);
+ }
+
+ did_sched = 0;
+ if ((count++ & 0x3fff) == 0) {
+ did_sched = 1;
+ schedule();
+ }
+
+ if (READ_ONCE(halt_test) == 1)
+ break;
+
+ seq = info.seq + 1;
+ }
+
+ pr_err(
+ "reader%lu: total_lost=%lu max_lost=%lu total_read=%lu seq=%llu\n",
+ num, total_lost, max_lost, count, info.seq);
+
+ pr_err("prbtest: end thread %03lu (reader)\n", num);
+
+ while (!kthread_should_stop())
+ msleep(1000);
+ test_running[num] = 0;
+
+ return 0;
+}
+
+static int module_test_running;
+static struct task_struct *reader_thread;
+
+static int start_test(void *arg)
+{
+ struct task_struct *thread;
+ unsigned long i;
+ int num_cpus;
+
+ num_cpus = num_online_cpus();
+ test_running = kzalloc(num_cpus, GFP_KERNEL);
+ if (!test_running)
+ return -ENOMEM;
+
+ module_test_running = 1;
+
+ pr_err("prbtest: starting test\n");
+
+ for (i = 0; i < num_cpus; i++) {
+ test_running[i] = 1;
+ if (i < num_cpus - 1) {
+ thread = kthread_run(prbtest_writer, (void *)i,
+ "prbtest writer");
+ } else {
+ thread = kthread_run(prbtest_reader, (void *)i,
+ "prbtest reader");
+ reader_thread = thread;
+ }
+ if (IS_ERR(thread)) {
+ pr_err("prbtest: unable to create thread %lu\n", i);
+ test_running[i] = 0;
+ }
+ }
+
+ for (;;) {
+ msleep(1000);
+
+ for (i = 0; i < num_cpus; i++) {
+ if (test_running[i] == 1)
+ break;
+ }
+ if (i == num_cpus)
+ break;
+ }
+
+ pr_err("prbtest: completed test\n");
+
+ dump_rb(&test_rb);
+
+ module_test_running = 0;
+
+ return 0;
+}
+
+static int prbtest_init(void)
+{
+ kthread_run(start_test, NULL, "prbtest");
+ return 0;
+}
+
+static void prbtest_exit(void)
+{
+ 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);
+}
+
+module_init(prbtest_init);
+module_exit(prbtest_exit);
+
+MODULE_AUTHOR("John Ogness <john.ogness@xxxxxxxxxxxxx>");
+MODULE_DESCRIPTION("printk ringbuffer test");
+MODULE_LICENSE("GPL v2");
--
2.20.1