From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-5.6 required=3.0 tests=DKIMWL_WL_HIGH,DKIM_SIGNED, DKIM_VALID,DKIM_VALID_AU,INCLUDES_PATCH,MAILING_LIST_MULTI,SPF_HELO_NONE, SPF_PASS,USER_AGENT_SANE_1 autolearn=ham autolearn_force=no version=3.4.0 Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id A1739C32771 for ; Sat, 18 Jan 2020 04:31:37 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [209.132.180.67]) by mail.kernel.org (Postfix) with ESMTP id 6D39F2467E for ; Sat, 18 Jan 2020 04:31:37 +0000 (UTC) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/simple; d=kernel.org; s=default; t=1579321897; bh=kAobHMIsQP5V2fhC9LIp/rPWRKlgG4nqSgufJiEwmqA=; h=Date:From:To:Cc:Subject:Reply-To:References:In-Reply-To:List-ID: From; b=gf74Zd4MbAlAuNexQ+jbGHOaHyeJwRELveXJeiqgTUfFPTOa5028UWaNsOSHBmpAN erT1t697HGdgI0Jj0ARRazmJMJgS/erNX1Oty5TriHeDfN5bmiLsTpA/vIlG1EFpIx jB2IhxssncYH8Fjq4NccDSX2iEhwDjeUYIrEDB/c= Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1726744AbgAREbh (ORCPT ); Fri, 17 Jan 2020 23:31:37 -0500 Received: from mail.kernel.org ([198.145.29.99]:60058 "EHLO mail.kernel.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1726566AbgAREbh (ORCPT ); Fri, 17 Jan 2020 23:31:37 -0500 Received: from paulmck-ThinkPad-P72.home (50-39-105-78.bvtn.or.frontiernet.net [50.39.105.78]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by mail.kernel.org (Postfix) with ESMTPSA id 560ED2467C; Sat, 18 Jan 2020 04:31:36 +0000 (UTC) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/simple; d=kernel.org; s=default; t=1579321896; bh=kAobHMIsQP5V2fhC9LIp/rPWRKlgG4nqSgufJiEwmqA=; h=Date:From:To:Cc:Subject:Reply-To:References:In-Reply-To:From; b=vJgo9gLpdrj+5fhllc+GhFakoXezoEBsPsR9dQ2InA4asGGl35vMF9COLRMcsNnD2 EgLJODezSKonTWioo9DfWv6BLanxhQmZf3vTgYdZ6xN/MfCp6axGSd3OkoWa9bj9o3 doxZyN4tOtP5vMhb4wGlM5FbEvosJjzyFxz4a5/k= Received: by paulmck-ThinkPad-P72.home (Postfix, from userid 1000) id 25D4C3522A3F; Fri, 17 Jan 2020 20:31:36 -0800 (PST) Date: Fri, 17 Jan 2020 20:31:36 -0800 From: "Paul E. McKenney" To: Joel Fernandes Cc: rcu@vger.kernel.org, rostedt@goodmis.org, bristot@redhat.com Subject: Re: RCU_BOOST not working for me Message-ID: <20200118043136.GS2935@paulmck-ThinkPad-P72> Reply-To: paulmck@kernel.org References: <20200117215814.GB206250@google.com> <20200117221804.GA211665@google.com> <20200117231756.GO2935@paulmck-ThinkPad-P72> <20200118021049.GC211665@google.com> <20200118023222.GA244899@google.com> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <20200118023222.GA244899@google.com> User-Agent: Mutt/1.9.4 (2018-02-28) Sender: rcu-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: rcu@vger.kernel.org On Fri, Jan 17, 2020 at 09:32:22PM -0500, Joel Fernandes wrote: > 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. Did you boot with kernel parameter rcu_tree.kthread_prio=61 or more? If not, RCU priority boosting is not going to be able to help. The writer does nothing for you. The priority of the task invoking synchronize_rcu() is irrelevant because synchronize_rcu() is inherently non-realtime. Thanx, Paul > 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 > +#include > +#include > +#include > +#include > +#include > + > +#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, ¶ms); > + kthread_bind(reader, smp_processor_id()); > + > + blocker = kthread_create(rcu_blocker, NULL, "blocker"); > + params.sched_priority = 60; > + sched_setscheduler(blocker, SCHED_FIFO, ¶ms); > + kthread_bind(blocker, smp_processor_id()); > + > + writer = kthread_create(rcu_writer, NULL, "writer"); > + params.sched_priority = 70; > + sched_setscheduler(writer, SCHED_FIFO, ¶ms); > + 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 >