2023-12-01 20:49:24

by Steven Rostedt

[permalink] [raw]
Subject: [RCU] rcu_tasks_trace_qs(): trc_reader_special.b.need_qs value incorrect likely()?

Paul,

I just started running my branch tracer (that checks all branches and also
gives likely and unlikely correctness). And I found this:

correct incorrect % Function File Line
------- --------- - -------- ---- ----
0 1217713 100 rcu_softirq_qs tree.c 247

Which comes down to this:


# define rcu_tasks_trace_qs(t) \
do { \
int ___rttq_nesting = READ_ONCE((t)->trc_reader_nesting); \
\
if (likely(!READ_ONCE((t)->trc_reader_special.b.need_qs)) && \
likely(!___rttq_nesting)) { \
rcu_trc_cmpxchg_need_qs((t), 0, TRC_NEED_QS_CHECKED); \
} else if (___rttq_nesting && ___rttq_nesting != INT_MIN && \
!READ_ONCE((t)->trc_reader_special.b.blocked)) { \
rcu_tasks_trace_qs_blkd(t); \
} \
} while (0)


I added just before the likely/unlikely to my test box and I see this:

trace_printk("need qs? %d %d\n", READ_ONCE((t)->trc_reader_special.b.need_qs), ___rttq_nesting); \

<idle>-0 [005] d.h1. 2.482412: rcu_sched_clock_irq: need qs? 2 0
<idle>-0 [002] d.h1. 2.482464: rcu_sched_clock_irq: need qs? 2 0
<idle>-0 [000] d.h1. 2.482766: rcu_sched_clock_irq: need qs? 2 0
<idle>-0 [001] d.h1. 2.482951: rcu_sched_clock_irq: need qs? 2 0
<idle>-0 [007] d.h1. 2.482958: rcu_sched_clock_irq: need qs? 2 0
<idle>-0 [005] d.h1. 2.483600: rcu_sched_clock_irq: need qs? 2 0
<idle>-0 [002] d.h1. 2.483624: rcu_sched_clock_irq: need qs? 2 0
<idle>-0 [000] d.h1. 2.483927: rcu_sched_clock_irq: need qs? 2 0
<idle>-0 [007] d.h1. 2.484068: rcu_sched_clock_irq: need qs? 2 0
<idle>-0 [001] d.h1. 2.484127: rcu_sched_clock_irq: need qs? 2 0
<idle>-0 [002] d.h1. 2.484723: rcu_sched_clock_irq: need qs? 2 0
<idle>-0 [005] d.h1. 2.484745: rcu_sched_clock_irq: need qs? 2 0
<idle>-0 [000] d.h1. 2.485015: rcu_sched_clock_irq: need qs? 2 0
<idle>-0 [007] d.h1. 2.485202: rcu_sched_clock_irq: need qs? 2 0
<idle>-0 [001] d.h1. 2.485258: rcu_sched_clock_irq: need qs? 2 0
<idle>-0 [002] d.h1. 2.485818: rcu_sched_clock_irq: need qs? 2 0
<idle>-0 [005] d.h1. 2.485929: rcu_sched_clock_irq: need qs? 2 0
<idle>-0 [000] d.h1. 2.486224: rcu_sched_clock_irq: need qs? 2 0
<idle>-0 [007] d.h1. 2.486370: rcu_sched_clock_irq: need qs? 2 0
<idle>-0 [001] d.h1. 2.486399: rcu_sched_clock_irq: need qs? 2 0
<idle>-0 [002] d.h1. 2.486895: rcu_sched_clock_irq: need qs? 2 0
<idle>-0 [005] d.h1. 2.487049: rcu_sched_clock_irq: need qs? 2 0
<idle>-0 [000] d.h1. 2.487318: rcu_sched_clock_irq: need qs? 2 0
<idle>-0 [007] d.h1. 2.487472: rcu_sched_clock_irq: need qs? 2 0
<idle>-0 [001] d.h1. 2.487522: rcu_sched_clock_irq: need qs? 2 0
<idle>-0 [002] d.h1. 2.488034: rcu_sched_clock_irq: need qs? 2 0
<idle>-0 [005] d.h1. 2.488220: rcu_sched_clock_irq: need qs? 2 0


Note, that "2" is the READ_ONCE() without the "!" to it. Thus:

