Message-ID: <Z0WiYr5eB1-MD0V0@pathway.suse.cz>
Date: Tue, 26 Nov 2024 11:26:42 +0100
From: Petr Mladek <pmladek@...e.com>
To: John Ogness <john.ogness@...utronix.de>
Cc: Sergey Senozhatsky <senozhatsky@...omium.org>,
	Steven Rostedt <rostedt@...dmis.org>,
	Brendan Higgins <brendanhiggins@...gle.com>,
	David Gow <davidgow@...gle.com>, Rae Moar <rmoar@...gle.com>,
	linux-kselftest@...r.kernel.org, kunit-dev@...glegroups.com,
	linux-kernel@...r.kernel.org,
	Thomas Weißschuh <thomas.weissschuh@...utronix.de>,
	Masahiro Yamada <masahiroy@...nel.org>,
	Miguel Ojeda <ojeda@...nel.org>,
	Andrew Morton <akpm@...ux-foundation.org>,
	Yoann Congal <yoann.congal@...le.fr>,
	Alice Ryhl <aliceryhl@...gle.com>,
	Randy Dunlap <rdunlap@...radead.org>,
	Roman Gushchin <roman.gushchin@...ux.dev>,
	Jens Axboe <axboe@...nel.dk>, Mark Rutland <mark.rutland@....com>,
	Jann Horn <jannh@...gle.com>
Subject: 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@...utronix.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

Powered by blists - more mailing lists