> On Aug 2, 2022, at 5:12 PM, Martin Lau <kafai@xxxxxx> wrote:
>
> On Tue, Aug 02, 2022 at 10:25:06PM +0000, Daniel Müller wrote:
>> Hi,
>>
>> I've seen the following deadlock warning when running the test_progs selftest:
>>
>> [ 127.404118] ============================================
>> [ 127.409306] WARNING: possible recursive locking detected
>> [ 127.414534] 5.19.0-rc8-02055-g43fe6c051c85 #257 Tainted: G OE
>> [ 127.421172] --------------------------------------------
>> [ 127.426256] test_progs/492 is trying to acquire lock:
>> [ 127.431356] ffff8ffe0d6c4bb8 (&storage->lock){+.-.}-{2:2}, at: __bpf_selem_unlink_storage+0x3a/0x150
>> [ 127.440305]
>> [ 127.440305] but task is already holding lock:
>> [ 127.445872] ffff8ffe0d6c4ab8 (&storage->lock){+.-.}-{2:2}, at: bpf_local_storage_update+0x31e/0x490
>> [ 127.454681]
>> [ 127.454681] other info that might help us debug this:
>> [ 127.461171] Possible unsafe locking scenario:
>> [ 127.461171]
>> [ 127.467377] CPU0
>> [ 127.469971] ----
>> [ 127.472497] lock(&storage->lock);
>> [ 127.475963] lock(&storage->lock);
>> [ 127.479391]
>> [ 127.479391] *** DEADLOCK ***
>> [ 127.479391]
>> [ 127.485434] May be due to missing lock nesting notation
>> [ 127.485434]
>> [ 127.492118] 3 locks held by test_progs/492:
>> [ 127.496484] #0: ffffffffbaf94b60 (rcu_read_lock_trace){....}-{0:0}, at: __bpf_prog_enter_sleepable+0x0/0xe0
>> [ 127.505888] #1: ffff8ffe0d6c4ab8 (&storage->lock){+.-.}-{2:2}, at: bpf_local_storage_update+0x31e/0x490
>> [ 127.514981] #2: ffffffffbaf957e0 (rcu_read_lock){....}-{1:2}, at: __bpf_prog_enter+0x0/0x100
>> [ 127.523310]
>> [ 127.523310] stack backtrace:
>> [ 127.527574] CPU: 7 PID: 492 Comm: test_progs Tainted: G OE 5.19.0-rc8-02055-g43fe6c051c85 #257
>> [ 127.536658] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.15.0-0-g2dd4b9b3f840-prebuilt.qemu.org 04/01/2014
>> [ 127.547462] Call Trace:
>> [ 127.549977] <TASK>
>> [ 127.552175] dump_stack_lvl+0x44/0x5b
>> [ 127.555758] __lock_acquire.cold.74+0x151/0x2aa
>> [ 127.560217] lock_acquire+0xc9/0x2f0
>> [ 127.563686] ? __bpf_selem_unlink_storage+0x3a/0x150
>> [ 127.568524] ? find_held_lock+0x2d/0xa0
>> [ 127.572378] _raw_spin_lock_irqsave+0x38/0x60
>> [ 127.576532] ? __bpf_selem_unlink_storage+0x3a/0x150
>> [ 127.581380] __bpf_selem_unlink_storage+0x3a/0x150
>> [ 127.586044] bpf_task_storage_delete+0x53/0xb0
>> [ 127.590385] bpf_prog_730e33528dbd2937_on_lookup+0x26/0x3d
>> [ 127.595673] bpf_trampoline_6442505865_0+0x47/0x1000
>> [ 127.600533] ? bpf_local_storage_update+0x250/0x490
>> [ 127.605253] bpf_local_storage_lookup+0x5/0x130
>> [ 127.609650] bpf_local_storage_update+0xf1/0x490
>> [ 127.614175] bpf_sk_storage_get+0xd3/0x130
>> [ 127.618126] bpf_prog_b4aaeb10c7178354_socket_bind+0x18e/0x297
>> [ 127.623815] bpf_trampoline_6442474456_1+0x5c/0x1000
>> [ 127.628591] bpf_lsm_socket_bind+0x5/0x10
>> [ 127.632476] security_socket_bind+0x30/0x50
>> [ 127.636755] __sys_bind+0xba/0xf0
>> [ 127.640113] ? ktime_get_coarse_real_ts64+0xb9/0xc0
>> [ 127.644910] ? lockdep_hardirqs_on+0x79/0x100
>> [ 127.649438] ? ktime_get_coarse_real_ts64+0xb9/0xc0
>> [ 127.654215] ? syscall_trace_enter.isra.16+0x157/0x200
>> [ 127.659255] __x64_sys_bind+0x16/0x20
>> [ 127.662894] do_syscall_64+0x3a/0x90
>> [ 127.666456] entry_SYSCALL_64_after_hwframe+0x63/0xcd
>> [ 127.671500] RIP: 0033:0x7fbba4b36ceb
>> [ 127.674982] Code: c3 48 8b 15 77 31 0c 00 f7 d8 64 89 02 b8 ff ff ff ff eb c2 66 2e 0f 1f 84 00 00 00 00 00 90 f3 0f 1e fa b8 31 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 8
>> [ 127.692457] RSP: 002b:00007fff4e9c9db8 EFLAGS: 00000206 ORIG_RAX: 0000000000000031
>> [ 127.699666] RAX: ffffffffffffffda RBX: 00007fbba5057000 RCX: 00007fbba4b36ceb
>> [ 127.706448] RDX: 000000000000001c RSI: 00007fff4e9c9e40 RDI: 0000000000000035
>> [ 127.713247] RBP: 00007fff4e9c9e00 R08: 0000000000000010 R09: 0000000000000000
>> [ 127.719938] R10: 0000000000000000 R11: 0000000000000206 R12: 000000000040d3a0
>> [ 127.726790] R13: 00007fff4e9ce330 R14: 0000000000000000 R15: 0000000000000000
>> [ 127.733820] </TASK>
>>
>> I am not entirely sure I am reading the call trace correctly (or whether it
>> really is all that accurate for that matter), but one way I could see a
>> recursive acquisition is if we first acquire the local_storage lock in
>> bpf_local_storage_update [0], then we call into bpf_local_storage_lookup in line
>> 439 (with the lock still held), and then attempt to acquire it again in line
>> 268.
> bpf_local_storage_lookup(..., cacheit_lockit = false) is called,
> so it won't acquire the lock again at line 268. Also, from the stack,
> it is two different locks. One is the sk storage lock and another is
> the task storage lock, so no dead lock.
>
>
> It is probably triggered when the "on_lookup" test (using the task storage)
> in task_ls_recursion.c is running in parallel with other sk/inode storage tests.
> Cc Song if he has insight on how to annotate lockdep in this case.
I think we can use lock_class_key to annotate these locks. There is some example
in hashtab.c (lockdep_set_class, lockdep_register_key, etc.).
Thanks,
Song
