linux-kernel - Re: [PATCH v2] rcu: Fix some incorrect trace log in rcu

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Date:   Sun, 19 Mar 2023 22:53:13 -0400
From:   Joel Fernandes <joel@...lfernandes.org>
To:     Zqiang <qiang1.zhang@...el.com>
Cc:     paulmck@...nel.org, frederic@...nel.org, rcu@...r.kernel.org,
        linux-kernel@...r.kernel.org
Subject: Re: [PATCH v2] rcu: Fix some incorrect trace log in rcu_boost and
 rcuc kthreads

On Sun, Mar 19, 2023 at 10:39 PM Zqiang <qiang1.zhang@...el.com> wrote:
>
> In rcu_boost kthreads, before invoke rcu_wait(), the trace string
> should mark "Start boost kthread@..._wait", after rcu_wait() end,
> mark "End boost kthread@..._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@..._yield"));
schedule_timeout_idle(2);
trace_rcu_utilization(TPS("End CPU kthread@..._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@...el.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 == 0) {
> -                       trace_rcu_utilization(TPS("End CPU kthread@..._wait"));
> +                       trace_rcu_utilization(TPS("Start CPU kthread@..._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@...t"));
>         for (;;) {
>                 WRITE_ONCE(rnp->boost_kthread_status, RCU_KTHREAD_WAITING);
> -               trace_rcu_utilization(TPS("End boost kthread@..._wait"));
> +               trace_rcu_utilization(TPS("Start boost kthread@..._wait"));
>                 rcu_wait(READ_ONCE(rnp->boost_tasks) ||
>                          READ_ONCE(rnp->exp_tasks));
> -               trace_rcu_utilization(TPS("Start boost kthread@..._wait"));
> +               trace_rcu_utilization(TPS("End boost kthread@..._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@..._yield"));
> -                       schedule_timeout_idle(2);
>                         trace_rcu_utilization(TPS("Start boost kthread@..._yield"));
> +                       schedule_timeout_idle(2);
> +                       trace_rcu_utilization(TPS("End boost kthread@..._yield"));
>                         spincnt = 0;
>                 }
>         }
> --
> 2.25.1
>