Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1595689 > unrolled thread

RCU used on incoming CPU before rcu_cpu_starting() called

Back to article view | Back to linux.kernel

Contents

  RCU used on incoming CPU before rcu_cpu_starting() called "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2017-03-09 07:10 +0100
    Re: RCU used on incoming CPU before rcu_cpu_starting() called Thomas Gleixner <tglx@linutronix.de> - 2017-03-09 14:10 +0100
      Re: RCU used on incoming CPU before rcu_cpu_starting() called Peter Zijlstra <peterz@infradead.org> - 2017-03-09 16:20 +0100
        Re: RCU used on incoming CPU before rcu_cpu_starting() called "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2017-03-09 16:40 +0100
          Re: RCU used on incoming CPU before rcu_cpu_starting() called "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2017-03-09 17:00 +0100
      Re: RCU used on incoming CPU before rcu_cpu_starting() called "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2017-03-09 16:30 +0100

#1595689 — RCU used on incoming CPU before rcu_cpu_starting() called

Hello!

I am seeing the following splat in rcutorture testing of v4.11-rc1:

[   30.694013] =============================
[   30.694013] WARNING: suspicious RCU usage
[   30.694013] 4.11.0-rc1+ #1 Not tainted
[   30.694013] -----------------------------
[   30.694013] /home/git/linux-2.6-tip/kernel/workqueue.c:712 sched RCU or wq_pool_mutex should be held!
[   30.694013] 
[   30.694013] other info that might help us debug this:
[   30.694013] 
[   30.694013] 
[   30.694013] RCU used illegally from offline CPU!
[   30.694013] rcu_scheduler_active = 2, debug_locks = 0
[   30.694013] no locks held by swapper/1/0.
[   30.694013] 
[   30.694013] stack backtrace:
[   30.694013] CPU: 1 PID: 0 Comm: swapper/1 Not tainted 4.11.0-rc1+ #1
[   30.694013] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
[   30.694013] Call Trace:
[   30.694013]  dump_stack+0x67/0x99
[   30.694013]  lockdep_rcu_suspicious+0xe7/0x120
[   30.694013]  get_work_pool+0x82/0x90
[   30.694013]  __queue_work+0x70/0x5f0
[   30.694013]  queue_work_on+0x33/0x70
[   30.694013]  clear_sched_clock_stable+0x33/0x40
[   30.694013]  early_init_intel+0xe7/0x2f0
[   30.694013]  init_intel+0x11/0x350
[   30.694013]  identify_cpu+0x344/0x5a0
[   30.694013]  identify_secondary_cpu+0x18/0x80
[   30.694013]  smp_store_cpu_info+0x39/0x40
[   30.694013]  start_secondary+0x4e/0x100
[   30.694013]  start_cpu+0x14/0x14

Here is the relevant code from x86's smp_callin():

	/*
	 * Save our processor parameters. Note: this information
	 * is needed for clock calibration.
	 */
	smp_store_cpu_info(cpuid);

	/*
	 * Get our bogomips.
	 * Update loops_per_jiffy in cpu_data. Previous call to
	 * smp_store_cpu_info() stored a value that is close but not as
	 * accurate as the value just calculated.
	 */
	calibrate_delay();
	cpu_data(cpuid).loops_per_jiffy = loops_per_jiffy;
	pr_debug("Stack at about %p\n", &cpuid);

	/*
	 * This must be done before setting cpu_online_mask
	 * or calling notify_cpu_starting.
	 */
	set_cpu_sibling_map(raw_smp_processor_id());
	wmb();

	notify_cpu_starting(cpuid);

The problem is that smp_store_cpu_info() indirectly invokes
schedule_work(), which wants to use RCU.  But RCU isn't informed
of the incoming CPU until the call to notify_cpu_starting(), which
causes lockdep to complain bitterly about the use of RCU by the
premature call to schedule_work().

I considered just moving the notify_cpu_starting() earlier in the
sequence, but the comments make it seem like this would not be
a wise choice.

Any suggestions?

						Thanx, Paul

[toc] | [next] | [standalone]

#1596053

