2023-03-18 13:20:04

by Zqiang

Subject: [PATCH] rcu: Fix incorrect trace string in rcu_boost_kthread()

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.

Signed-off-by: Zqiang <[email protected]>
---
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"));
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

2023-03-19 01:31:26

by Joel Fernandes

Subject: Re: [PATCH] rcu: Fix incorrect trace string in rcu_boost_kthread()

On Sat, Mar 18, 2023 at 9:20 AM Zqiang <[email protected]> wrote:
>
> 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 <[email protected]>
> ---
> 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 = 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 = 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
>

2023-03-19 01:49:51

by Zqiang

Subject: RE: [PATCH] rcu: Fix incorrect trace string in rcu_boost_kthread()

>
> 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 <[email protected]>
> ---
> 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 = rcu_boost(rnp);
>
>Also, it is weird here that you are calling rcu_boost() right after
>printing "End boost kthread".
>

Hi Joel

Shouldn't that be the normal logic? Or I misunderstood?

trace_rcu_utilization(TPS("Start boost kthread@rcu_wait")); //start wait
rcu_wait();
trace_rcu_utilization(TPS("End boost kthread@rcu_wait")); // end wait

Thanks
Zqiang


>thanks,
>
>- Joel
>
>
>
> 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
>

2023-03-19 02:03:52

by Zqiang

Subject: RE: [PATCH] rcu: Fix incorrect trace string in rcu_boost_kthread()

On Sat, Mar 18, 2023 at 9:20 AM Zqiang <[email protected]> wrote:
>
> 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 <[email protected]>
> ---
> 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 = rcu_boost(rnp);
>
>Also, it is weird here that you are calling rcu_boost() right after
>printing "End boost kthread".


The trace I understand should be like this:

rcu_boost_kthread()
{
trace_rcu_utilization(TPS("Start boost kthread@init"));

for (;;) {
trace_rcu_utilization(TPS("Start boost kthread@rcu_wait"));
rcu_wait();
trace_rcu_utilization(TPS("End boost kthread@rcu_wait"));

rcu_boost()

trace_rcu_utilization(TPS("Start boost kthread@rcu_yield"));
schedule_timeout_idle(2);
trace_rcu_utilization(TPS("End boost kthread@rcu_yield"));
}

}

Thanks
Zqiang



>
>thanks,
>
> - Joel
>
>
>
> 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
>