Re: slow sync rcu_tasks_trace

[Jiri Olsa <jolsa@redhat.com>]

On Wed, Sep 09, 2020 at 04:38:58AM -0700, Paul E. McKenney wrote:
> On Tue, Sep 08, 2020 at 07:34:20PM -0700, Alexei Starovoitov wrote:
> > Hi Paul,
> > 
> > Looks like sync rcu_tasks_trace got slower or we simply didn't notice
> > it earlier.
> > 
> > In selftests/bpf try:
> > time ./test_progs -t trampoline_count
> > #101 trampoline_count:OK
> > Summary: 1/0 PASSED, 0 SKIPPED, 0 FAILED
> > 
> > real    1m17.082s
> > user    0m0.145s
> > sys    0m1.369s
> > 
> > But with the following hack:
> > diff --git a/kernel/bpf/trampoline.c b/kernel/bpf/trampoline.c
> > index 7dd523a7e32d..c417b817ec5d 100644
> > --- a/kernel/bpf/trampoline.c
> > +++ b/kernel/bpf/trampoline.c
> > @@ -217,7 +217,7 @@ static int bpf_trampoline_update(struct bpf_trampoline *tr)
> >          * programs finish executing.
> >          * Wait for these two grace periods together.
> >          */
> > -       synchronize_rcu_mult(call_rcu_tasks, call_rcu_tasks_trace);
> > +//     synchronize_rcu_mult(call_rcu_tasks, call_rcu_tasks_trace);
> > 
> > I see:
> > time ./test_progs -t trampoline_count
> > #101 trampoline_count:OK
> > Summary: 1/0 PASSED, 0 SKIPPED, 0 FAILED
> > 
> > real    0m1.588s
> > user    0m0.131s
> > sys    0m1.342s
> > 
> > It takes an extra minute to do 40 sync rcu_tasks_trace calls.
> > It means that every sync takes more than a second.
> > That feels excessive.
> > 
> > Doing:
> > -       synchronize_rcu_mult(call_rcu_tasks, call_rcu_tasks_trace);
> > +       synchronize_rcu();
> > is also fast:
> > time ./test_progs -t trampoline_count
> > #101 trampoline_count:OK
> > Summary: 1/0 PASSED, 0 SKIPPED, 0 FAILED
> > 
> > real    0m2.089s
> > user    0m0.139s
> > sys    0m1.282s
> > 
> > sync rcu_tasks() is fast too:
> > -       synchronize_rcu_mult(call_rcu_tasks, call_rcu_tasks_trace);
> > +       synchronize_rcu_tasks();
> > time ./test_progs -t trampoline_count
> > #101 trampoline_count:OK
> > Summary: 1/0 PASSED, 0 SKIPPED, 0 FAILED
> > 
> > real    0m2.209s
> > user    0m0.117s
> > sys    0m1.344s
> > 
> > so it's really something going on with sync rcu_tasks_trace.
> > Could you please take a look?
> 
> I am guessing that your .config has CONFIG_TASKS_TRACE_RCU_READ_MB=n.
> If I am wrong, please try CONFIG_TASKS_TRACE_RCU_READ_MB=y.

hi,
I noticed the slowdown as well, and adding CONFIG_TASKS_TRACE_RCU_READ_MB=y
speeds it up for me

thanks,
jirka

> 
> Otherwise (or alternatively), could you please try booting with
> rcupdate.rcu_task_ipi_delay=50?  The default value is 500, or half a
> second on a HZ=1000 system, which on a busy system could easily result
> in the grace-period delays that you are seeing.  The value of this
> kernel boot parameter does interact with the tasklist-scan backoffs,
> so its effect will not likely be linear.
> 
> Do either of those approaches help?
> 
> 							Thanx, Paul
>