MIME-Version: 1.0
References: <20230318132435.3671003-1-qiang1.zhang@intel.com>
In-Reply-To: <20230318132435.3671003-1-qiang1.zhang@intel.com>
From:   Joel Fernandes <joel@joelfernandes.org>
Date:   Sat, 18 Mar 2023 21:31:08 -0400
Message-ID: <CAEXW_YQ2xGuy4ebPjyVAp4SJQUo=Wr8uAw9BnUsjgvozzhuUeg@mail.gmail.com>
Subject: Re: [PATCH] rcu: Fix incorrect trace string in rcu_boost_kthread()
To:     Zqiang <qiang1.zhang@intel.com>
Cc:     paulmck@kernel.org, frederic@kernel.org, quic_neeraju@quicinc.com,
        rcu@vger.kernel.org, linux-kernel@vger.kernel.org,
        Steven Rostedt <rostedt@goodmis.org>
Content-Type: text/plain; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable
Precedence: bulk

On Sat, Mar 18, 2023 at 9:20=E2=80=AFAM Zqiang <qiang1.zhang@intel.com> wro=
te:
>
> Currently, the trace string information before and after rcu_wait()
> and schedule_timeout_idle() are reversed, this commit therefore
> switches these strings in order to correctly trace.

I suggest provide more details of how this affects your tracing. One
commit to draw inspiration from could be:

f7f7bac9cb1c ("rcu: Have the RCU tracepoints use the tracepoint_string
infrastructure")

Which also modifies the same code.

>
> Signed-off-by: Zqiang <qiang1.zhang@intel.com>
> ---
>  kernel/rcu/tree_plugin.h | 8 ++++----
>  1 file changed, 4 insertions(+), 4 deletions(-)
>
> 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")=
);

Doesn't that look weird because now you will have 2 "Start boost
kthread@" messages in succession (one of them coming before the for
loop) ?

>                 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);

Also, it is weird here that you are calling rcu_boost() right after
printing "End boost kthread".

thanks,

 - Joel


>                 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
>