On Wed, 8 Mar 2017, Paul E. McKenney wrote:
> [   30.694013]  lockdep_rcu_suspicious+0xe7/0x120
> [   30.694013]  get_work_pool+0x82/0x90
> [   30.694013]  __queue_work+0x70/0x5f0
> [   30.694013]  queue_work_on+0x33/0x70
> [   30.694013]  clear_sched_clock_stable+0x33/0x40
> [   30.694013]  early_init_intel+0xe7/0x2f0
> [   30.694013]  init_intel+0x11/0x350
> [   30.694013]  identify_cpu+0x344/0x5a0
> [   30.694013]  identify_secondary_cpu+0x18/0x80
> [   30.694013]  smp_store_cpu_info+0x39/0x40
> [   30.694013]  start_secondary+0x4e/0x100
> [   30.694013]  start_cpu+0x14/0x14
> 
> Here is the relevant code from x86's smp_callin():
> 
> 	/*
> 	 * Save our processor parameters. Note: this information
> 	 * is needed for clock calibration.
> 	 */
> 	smp_store_cpu_info(cpuid);
>
> The problem is that smp_store_cpu_info() indirectly invokes
> schedule_work(), which wants to use RCU.  But RCU isn't informed
> of the incoming CPU until the call to notify_cpu_starting(), which
> causes lockdep to complain bitterly about the use of RCU by the
> premature call to schedule_work().

Right. And that want's to be fixed, not hacked around by silencing RCU.

Peter????

Thanks,

	tglx

[toc] | [prev] | [next] | [standalone]

#1596147

On Thu, Mar 09, 2017 at 02:08:23PM +0100, Thomas Gleixner wrote:
> On Wed, 8 Mar 2017, Paul E. McKenney wrote:
> > [   30.694013]  lockdep_rcu_suspicious+0xe7/0x120
> > [   30.694013]  get_work_pool+0x82/0x90
> > [   30.694013]  __queue_work+0x70/0x5f0
> > [   30.694013]  queue_work_on+0x33/0x70
> > [   30.694013]  clear_sched_clock_stable+0x33/0x40
> > [   30.694013]  early_init_intel+0xe7/0x2f0
> > [   30.694013]  init_intel+0x11/0x350
> > [   30.694013]  identify_cpu+0x344/0x5a0
> > [   30.694013]  identify_secondary_cpu+0x18/0x80
> > [   30.694013]  smp_store_cpu_info+0x39/0x40
> > [   30.694013]  start_secondary+0x4e/0x100
> > [   30.694013]  start_cpu+0x14/0x14
> > 
> > Here is the relevant code from x86's smp_callin():
> > 
> > 	/*
> > 	 * Save our processor parameters. Note: this information
> > 	 * is needed for clock calibration.
> > 	 */
> > 	smp_store_cpu_info(cpuid);
> >
> > The problem is that smp_store_cpu_info() indirectly invokes
> > schedule_work(), which wants to use RCU.  But RCU isn't informed
> > of the incoming CPU until the call to notify_cpu_starting(), which
> > causes lockdep to complain bitterly about the use of RCU by the
> > premature call to schedule_work().
> 
> Right. And that want's to be fixed, not hacked around by silencing RCU.
> 
> Peter????

I'm thinking this is hotplug? 30 seconds after boot is far too late for
SMP bringup, or you have a stupid slow machine.

Because it only calls schedule_work() after SMP-init. In which case
there's then two cases, either:

 - TSC was stable, hotplug wrecked it, TSC is now unstable, and we're
   screwed.

 - TSC was unstable, hotplug triggers and we want to mark it unstable
   _again_.

If this is the second, the below should fix it, if its the first, I've
no idea yet on how to fix that properly :/

Bloody hotplug..

---
 kernel/sched/clock.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/kernel/sched/clock.c b/kernel/sched/clock.c
index a08795e..eecf388 100644
--- a/kernel/sched/clock.c
+++ b/kernel/sched/clock.c
@@ -172,7 +172,7 @@ void clear_sched_clock_stable(void)
 
 	smp_mb(); /* matches sched_clock_init_late() */
 
-	if (sched_clock_running == 2)
+	if (sched_clock_running == 2 && sched_clock_stable())
 		schedule_work(&sched_clock_work);
 }
 

[toc] | [prev] | [next] | [standalone]

#1596156

