MIME-Version: 1.0
References: <20230320024341.3956543-1-qiang1.zhang@intel.com>
In-Reply-To: <20230320024341.3956543-1-qiang1.zhang@intel.com>
From:   Joel Fernandes <joel@joelfernandes.org>
Date:   Sun, 19 Mar 2023 22:53:13 -0400
Message-ID: <CAEXW_YTMVF4qhFya5kW=xi5pLGd_gb_n-ZA+8+41iaG1S4YdMg@mail.gmail.com>
Subject: Re: [PATCH v2] rcu: Fix some incorrect trace log in rcu_boost and
 rcuc kthreads
To:     Zqiang <qiang1.zhang@intel.com>
Cc:     paulmck@kernel.org, frederic@kernel.org, rcu@vger.kernel.org,
        linux-kernel@vger.kernel.org
Content-Type: text/plain; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable
Precedence: bulk

On Sun, Mar 19, 2023 at 10:39=E2=80=AFPM Zqiang <qiang1.zhang@intel.com> wr=
ote:
>
> 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 =3D 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 =3D 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@intel.com>
> ---
>  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 =3D=3D 0) {
> -                       trace_rcu_utilization(TPS("End CPU kthread@rcu_wa=
it"));
> +                       trace_rcu_utilization(TPS("Start CPU kthread@rcu_=
wait"));
>                         *statusp =3D 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")=
);
>                 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 =3D rcu_boost(rnp);
>                 if (more2boost)
> @@ -1126,9 +1126,9 @@ static int rcu_boost_kthread(void *arg)
>                         spincnt =3D 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@rc=
u_yield"));
> +                       schedule_timeout_idle(2);
> +                       trace_rcu_utilization(TPS("End boost kthread@rcu_=
yield"));
>                         spincnt =3D 0;
>                 }
>         }
> --
> 2.25.1
>