[bpf-next] bpf: Fix deadlock between rcu_tasks_trace and event_mutex.

Commit Message

Alexei Starovoitov Feb. 24, 2025, 10:16 p.m. UTC

From: Alexei Starovoitov <[e-mail]>

Fix the following deadlock:
CPU A
_free_event()
  perf_kprobe_destroy()
    mutex_lock(&event_mutex)
      perf_trace_event_unreg()
        synchronize_rcu_tasks_trace()

There are several paths where _free_event() grabs event_mutex
and calls sync_rcu_tasks_trace. Above is one such case.

CPU B
bpf_prog_test_run_syscall()
  rcu_read_lock_trace()
    bpf_prog_run_pin_on_cpu()
      bpf_prog_load()
        bpf_tracing_func_proto()
          trace_set_clr_event()
            mutex_lock(&event_mutex)

Delegate trace_set_clr_event() to workqueue to avoid
such lock dependency.

Signed-off-by: Alexei Starovoitov <[e-mail]>
---
 kernel/trace/bpf_trace.c | 7 ++++---
 1 file changed, 4 insertions(+), 3 deletions(-)

Comments

Andrii Nakryiko Feb. 25, 2025, 1:06 a.m. UTC | #1

On Mon, Feb 24, 2025 at 2:16 PM Alexei Starovoitov
<[e-mail]> wrote:
>
> From: Alexei Starovoitov <[e-mail]>
>
> Fix the following deadlock:
> CPU A
> _free_event()
>   perf_kprobe_destroy()
>     mutex_lock(&event_mutex)
>       perf_trace_event_unreg()
>         synchronize_rcu_tasks_trace()
>
> There are several paths where _free_event() grabs event_mutex
> and calls sync_rcu_tasks_trace. Above is one such case.
>
> CPU B
> bpf_prog_test_run_syscall()
>   rcu_read_lock_trace()
>     bpf_prog_run_pin_on_cpu()
>       bpf_prog_load()
>         bpf_tracing_func_proto()
>           trace_set_clr_event()
>             mutex_lock(&event_mutex)
>
> Delegate trace_set_clr_event() to workqueue to avoid
> such lock dependency.
>
> Signed-off-by: Alexei Starovoitov <[e-mail]>
> ---
>  kernel/trace/bpf_trace.c | 7 ++++---
>  1 file changed, 4 insertions(+), 3 deletions(-)
>

There is a tiny chance that bpf_printk() might not produce data (for a
little bit) if the time between program verification and its
triggering right after that is shorter than workqueue delay, right?
It's probably negligible in practice, so lgtm

Acked-by: Andrii Nakryiko <[e-mail]>

