Re: [PATCH printk v1] printk: ringbuffer: Add KUnit test

On Thu 2024-11-21 15:56:34, John Ogness wrote:

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.

Thanks a lot for upstreaming this test!

--- 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

I would call it PRINTK_RINGBUFFER_KUNIT_TEST to make it clear that it is a KUNIT test. Also it helps to find KUNIT tests in .config.

Anyway, Documentation/dev-tools/kunit/style.rst suggests the FOO_KUNIT_TEST name.

• 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 --- /dev/null +++ b/kernel/printk/printk_ringbuffer_test.c @@ -0,0 +1,350 @@

[...]

+/* 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)

It is far from clear what the two +1 are for here. Also 0x7f is hardcoded below once again.

I would personally do:

/* A mask used to generate random text len. */ #define RBDATA_TEXT_LEN_RND_MASK 0x7f /* +2 to ensure at least 1 character + terminator. */ #define MAX_RBDATA_TEXT_SIZE (RBDATA_TEXT_LEN_RND_MASK + 2) #define MAX_PRB_RECORD_SIZE (sizeof(struct rbdata) + MAX_RBDATA_TEXT_SIZE)

Note that I used the suffix _SIZE because I counted the terminator in both definitions, see below.

+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];

char buf[MAX_RBDATA_TEXT_SIZE];

• 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);

len = strnlen(dat->text, MAX_RBDATA_TEXT_SIZE);

• /* Sane length? */
• if (len != dat->len || !len || len > MAX_RBDATA_LEN)

if (len != dat->len || !len || len >= MAX_RBDATA_TEXT_SIZE)

Note that I have used >= instead of > because it is the _SIZE.

• 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;
  

len = sizeof(struct rbdata) + (get_random_u32() & RBDATA_TEXT_LEN_RND_MASK) + 2;

I would add

WARN_ON_ONCE(len <= MAX_PRB_RECORD_SIZE);

• /* 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;
  

I would add brackets to make it more clear that we actually substract the "1":

len -= (sizeof(struct rbdata) + 1);

or even better might be to create two variables:

/* +1 to ensure at least 1 character*/ len = (get_random_u32() & 0x7f) + 1; size = sizeof(struct rbdata) + len + 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();
  

I think that the counting of the time will be misleading in CONFIG_PREEMPT=y. We should disable preemption or even interrupts to get right numbers.

• 	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();
  

This won't work as expected with CONFIG_PREEMPT=y. IMHO, we should use simply use cond_resched() here. a

• 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();
  

• }
  

This won't work with CONFIG_PREEMPT=Y. I would use cond_resched() and detect scheduling by checking the switch count. I think that it should be:

switch_count = READ_ONCE(current->nvcsw + current->nivcsw);

It is inspired by check_hung_task().

• 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;

+}

This is what I have found on top of the review by David Gow.

Best Regards, Petr