[apic_ap_setup] WARNING: suspicious RCU usage

From: Fengguang Wu
Date: Mon Nov 06 2017 - 20:47:58 EST


Hi,

Here is a warning in 4.14-rc8 -- it's not necessarily a new bug.

[ 112.658399] smpboot: Booting Node 0 Processor 1 APIC 0x1
[ 112.669928] kvm-clock: cpu 1, msr 0:3544e041, secondary cpu clock
[ 112.670585] masked ExtINT on CPU#1
[[ 112.671160] [ 112.671161] =============================
[ 112.671161] WARNING: suspicious RCU usage
[ 112.671161] 4.14.0-rc8 #58 Not tainted
[ 112.671162] -----------------------------
[0m
[ 112.671164] ] [ 112.671165] 3 locks held by swapper/1/0:
[ 112.671166] #0: ((console_sem).lock){-...}, at: [<ffffffffbcad859d>] up+0xa/0x35
[ 112.671168] #1: (&p->pi_lock){-.-.}, at: [<ffffffffbcac3216>] try_to_wake_up+0x2f/0x22d
Failed to start [ 112.671172] stack backtrace:
[ 112.671173] CPU: 1 PID: 0 Comm: swapper/1 Not tainted 4.14.0-rc8 #58
[ 112.671173] Call Trace:
[ 112.671173] ? dump_stack+0x79/0xab
[ 112.671174] ? select_task_rq_fair+0x1b8/0xa8a
[ 112.671174] ? try_to_wake_up+0x2f/0x22d

[ 112.671175] ? __lock_is_held+0x40/0x71
[ 112.671175] ? select_task_rq+0x58/0xa6
[ 112.671176] ? try_to_wake_up+0x123/0x22d
[ 112.671176] ? up+0x28/0x35
[ 112.671176] ? __up_console_sem+0x33/0x5a
[ 112.671177] ? console_unlock+0x2f8/0x42e
[ 112.671177] ? vprintk_emit+0x223/0x234
[ 112.671178] ? printk+0x3e/0x46
[ 112.671178] ? setup_local_APIC+0x1ca/0x212
[ 112.671178] ? apic_ap_setup+0x5/0xa
[ 112.671179] ? start_secondary+0x42/0xfd
[ 112.671179] ? secondary_startup_64+0xa5/0xa5
[ 112.671180] [ 112.671180] =============================
[ 112.671180] WARNING: suspicious RCU usage
[ 112.671181] 4.14.0-rc8 #58 Not tainted
[ 112.671181] -----------------------------
[ 112.671182] kernel/sched/fair.c:5828 suspicious rcu_dereference_check() usage!
[ 112.671182] [ 112.671183] other info that might help us debug this:
[ 112.671183] [ 112.671184] RCU used illegally from offline CPU!
[ 112.671184] rcu_scheduler_active = 2, debug_locks = 1
[ 112.671185] 3 locks held by swapper/1/0:
[ 112.671185] #0: ((console_sem).lock){-...}, at: [<ffffffffbcad859d>] up+0xa/0x35
[ 112.671187] #1: (&p->pi_lock){-.-.}, at: [<ffffffffbcac3216>] try_to_wake_up+0x2f/0x22d
[ 112.671189] #2: (rcu_read_lock){....}, at: [<ffffffffbcac7d20>] rcu_read_lock+0x0/0x69
[ 112.671190] [ 112.671191] stack backtrace:
[ 112.671191] CPU: 1 PID: 0 Comm: swapper/1 Not tainted 4.14.0-rc8 #58
[ 112.671192] Call Trace:
[ 112.671192] ? dump_stack+0x79/0xab
[ 112.671193] ? select_task_rq_fair+0x3b3/0xa8a
[ 112.671193] ? try_to_wake_up+0x2f/0x22d
[ 112.671194] ? __lock_is_held+0x40/0x71
[ 112.671194] ? select_task_rq+0x58/0xa6
[ 112.671195] ? try_to_wake_up+0x123/0x22d
[ 112.671195] ? up+0x28/0x35
[ 112.671195] ? __up_console_sem+0x33/0x5a
[ 112.671196] ? console_unlock+0x2f8/0x42e
[ 112.671196] ? vprintk_emit+0x223/0x234
[ 112.671197] ? printk+0x3e/0x46
[ 112.671197] ? setup_local_APIC+0x1ca/0x212
[ 112.671198] ? apic_ap_setup+0x5/0xa
[ 112.671198] ? start_secondary+0x42/0xfd
[ 112.671198] ? secondary_startup_64+0xa5/0xa5
See 'systemctl status lkp-bootstrap.service' for details.
[ 112.708409] KVM setup async PF for cpu 1
[ 112.708909] kvm-stealtime: cpu 1, msr 3530c580
Starting watchdog daemon...
[ 112.912274] Unregister pv shared memory for cpu 1

/pkg/linux/x86_64-randconfig-ws0-11062157/gcc-6/39dae59d66acd86d1de24294bd2f343fd5e7a625/dmesg-quantal-intel12-12:20171106225942:x86_64-randconfig-ws0-11062157:4.14.0-rc8:64

[ 1.684524] serial8250: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A
[ 1.709802] serial8250: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A
[ 1.711772] console [ttyS0] disabled

Thanks,
Fengguang