[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-Id: <20190509173654.GA23530@linux.ibm.com>
Date: Thu, 9 May 2019 10:36:54 -0700
From: "Paul E. McKenney" <paulmck@...ux.ibm.com>
To: Steven Rostedt <rostedt@...dmis.org>
Cc: Peter Zijlstra <peterz@...radead.org>,
linux-kernel@...r.kernel.org, andrea.parri@...rulasolutions.com
Subject: Re: Question about sched_setaffinity()
On Tue, May 07, 2019 at 03:16:13PM -0700, Paul E. McKenney wrote:
> On Wed, May 01, 2019 at 01:27:13PM -0700, Paul E. McKenney wrote:
> > On Wed, May 01, 2019 at 03:16:55PM -0400, Steven Rostedt wrote:
> > > On Wed, 1 May 2019 12:12:13 -0700
> > > "Paul E. McKenney" <paulmck@...ux.ibm.com> wrote:
> > >
> > >
> > > > OK, what I did was to apply the patch at the end of this email to -rcu
> > > > branch dev, then run rcutorture as follows:
> > > >
> > > > nohup tools/testing/selftests/rcutorture/bin/kvm.sh --cpus 8 --duration 2 --configs "TRIVIAL" --bootargs "trace_event=sched:sched_switch,sched:sched_wakeup ftrace=function_graph ftrace_graph_filter=sched_setaffinity,migration_cpu_stop"
> > > >
> > > > This resulted in the console output that I placed here:
> > > >
> > > > http://www2.rdrop.com/~paulmck/submission/console.log.gz
> > > >
> > > > But I don't see calls to sched_setaffinity() or migration_cpu_stop().
> > > > Steve, is something else needed on the kernel command line in addition to
> > > > the following?
> > > >
> > > > ftrace=function_graph ftrace_graph_filter=sched_setaffinity,migration_cpu_stop
> > >
> > > Do you have function graph enabled in the config?
> > >
> > > [ 2.098303] ftrace bootup tracer 'function_graph' not registered.
> >
> > I guess I don't! Thank you, will fix.
> >
> > Let's see...
> >
> > My .config has CONFIG_HAVE_FUNCTION_GRAPH_TRACER=y. It looks like I
> > need CONFIG_FUNCTION_GRAPH_TRACER=y, which I don't have. And it looks
> > like that needs CONFIG_FUNCTION_TRACER=y, which I also don't have.
> > But I do have CONFIG_HAVE_FUNCTION_TRACER=y. So I should add this
> > to my rcutorture command line:
> >
> > --kconfig "CONFIG_FUNCTION_TRACER=y CONFIG_FUNCTION_GRAPH_TRACER=y".
> >
> > I fired this up. Here is hoping! ;-)
> >
> > And it does have sched_setaffinity(), woo-hoo!!! I overwrote the old file:
> >
> > http://www2.rdrop.com/~paulmck/submission/console.log.gz
>
> And I reran after adding a trace_printk(), which shows up as follows:
>
> [ 211.409565] 6) | /* On unexpected CPU 6, expected 4!!! */
>
> I placed the console log here:
>
> http://www2.rdrop.com/~paulmck/submission/console.tpk.log.gz
>
> Just in case the earlier log proves useful.
>
> And it is acting as if the destination CPU proved to be offline. Except
> that this rcutorture scenario doesn't offline anything, and I don't see
> any CPU-hotplug removal messages. So I added another trace_printk() to
> print out cpu_online_mask. This gets me the following:
>
> [ 31.565605] 0) | /* On unexpected CPU 0, expected 1!!! */
> [ 31.565605] 0) | /* Online CPUs: 0-7 */
>
> So we didn't make it to CPU 1 despite its being online. I placed the
> console log here:
>
> http://www2.rdrop.com/~paulmck/submission/console.tpkol.log.gz
>
> Thoughts?
>
> Updated patch against -rcu below in case it is useful.
I added more debug and got this:
[ 215.097318] 4) | /* On unexpected CPU 4, expected 5!!! */
[ 215.098285] 4) | /* Online CPUs: 0-7 Active CPUs: 0-7 */
[ 215.099283] 4) | /* ret = 0, ->cpus_allowed 0-4,6-7 */
http://www.rdrop.com/~paulmck/submission/console.tpkm.log.gz
The task's ->cpus_allowed got set to the bitwise not of the requested
mask. I took a quick scan through the code but don't see how this
happens.
Very strange.
Any suggestions for further debugging? Left to myself, I would copy
the requested cpumask to a per-task location and insert checks in the
sched_setaffinity() code path, crude and ugly though that might seem.
(Ugly enough that I will wait until tomorrow to try it out.)
Thanx, Paul
------------------------------------------------------------------------
diff --git a/kernel/rcu/rcutorture.c b/kernel/rcu/rcutorture.c
index da04b5073dc3..51db19543012 100644
--- a/kernel/rcu/rcutorture.c
+++ b/kernel/rcu/rcutorture.c
@@ -680,12 +680,31 @@ static struct rcu_torture_ops tasks_ops = {
static void synchronize_rcu_trivial(void)
{
int cpu;
+ int destcpu;
+ static int dont_trace;
+ static cpumask_t my_cpumask;
+ static DEFINE_SPINLOCK(my_cpumask_lock);
+ int ret;
for_each_online_cpu(cpu) {
- while (raw_smp_processor_id() != cpu)
- rcutorture_sched_setaffinity(current->pid,
- cpumask_of(cpu));
- WARN_ON_ONCE(raw_smp_processor_id() != cpu);
+ if (!READ_ONCE(dont_trace))
+ tracing_on();
+ rcutorture_sched_setaffinity(current->pid, cpumask_of(cpu));
+ destcpu = raw_smp_processor_id();
+ if (destcpu == cpu) {
+ tracing_off();
+ } else {
+ trace_printk("On unexpected CPU %d, expected %d!!!\n", destcpu, cpu);
+ trace_printk("Online CPUs: %*pbl Active CPUs: %*pbl\n", cpumask_pr_args(cpu_online_mask), cpumask_pr_args(cpu_active_mask));
+ spin_lock(&my_cpumask_lock);
+ ret = sched_getaffinity(current->pid, &my_cpumask);
+ trace_printk("ret = %d, ->cpus_allowed %*pbl\n", ret, cpumask_pr_args(&my_cpumask));
+ spin_unlock(&my_cpumask_lock);
+ tracing_stop();
+ WRITE_ONCE(dont_trace, 1);
+ WARN_ON_ONCE(1);
+ rcu_ftrace_dump(DUMP_ALL);
+ }
}
}
diff --git a/kernel/rcu/tree.c b/kernel/rcu/tree.c
index caffee644932..edaf0ca22ff7 100644
--- a/kernel/rcu/tree.c
+++ b/kernel/rcu/tree.c
@@ -3495,6 +3495,7 @@ void __init rcu_init(void)
rcu_par_gp_wq = alloc_workqueue("rcu_par_gp", WQ_MEM_RECLAIM, 0);
WARN_ON(!rcu_par_gp_wq);
srcu_init();
+ tracing_off();
}
#include "tree_stall.h"
Powered by blists - more mailing lists