Greeting,
FYI, we noticed WARNING:inconsistent_lock_state due to commit (built with gcc-11):
commit: 98ccdf3d86014216f3168d7f91ce37cfc31d8d8f ("[PATCH] rcu: Dump memory object info if callback is invalid")
url: https://github.com/intel-lab-lkp/linux/commits/Zhen-Lei/rcu-Dump-memory-object-info-if-callback-is-invalid/20221105-103913
base: https://git.kernel.org/cgit/linux/kernel/git/paulmck/linux-rcu.git dev
patch subject: [PATCH] rcu: Dump memory object info if callback is invalid
in testcase: boot
on test machine: qemu-system-i386 -enable-kvm -cpu SandyBridge -smp 2 -m 4G
caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
[ 267.167919][ C0] WARNING: inconsistent lock state
[ 267.167583][ T1] calling cpu_hotplug_pm_sync_init+0x0/0x11 @ 1
[ 267.169690][ C0] 6.1.0-rc1-00115-g98ccdf3d8601 #1 Not tainted
[ 267.167583][ T1] initcall cpu_hotplug_pm_sync_init+0x0/0x11 returned 0 after 0 usecs
[ 267.171238][ C0] --------------------------------
[ 267.169196][ T1] calling wq_sysfs_init+0x0/0x24 @ 1
[ 267.173152][ C0] inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
[ 267.171114][ T1] initcall wq_sysfs_init+0x0/0x24 returned 0 after 0 usecs
[ 267.174609][ C0] swapper/0/0 [HC0[0]:SC1[1]:HE1:SE0] takes:
[ 267.172669][ T1] calling ksysfs_init+0x0/0x78 @ 1
[ 267.176493][ C0] c2957230 (vmap_area_lock){+.?.}-{2:2}, at: find_vmap_area (??:?)
[ 267.177532][ C0] {SOFTIRQ-ON-W} state was registered at:
[ 267.177532][ C0] mark_usage (lockdep.c:?)
[ 267.174448][ T1] initcall ksysfs_init+0x0/0x78 returned 0 after 0 usecs
[ 267.177532][ C0] __lock_acquire (lockdep.c:?)
[ 267.174448][ T1] calling schedutil_gov_init+0x0/0xf @ 1
[ 267.177532][ C0] lock_acquire (??:?)
[ 267.174448][ T1] initcall schedutil_gov_init+0x0/0xf returned 0 after 0 usecs
[ 267.177532][ C0] _raw_spin_lock (??:?)
[ 267.174448][ T1] calling pm_init+0x0/0x4a @ 1
[ 267.174448][ T1] initcall pm_init+0x0/0x4a returned 0 after 0 usecs
[ 267.174448][ T1] calling rcu_set_runtime_mode+0x0/0x20 @ 1
[ 267.177532][ C0] alloc_vmap_area (vmalloc.c:?)
[ 267.177532][ C0] __get_vm_area_node+0xaf/0xfd
[ 267.177532][ C0] get_vm_area_caller (??:?)
[ 267.177532][ C0] __ioremap_caller+0x1a7/0x234
[ 267.177532][ C0] ioremap_cache (??:?)
[ 267.177532][ C0] acpi_os_map_iomem (??:?)
[ 267.177532][ C0] acpi_os_map_memory (??:?)
[ 267.177532][ C0] acpi_tb_acquire_table (??:?)
[ 267.177532][ C0] acpi_tb_validate_table (??:?)
[ 267.177532][ C0] acpi_tb_validate_temp_table (??:?)
[ 267.177532][ C0] acpi_tb_verify_temp_table (??:?)
[ 267.177532][ C0] acpi_reallocate_root_table (??:?)
[ 267.177532][ C0] acpi_early_init (??:?)
[ 267.177532][ C0] start_kernel (??:?)
[ 267.177532][ C0] i386_start_kernel (??:?)
[ 267.177532][ C0] startup_32_smp (??:?)
[ 267.177532][ C0] irq event stamp: 3448
[ 267.177532][ C0] hardirqs last enabled at (3448): rcu_nocb_unlock_irqrestore+0xe/0x12
[ 267.177532][ C0] hardirqs last disabled at (3447): rcu_do_batch (tree.c:?)
[ 267.177532][ C0] softirqs last enabled at (3408): __do_softirq (??:?)
[ 267.177532][ C0] softirqs last disabled at (3433): do_softirq_own_stack (??:?)
[ 267.177532][ C0]
[ 267.177532][ C0] other info that might help us debug this:
[ 267.177532][ C0] Possible unsafe locking scenario:
[ 267.177532][ C0]
[ 267.177532][ C0] CPU0
[ 267.177532][ C0] ----
[ 267.177532][ C0] lock(vmap_area_lock);
[ 267.177532][ C0] <Interrupt>
[ 267.177532][ C0] lock(vmap_area_lock);
[ 267.177532][ C0]
[ 267.177532][ C0] *** DEADLOCK ***
[ 267.177532][ C0]
[ 267.177532][ C0] 1 lock held by swapper/0/0:
[ 267.177532][ C0] #0: c292b648 (rcu_callback){....}-{0:0}, at: rcu_lock_acquire (notifier.c:?)
[ 267.177532][ C0]
[ 267.177532][ C0] stack backtrace:
[ 267.177532][ C0] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 6.1.0-rc1-00115-g98ccdf3d8601 #1
[ 267.177532][ C0] Call Trace:
[ 267.177532][ C0] <SOFTIRQ>
[ 267.177532][ C0] dump_stack_lvl (??:?)
[ 267.177532][ C0] dump_stack (??:?)
[ 267.177532][ C0] print_usage_bug (lockdep.c:?)
[ 267.177532][ C0] valid_state (lockdep.c:?)
[ 267.177532][ C0] mark_lock_irq (lockdep.c:?)
[ 267.177532][ C0] ? save_trace (lockdep.c:?)
[ 267.177532][ C0] mark_lock+0xb5/0x107
[ 267.177532][ C0] mark_usage (lockdep.c:?)
[ 267.177532][ C0] __lock_acquire (lockdep.c:?)
[ 267.177532][ C0] ? find_vmap_area (??:?)
[ 267.177532][ C0] lock_acquire (??:?)
[ 267.177532][ C0] ? find_vmap_area (??:?)
[ 267.177532][ C0] ? rcu_gp_torture_wait (tree.c:?)
[ 267.177532][ C0] ? lock_acquire (??:?)
[ 267.177532][ C0] ? rcu_gp_torture_wait (tree.c:?)
[ 267.177532][ C0] _raw_spin_lock (??:?)
[ 267.177532][ C0] ? find_vmap_area (??:?)
[ 267.177532][ C0] find_vmap_area (??:?)
[ 267.177532][ C0] find_vm_area (??:?)
[ 267.177532][ C0] vmalloc_dump_obj (??:?)
[ 267.177532][ C0] mem_dump_obj (??:?)
[ 267.177532][ C0] rcu_do_batch (tree.c:?)
[ 267.177532][ C0] ? show_rcu_tasks_gp_kthreads (sync.c:?)
[ 267.177532][ C0] rcu_core (tree.c:?)
[ 267.177532][ C0] rcu_core_si (tree.c:?)
[ 267.177532][ C0] __do_softirq (??:?)
[ 267.177532][ C0] ? __entry_text_end (??:?)
[ 267.177532][ C0] do_softirq_own_stack (??:?)
[ 267.177532][ C0] </SOFTIRQ>
[ 267.177532][ C0] ? sysvec_call_function_single (??:?)
[ 267.177532][ C0] __irq_exit_rcu (softirq.c:?)
[ 267.177532][ C0] irq_exit_rcu (??:?)
[ 267.177532][ C0] sysvec_apic_timer_interrupt (??:?)
[ 267.177532][ C0] handle_exception (entry_32.o:?)
[ 267.177532][ C0] EIP: native_safe_halt (process.c:?)
[ 267.177532][ C0] Code: e8 bb 57 62 ff e8 96 be ff ff 8b 4d f8 89 d8 31 d2 e8 a9 0f b1 ff 5b 5b 5d c3 cc cc cc cc cc cc 55 89 e5 e8 27 b4 5d ff fb f4 <5d> c3 55 89 e5 e8 ec ff ff ff 5d c3 55 64 8b 0d 00 78 bb c2 89 e5
All code
========
0: e8 bb 57 62 ff callq 0xffffffffff6257c0
5: e8 96 be ff ff callq 0xffffffffffffbea0
a: 8b 4d f8 mov -0x8(%rbp),%ecx
d: 89 d8 mov %ebx,%eax
f: 31 d2 xor %edx,%edx
11: e8 a9 0f b1 ff callq 0xffffffffffb10fbf
16: 5b pop %rbx
17: 5b pop %rbx
18: 5d pop %rbp
19: c3 retq
1a: cc int3
1b: cc int3
1c: cc int3
1d: cc int3
1e: cc int3
1f: cc int3
20: 55 push %rbp
21: 89 e5 mov %esp,%ebp
23: e8 27 b4 5d ff callq 0xffffffffff5db44f
28: fb sti
29: f4 hlt
2a:* 5d pop %rbp <-- trapping instruction
2b: c3 retq
2c: 55 push %rbp
2d: 89 e5 mov %esp,%ebp
2f: e8 ec ff ff ff callq 0x20
34: 5d pop %rbp
35: c3 retq
36: 55 push %rbp
37: 64 8b 0d 00 78 bb c2 mov %fs:-0x3d448800(%rip),%ecx # 0xffffffffc2bb783e
3e: 89 e5 mov %esp,%ebp
Code starting with the faulting instruction
===========================================
0: 5d pop %rbp
1: c3 retq
2: 55 push %rbp
3: 89 e5 mov %esp,%ebp
5: e8 ec ff ff ff callq 0xfffffffffffffff6
a: 5d pop %rbp
b: c3 retq
c: 55 push %rbp
d: 64 8b 0d 00 78 bb c2 mov %fs:-0x3d448800(%rip),%ecx # 0xffffffffc2bb7814
14: 89 e5 mov %esp,%ebp
If you fix the issue, kindly add following tag
| Reported-by: kernel test robot <[email protected]>
| Link: https://lore.kernel.org/oe-lkp/[email protected]
To reproduce:
# build kernel
cd linux
cp config-6.1.0-rc1-00115-g98ccdf3d8601 .config
make HOSTCC=gcc-11 CC=gcc-11 ARCH=i386 olddefconfig prepare modules_prepare bzImage modules
make HOSTCC=gcc-11 CC=gcc-11 ARCH=i386 INSTALL_MOD_PATH=<mod-install-dir> modules_install
cd <mod-install-dir>
find lib/ | cpio -o -H newc --quiet | gzip > modules.cgz
git clone https://github.com/intel/lkp-tests.git
cd lkp-tests
bin/lkp qemu -k <bzImage> -m modules.cgz job-script # job-script is attached in this email
# if come across any failure that blocks the test,
# please remove ~/.lkp and /lkp dir to run from a clean state.
--
0-DAY CI Kernel Test Service
https://01.org/lkp