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.4 required=3.0 tests=DKIM_SIGNED,DKIM_VALID, DKIM_VALID_AU,HEADER_FROM_DIFFERENT_DOMAINS,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 5FCAEC33C9E for ; Sat, 18 Jan 2020 02:32:25 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [209.132.180.67]) by mail.kernel.org (Postfix) with ESMTP id 297FE21D7D for ; Sat, 18 Jan 2020 02:32:25 +0000 (UTC) Authentication-Results: mail.kernel.org; dkim=pass (1024-bit key) header.d=joelfernandes.org header.i=@joelfernandes.org header.b="xaO4Skou" Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1730588AbgARCcY (ORCPT ); Fri, 17 Jan 2020 21:32:24 -0500 Received: from mail-pl1-f194.google.com ([209.85.214.194]:35815 "EHLO mail-pl1-f194.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1727033AbgARCcY (ORCPT ); Fri, 17 Jan 2020 21:32:24 -0500 Received: by mail-pl1-f194.google.com with SMTP id g6so10620814plt.2 for ; Fri, 17 Jan 2020 18:32:24 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=joelfernandes.org; s=google; h=date:from:to:cc:subject:message-id:references:mime-version :content-disposition:in-reply-to:user-agent; bh=b73IdapxKTTUqHCQthFXAhGf7sGyUVHiDaBcs6sZ8kw=; b=xaO4SkoudbtroYOSlbHHcn9h2T5R9u1PgnU2yvryOE811UJM081cIGNcFruDF8Appi +Zx3mnn0uLBqIT315uxT/SZdH31aVeaWNeFxratcR1jUunsetXoQ/Tf9WyaHHPnm/9lv SBWbuvDBUWRB3h9T4JMbiw0aqVNbO4f8Uf0Pw= X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:date:from:to:cc:subject:message-id:references :mime-version:content-disposition:in-reply-to:user-agent; bh=b73IdapxKTTUqHCQthFXAhGf7sGyUVHiDaBcs6sZ8kw=; b=YyqMqg3hO7hFspAaJoLEv1Ls4vkMOpsZD63OCn93GXHOnNqoSBVcEbxAK81weO/5Sr b/dDTUxEMpftc8nYsSMwYv1hGzbI9vi6sYOj7DL4YhVhWgv6gPj3qXsbHhDvsoZxWk5H VCylkAi1UTHzNACtLPa1hoFaOGUNR/ALyosTUMCHzPVxbsi9ge6nrTqlS/dChEZUrJAi RA7Ci8OhwDPJ9asIXrH9LhsDfB77lha9Xa1DT4ZT9sposhDUi+MoCIqKEBtEy/DpMYq4 h5VaomZlAz1QAMYvpwbVmT3qWZVhVl1ZOhSsj8VMAZIxm3SLVgCGnda6O94VxnJFXJnZ DI/g== X-Gm-Message-State: APjAAAVbewFwvgjIV7O8QAnFS1bgiALUHYtYIbCl+qLIfL+RgxIqVfzj 85rn07Xc6Fp7+BbvkGJEjTSUlA== X-Google-Smtp-Source: APXvYqwhBChq60OPFj3/bh1sd81CmIOqxZacumOBxnGwG8TF6Uc3WiU0YFutQTz1u2npjZLkXz3snQ== X-Received: by 2002:a17:90a:8008:: with SMTP id b8mr9660510pjn.37.1579314743686; Fri, 17 Jan 2020 18:32:23 -0800 (PST) Received: from localhost ([2620:15c:6:12:9c46:e0da:efbf:69cc]) by smtp.gmail.com with ESMTPSA id k12sm28817299pgm.65.2020.01.17.18.32.22 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Fri, 17 Jan 2020 18:32:23 -0800 (PST) Date: Fri, 17 Jan 2020 21:32:22 -0500 From: Joel Fernandes To: "Paul E. McKenney" Cc: rcu@vger.kernel.org, rostedt@goodmis.org, bristot@redhat.com Subject: Re: RCU_BOOST not working for me Message-ID: <20200118023222.GA244899@google.com> References: <20200117215814.GB206250@google.com> <20200117221804.GA211665@google.com> <20200117231756.GO2935@paulmck-ThinkPad-P72> <20200118021049.GC211665@google.com> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <20200118021049.GC211665@google.com> User-Agent: Mutt/1.10.1 (2018-07-13) Sender: rcu-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: rcu@vger.kernel.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 +#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