| Message ID | 20230318132435.3671003-1-qiang1.zhang@intel.com (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
| Series | rcu: Fix incorrect trace string in rcu_boost_kthread() | expand |
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 >
> > 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 >
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 >
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; } }
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(-)