if (likely(!READ_ONCE((t)->trc_reader_special.b.need_qs)) && \

Is unlikely to be true.

Was this supposed to be:

if (!likely(READ_ONCE((t)->trc_reader_special.b.need_qs)) && \

Or could it be converted to:

if (unlikely(!READ_ONCE((t)->trc_reader_special.b.need_qs)) && \

?

Note, the unlikely tracing is running on my production server v6.6.3.

The above trace is from my test box with latest Linus's tree.

-- Steve


2023-12-02 22:24:37

by Paul E. McKenney

[permalink] [raw]
Subject: Re: [RCU] rcu_tasks_trace_qs(): trc_reader_special.b.need_qs value incorrect likely()?

On Fri, Dec 01, 2023 at 03:49:32PM -0500, Steven Rostedt wrote:
> Paul,
>
> I just started running my branch tracer (that checks all branches and also
> gives likely and unlikely correctness). And I found this:
>
> correct incorrect % Function File Line
> ------- --------- - -------- ---- ----
> 0 1217713 100 rcu_softirq_qs tree.c 247
>
> Which comes down to this:
>
>
> # define rcu_tasks_trace_qs(t) \
> do { \
> int ___rttq_nesting = READ_ONCE((t)->trc_reader_nesting); \
> \
> if (likely(!READ_ONCE((t)->trc_reader_special.b.need_qs)) && \
> likely(!___rttq_nesting)) { \
> rcu_trc_cmpxchg_need_qs((t), 0, TRC_NEED_QS_CHECKED); \
> } else if (___rttq_nesting && ___rttq_nesting != INT_MIN && \
> !READ_ONCE((t)->trc_reader_special.b.blocked)) { \
> rcu_tasks_trace_qs_blkd(t); \
> } \
> } while (0)
>
>
> I added just before the likely/unlikely to my test box and I see this:
>
> trace_printk("need qs? %d %d\n", READ_ONCE((t)->trc_reader_special.b.need_qs), ___rttq_nesting); \
>
> <idle>-0 [005] d.h1. 2.482412: rcu_sched_clock_irq: need qs? 2 0
> <idle>-0 [002] d.h1. 2.482464: rcu_sched_clock_irq: need qs? 2 0
> <idle>-0 [000] d.h1. 2.482766: rcu_sched_clock_irq: need qs? 2 0
> <idle>-0 [001] d.h1. 2.482951: rcu_sched_clock_irq: need qs? 2 0
> <idle>-0 [007] d.h1. 2.482958: rcu_sched_clock_irq: need qs? 2 0
> <idle>-0 [005] d.h1. 2.483600: rcu_sched_clock_irq: need qs? 2 0
> <idle>-0 [002] d.h1. 2.483624: rcu_sched_clock_irq: need qs? 2 0
> <idle>-0 [000] d.h1. 2.483927: rcu_sched_clock_irq: need qs? 2 0
> <idle>-0 [007] d.h1. 2.484068: rcu_sched_clock_irq: need qs? 2 0
> <idle>-0 [001] d.h1. 2.484127: rcu_sched_clock_irq: need qs? 2 0
> <idle>-0 [002] d.h1. 2.484723: rcu_sched_clock_irq: need qs? 2 0
> <idle>-0 [005] d.h1. 2.484745: rcu_sched_clock_irq: need qs? 2 0
> <idle>-0 [000] d.h1. 2.485015: rcu_sched_clock_irq: need qs? 2 0
> <idle>-0 [007] d.h1. 2.485202: rcu_sched_clock_irq: need qs? 2 0
> <idle>-0 [001] d.h1. 2.485258: rcu_sched_clock_irq: need qs? 2 0
> <idle>-0 [002] d.h1. 2.485818: rcu_sched_clock_irq: need qs? 2 0
> <idle>-0 [005] d.h1. 2.485929: rcu_sched_clock_irq: need qs? 2 0
> <idle>-0 [000] d.h1. 2.486224: rcu_sched_clock_irq: need qs? 2 0
> <idle>-0 [007] d.h1. 2.486370: rcu_sched_clock_irq: need qs? 2 0
> <idle>-0 [001] d.h1. 2.486399: rcu_sched_clock_irq: need qs? 2 0
> <idle>-0 [002] d.h1. 2.486895: rcu_sched_clock_irq: need qs? 2 0
> <idle>-0 [005] d.h1. 2.487049: rcu_sched_clock_irq: need qs? 2 0
> <idle>-0 [000] d.h1. 2.487318: rcu_sched_clock_irq: need qs? 2 0
> <idle>-0 [007] d.h1. 2.487472: rcu_sched_clock_irq: need qs? 2 0
> <idle>-0 [001] d.h1. 2.487522: rcu_sched_clock_irq: need qs? 2 0
> <idle>-0 [002] d.h1. 2.488034: rcu_sched_clock_irq: need qs? 2 0
> <idle>-0 [005] d.h1. 2.488220: rcu_sched_clock_irq: need qs? 2 0
>
>
> Note, that "2" is the READ_ONCE() without the "!" to it. Thus:
>
> if (likely(!READ_ONCE((t)->trc_reader_special.b.need_qs)) && \
>
> Is unlikely to be true.
>
> Was this supposed to be:
>
> if (!likely(READ_ONCE((t)->trc_reader_special.b.need_qs)) && \
>
> Or could it be converted to:
>
> if (unlikely(!READ_ONCE((t)->trc_reader_special.b.need_qs)) && \
>
> ?
>
> Note, the unlikely tracing is running on my production server v6.6.3.
>
> The above trace is from my test box with latest Linus's tree.

Nice tool!!!

My kneejerk reaction is that that condition is suboptimal. Does the
(untested) patch below help things?

Thanx, Paul

diff --git a/include/linux/rcupdate.h b/include/linux/rcupdate.h
index aa87c82236dd..1df1dc9e8620 100644
--- a/include/linux/rcupdate.h
+++ b/include/linux/rcupdate.h
@@ -184,9 +184,9 @@ void rcu_tasks_trace_qs_blkd(struct task_struct *t);
do { \
int ___rttq_nesting = READ_ONCE((t)->trc_reader_nesting); \
\
- if (likely(!READ_ONCE((t)->trc_reader_special.b.need_qs)) && \
+ if (unlikely(READ_ONCE((t)->trc_reader_special.b.need_qs) == TRC_NEED_QS) && \
likely(!___rttq_nesting)) { \
- rcu_trc_cmpxchg_need_qs((t), 0, TRC_NEED_QS_CHECKED); \
+ rcu_trc_cmpxchg_need_qs((t), TRC_NEED_QS, TRC_NEED_QS_CHECKED); \
} else if (___rttq_nesting && ___rttq_nesting != INT_MIN && \
!READ_ONCE((t)->trc_reader_special.b.blocked)) { \
rcu_tasks_trace_qs_blkd(t); \

2023-12-02 23:45:40

by Steven Rostedt

[permalink] [raw]
Subject: Re: [RCU] rcu_tasks_trace_qs(): trc_reader_special.b.need_qs value incorrect likely()?

On Sat, 2 Dec 2023 14:24:26 -0800
"Paul E. McKenney" <[email protected]> wrote:

> > Note, the unlikely tracing is running on my production server v6.6.3.
> >
> > The above trace is from my test box with latest Linus's tree.
>
> Nice tool!!!

Thanks! It's only been in the kernel since 2008 ;-)

1f0d69a9fc815 ("tracing: profile likely and unlikely annotations")

>
> My kneejerk reaction is that that condition is suboptimal. Does the
> (untested) patch below help things?

I'll give it a try on Monday.

Thanks,

-- Steve

2023-12-05 20:59:15

by Steven Rostedt

[permalink] [raw]
Subject: Re: [RCU] rcu_tasks_trace_qs(): trc_reader_special.b.need_qs value incorrect likely()?

On Sat, 2 Dec 2023 18:45:07 -0500
Steven Rostedt <[email protected]> wrote:

> On Sat, 2 Dec 2023 14:24:26 -0800
> "Paul E. McKenney" <[email protected]> wrote:
>
> > > Note, the unlikely tracing is running on my production server v6.6.3.
> > >
> > > The above trace is from my test box with latest Linus's tree.
> >
> > Nice tool!!!
>
> Thanks! It's only been in the kernel since 2008 ;-)
>
> 1f0d69a9fc815 ("tracing: profile likely and unlikely annotations")
>
> >
> > My kneejerk reaction is that that condition is suboptimal. Does the
> > (untested) patch below help things?
>
> I'll give it a try on Monday.
>

This looks to have caused a difference. Although there's other RCU
functions that need dealing with, but that's for when I have time to
analyze all the places that have bad annotations.


Anyway:

correct incorrect % Function File Line
------- --------- - -------- ---- ----
[..]
17924 0 0 rcu_softirq_qs tree.c 247

Tested-by: Steven Rostedt (Google) <[email protected]>

-- Steve

2023-12-05 22:01:35

by Paul E. McKenney

[permalink] [raw]
Subject: Re: [RCU] rcu_tasks_trace_qs(): trc_reader_special.b.need_qs value incorrect likely()?

On Tue, Dec 05, 2023 at 03:59:27PM -0500, Steven Rostedt wrote:
> On Sat, 2 Dec 2023 18:45:07 -0500
> Steven Rostedt <[email protected]> wrote:
>
> > On Sat, 2 Dec 2023 14:24:26 -0800
> > "Paul E. McKenney" <[email protected]> wrote:
> >
> > > > Note, the unlikely tracing is running on my production server v6.6.3.
> > > >
> > > > The above trace is from my test box with latest Linus's tree.
> > >
> > > Nice tool!!!
> >
> > Thanks! It's only been in the kernel since 2008 ;-)
> >
> > 1f0d69a9fc815 ("tracing: profile likely and unlikely annotations")
> >
> > >
> > > My kneejerk reaction is that that condition is suboptimal. Does the
> > > (untested) patch below help things?
> >
> > I'll give it a try on Monday.
> >
>
> This looks to have caused a difference. Although there's other RCU
> functions that need dealing with, but that's for when I have time to
> analyze all the places that have bad annotations.
>
>
> Anyway:
>
> correct incorrect % Function File Line
> ------- --------- - -------- ---- ----
> [..]
> 17924 0 0 rcu_softirq_qs tree.c 247
>
> Tested-by: Steven Rostedt (Google) <[email protected]>

Thank you very much, and I will apply this on my next rebase.

One of the disadvantages of userspace-free rcutorture testing...

Thanx, Paul