vmap_area_lock lockdep warning

vmap_area_lock lockdep warning

[Yu Zhao]

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

Re: vmap_area_lock lockdep warning

[Andrew Morton]

On Sat, 3 Sep 2022 13:40:59 -0600 Yu Zhao <yuzhao@google.com> wrote:

> 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.

Thanks.

> 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

copy_from_user_nmi() is such a specialized, low-level thing and needs
to be robust against whatever else is going on.  How about making it
directly call raw_copy_from_user()?