Received-SPF: pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) client-ip=209.132.180.67;
Date:   Thu, 9 May 2019 23:56:35 +0200
From:   Andrea Parri <andrea.parri@amarulasolutions.com>
To:     "Paul E. McKenney" <paulmck@linux.ibm.com>
Cc:     Steven Rostedt <rostedt@goodmis.org>,
        Peter Zijlstra <peterz@infradead.org>,
        linux-kernel@vger.kernel.org, Ingo Molnar <mingo@redhat.com>,
        Juri Lelli <juri.lelli@redhat.com>,
        Morten Rasmussen <morten.rasmussen@arm.com>,
        Joel Fernandes <joelaf@google.com>,
        Vincent Guittot <vincent.guittot@linaro.org>,
        Thomas Gleixner <tglx@linutronix.de>,
        Sebastian Andrzej Siewior <bigeasy@linutronix.de>
Subject: Re: Question about sched_setaffinity()
Message-ID: <20190509215505.GB5820@andrea>
References: <20190427180246.GA15502@linux.ibm.com>
 <20190430100318.GP2623@hirez.programming.kicks-ass.net>
 <20190430105129.GA3923@linux.ibm.com>
 <20190430115551.GT2623@hirez.programming.kicks-ass.net>
 <20190501191213.GX3923@linux.ibm.com>
 <20190501151655.51469a4c@gandalf.local.home>
 <20190501202713.GY3923@linux.ibm.com>
 <20190507221613.GA11057@linux.ibm.com>
 <20190509173654.GA23530@linux.ibm.com>
 <20190509214025.GA5385@andrea>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <20190509214025.GA5385@andrea>
User-Agent: Mutt/1.5.24 (2015-08-30)
Sender: linux-kernel-owner@vger.kernel.org
Precedence: bulk

On Thu, May 09, 2019 at 11:40:25PM +0200, Andrea Parri wrote:
> 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@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?
> 
> 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.

+Thomas, +Sebastian

Thread starts here:

http://lkml.kernel.org/r/20190427180246.GA15502@linux.ibm.com

  Andrea


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