Naveen reported recursive locking of direct_mutex with sample
ftrace-direct-modify.ko:
[ 74.762406] WARNING: possible recursive locking detected
[ 74.762887] 6.0.0-rc6+ #33 Not tainted
[ 74.763216] --------------------------------------------
[ 74.763672] event-sample-fn/1084 is trying to acquire lock:
[ 74.764152] ffffffff86c9d6b0 (direct_mutex){+.+.}-{3:3}, at: \
register_ftrace_function+0x1f/0x180
[ 74.764922]
[ 74.764922] but task is already holding lock:
[ 74.765421] ffffffff86c9d6b0 (direct_mutex){+.+.}-{3:3}, at: \
modify_ftrace_direct+0x34/0x1f0
[ 74.766142]
[ 74.766142] other info that might help us debug this:
[ 74.766701] Possible unsafe locking scenario:
[ 74.766701]
[ 74.767216] CPU0
[ 74.767437] ----
[ 74.767656] lock(direct_mutex);
[ 74.767952] lock(direct_mutex);
[ 74.768245]
[ 74.768245] *** DEADLOCK ***
[ 74.768245]
[ 74.768750] May be due to missing lock nesting notation
[ 74.768750]
[ 74.769332] 1 lock held by event-sample-fn/1084:
[ 74.769731] #0: ffffffff86c9d6b0 (direct_mutex){+.+.}-{3:3}, at: \
modify_ftrace_direct+0x34/0x1f0
[ 74.770496]
[ 74.770496] stack backtrace:
[ 74.770884] CPU: 4 PID: 1084 Comm: event-sample-fn Not tainted ...
[ 74.771498] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), ...
[ 74.772474] Call Trace:
[ 74.772696] <TASK>
[ 74.772896] dump_stack_lvl+0x44/0x5b
[ 74.773223] __lock_acquire.cold.74+0xac/0x2b7
[ 74.773616] lock_acquire+0xd2/0x310
[ 74.773936] ? register_ftrace_function+0x1f/0x180
[ 74.774357] ? lock_is_held_type+0xd8/0x130
[ 74.774744] ? my_tramp2+0x11/0x11 [ftrace_direct_modify]
[ 74.775213] __mutex_lock+0x99/0x1010
[ 74.775536] ? register_ftrace_function+0x1f/0x180
[ 74.775954] ? slab_free_freelist_hook.isra.43+0x115/0x160
[ 74.776424] ? ftrace_set_hash+0x195/0x220
[ 74.776779] ? register_ftrace_function+0x1f/0x180
[ 74.777194] ? kfree+0x3e1/0x440
[ 74.777482] ? my_tramp2+0x11/0x11 [ftrace_direct_modify]
[ 74.777941] ? __schedule+0xb40/0xb40
[ 74.778258] ? register_ftrace_function+0x1f/0x180
[ 74.778672] ? my_tramp1+0xf/0xf [ftrace_direct_modify]
[ 74.779128] register_ftrace_function+0x1f/0x180
[ 74.779527] ? ftrace_set_filter_ip+0x33/0x70
[ 74.779910] ? __schedule+0xb40/0xb40
[ 74.780231] ? my_tramp1+0xf/0xf [ftrace_direct_modify]
[ 74.780678] ? my_tramp2+0x11/0x11 [ftrace_direct_modify]
[ 74.781147] ftrace_modify_direct_caller+0x5b/0x90
[ 74.781563] ? 0xffffffffa0201000
[ 74.781859] ? my_tramp1+0xf/0xf [ftrace_direct_modify]
[ 74.782309] modify_ftrace_direct+0x1b2/0x1f0
[ 74.782690] ? __schedule+0xb40/0xb40
[ 74.783014] ? simple_thread+0x2a/0xb0 [ftrace_direct_modify]
[ 74.783508] ? __schedule+0xb40/0xb40
[ 74.783832] ? my_tramp2+0x11/0x11 [ftrace_direct_modify]
[ 74.784294] simple_thread+0x76/0xb0 [ftrace_direct_modify]
[ 74.784766] kthread+0xf5/0x120
[ 74.785052] ? kthread_complete_and_exit+0x20/0x20
[ 74.785464] ret_from_fork+0x22/0x30
[ 74.785781] </TASK>
Fix this by using register_ftrace_function_nolock in
ftrace_modify_direct_caller.
Fixes: 53cd885bc5c3 ("ftrace: Allow IPMODIFY and DIRECT ops on the same function")
Reported-and-tested-by: Naveen N. Rao <[email protected]>
Signed-off-by: Song Liu <[email protected]>
---
kernel/trace/ftrace.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
index 439e2ab6905e..d308d0674805 100644
--- a/kernel/trace/ftrace.c
+++ b/kernel/trace/ftrace.c
@@ -5461,7 +5461,7 @@ int __weak ftrace_modify_direct_caller(struct ftrace_func_entry *entry,
if (ret)
goto out_lock;
- ret = register_ftrace_function(&stub_ops);
+ ret = register_ftrace_function_nolock(&stub_ops);
if (ret) {
ftrace_set_filter_ip(&stub_ops, ip, 1, 0);
goto out_lock;
--
2.30.2
Hi Steven,
Does this fix make sense to you?
Thanks,
Song
On Mon, Sep 19, 2022 at 10:30 AM Song Liu <[email protected]> wrote:
>
> Naveen reported recursive locking of direct_mutex with sample
> ftrace-direct-modify.ko:
>
> [ 74.762406] WARNING: possible recursive locking detected
> [ 74.762887] 6.0.0-rc6+ #33 Not tainted
> [ 74.763216] --------------------------------------------
> [ 74.763672] event-sample-fn/1084 is trying to acquire lock:
> [ 74.764152] ffffffff86c9d6b0 (direct_mutex){+.+.}-{3:3}, at: \
> register_ftrace_function+0x1f/0x180
> [ 74.764922]
> [ 74.764922] but task is already holding lock:
> [ 74.765421] ffffffff86c9d6b0 (direct_mutex){+.+.}-{3:3}, at: \
> modify_ftrace_direct+0x34/0x1f0
> [ 74.766142]
> [ 74.766142] other info that might help us debug this:
> [ 74.766701] Possible unsafe locking scenario:
> [ 74.766701]
> [ 74.767216] CPU0
> [ 74.767437] ----
> [ 74.767656] lock(direct_mutex);
> [ 74.767952] lock(direct_mutex);
> [ 74.768245]
> [ 74.768245] *** DEADLOCK ***
> [ 74.768245]
> [ 74.768750] May be due to missing lock nesting notation
> [ 74.768750]
> [ 74.769332] 1 lock held by event-sample-fn/1084:
> [ 74.769731] #0: ffffffff86c9d6b0 (direct_mutex){+.+.}-{3:3}, at: \
> modify_ftrace_direct+0x34/0x1f0
> [ 74.770496]
> [ 74.770496] stack backtrace:
> [ 74.770884] CPU: 4 PID: 1084 Comm: event-sample-fn Not tainted ...
> [ 74.771498] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), ...
> [ 74.772474] Call Trace:
> [ 74.772696] <TASK>
> [ 74.772896] dump_stack_lvl+0x44/0x5b
> [ 74.773223] __lock_acquire.cold.74+0xac/0x2b7
> [ 74.773616] lock_acquire+0xd2/0x310
> [ 74.773936] ? register_ftrace_function+0x1f/0x180
> [ 74.774357] ? lock_is_held_type+0xd8/0x130
> [ 74.774744] ? my_tramp2+0x11/0x11 [ftrace_direct_modify]
> [ 74.775213] __mutex_lock+0x99/0x1010
> [ 74.775536] ? register_ftrace_function+0x1f/0x180
> [ 74.775954] ? slab_free_freelist_hook.isra.43+0x115/0x160
> [ 74.776424] ? ftrace_set_hash+0x195/0x220
> [ 74.776779] ? register_ftrace_function+0x1f/0x180
> [ 74.777194] ? kfree+0x3e1/0x440
> [ 74.777482] ? my_tramp2+0x11/0x11 [ftrace_direct_modify]
> [ 74.777941] ? __schedule+0xb40/0xb40
> [ 74.778258] ? register_ftrace_function+0x1f/0x180
> [ 74.778672] ? my_tramp1+0xf/0xf [ftrace_direct_modify]
> [ 74.779128] register_ftrace_function+0x1f/0x180
> [ 74.779527] ? ftrace_set_filter_ip+0x33/0x70
> [ 74.779910] ? __schedule+0xb40/0xb40
> [ 74.780231] ? my_tramp1+0xf/0xf [ftrace_direct_modify]
> [ 74.780678] ? my_tramp2+0x11/0x11 [ftrace_direct_modify]
> [ 74.781147] ftrace_modify_direct_caller+0x5b/0x90
> [ 74.781563] ? 0xffffffffa0201000
> [ 74.781859] ? my_tramp1+0xf/0xf [ftrace_direct_modify]
> [ 74.782309] modify_ftrace_direct+0x1b2/0x1f0
> [ 74.782690] ? __schedule+0xb40/0xb40
> [ 74.783014] ? simple_thread+0x2a/0xb0 [ftrace_direct_modify]
> [ 74.783508] ? __schedule+0xb40/0xb40
> [ 74.783832] ? my_tramp2+0x11/0x11 [ftrace_direct_modify]
> [ 74.784294] simple_thread+0x76/0xb0 [ftrace_direct_modify]
> [ 74.784766] kthread+0xf5/0x120
> [ 74.785052] ? kthread_complete_and_exit+0x20/0x20
> [ 74.785464] ret_from_fork+0x22/0x30
> [ 74.785781] </TASK>
>
> Fix this by using register_ftrace_function_nolock in
> ftrace_modify_direct_caller.
>
> Fixes: 53cd885bc5c3 ("ftrace: Allow IPMODIFY and DIRECT ops on the same function")
> Reported-and-tested-by: Naveen N. Rao <[email protected]>
> Signed-off-by: Song Liu <[email protected]>
> ---
> kernel/trace/ftrace.c | 2 +-
> 1 file changed, 1 insertion(+), 1 deletion(-)
>
> diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
> index 439e2ab6905e..d308d0674805 100644
> --- a/kernel/trace/ftrace.c
> +++ b/kernel/trace/ftrace.c
> @@ -5461,7 +5461,7 @@ int __weak ftrace_modify_direct_caller(struct ftrace_func_entry *entry,
> if (ret)
> goto out_lock;
>
> - ret = register_ftrace_function(&stub_ops);
> + ret = register_ftrace_function_nolock(&stub_ops);
> if (ret) {
> ftrace_set_filter_ip(&stub_ops, ip, 1, 0);
> goto out_lock;
> --
> 2.30.2
>
On Mon, 19 Sep 2022 10:29:55 -0700
Song Liu <[email protected]> wrote:
> diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
> index 439e2ab6905e..d308d0674805 100644
> --- a/kernel/trace/ftrace.c
> +++ b/kernel/trace/ftrace.c
> @@ -5461,7 +5461,7 @@ int __weak ftrace_modify_direct_caller(struct ftrace_func_entry *entry,
> if (ret)
> goto out_lock;
>
> - ret = register_ftrace_function(&stub_ops);
> + ret = register_ftrace_function_nolock(&stub_ops);
> if (ret) {
> ftrace_set_filter_ip(&stub_ops, ip, 1, 0);
> goto out_lock;
> --
We need to update the comments to this function, as well add an:
#define lock_direct_assert_held() lockdep_assert_held(&direct_mutex);
And call that in this function. Otherwise, we can be calling this code
without it held and cause races.
-- Steve