Re: lockdep splat for acpi power meter

[Guenter Roeck]

On Wed, Feb 19, 2020 at 09:15:28AM +0000, Damien Le Moal wrote:
> Jean, Guenter,
> 
> I am getting the following lockdep splat on boot since 5.5-rc1 (my
> apologies for not signaling this earlier). I do not see this with 5.4
> and as of 5.6-rc2, it still shows up 100% of the time on boot.
> 
I think this is a real problem. I am not sure though what makes it
appear now; there have been no interesting changes in the acpi
code or in the hwmon driver. There _have_ been some locking related
changes in kernfs, though. I don't know if those changes cause the
problem, or if they expose it.

Either case, the acpi_power_meter driver locks its resources, then
removes and re-creates all its attributes (which requires a kernfs
lock). At the same time, if an attribute is read, the same lock
is acquired by kernfs, then the driver locks its resources. Perfect
deadlock.

I may be missing something, but I think this entire code is broken.
Not only deletes and re-creates it all attributes while the hwmon
driver is active, it also releases and re-creates various strings
while potentially accessing those very same strings ... without
any locking. This is just asking for trouble.

We can (try to) work around the lockdep splat, but I don't think
that will solve all the problems. Jean, any thoughts ?

Guenter

> If you are not the right persons to look into this, please let me know.
> Thanks !
> 
> [   64.145761] ======================================================
> [   64.152295] WARNING: possible circular locking dependency detected
> [   64.158850] 5.6.0-rc2+ #629 Not tainted
> [   64.158851] ------------------------------------------------------
> [   64.158854] python/1397 is trying to acquire lock:
> [   64.177039] ffff888619080070 (&resource->lock){+.+.}, at:
> show_power+0x3c/0xa0 [acpi_power_meter]
> [   64.177050] 
>                but task is already holding lock:
> [   64.177050] ffff88881643f188 (kn->count#119){++++}, at:
> kernfs_seq_start+0x6a/0x160
> [   64.177058] 
>                which lock already depends on the new lock.
> 
> [   64.177058] 
>                the existing dependency chain (in reverse order) is:
> [   64.177059] 
>                -> #1 (kn->count#119){++++}:
> [   64.177066]        __kernfs_remove+0x626/0x7e0
> [   64.177068]        kernfs_remove_by_name_ns+0x41/0x80
> [   64.177070]        remove_attrs+0xcb/0x3c0 [acpi_power_meter]
> [   64.177073]        acpi_power_meter_notify+0x1f7/0x310
> [acpi_power_meter]
> [   64.177078]        acpi_ev_notify_dispatch+0x198/0x1f3
> [   64.177081]        acpi_os_execute_deferred+0x4d/0x70
> [   64.177085]        process_one_work+0x7c8/0x1340
> [   64.177087]        worker_thread+0x94/0xc70
> [   64.177089]        kthread+0x2ed/0x3f0
> [   64.177094]        ret_from_fork+0x24/0x30
> [   64.177094] 
>                -> #0 (&resource->lock){+.+.}:
> [   64.177100]        __lock_acquire+0x20be/0x49b0
> [   64.177101]        lock_acquire+0x127/0x340
> [   64.177104]        __mutex_lock+0x15b/0x1350
> [   64.177106]        show_power+0x3c/0xa0 [acpi_power_meter]
> [   64.177110]        dev_attr_show+0x3f/0x80
> [   64.177112]        sysfs_kf_seq_show+0x216/0x410
> [   64.177114]        seq_read+0x407/0xf90
> [   64.177119]        vfs_read+0x152/0x2c0
> [   64.177121]        ksys_read+0xf3/0x1d0
> [   64.177125]        do_syscall_64+0x95/0x1010
> [   64.177127]        entry_SYSCALL_64_after_hwframe+0x49/0xbe
> [   64.177128] 
>                other info that might help us debug this:
> 
> [   64.177129]  Possible unsafe locking scenario:
> 
> [   64.177130]        CPU0                    CPU1
> [   64.177130]        ----                    ----
> [   64.177131]   lock(kn->count#119);
> [   64.177132]                                lock(&resource->lock);
> [   64.177134]                                lock(kn->count#119);
> [   64.177135]   lock(&resource->lock);
> [   64.177137] 
>                 *** DEADLOCK ***
> [   64.177138] 4 locks held by python/1397:
> [   64.177139]  #0: ffff8890242d64e0 (&f->f_pos_lock){+.+.}, at:
> __fdget_pos+0x9b/0xb0
> [   64.177145]  #1: ffff889040be74e0 (&p->lock){+.+.}, at:
> seq_read+0x6b/0xf90
> [   64.177148]  #2: ffff8890448eb880 (&of->mutex){+.+.}, at:
> kernfs_seq_start+0x47/0x160
> [   64.177151]  #3: ffff88881643f188 (kn->count#119){++++}, at:
> kernfs_seq_start+0x6a/0x160
> [   64.177155] 
>                stack backtrace:
> [   64.177158] CPU: 10 PID: 1397 Comm: python Not tainted 5.6.0-rc2+
> #629
> [   64.177159] Hardware name: Supermicro Super Server/X11DPL-i, BIOS
> 3.1 05/21/2019
> [   64.177160] Call Trace:
> [   64.177167]  dump_stack+0x97/0xe0
> [   64.177170]  check_noncircular+0x32e/0x3e0
> [   64.177172]  ? print_circular_bug.isra.0+0x1e0/0x1e0
> [   64.177177]  ? unwind_next_frame+0xb9a/0x1890
> [   64.177180]  ? entry_SYSCALL_64_after_hwframe+0x49/0xbe
> [   64.177182]  ? graph_lock+0x79/0x170
> [   64.177183]  ? __lockdep_reset_lock+0x3c0/0x3c0
> [   64.177185]  ? mark_lock+0xbc/0x1150
> [   64.177187]  __lock_acquire+0x20be/0x49b0
> [   64.177190]  ? mark_held_locks+0xe0/0xe0
> [   64.177194]  ? stack_trace_save+0x91/0xc0
> [   64.177196]  lock_acquire+0x127/0x340
> [   64.177199]  ? show_power+0x3c/0xa0 [acpi_power_meter]
> [   64.177201]  ? device_remove_bin_file+0x10/0x10
> [   64.177203]  ? device_remove_bin_file+0x10/0x10
> [   64.177205]  __mutex_lock+0x15b/0x1350
> [   64.177208]  ? show_power+0x3c/0xa0 [acpi_power_meter]
> [   64.177210]  ? show_power+0x3c/0xa0 [acpi_power_meter]
> [   64.177212]  ? mutex_lock_io_nested+0x11f0/0x11f0
> [   64.177214]  ? lock_downgrade+0x6a0/0x6a0
> [   64.177216]  ? kernfs_seq_start+0x47/0x160
> [   64.177218]  ? lock_acquire+0x127/0x340
> [   64.177219]  ? kernfs_seq_start+0x6a/0x160
> [   64.177222]  ? device_remove_bin_file+0x10/0x10
> [   64.177226]  ? show_power+0x3c/0xa0 [acpi_power_meter]
> [   64.572676]  show_power+0x3c/0xa0 [acpi_power_meter]
> [   64.572681]  dev_attr_show+0x3f/0x80
> [   64.581931]  ? memset+0x20/0x40
> [   64.581935]  sysfs_kf_seq_show+0x216/0x410
> [   64.581938]  seq_read+0x407/0xf90
> [   64.581943]  ? security_file_permission+0x16f/0x2c0
> [   64.581948]  vfs_read+0x152/0x2c0
> [   64.581951]  ksys_read+0xf3/0x1d0
> [   64.581954]  ? kernel_write+0x120/0x120
> [   64.581957]  ? filp_open+0x50/0x50
> [   64.581962]  do_syscall_64+0x95/0x1010
> [   64.581967]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
> [   64.581971] RIP: 0033:0x7fbb4e2c644c
> [   64.581974] Code: ec 28 48 89 54 24 18 48 89 74 24 10 89 7c 24 08 e8
> d9 49 f9 ff 48 8b 54 24 18 48 8b 74 24 10 41 89 c0 8b 7c 24 08 31 c0 0f
> 05 <48> 3d 00 f0 ff ff 77 30 44 89 c7 48 89 44 24 08 e8 0f 4a f9 ff 48
> [   64.581976] RSP: 002b:00007ffe30d33400 EFLAGS: 00000246 ORIG_RAX:
> 0000000000000000
> [   64.581979] RAX: ffffffffffffffda RBX: 00005569d016e1e0 RCX:
> 00007fbb4e2c644c
> [   64.581980] RDX: 0000000000001000 RSI: 00005569d0222970 RDI:
> 0000000000000003
> [   64.581982] RBP: 00007fbb4e398300 R08: 0000000000000000 R09:
> 00007fbb4e397190
> [   64.581984] R10: 0000000000000000 R11: 0000000000000246 R12:
> 00005569d016e1e0
> [   64.581985] R13: 00007fbb4e397700 R14: 0000000000000d68 R15:
> 0000000000000d68
> 
> 
> -- 
> Damien Le Moal
> Western Digital Research