> diff --git a/kernel/trace/bpf_trace.c b/kernel/trace/bpf_trace.c
> index a612f6f182e5..13bef2462e94 100644
> --- a/kernel/trace/bpf_trace.c
> +++ b/kernel/trace/bpf_trace.c
> @@ -392,7 +392,7 @@ static const struct bpf_func_proto bpf_trace_printk_proto = {
>         .arg2_type      = ARG_CONST_SIZE,
>  };
>
> -static void __set_printk_clr_event(void)
> +static void __set_printk_clr_event(struct work_struct *work)
>  {
>         /*
>          * This program might be calling bpf_trace_printk,
> @@ -405,10 +405,11 @@ static void __set_printk_clr_event(void)
>         if (trace_set_clr_event("bpf_trace", "bpf_trace_printk", 1))
>                 pr_warn_ratelimited("could not enable bpf_trace_printk events");
>  }
> +static DECLARE_WORK(set_printk_work, __set_printk_clr_event);
>
>  const struct bpf_func_proto *bpf_get_trace_printk_proto(void)
>  {
> -       __set_printk_clr_event();
> +       schedule_work(&set_printk_work);
>         return &bpf_trace_printk_proto;
>  }
>
> @@ -451,7 +452,7 @@ static const struct bpf_func_proto bpf_trace_vprintk_proto = {
>
>  const struct bpf_func_proto *bpf_get_trace_vprintk_proto(void)
>  {
> -       __set_printk_clr_event();
> +       schedule_work(&set_printk_work);
>         return &bpf_trace_vprintk_proto;
>  }
>
> --
> 2.43.5
>

Alexei Starovoitov Feb. 25, 2025, 1:56 a.m. UTC | #2

On Mon, Feb 24, 2025 at 5:06 PM Andrii Nakryiko
<[e-mail]> wrote:
>
> On Mon, Feb 24, 2025 at 2:16 PM Alexei Starovoitov
> <[e-mail]> wrote:
> >
> > From: Alexei Starovoitov <[e-mail]>
> >
> > Fix the following deadlock:
> > CPU A
> > _free_event()
> >   perf_kprobe_destroy()
> >     mutex_lock(&event_mutex)
> >       perf_trace_event_unreg()
> >         synchronize_rcu_tasks_trace()
> >
> > There are several paths where _free_event() grabs event_mutex
> > and calls sync_rcu_tasks_trace. Above is one such case.
> >
> > CPU B
> > bpf_prog_test_run_syscall()
> >   rcu_read_lock_trace()
> >     bpf_prog_run_pin_on_cpu()
> >       bpf_prog_load()
> >         bpf_tracing_func_proto()
> >           trace_set_clr_event()
> >             mutex_lock(&event_mutex)
> >
> > Delegate trace_set_clr_event() to workqueue to avoid
> > such lock dependency.
> >
> > Signed-off-by: Alexei Starovoitov <[e-mail]>
> > ---
> >  kernel/trace/bpf_trace.c | 7 ++++---
> >  1 file changed, 4 insertions(+), 3 deletions(-)
> >
>
> There is a tiny chance that bpf_printk() might not produce data (for a
> little bit) if the time between program verification and its
> triggering right after that is shorter than workqueue delay, right?

yeah, but also see the comment in __set_printk_clr_event().
Unfortunately users can enable/disable this event at any time
just like other ftrace events.
The trace_bpf_trace_printk is fragile and racy.
In addition, trace_pipe can be configured in weird ways.
cat /sys/kernel/tracing/trace_pipe
will look nothing like normal.
All existing footgun warnings apply.

With Kumar we started discussing a new debug/printk mechanism.
So that arena faults, res_spin_lock timeous can be printed there
and consumed per program instead of global trace_pipe.

> It's probably negligible in practice, so lgtm
>
> Acked-by: Andrii Nakryiko <[e-mail]>
>
> > diff --git a/kernel/trace/bpf_trace.c b/kernel/trace/bpf_trace.c
> > index a612f6f182e5..13bef2462e94 100644
> > --- a/kernel/trace/bpf_trace.c
> > +++ b/kernel/trace/bpf_trace.c
> > @@ -392,7 +392,7 @@ static const struct bpf_func_proto bpf_trace_printk_proto = {
> >         .arg2_type      = ARG_CONST_SIZE,
> >  };
> >
> > -static void __set_printk_clr_event(void)
> > +static void __set_printk_clr_event(struct work_struct *work)
> >  {
> >         /*
> >          * This program might be calling bpf_trace_printk,
> > @@ -405,10 +405,11 @@ static void __set_printk_clr_event(void)
> >         if (trace_set_clr_event("bpf_trace", "bpf_trace_printk", 1))
> >                 pr_warn_ratelimited("could not enable bpf_trace_printk events");
> >  }
> > +static DECLARE_WORK(set_printk_work, __set_printk_clr_event);
> >
> >  const struct bpf_func_proto *bpf_get_trace_printk_proto(void)
> >  {
> > -       __set_printk_clr_event();
> > +       schedule_work(&set_printk_work);
> >         return &bpf_trace_printk_proto;
> >  }
> >
> > @@ -451,7 +452,7 @@ static const struct bpf_func_proto bpf_trace_vprintk_proto = {
> >
> >  const struct bpf_func_proto *bpf_get_trace_vprintk_proto(void)
> >  {
> > -       __set_printk_clr_event();
> > +       schedule_work(&set_printk_work);
> >         return &bpf_trace_vprintk_proto;
> >  }
> >
> > --
> > 2.43.5
> >

Patch

diff --git a/kernel/trace/bpf_trace.c b/kernel/trace/bpf_trace.c
index a612f6f182e5..13bef2462e94 100644
--- a/kernel/trace/bpf_trace.c
+++ b/kernel/trace/bpf_trace.c
@@ -392,7 +392,7 @@  static const struct bpf_func_proto bpf_trace_printk_proto = {
 	.arg2_type	= ARG_CONST_SIZE,
 };
 
-static void __set_printk_clr_event(void)
+static void __set_printk_clr_event(struct work_struct *work)
 {
 	/*
 	 * This program might be calling bpf_trace_printk,
@@ -405,10 +405,11 @@  static void __set_printk_clr_event(void)
 	if (trace_set_clr_event("bpf_trace", "bpf_trace_printk", 1))
 		pr_warn_ratelimited("could not enable bpf_trace_printk events");
 }
+static DECLARE_WORK(set_printk_work, __set_printk_clr_event);
 
 const struct bpf_func_proto *bpf_get_trace_printk_proto(void)
 {
-	__set_printk_clr_event();
+	schedule_work(&set_printk_work);
 	return &bpf_trace_printk_proto;
 }
 
@@ -451,7 +452,7 @@  static const struct bpf_func_proto bpf_trace_vprintk_proto = {
 
 const struct bpf_func_proto *bpf_get_trace_vprintk_proto(void)
 {
-	__set_printk_clr_event();
+	schedule_work(&set_printk_work);
 	return &bpf_trace_vprintk_proto;
 }