On Thu, Mar 09, 2017 at 04:12:55PM +0100, Peter Zijlstra wrote:
> On Thu, Mar 09, 2017 at 02:08:23PM +0100, Thomas Gleixner wrote:
> > On Wed, 8 Mar 2017, Paul E. McKenney wrote:
> > > [   30.694013]  lockdep_rcu_suspicious+0xe7/0x120
> > > [   30.694013]  get_work_pool+0x82/0x90
> > > [   30.694013]  __queue_work+0x70/0x5f0
> > > [   30.694013]  queue_work_on+0x33/0x70
> > > [   30.694013]  clear_sched_clock_stable+0x33/0x40
> > > [   30.694013]  early_init_intel+0xe7/0x2f0
> > > [   30.694013]  init_intel+0x11/0x350
> > > [   30.694013]  identify_cpu+0x344/0x5a0
> > > [   30.694013]  identify_secondary_cpu+0x18/0x80
> > > [   30.694013]  smp_store_cpu_info+0x39/0x40
> > > [   30.694013]  start_secondary+0x4e/0x100
> > > [   30.694013]  start_cpu+0x14/0x14
> > > 
> > > Here is the relevant code from x86's smp_callin():
> > > 
> > > 	/*
> > > 	 * Save our processor parameters. Note: this information
> > > 	 * is needed for clock calibration.
> > > 	 */
> > > 	smp_store_cpu_info(cpuid);
> > >
> > > The problem is that smp_store_cpu_info() indirectly invokes
> > > schedule_work(), which wants to use RCU.  But RCU isn't informed
> > > of the incoming CPU until the call to notify_cpu_starting(), which
> > > causes lockdep to complain bitterly about the use of RCU by the
> > > premature call to schedule_work().
> > 
> > Right. And that want's to be fixed, not hacked around by silencing RCU.
> > 
> > Peter????
> 
> I'm thinking this is hotplug? 30 seconds after boot is far too late for
> SMP bringup, or you have a stupid slow machine.

And this certainly does qualify as "shortly", thank you!

Yes, this only happens on hotplug with lockdep enabled, specifically
on rcutorture scenarios TASKS01 and TREE05.

> Because it only calls schedule_work() after SMP-init. In which case
> there's then two cases, either:
> 
>  - TSC was stable, hotplug wrecked it, TSC is now unstable, and we're
>    screwed.
> 
>  - TSC was unstable, hotplug triggers and we want to mark it unstable
>    _again_.
> 
> If this is the second, the below should fix it, if its the first, I've
> no idea yet on how to fix that properly :/

I have applied this patch and started tests on TREE05 and TASKS01, should
get results shortly.

							Thanx, Paul

> Bloody hotplug..
> 
> ---
>  kernel/sched/clock.c | 2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
> 
> diff --git a/kernel/sched/clock.c b/kernel/sched/clock.c
> index a08795e..eecf388 100644
> --- a/kernel/sched/clock.c
> +++ b/kernel/sched/clock.c
> @@ -172,7 +172,7 @@ void clear_sched_clock_stable(void)
> 
>  	smp_mb(); /* matches sched_clock_init_late() */
> 
> -	if (sched_clock_running == 2)
> +	if (sched_clock_running == 2 && sched_clock_stable())
>  		schedule_work(&sched_clock_work);
>  }
> 
> 

[toc] | [prev] | [next] | [standalone]

#1596172

