1. Patchew
  2. linux
  3. View series

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

Zqiang posted 1 patch 1 year, 1 month ago 
kernel/rcu/tree_plugin.h | 8 ++++----
1 file changed, 4 insertions(+), 4 deletions(-)
[PATCH] rcu: Fix incorrect trace string in rcu_boost_kthread()
Posted by Zqiang 1 year, 1 month ago 
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 <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"));
 		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
Re: [PATCH] rcu: Fix incorrect trace string in rcu_boost_kthread()
Posted by Joel Fernandes 1 year, 1 month ago 
On Sat, Mar 18, 2023 at 9:20 AM Zqiang <qiang1.zhang@intel.com> 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 <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 = 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
>
RE: [PATCH] rcu: Fix incorrect trace string in rcu_boost_kthread()
Posted by Zhang, Qiang1 1 year, 1 month ago 
On Sat, Mar 18, 2023 at 9:20 AM Zqiang <qiang1.zhang@intel.com> 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 <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 = 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
>
RE: [PATCH] rcu: Fix incorrect trace string in rcu_boost_kthread()
Posted by Zhang, Qiang1 1 year, 1 month ago 
>
> 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 = 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
>

Patchew 2.1-devel-0870f84

© 2016 - 2024 Red Hat, Inc.