Re: RCU_BOOST not working for me

[Joel Fernandes <joel@joelfernandes.org>]

On Fri, Jan 17, 2020 at 09:10:49PM -0500, Joel Fernandes wrote:
> On Fri, Jan 17, 2020 at 03:17:56PM -0800, Paul E. McKenney wrote:
> > On Fri, Jan 17, 2020 at 05:18:04PM -0500, Joel Fernandes wrote:
> > > On Fri, Jan 17, 2020 at 04:58:14PM -0500, Joel Fernandes wrote:
> > > > Hi,
> > > > Me and Daniel were poking around with RCU_BOOST. I wrote a kernel module to
> > > > test it a bit and I don't see the boost happening (thanks to Daniel for idea
> > > > of writing a module). Haven't debugged it more yet. Will look more tomorrow.
> > > > But below is the kernel module code and it prints a FAIL message to kernel
> > > > logs in a few seconds.
> > > > 
> > > > I see the reader thread not getting CPU for several seconds. RCU_BOOST_DELAY
> > > > is set to 500.
> > > > 
> > > > Thoughts?
> > > 
> > > So this could be because I did not start a grace period which is quite silly.
> > > I am sorry about that. I will add another thread to start grace periods as
> > > well and let you know if I still see a problem.
> > 
> > In addition, the RCU_READER_DELAY isn't long enough to trigger RCU priority
> > boosting.  And RCU_BLOCKER_DELAY would be, except that I am not seeing
> > an RCU read-side critical section surrounding it.
> 
> I was assuming that only the thread being preempted needs an RCU read-side
> critical section. That preempted section would inherit the priority of the
> thread preempting it (the blocking thread). So the blocking thread would not
> need a read-side critical section, it just would need to be higher priority
> than the thread it is preempting and preempt it long enough to trigger the
> boosting.
> 
> Did I miss something?

I started GPs and still see the issue, trace as follows showing GP took 4
seconds. This time I increased RCU_BLOCK_DELAY to 800ms. Updated test patch
appended below.

          reader-240   [004] ....     5.389458: rcu_reader: rcu_reader entering RSCS
         blocker-241   [004] ....     5.443703: rcu_blocker: rcu_blocker entering
          writer-242   [004] ....     5.543743: rcu_writer: starting gp
         blocker-241   [004] ....     6.243457: rcu_blocker: rcu_blocker exiting
         blocker-241   [004] ....     6.243458: rcu_blocker: rcu_blocker entering
         blocker-241   [004] ....     7.043453: rcu_blocker: rcu_blocker exiting

	      ^^^ --- reader got blocked by blocker and did not get CPU...

         blocker-241   [004] ....     7.043453: rcu_blocker: rcu_blocker entering
         blocker-241   [004] ....     7.843450: rcu_blocker: rcu_blocker exiting
         blocker-241   [004] ....     7.843450: rcu_blocker: rcu_blocker entering
         blocker-241   [004] ....     8.643454: rcu_blocker: rcu_blocker exiting
         blocker-241   [004] ....     8.643454: rcu_blocker: rcu_blocker entering
         blocker-241   [004] ....     9.443448: rcu_blocker: rcu_blocker exiting
          reader-240   [004] ....     9.490381: rcu_reader: rcu_reader exiting RSCS

	      ^^^ --- ...until the blocker thread quit.

          writer-242   [004] ....     9.492684: rcu_writer: ending gp

---8<-----------------------

diff --git a/drivers/misc/Makefile b/drivers/misc/Makefile
index c1860d35dc7e..ba34957dff26 100644
--- a/drivers/misc/Makefile
+++ b/drivers/misc/Makefile
@@ -2,7 +2,7 @@
 #
 # Makefile for misc devices that really don't fit anywhere else.
 #
-
+obj-m += ptest.o
 obj-$(CONFIG_IBM_ASM)		+= ibmasm/
 obj-$(CONFIG_IBMVMC)		+= ibmvmc.o
 obj-$(CONFIG_AD525X_DPOT)	+= ad525x_dpot.o