On Thu, Mar 09, 2017 at 07:29:26AM -0800, Paul E. McKenney wrote:
> On Thu, Mar 09, 2017 at 04:12:55PM +0100, Peter Zijlstra wrote:
> > On Thu, Mar 09, 2017 at 02:08:23PM +0100, Thomas Gleixner wrote:
> > > On Wed, 8 Mar 2017, Paul E. McKenney wrote:
> > > > [   30.694013]  lockdep_rcu_suspicious+0xe7/0x120
> > > > [   30.694013]  get_work_pool+0x82/0x90
> > > > [   30.694013]  __queue_work+0x70/0x5f0
> > > > [   30.694013]  queue_work_on+0x33/0x70
> > > > [   30.694013]  clear_sched_clock_stable+0x33/0x40
> > > > [   30.694013]  early_init_intel+0xe7/0x2f0
> > > > [   30.694013]  init_intel+0x11/0x350
> > > > [   30.694013]  identify_cpu+0x344/0x5a0
> > > > [   30.694013]  identify_secondary_cpu+0x18/0x80
> > > > [   30.694013]  smp_store_cpu_info+0x39/0x40
> > > > [   30.694013]  start_secondary+0x4e/0x100
> > > > [   30.694013]  start_cpu+0x14/0x14
> > > > 
> > > > Here is the relevant code from x86's smp_callin():
> > > > 
> > > > 	/*
> > > > 	 * Save our processor parameters. Note: this information
> > > > 	 * is needed for clock calibration.
> > > > 	 */
> > > > 	smp_store_cpu_info(cpuid);
> > > >
> > > > The problem is that smp_store_cpu_info() indirectly invokes
> > > > schedule_work(), which wants to use RCU.  But RCU isn't informed
> > > > of the incoming CPU until the call to notify_cpu_starting(), which
> > > > causes lockdep to complain bitterly about the use of RCU by the
> > > > premature call to schedule_work().
> > > 
> > > Right. And that want's to be fixed, not hacked around by silencing RCU.
> > > 
> > > Peter????
> > 
> > I'm thinking this is hotplug? 30 seconds after boot is far too late for
> > SMP bringup, or you have a stupid slow machine.
> 
> And this certainly does qualify as "shortly", thank you!
> 
> Yes, this only happens on hotplug with lockdep enabled, specifically
> on rcutorture scenarios TASKS01 and TREE05.
> 
> > Because it only calls schedule_work() after SMP-init. In which case
> > there's then two cases, either:
> > 
> >  - TSC was stable, hotplug wrecked it, TSC is now unstable, and we're
> >    screwed.
> > 
> >  - TSC was unstable, hotplug triggers and we want to mark it unstable
> >    _again_.
> > 
> > If this is the second, the below should fix it, if its the first, I've
> > no idea yet on how to fix that properly :/
> 
> I have applied this patch and started tests on TREE05 and TASKS01, should
> get results shortly.

And the below patch passed light rcutorture testing, so looking good!

							Thanx, Paul

> > Bloody hotplug..
> > 
> > ---
> >  kernel/sched/clock.c | 2 +-
> >  1 file changed, 1 insertion(+), 1 deletion(-)
> > 
> > diff --git a/kernel/sched/clock.c b/kernel/sched/clock.c
> > index a08795e..eecf388 100644
> > --- a/kernel/sched/clock.c
> > +++ b/kernel/sched/clock.c
> > @@ -172,7 +172,7 @@ void clear_sched_clock_stable(void)
> > 
> >  	smp_mb(); /* matches sched_clock_init_late() */
> > 
> > -	if (sched_clock_running == 2)
> > +	if (sched_clock_running == 2 && sched_clock_stable())
> >  		schedule_work(&sched_clock_work);
> >  }
> > 
> > 

[toc] | [prev] | [next] | [standalone]

#1596154

On Thu, Mar 09, 2017 at 02:08:23PM +0100, Thomas Gleixner wrote:
> On Wed, 8 Mar 2017, Paul E. McKenney wrote:
> > [   30.694013]  lockdep_rcu_suspicious+0xe7/0x120
> > [   30.694013]  get_work_pool+0x82/0x90
> > [   30.694013]  __queue_work+0x70/0x5f0
> > [   30.694013]  queue_work_on+0x33/0x70
> > [   30.694013]  clear_sched_clock_stable+0x33/0x40
> > [   30.694013]  early_init_intel+0xe7/0x2f0
> > [   30.694013]  init_intel+0x11/0x350
> > [   30.694013]  identify_cpu+0x344/0x5a0
> > [   30.694013]  identify_secondary_cpu+0x18/0x80
> > [   30.694013]  smp_store_cpu_info+0x39/0x40
> > [   30.694013]  start_secondary+0x4e/0x100
> > [   30.694013]  start_cpu+0x14/0x14
> > 
> > Here is the relevant code from x86's smp_callin():
> > 
> > 	/*
> > 	 * Save our processor parameters. Note: this information
> > 	 * is needed for clock calibration.
> > 	 */
> > 	smp_store_cpu_info(cpuid);
> >
> > The problem is that smp_store_cpu_info() indirectly invokes
> > schedule_work(), which wants to use RCU.  But RCU isn't informed
> > of the incoming CPU until the call to notify_cpu_starting(), which
> > causes lockdep to complain bitterly about the use of RCU by the
> > premature call to schedule_work().
> 
> Right. And that want's to be fixed, not hacked around by silencing RCU.

Fair enough!

I have updated my commit to indicate yours and Frederic's discomfort with
it and marked it as not intended for upstream.  If we get an alternative
fix shortly, I will drop my commit -- but failing that at some point I
will of course start pushing this patch again.

							Thanx, Paul

> Peter????
> 
> Thanks,
> 
> 	tglx
> 

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web