TLDR: find_vmap_area can be called in irq context, e.g., soft lockup timer.
Somehow I only started hitting this recently. Hopefully somebody will
have a better idea than I do. Thanks.
>From mm-unstable-2022-09-02-23-35:
================================
WARNING: inconsistent lock state
6.0.0-dbg-DEV #1 Tainted: G S O
--------------------------------
inconsistent {HARDIRQ-ON-W} -> {IN-HARDIRQ-W} usage.
stress-ng/49028 [HC1[1]:SC0[0]:HE0:SE1] takes:
ffffffff9ec42d48 (vmap_area_lock){?.+.}-{2:2}, at: find_vmap_area+0x1b/0x70
{HARDIRQ-ON-W} state was registered at:
lock_acquire+0xb2/0x190
_raw_spin_lock+0x2f/0x40
alloc_vmap_area+0x6e2/0x7a0
__get_vm_area_node+0xe9/0x160
get_vm_area_caller+0x43/0x60
__ioremap_caller+0x205/0x300
ioremap_cache+0x17/0x20
acpi_os_map_iomem+0x12e/0x1d0
acpi_os_map_memory+0xe/0x10
acpi_tb_acquire_table+0x42/0x6e
acpi_tb_validate_temp_table+0x43/0x55
acpi_tb_verify_temp_table+0x31/0x240
acpi_reallocate_root_table+0xe4/0x156
acpi_early_init+0x4d/0xcd
start_kernel+0x320/0x43f
x86_64_start_reservations+0x24/0x26
x86_64_start_kernel+0x124/0x12b
secondary_startup_64_no_verify+0xe6/0xeb
irq event stamp: 1872092
hardirqs last enabled at (1872091): [<ffffffff9d90f8af>]
irqentry_exit+0x5f/0x80
hardirqs last disabled at (1872092): [<ffffffff9d90e71f>]
sysvec_apic_timer_interrupt+0xf/0x90
softirqs last enabled at (1870920): [<ffffffff9cd9c741>]
__irq_exit_rcu+0x91/0xf0
softirqs last disabled at (1870897): [<ffffffff9cd9c741>]
__irq_exit_rcu+0x91/0xf0
other info that might help us debug this:
Possible unsafe locking scenario:
CPU0
----
lock(vmap_area_lock);
<Interrupt>
lock(vmap_area_lock);
*** DEADLOCK ***
1 lock held by stress-ng/49028:
#0: ffff924f9cd5fa58 (&mm->mmap_lock#2){++++}-{3:3}, at:
do_mas_align_munmap+0x407/0x650
stack backtrace:
CPU: 95 PID: 49028 Comm: stress-ng Tainted: G S O
6.0.0-dbg-DEV #1
Call Trace:
<IRQ>
dump_stack_lvl+0x69/0xaa
dump_stack+0x10/0x12
print_usage_bug+0x336/0x340
mark_lock_irq+0x494/0x4a0
mark_lock+0x125/0x190
__lock_acquire+0x595/0x30d0
lock_acquire+0xb2/0x190
_raw_spin_lock+0x2f/0x40
find_vmap_area+0x1b/0x70
check_heap_object+0x23/0x2a0
__check_object_size+0x69/0x140
copy_from_user_nmi+0x53/0x80
show_opcodes+0xa6/0x120
show_iret_regs+0x36/0x60
__show_regs+0x27/0x2f0
show_regs_if_on_stack+0xde/0xf0
show_trace_log_lvl+0x276/0x400
show_regs+0x5d/0x60
watchdog_timer_fn+0x182/0x220
__hrtimer_run_queues+0x13b/0x220
hrtimer_interrupt+0xf1/0x380
__sysvec_apic_timer_interrupt+0x52/0xc0
sysvec_apic_timer_interrupt+0x71/0x90
</IRQ>
<TASK>
asm_sysvec_apic_timer_interrupt+0x1b/0x20
RIP: 0010:_raw_spin_unlock_irqrestore+0x3d/0x50
Code: 83 c7 18 48 8b 75 08 e8 71 6a 4f ff 48 89 df e8 39 c6 4f ff 41
f7 c6 00 02 00 00 74 06 e8 9b b9 5c ff fb 65 ff 0d 9b 60 70 62 <5b> 41
5e 5d c3 66 66 66 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44
RSP: 0018:ffffac87f76dbb28 EFLAGS: 00000246
RAX: a33534c87c735300 RBX: ffff9247c6b42050 RCX: 0000000000000001
RDX: 0000000000000007 RSI: ffff924e84aba198 RDI: ffffffff9d919ea5
RBP: ffffac87f76dbb38 R08: 0000000000000001 R09: 0000000000000001
R10: ffffffff9d08a070 R11: 0000000000000000 R12: 00000000000001ed
R13: ffff9247c6b42000 R14: 0000000000000286 R15: ffffe7151ae30240
release_pages+0x1af/0xaa0
free_pages_and_swap_cache+0x41/0x50
tlb_flush_mmu+0x136/0x180
tlb_finish_mmu+0x44/0x80
unmap_region+0x170/0x1a0
do_mas_align_munmap+0x445/0x650
do_mas_munmap+0xf3/0x110
__vm_munmap+0xd3/0x180
__x64_sys_munmap+0x1b/0x20
