FYI, we noticed the following commit (built with gcc-6):
commit: 1b0a8f5c66d2a862716135572541fdad754377dc ("rcu: Defer reporting RCU-preempt quiescent states when disabled")
https://git.kernel.org/cgit/linux/kernel/git/paulmck/linux-rcu.git dev.2018.06.28a
in testcase: boot
on test machine: qemu-system-x86_64 -enable-kvm -smp 2 -m 512M
caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
+-------------------------------------------------------------------------------+------------+------------+
| | 1376a53461 | 1b0a8f5c66 |
+-------------------------------------------------------------------------------+------------+------------+
| boot_successes | 2 | 3 |
| boot_failures | 59 | 64 |
| invoked_oom-killer:gfp_mask=0x | 50 | 24 |
| RIP:__put_user_4 | 1 | 1 |
| Mem-Info | 50 | 24 |
| Out_of_memory:Kill_process | 50 | 24 |
| RIP:__clear_user | 7 | 2 |
| RIP:copy_user_generic_string | 6 | 2 |
| Kernel_panic-not_syncing:Out_of_memory_and_no_killable_processes | 26 | 13 |
| IP-Config:Auto-configuration_of_network_failed | 9 | 10 |
| WARNING:suspicious_RCU_usage | 0 | 41 |
| include/trace/events/sched.h:#suspicious_rcu_dereference_check()usage | 0 | 41 |
| WARNING:possible_circular_locking_dependency_detected | 0 | 15 |
| include/linux/rcupdate.h:#rcu_read_lock()used_illegally_while_idle | 0 | 28 |
| include/linux/rcupdate.h:#rcu_read_unlock()used_illegally_while_idle | 0 | 28 |
| RIP:create_elf_tables | 0 | 1 |
| page_allocation_failure:order:#,mode:#(GFP_NOWAIT|__GFP_COMP),nodemask=(null) | 0 | 1 |
| RIP:arch_local_irq_restore | 0 | 1 |
| RIP:__asan_load4 | 0 | 1 |
| RIP:arch_local_irq_enable | 0 | 2 |
| RIP:arch_local_save_flags | 0 | 1 |
+-------------------------------------------------------------------------------+------------+------------+
[ 484.135150] WARNING: suspicious RCU usage
[ 484.136572] 4.18.0-rc1-00138-g1b0a8f5 #1 Not tainted
[ 484.138166] -----------------------------
[ 484.139488] include/trace/events/sched.h:90 suspicious rcu_dereference_check() usage!
[ 484.142645]
[ 484.142645] other info that might help us debug this:
[ 484.142645]
[ 484.158172]
[ 484.158172] RCU used illegally from idle CPU!
[ 484.158172] rcu_scheduler_active = 2, debug_locks = 1
[ 484.161431] RCU used illegally from extended quiescent state!
[ 484.163124] 2 locks held by sh/287:
[ 484.164300] #0: (____ptrval____) (&rsp->expedited_wq){-.-.}, at: swake_up+0x16/0x44
[ 484.166864] #1: (____ptrval____) (&p->pi_lock){-.-.}, at: try_to_wake_up+0x91/0x532
[ 484.169041]
[ 484.169041] stack backtrace:
[ 484.170602] CPU: 0 PID: 287 Comm: sh Not tainted 4.18.0-rc1-00138-g1b0a8f5 #1
[ 484.185786] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[ 484.188314] Call Trace:
[ 484.189265] dump_stack+0x12b/0x1b0
[ 484.190488] lockdep_rcu_suspicious+0x177/0x185
[ 484.191948] trace_sched_waking+0xdb/0x1f4
[ 484.193277] try_to_wake_up+0xc8/0x532
[ 484.194589] ? cpus_share_cache+0x73/0x73
[ 484.195947] ? lock_acquire+0x1a2/0x2fc
[ 484.208493] ? lock_acquire+0x1a2/0x2fc
[ 484.209815] ? swake_up+0x16/0x44
[ 484.211015] ? lock_acquire+0x1cc/0x2fc
[ 484.212342] wake_up_process+0x1c/0x25
[ 484.213667] swake_up_locked+0x4b/0x64
[ 484.214975] swake_up+0x28/0x44
[ 484.216122] __rcu_report_exp_rnp+0xd6/0x169
[ 484.217568] rcu_report_exp_cpu_mult+0x7b/0x8b
[ 484.219110] rcu_report_exp_rdp+0x4d/0x59
[ 484.220943] rcu_preempt_deferred_qs_irqrestore+0x19e/0x6f8
[ 484.222700] ? get_vtime_delta+0x1c4/0x1da
[ 484.224067] rcu_preempt_deferred_qs+0x4e/0x58
[ 484.225498] rcu_eqs_enter+0x19e/0x1aa
[ 484.227050] rcu_user_enter+0xb6/0xbf
[ 484.228272] __context_tracking_enter+0x19e/0x2b6
[ 484.229778] prepare_exit_to_usermode+0x349/0x36f
[ 484.231328] syscall_return_slowpath+0x2b4/0x3dc
[ 484.232846] do_syscall_64+0xc2/0xce
[ 484.234119] entry_SYSCALL_64_after_hwframe+0x49/0xbe
[ 484.235801] RIP: 0033:0x7f93f6324257
[ 484.237053] Code: f3 c3 90 c7 05 5a c0 20 00 16 00 00 00 b8 ff ff ff ff c3 f7 d8 89 05 4c c0 20 00 48 83 c8 ff c3 90 90 90 b8 02 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8d 0d 2d c0 20 00 31 d2 48 29 c2 89
[ 484.244297] RSP: 002b:00007ffe515ac988 EFLAGS: 00000246 ORIG_RAX: 0000000000000002
[ 484.246809] RAX: 0000000000000003 RBX: 00007f93f652b2f5 RCX: 00007f93f6324257
[ 484.248932] RDX: 0000000000000000 RSI: 0000000000080000 RDI: 00007f93f652b2f5
[ 484.251110] RBP: 00007ffe515ac9f0 R08: 00007ffe515acdcf R09: 0000000000000000
[ 484.253298] R10: 00007f93f652b2f4 R11: 0000000000000246 R12: 00007ffe515aca60
[ 484.255509] R13: 00007f93f6529000 R14: 0000000000000008 R15: 00007f93f652b2f5
[ 484.257812]
[ 484.257822] =============================
[ 484.257831] WARNING: suspicious RCU usage
[ 484.257839] 4.18.0-rc1-00138-g1b0a8f5 #1 Not tainted
[ 484.257846] -----------------------------
[ 484.257859] include/linux/rcupdate.h:631 rcu_read_lock() used illegally while idle!
[ 484.257867]
[ 484.257875] other info that might help us debug this:
[ 484.257882]
[ 484.257889]
[ 484.257897] RCU used illegally from idle CPU!
[ 484.257905] rcu_scheduler_active = 2, debug_locks = 1
[ 484.257921] RCU used illegally from extended quiescent state!
[ 484.257925] 6 locks held by sh/287:
[ 484.257928] #0: (____ptrval____) (&rsp->expedited_wq){-.-.}, at: swake_up+0x16/0x44
[ 484.257960] #1: (____ptrval____) (&p->pi_lock){-.-.}, at: try_to_wake_up+0x91/0x532
[ 484.258001] #2: (____ptrval____) (console_lock){+.+.}, at: vprintk_emit+0x4ab/0x704
[ 484.258043] #3: (____ptrval____) (console_owner){-...}, at: console_unlock+0x2ee/0x8bc
[ 484.258086] #4: (____ptrval____) (printing_lock){....}, at: vt_console_print+0x5c/0x579
[ 484.258122] #5: (____ptrval____) (rcu_read_lock){....}, at: rcu_lock_acquire+0x0/0x2e
[ 484.258165]
[ 484.258172] stack backtrace:
[ 484.258182] CPU: 0 PID: 287 Comm: sh Not tainted 4.18.0-rc1-00138-g1b0a8f5 #1
[ 484.258192] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[ 484.258200] Call Trace:
[ 484.258208] dump_stack+0x12b/0x1b0
[ 484.258216] lockdep_rcu_suspicious+0x177/0x185
[ 484.258226] __atomic_notifier_call_chain+0xa6/0x16e
[ 484.258235] atomic_notifier_call_chain+0x17/0x1f
[ 484.258242] notify_write+0x72/0x8b
[ 484.258251] ? notify_update+0x90/0x90
[ 484.258259] ? hide_cursor+0x67/0x132
[ 484.258267] vt_console_print+0x3da/0x579
[ 484.258276] console_unlock+0x505/0x8bc
[ 484.258283] vprintk_emit+0x6b1/0x704
[ 484.258291] vprintk_default+0x20/0x28
[ 484.258299] vprintk_func+0xbd/0xc5
[ 484.258307] printk+0x9b/0xbe
[ 484.258316] ? init_section_contains+0x34/0x34
[ 484.258324] ? lock_acquire+0x1a2/0x2fc
[ 484.258332] ? debug_show_all_locks+0x2ed/0x2ed
[ 484.258341] ? rcu_dynticks_curr_cpu_in_eqs+0x44/0x52
[ 484.258349] lockdep_rcu_suspicious+0x22/0x185
[ 484.258356] trace_sched_waking+0xdb/0x1f4
[ 484.258365] try_to_wake_up+0xc8/0x532
[ 484.258373] ? cpus_share_cache+0x73/0x73
[ 484.258381] ? lock_acquire+0x1a2/0x2fc
[ 484.258389] ? lock_acquire+0x1a2/0x2fc
[ 484.258397] ? swake_up+0x16/0x44
[ 484.258404] ? lock_acquire+0x1cc/0x2fc
[ 484.258412] wake_up_process+0x1c/0x25
[ 484.258420] swake_up_locked+0x4b/0x64
[ 484.258428] swake_up+0x28/0x44
[ 484.258436] __rcu_report_exp_rnp+0xd6/0x169
[ 484.258444] rcu_report_exp_cpu_mult+0x7b/0x8b
[ 484.258452] rcu_report_exp_rdp+0x4d/0x59
[ 484.258461] rcu_preempt_deferred_qs_irqrestore+0x19e/0x6f8
[ 484.258469] ? get_vtime_delta+0x1c4/0x1da
[ 484.258478] rcu_preempt_deferred_qs+0x4e/0x58
[ 484.258486] rcu_eqs_enter+0x19e/0x1aa
[ 484.258493] rcu_user_enter+0xb6/0xbf
[ 484.258502] __context_tracking_enter+0x19e/0x2b6
[ 484.258509] prepare_exit_to_usermode+0x349/0x36f
[ 484.258518] syscall_return_slowpath+0x2b4/0x3dc
[ 484.258527] do_syscall_64+0xc2/0xce
[ 484.258535] entry_SYSCALL_64_after_hwframe+0x49/0xbe
[ 484.258542] RIP: 0033:0x7f93f6324257
[ 484.258549] Code: f3 c3 90 c7 05 5a c0 20 00 16 00 00 00 b8 ff ff ff ff c3 f7 d8 89 05 4c c0 20 00 48 83 c8 ff c3 90 90 90 b8 02 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8d 0d 2d c0 20 00 31 d2 48 29 c2 89
[ 484.258973] RSP: 002b:00007ffe515ac988 EFLAGS: 00000246 ORIG_RAX: 0000000000000002
[ 484.258991] RAX: 0000000000000003 RBX: 00007f93f652b2f5 RCX: 00007f93f6324257
[ 484.259001] RDX: 0000000000000000 RSI: 0000000000080000 RDI: 00007f93f652b2f5
[ 484.259010] RBP: 00007ffe515ac9f0 R08: 00007ffe515acdcf R09: 0000000000000000
[ 484.259019] R10: 00007f93f652b2f4 R11: 0000000000000246 R12: 00007ffe515aca60
[ 484.259028] R13: 00007f93f6529000 R14: 0000000000000008 R15: 00007f93f652b2f5
[ 484.259037]
[ 484.259044] =============================
[ 484.259053] WARNING: suspicious RCU usage
[ 484.259061] 4.18.0-rc1-00138-g1b0a8f5 #1 Not tainted
[ 484.259069] -----------------------------
[ 484.259079] include/linux/rcupdate.h:680 rcu_read_unlock() used illegally while idle!
[ 484.259086]
[ 484.259095] other info that might help us debug this:
[ 484.259102]
[ 484.259109]
[ 484.259117] RCU used illegally from idle CPU!
[ 484.259126] rcu_scheduler_active = 2, debug_locks = 1
[ 484.259134] RCU used illegally from extended quiescent state!
[ 484.259143] 6 locks held by sh/287:
[ 484.259149] #0: (____ptrval____) (&rsp->expedited_wq){-.-.}, at: swake_up+0x16/0x44
[ 484.259191] #1: (____ptrval____) (&p->pi_lock){-.-.}, at: try_to_wake_up+0x91/0x532
[ 484.259233] #2: (____ptrval____) (console_lock){+.+.}, at: vprintk_emit+0x4ab/0x704
[ 484.259275] #3: (____ptrval____) (console_owner){-...}, at: console_unlock+0x2ee/0x8bc
[ 484.259319] #4: (____ptrval____) (printing_lock){....}, at: vt_console_print+0x5c/0x579
[ 484.259361] #5: (____ptrval____) (rcu_read_lock){....}, at: rcu_lock_acquire+0x0/0x2e
[ 484.259402]
[ 484.259410] stack backtrace:
[ 484.259418] CPU: 0 PID: 287 Comm: sh Not tainted 4.18.0-rc1-00138-g1b0a8f5 #1
[ 484.259428] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[ 484.259436] Call Trace:
[ 484.259444] dump_stack+0x12b/0x1b0
[ 484.259453] lockdep_rcu_suspicious+0x177/0x185
[ 484.259462] __atomic_notifier_call_chain+0x136/0x16e
[ 484.259470] atomic_notifier_call_chain+0x17/0x1f
[ 484.259479] notify_write+0x72/0x8b
[ 484.259487] ? notify_update+0x90/0x90
[ 484.259495] ? hide_cursor+0x67/0x132
[ 484.259503] vt_console_print+0x3da/0x579
[ 484.259511] console_unlock+0x505/0x8bc
[ 484.259518] vprintk_emit+0x6b1/0x704
[ 484.259527] vprintk_default+0x20/0x28
[ 484.259535] vprintk_func+0xbd/0xc5
[ 484.259543] printk+0x9b/0xbe
[ 484.259553] ? init_section_contains+0x34/0x34
[ 484.259561] ? lock_acquire+0x1a2/0x2fc
[ 484.259570] ? debug_show_all_locks+0x2ed/0x2ed
[ 484.259578] ? rcu_dynticks_curr_cpu_in_eqs+0x44/0x52
[ 484.259587] lockdep_rcu_suspicious+0x22/0x185
[ 484.259596] trace_sched_waking+0xdb/0x1f4
[ 484.259605] try_to_wake_up+0xc8/0x532
[ 484.259613] ? cpus_share_cache+0x73/0x73
[ 484.259622] ? lock_acquire+0x1a2/0x2fc
[ 484.259630] ? lock_acquire+0x1a2/0x2fc
[ 484.259639] ? swake_up+0x16/0x44
[ 484.259648] ? lock_acquire+0x1cc/0x2fc
[ 484.259656] wake_up_process+0x1c/0x25
[ 484.259665] swake_up_locked+0x4b/0x64
[ 484.259672] swake_up+0x28/0x44
[ 484.259681] __rcu_report_exp_rnp+0xd6/0x169
[ 484.259689] rcu_report_exp_cpu_mult+0x7b/0x8b
[ 484.259698] rcu_report_exp_rdp+0x4d/0x59
[ 484.259707] rcu_preempt_deferred_qs_irqrestore+0x19e/0x6f8
[ 484.259715] ? get_vtime_delta+0x1c4/0x1da
[ 484.259723] rcu_preempt_deferred_qs+0x4e/0x58
[ 484.259732] rcu_eqs_enter+0x19e/0x1aa
[ 484.259741] rcu_user_enter+0xb6/0xbf
[ 484.259749] __context_tracking_enter+0x19e/0x2b6
[ 484.259758] prepare_exit_to_usermode+0x349/0x36f
[ 484.259766] syscall_return_slowpath+0x2b4/0x3dc
[ 484.259775] do_syscall_64+0xc2/0xce
[ 484.259784] entry_SYSCALL_64_after_hwframe+0x49/0xbe
[ 484.259793] RIP: 0033:0x7f93f6324257
[ 484.259800] Code: f3 c3 90 c7 05 5a c0 20 00 16 00 00 00 b8 ff ff ff ff c3 f7 d8 89 05 4c c0 20 00 48 83 c8 ff c3 90 90 90 b8 02 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8d 0d 2d c0 20 00 31 d2 48 29 c2 89
[ 484.260211] RSP: 002b:00007ffe515ac988 EFLAGS: 00000246 ORIG_RAX: 0000000000000002
[ 484.260228] RAX: 0000000000000003 RBX: 00007f93f652b2f5 RCX: 00007f93f6324257
[ 484.260238] RDX: 0000000000000000 RSI: 0000000000080000 RDI: 00007f93f652b2f5
[ 484.260247] RBP: 00007ffe515ac9f0 R08: 00007ffe515acdcf R09: 0000000000000000
[ 484.260257] R10: 00007f93f652b2f4 R11: 0000000000000246 R12: 00007ffe515aca60
[ 484.260265] R13: 00007f93f6529000 R14: 0000000000000008 R15: 00007f93f652b2f5
udevd[291]: fail
Elapsed time: 2190
#!/bin/bash
# To reproduce,
# 1) save job-script and this script (both are attached in 0day report email)
# 2) run this script with your compiled kernel and optional env $INSTALL_MOD_PATH
kernel=$1
initrds=(
/osimage/quantal/quantal-core-x86_64.cgz
/lkp/lkp/lkp-x86_64.cgz
)
HTTP_PREFIX=https://download.01.org/0day-ci/lkp-qemu
wget --timestamping "${initrds[@]/#/$HTTP_PREFIX}"
{
cat "${initrds[@]//*\//}"
[[ $INSTALL_MOD_PATH ]] && (
cd "$INSTALL_MOD_PATH"
find lib | cpio -o -H newc --quiet | gzip
)
echo job-script | cpio -o -H newc --quiet | gzip
} > initrd.img
kvm=(
To reproduce:
git clone https://github.com/intel/lkp-tests.git
cd lkp-tests
bin/lkp qemu -k <bzImage> job-script # job-script is attached in this email
Thanks,
Xiaolong