FYI, we noticed the following commit (built with gcc-4.9):
commit: 6c0a1d639cb7e989007cc3153b2f4eafb2e5bb7b ("rcu: Parallelize expedited grace-period initialization")
https://git.kernel.org/cgit/linux/kernel/git/paulmck/linux-rcu.git rcu/dev
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-i386 -enable-kvm -smp 2 -m 320M
caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
+-------------------------------------------------------+------------+------------+
| | 0f0a62adf1 | 6c0a1d639c |
+-------------------------------------------------------+------------+------------+
| boot_successes | 0 | 0 |
| boot_failures | 196 | 67 |
| WARNING:possible_circular_locking_dependency_detected | 196 | |
| WARNING:at_drivers/pci/pci-sysfs.c:#pci_mmap_resource | 20 | |
| EIP:pci_mmap_resource | 22 | |
| invoked_oom-killer:gfp_mask=0x | 1 | |
| Mem-Info | 10 | |
| EIP:__put_user_4 | 1 | |
| BUG:scheduling_while_atomic | 0 | 67 |
| WARNING:at_kernel/locking/lockdep.c:#lock_release | 0 | 67 |
| EIP:lock_release | 0 | 67 |
| WARNING:at_kernel/locking/lockdep.c:#lock_unpin_lock | 0 | 67 |
| EIP:lock_unpin_lock | 0 | 67 |
+-------------------------------------------------------+------------+------------+
[ 0.066192] BUG: scheduling while atomic: swapper/0/0/0x00000002
[ 0.068160] 1 lock held by swapper/0/0:
[ 0.070023] #0: (rcu_preempt_state.exp_mutex){+.+.}, at: [<c10d920a>] _synchronize_rcu_expedited+0x7aa/0xa10
[ 0.073303] Modules linked in:
[ 0.074521] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.15.0-rc1-00112-g6c0a1d63 #774
[ 0.077215] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[ 0.080000] Call Trace:
[ 0.080000] dump_stack+0x76/0xa9
[ 0.080000] __schedule_bug+0x72/0xa0
[ 0.080000] __schedule+0x871/0xb30
[ 0.080000] ? mark_held_locks+0x73/0xa0
[ 0.080000] ? _raw_spin_unlock_irqrestore+0x4d/0x70
[ 0.080000] schedule+0x35/0x80
[ 0.080000] schedule_timeout+0x192/0x490
[ 0.080000] ? collect_expired_timers+0xc0/0xc0
[ 0.080000] rcu_exp_wait_wake+0xaf/0x940
[ 0.080000] ? trace_hardirqs_on+0xb/0x10
[ 0.080000] _synchronize_rcu_expedited+0x931/0xa10
[ 0.080000] ? native_set_pte+0x10/0x10
[ 0.080000] ? native_set_pte_at+0x10/0x10
[ 0.080000] ? __ptep_modify_prot_start+0x10/0x10
[ 0.080000] ? __paravirt_pgd_alloc+0x10/0x10
[ 0.080000] ? rcu_report_exp_cpu_mult+0x70/0x70
[ 0.080000] ? __paravirt_pgd_alloc+0x10/0x10
[ 0.080000] ? rewind_stack_do_exit+0x13/0x13
[ 0.080000] ? rewind_stack_do_exit+0x13/0x13
[ 0.080000] ? rewind_stack_do_exit+0x13/0x13
[ 0.080000] ? end_pv_irq_ops_irq_disable+0x1/0x1
[ 0.080000] ? ___ratelimit+0xb7/0x110
[ 0.080000] ? trace_hardirqs_on+0xb/0x10
[ 0.080000] ? apply_paravirt+0xc7/0x130
[ 0.080000] ? ___ratelimit+0xb7/0x110
[ 0.080000] ? wake_up_klogd+0x8/0x50
[ 0.080000] ? ___might_sleep+0x2f/0x1f0
[ 0.080000] ? acpi_hw_validate_io_request+0xe/0xed
[ 0.080000] ? acpi_os_read_port+0xb/0x60
[ 0.080000] synchronize_rcu_expedited+0x37/0xb0
[ 0.080000] synchronize_rcu+0xb5/0xe0
[ 0.080000] ? acpi_hw_read_multiple+0x1a/0x47
[ 0.080000] ? ___might_sleep+0x2f/0x1f0
[ 0.080000] ? acpi_hw_register_read+0x56/0xbc
[ 0.080000] ? __might_sleep+0x33/0x90
[ 0.080000] ? find_next_bit+0x12/0x20
[ 0.080000] ? cpumask_next+0x15/0x20
[ 0.080000] ? synchronize_sched_expedited+0x3c/0xe0
[ 0.080000] rcu_test_sync_prims+0xd/0x30
[ 0.080000] rcu_scheduler_starting+0x34/0x60
[ 0.080000] rest_init+0xe/0x1f0
[ 0.080000] start_kernel+0x44f/0x457
[ 0.080000] i386_start_kernel+0x8f/0x93
[ 0.080000] startup_32_smp+0x164/0x170
[ 0.080044] ------------[ cut here ]------------
[ 0.082082] releasing a pinned lock
[ 0.083741] WARNING: CPU: 0 PID: 0 at kernel/locking/lockdep.c:3780 lock_release+0x45c/0x4b0
[ 0.087752] Modules linked in:
[ 0.089169] CPU: 0 PID: 0 Comm: swapper/0 Tainted: G W 4.15.0-rc1-00112-g6c0a1d63 #774
[ 0.090000] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[ 0.090000] task: c1ba3340 task.stack: c1b98000
[ 0.090000] EIP: lock_release+0x45c/0x4b0
[ 0.090000] EFLAGS: 00210082 CPU: 0
[ 0.090000] EAX: 00000017 EBX: d244b2c0 ECX: c10c08f0 EDX: c10c090c
[ 0.090000] ESI: c1ba39b8 EDI: c1ba3340 EBP: c1b99c64 ESP: c1b99c34
[ 0.090000] DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068
[ 0.090000] CR0: 80050033 CR2: ffffffff CR3: 01e7a000 CR4: 00000690
[ 0.090000] Call Trace:
[ 0.090000] ? dequeue_task_idle+0x13/0x40
[ 0.090000] _raw_spin_unlock_irq+0x1b/0x50
[ 0.090000] dequeue_task_idle+0x13/0x40
[ 0.090000] deactivate_task+0xb8/0x160
[ 0.090000] __schedule+0x55c/0xb30
[ 0.090000] ? _raw_spin_unlock_irqrestore+0x4d/0x70
[ 0.090000] schedule+0x35/0x80
[ 0.090000] schedule_timeout+0x192/0x490
[ 0.090000] ? collect_expired_timers+0xc0/0xc0
[ 0.090000] rcu_exp_wait_wake+0xaf/0x940
[ 0.090000] ? trace_hardirqs_on+0xb/0x10
[ 0.090000] _synchronize_rcu_expedited+0x931/0xa10
[ 0.090000] ? native_set_pte+0x10/0x10
[ 0.090000] ? native_set_pte_at+0x10/0x10
[ 0.090000] ? __ptep_modify_prot_start+0x10/0x10
[ 0.090000] ? __paravirt_pgd_alloc+0x10/0x10
[ 0.090000] ? rcu_report_exp_cpu_mult+0x70/0x70
[ 0.090000] ? __paravirt_pgd_alloc+0x10/0x10
[ 0.090000] ? rewind_stack_do_exit+0x13/0x13
[ 0.090000] ? rewind_stack_do_exit+0x13/0x13
[ 0.090000] ? rewind_stack_do_exit+0x13/0x13
[ 0.090000] ? end_pv_irq_ops_irq_disable+0x1/0x1
[ 0.090000] ? ___ratelimit+0xb7/0x110
[ 0.090000] ? trace_hardirqs_on+0xb/0x10
[ 0.090000] ? apply_paravirt+0xc7/0x130
[ 0.090000] ? ___ratelimit+0xb7/0x110
[ 0.090000] ? wake_up_klogd+0x8/0x50
[ 0.090000] ? ___might_sleep+0x2f/0x1f0
[ 0.090000] ? acpi_hw_validate_io_request+0xe/0xed
[ 0.090000] ? acpi_os_read_port+0xb/0x60
[ 0.090000] synchronize_rcu_expedited+0x37/0xb0
[ 0.090000] synchronize_rcu+0xb5/0xe0
[ 0.090000] ? acpi_hw_read_multiple+0x1a/0x47
[ 0.090000] ? ___might_sleep+0x2f/0x1f0
[ 0.090000] ? acpi_hw_register_read+0x56/0xbc
[ 0.090000] ? __might_sleep+0x33/0x90
[ 0.090000] ? find_next_bit+0x12/0x20
[ 0.090000] ? cpumask_next+0x15/0x20
[ 0.090000] ? synchronize_sched_expedited+0x3c/0xe0
[ 0.090000] rcu_test_sync_prims+0xd/0x30
[ 0.090000] rcu_scheduler_starting+0x34/0x60
[ 0.090000] rest_init+0xe/0x1f0
[ 0.090000] start_kernel+0x44f/0x457
[ 0.090000] i386_start_kernel+0x8f/0x93
[ 0.090000] startup_32_smp+0x164/0x170
[ 0.090000] Code: c1 ba 3f 00 00 00 b8 08 11 a9 c1 c6 05 6e f3 c5 c1 01 e8 08 b4 ff ff e9 cd fd ff ff 8d 76 00 c7 04 24 9f fc a8 c1 e8 34 5c fa ff <0f> ff e9 6c fc ff ff e8 c2 c4 f4 ff e9 57 fc ff ff 8d 44 03 74
[ 0.090000] ---[ end trace 677d86ae136591a1 ]---
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