Re: Question about sched_setaffinity()

From: Andrea Parri
Date: Thu May 09 2019 - 17:41:51 EST


On Thu, May 09, 2019 at 10:36:54AM -0700, Paul E. McKenney wrote:
> 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@xxxxxxxxxxxxx> 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?

And I can finally see/reproduce it!!

Frankly, no idea how this is happening (I have been staring at these
traces/functions for hours/days now... ;-/ )

Adding some "sched" folks in Cc: hopefully, they can shed some light
about this.

And yes, my only suggestion/approach would be to keep bisecting this
code with printk*..., 'fun' ;-/

Andrea