FYI, we noticed the following commit (built with gcc-7):
commit: 7b0a7531cd210e510e4bcf40a732060ec7503107 ("debug")
https://git.kernel.org/cgit/linux/kernel/git/frederic/linux-dynticks.git
softirq/soft-interruptible-v2-0day
in testcase: trinity
with following parameters:
runtime: 300s
test-description: Trinity is a linux system call fuzz tester.
test-url:
http://codemonkey.org.uk/projects/trinity/
on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 2G
caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
+---------------------------------------------------------+------------+------------+
| | 62fd64b7f1 | 7b0a7531cd |
+---------------------------------------------------------+------------+------------+
| boot_successes | 44 | 1 |
| boot_failures | 2 | 23 |
| BUG:kernel_in_stage | 2 | 2 |
| WARNING:possible_irq_lock_inversion_dependency_detected | 0 | 21 |
+---------------------------------------------------------+------------+------------+
[ 15.123927] WARNING: possible irq lock inversion dependency detected
[ 15.125747] 5.0.0-rc2-00264-g7b0a753 #168 Not tainted
[ 15.127213] --------------------------------------------------------
[ 15.129053] systemd/1 just changed the state of lock:
[ 15.130454] (____ptrval____) (__prout_spinB){+.+.+.+.+.+.+.+.+.+.+.}, at:
proc_pid_cmdline_read+0xcd/0x32a
[ 15.133232] but this lock was taken by another, BLOCK_SOFTIRQ-safe lock in the past:
[ 15.135467] (__prout_spinA){+.+.+.+.+.-.+.+.+.+.+.}
[ 15.135471]
[ 15.135471]
[ 15.135471] and interrupts could create inverse lock ordering between them.
[ 15.135471]
[ 15.140008]
[ 15.140008] other info that might help us debug this:
[ 15.141878] Possible interrupt unsafe locking scenario:
[ 15.141878]
[ 15.143788] CPU0 CPU1
[ 15.145117] ---- ----
[ 15.146416] lock(__prout_spinB);
[ 15.147438] local_irq_disable();
[ 15.149152] lock(__prout_spinA);
[ 15.150871] lock(__prout_spinB);
[ 15.152586] <Interrupt>
[ 15.153342] lock(__prout_spinA);
[ 15.154401]
[ 15.154401] *** DEADLOCK ***
[ 15.154401]
[ 15.156147] no locks held by systemd/1.
[ 15.157268]
[ 15.157268] the shortest dependencies between 2nd lock and 1st lock:
[ 15.159503] -> (__prout_spinA){+.+.+.+.+.-.+.+.+.+.+.} {
[ 15.161111] HARDIRQ-ON-W at:
[ 15.162053] _raw_spin_lock+0x2e/0x5f
[ 15.163641] proc_pid_cmdline_read+0x64/0x32a
[ 15.165372] __vfs_read+0x1e/0xa2
[ 15.166961] vfs_read+0xa4/0xc0
[ 15.168372] ksys_read+0x4b/0x79
[ 15.169879] do_syscall_64+0x14f/0x160
[ 15.171411] entry_SYSCALL_64_after_hwframe+0x49/0xbe
[ 15.173371] HI_SOFTIRQ-ON-W at:
[ 15.174440] _raw_spin_lock_bh_mask+0x3a/0x71
[ 15.176351] proc_pid_cmdline_read+0x99/0x32a
[ 15.178199] __vfs_read+0x1e/0xa2
[ 15.179889] vfs_read+0xa4/0xc0
[ 15.181391] ksys_read+0x4b/0x79
[ 15.182955] do_syscall_64+0x14f/0x160
[ 15.184623] entry_SYSCALL_64_after_hwframe+0x49/0xbe
[ 15.186777] TIMER_SOFTIRQ-ON-W at:
[ 15.187878] _raw_spin_lock_bh_mask+0x3a/0x71
[ 15.189784] proc_pid_cmdline_read+0x99/0x32a
[ 15.191705] __vfs_read+0x1e/0xa2
[ 15.193305] vfs_read+0xa4/0xc0
[ 15.194940] ksys_read+0x4b/0x79
[ 15.196533] do_syscall_64+0x14f/0x160
[ 15.198269] entry_SYSCALL_64_after_hwframe+0x49/0xbe
[ 15.200426] NET_TX_SOFTIRQ-ON-W at:
[ 15.201577] _raw_spin_lock_bh_mask+0x3a/0x71
[ 15.203468] proc_pid_cmdline_read+0x99/0x32a
[ 15.205435] __vfs_read+0x1e/0xa2
[ 15.207202] vfs_read+0xa4/0xc0
[ 15.208853] ksys_read+0x4b/0x79
[ 15.210596] do_syscall_64+0x14f/0x160
[ 15.212307] entry_SYSCALL_64_after_hwframe+0x49/0xbe
[ 15.214334] NET_RX_SOFTIRQ-ON-W at:
[ 15.215442] _raw_spin_lock_bh_mask+0x3a/0x71
[ 15.217410] proc_pid_cmdline_read+0x99/0x32a
[ 15.219434] __vfs_read+0x1e/0xa2
[ 15.221162] vfs_read+0xa4/0xc0
[ 15.222747] ksys_read+0x4b/0x79
[ 15.224346] do_syscall_64+0x14f/0x160
[ 15.226067] entry_SYSCALL_64_after_hwframe+0x49/0xbe
[ 15.228155] IN-BLOCK_SOFTIRQ-W at:
[ 15.229292] _raw_spin_lock+0x2e/0x5f
[ 15.230958] proc_pid_cmdline_read+0x64/0x32a
[ 15.232867] __vfs_read+0x1e/0xa2
[ 15.234418] vfs_read+0xa4/0xc0
[ 15.235933] ksys_read+0x4b/0x79
[ 15.237551] do_syscall_64+0x14f/0x160
[ 15.239314] entry_SYSCALL_64_after_hwframe+0x49/0xbe
[ 15.241419] IRQ_POLL_SOFTIRQ-ON-W at:
[ 15.242666] _raw_spin_lock_bh_mask+0x3a/0x71
[ 15.244626] proc_pid_cmdline_read+0x99/0x32a
[ 15.246665] __vfs_read+0x1e/0xa2
[ 15.248330] vfs_read+0xa4/0xc0
[ 15.249974] ksys_read+0x4b/0x79
[ 15.251593] do_syscall_64+0x14f/0x160
[ 15.253388] entry_SYSCALL_64_after_hwframe+0x49/0xbe
[ 15.255653] TASKLET_SOFTIRQ-ON-W at:
[ 15.256752] _raw_spin_lock_bh_mask+0x3a/0x71
[ 15.258747] proc_pid_cmdline_read+0x99/0x32a
[ 15.260689] __vfs_read+0x1e/0xa2
[ 15.262363] vfs_read+0xa4/0xc0
[ 15.264145] ksys_read+0x4b/0x79
[ 15.265795] do_syscall_64+0x14f/0x160
[ 15.267570] entry_SYSCALL_64_after_hwframe+0x49/0xbe
[ 15.269670] SCHED_SOFTIRQ-ON-W at:
[ 15.270746] _raw_spin_lock_bh_mask+0x3a/0x71
[ 15.272641] proc_pid_cmdline_read+0x99/0x32a
[ 15.274667] __vfs_read+0x1e/0xa2
[ 15.276222] vfs_read+0xa4/0xc0
[ 15.277717] ksys_read+0x4b/0x79
[ 15.279266] do_syscall_64+0x14f/0x160
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,
Rong Chen