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" <paul...@linux.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"