diff --git a/drivers/misc/ptest.c b/drivers/misc/ptest.c
new file mode 100644
index 000000000000..c7456b2f5570
--- /dev/null
+++ b/drivers/misc/ptest.c
@@ -0,0 +1,134 @@
+#include <linux/init.h>
+#include <linux/module.h>
+#include <linux/kernel.h>
+#include <linux/vmalloc.h>
+#include <linux/kthread.h>
+#include <linux/delay.h>
+
+#define RCU_READER_DELAY 100 //ms
+#define RCU_BLOCKER_DELAY 800 //ms
+
+MODULE_LICENSE("GPL");
+
+struct sched_param {
+	int sched_priority;
+};
+
+int stop_test = 0;
+int test_pass = 1;
+int reader_exit = 0;
+s64 delta_fail;
+
+#define ns_to_ms(delta) (delta / 1000000ULL)
+
+static int rcu_writer(void *a)
+{
+	while (!kthread_should_stop() && !stop_test) {
+		trace_printk("starting gp\n");
+		synchronize_rcu();
+		trace_printk("ending gp\n");
+		msleep(10);
+	}
+
+	return 0;
+}
+
+static int rcu_reader(void *a)
+{
+	ktime_t start, end, reader_begin;
+	s64 delta;
+
+	reader_begin = ktime_get();
+
+	while (!kthread_should_stop() && !stop_test) {
+		rcu_read_lock();
+		trace_printk("rcu_reader entering RSCS\n");
+		start = ktime_get();
+		mdelay(RCU_READER_DELAY);
+		end = ktime_get();
+		trace_printk("rcu_reader exiting RSCS\n");
+		rcu_read_lock();
+		delta = ktime_to_ns(ktime_sub(end, start));
+
+		if (delta < 0 || (ns_to_ms(delta) > (2 * RCU_READER_DELAY))) {
+			delta_fail = delta;
+			test_pass = 0;
+			break;
+		}
+
+		// Don't let the rcu_reader() run more than 3s inorder to
+		// not starve the blocker incase reader prio > blocker prio.
+		delta = ktime_to_ns(ktime_sub(end, reader_begin));
+		if (ns_to_ms(delta) > 3000)
+			break;
+	}
+
+	stop_test = 1;
+	reader_exit = 1;
+	pr_err("Exiting reader\n");
+	return 0;
+}
+
+static int rcu_blocker(void *a)
+{
+	int loops = 5;
+
+	while (!kthread_should_stop() && loops-- && !stop_test) {
+		trace_printk("rcu_blocker entering\n");
+		mdelay(RCU_BLOCKER_DELAY);
+		trace_printk("rcu_blocker exiting\n");
+	}
+
+	pr_err("Exiting blocker\n");
+	stop_test = 1;
+
+	// Wait for reader to finish
+	while (!reader_exit)
+		schedule_timeout_uninterruptible(1);
+
+	if (test_pass)
+		pr_err("TEST PASSED\n");
+	else
+		pr_err("TEST FAILED, failing delta=%lldms\n", ns_to_ms(delta_fail));
+
+	return 0;
+}
+
+static int __init ptest_init(void){
+	struct sched_param params;
+	struct task_struct *reader, *blocker, *writer;
+
+	reader = kthread_create(rcu_reader, NULL, "reader");
+	params.sched_priority = 50;
+	sched_setscheduler(reader, SCHED_FIFO, &params);
+	kthread_bind(reader, smp_processor_id());
+
+	blocker = kthread_create(rcu_blocker, NULL, "blocker");
+	params.sched_priority = 60;
+	sched_setscheduler(blocker, SCHED_FIFO, &params);
+	kthread_bind(blocker, smp_processor_id());
+
+	writer = kthread_create(rcu_writer, NULL, "writer");
+	params.sched_priority = 70;
+	sched_setscheduler(writer, SCHED_FIFO, &params);
+	kthread_bind(writer, smp_processor_id());
+
+	wake_up_process(reader);
+
+	// Let reader run a little
+	mdelay(50);
+
+	wake_up_process(blocker);
+
+	// Let blocker run a little
+	mdelay(100);
+
+	wake_up_process(writer);
+	return 0;
+}
+
+static void __exit ptest_exit(void){
+}
+
+module_init(ptest_init);
+module_exit(ptest_exit);
-- 
2.25.0.341.g760bfbb309-goog