RE: [PATCH v2] rcu: Fix some incorrect trace log in rcu_boost and rcuc kthreads

[Zhang, Qiang1]

>On Sun, Mar 19, 2023 at 10:39 PM Zqiang <qiang1.zhang@xxxxxxxxx> wrote:
>
> In rcu_boost kthreads, before invoke rcu_wait(), the trace string
> should mark "Start boost kthread@rcu_wait", after rcu_wait() end,
> mark "End boost kthread@rcu_wait". for boost kthread enter idle
> state, the trace should also do same.
> In rcuc kthreads, when the rcu_cpu_has_work is set zero, indicates
> that there are no works to process, the rcuc kthreads will enter
> waiting state, so the trace string should mark "Start @rcu_wait".
>
>Nope. Unfortunately, in this hard to read change log, you are making
>the "Start @rcu_wait" up.
>
>The trace clearly says "Start boost kthread @...",
>
>So first of all, don't make things up please based on imagination. Let
>us go by the actual trace message precisely and not skip important
>words in it.
>
>Now, an interpretation of the trace might be , we print a "Start"
>whenever the thread is RUNNING and "End" whenever the thread is
>SLEEPING. That makes much more sense so the existing code for the
>boost kthread is already correct.
>
>However, I did notice this bit of code in tree.c might have been
>causing confusion:
>
>*statusp = RCU_KTHREAD_YIELDING;
>trace_rcu_utilization(TPS("Start CPU kthread@rcu_yield"));
>schedule_timeout_idle(2);
>trace_rcu_utilization(TPS("End CPU kthread@rcu_yield"));
>*statusp = RCU_KTHREAD_WAITING;
>
>So perhaps a proper fix might be - in this fragment the Start and End
>should be swapped instead.
>
>thanks,
>
> - Joel
>
>
>
> Signed-off-by: Zqiang <qiang1.zhang@xxxxxxxxx>
> ---
>  kernel/rcu/tree.c        | 2 +-
>  kernel/rcu/tree_plugin.h | 8 ++++----
>  2 files changed, 5 insertions(+), 5 deletions(-)
>
> diff --git a/kernel/rcu/tree.c b/kernel/rcu/tree.c
> index 734c252c1e80..c1915408796f 100644
> --- a/kernel/rcu/tree.c
> +++ b/kernel/rcu/tree.c
> @@ -2465,7 +2465,7 @@ static void rcu_cpu_kthread(unsigned int cpu)
>                         rcu_core();
>                 local_bh_enable();
>                 if (*workp == 0) {
> -                       trace_rcu_utilization(TPS("End CPU kthread@rcu_wait"));
> +                       trace_rcu_utilization(TPS("Start CPU kthread@rcu_wait"));
>                         *statusp = RCU_KTHREAD_WAITING;
>                         return;
>                 }
> diff --git a/kernel/rcu/tree_plugin.h b/kernel/rcu/tree_plugin.h
> index 7b0fe741a088..7b622b5196a8 100644
> --- a/kernel/rcu/tree_plugin.h
> +++ b/kernel/rcu/tree_plugin.h
> @@ -1114,10 +1114,10 @@ static int rcu_boost_kthread(void *arg)
>         trace_rcu_utilization(TPS("Start boost kthread@init"));
>         for (;;) {
>                 WRITE_ONCE(rnp->boost_kthread_status, RCU_KTHREAD_WAITING);
> -               trace_rcu_utilization(TPS("End boost kthread@rcu_wait"));
> +               trace_rcu_utilization(TPS("Start boost kthread@rcu_wait"));

Hi Joel,

Sorry now I understand what you mean, the start you describe is for boost kthread, 
and the start I describe is for rcu_wait().  

Thanks
Zqiang


>                 rcu_wait(READ_ONCE(rnp->boost_tasks) ||
>                          READ_ONCE(rnp->exp_tasks));
> -               trace_rcu_utilization(TPS("Start boost kthread@rcu_wait"));
> +               trace_rcu_utilization(TPS("End boost kthread@rcu_wait"));
>                 WRITE_ONCE(rnp->boost_kthread_status, RCU_KTHREAD_RUNNING);
>                 more2boost = rcu_boost(rnp);
>                 if (more2boost)
> @@ -1126,9 +1126,9 @@ static int rcu_boost_kthread(void *arg)
>                         spincnt = 0;
>                 if (spincnt > 10) {
>                         WRITE_ONCE(rnp->boost_kthread_status, RCU_KTHREAD_YIELDING);
> -                       trace_rcu_utilization(TPS("End boost kthread@rcu_yield"));
> -                       schedule_timeout_idle(2);
>                         trace_rcu_utilization(TPS("Start boost kthread@rcu_yield"));
> +                       schedule_timeout_idle(2);
> +                       trace_rcu_utilization(TPS("End boost kthread@rcu_yield"));
>                         spincnt = 0;
>                 }
>         }
> --
> 2.25.1
>