Re: RCU used on incoming CPU before rcu_cpu_starting() called

[Frederic Weisbecker]

On Wed, Mar 08, 2017 at 03:41:52PM -0800, Paul E. McKenney wrote:
> On Wed, Mar 08, 2017 at 02:16:56PM -0800, Paul E. McKenney wrote:
> > 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?

Calling schedule_work() from an offline (booting) CPU doesn't sound like a good
idea in the first place. And neither is it a good idea to allow using
RCU on a CPU that is not yet online.

Perhaps we could delay this sched clock stability check to a later
stage in the secondary CPU boot-up code? Once the CPU is online
and RCU is initialized? For example it could be a CPU_ONLINE hotplug
callback.