Re: [PATCH] rcu: wrong stall log when only one task blocked within RCU read-side

[Xu, Yanfei]

On 5/16/21 2:36 AM, Paul E. McKenney wrote:
> [Please note: This e-mail is from an EXTERNAL e-mail address]
>
> On Sun, May 16, 2021 at 12:45:11AM +0800, yanfei.xu@xxxxxxxxxxxxx wrote:
> > From: Yanfei Xu <yanfei.xu@xxxxxxxxxxxxx>
> >
> > The for loop in rcu_print_task_stall() always omits the first blocked
> > task in RCU read-ride critical section. It will cause status of the
> > blocked task can't be printed and lead a wrong ndetected variable.
> > With the above, the wired stall log comes, All QSes seen, but qsmask
> > still is not zero:
> >
> > rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
> > rcu:    Tasks blocked on level-1 rcu_node (CPUs 12-23):
> >          (detected by 15, t=6504 jiffies, g=164777, q=9011209)
> > rcu: All QSes seen, last rcu_preempt kthread activity 1
> > (4295252379-4295252378), jiffies_till_next_fqs=1, root ->qsmask 0x2
> > BUG: sleeping function called from invalid context at
> > include/linux/uaccess.h:156
> > in_atomic(): 1, irqs_disabled(): 0, non_block: 0, pid: 70613, name:
> > msgstress04
> > INFO: lockdep is turned off.
> > Preemption disabled at:
> > [<ffff8000104031a4>] create_object.isra.0+0x204/0x4b0
> > CPU: 15 PID: 70613 Comm: msgstress04 Kdump: loaded Not tainted
> > 5.12.2-yoctodev-standard #1
> > Hardware name: Marvell OcteonTX CN96XX board (DT)
> > Call trace:
> >   dump_backtrace+0x0/0x2cc
> >   show_stack+0x24/0x30
> >   dump_stack+0x110/0x188
> >   ___might_sleep+0x214/0x2d0
> >   __might_sleep+0x7c/0xe0
> >
> > Fixes: c583bcb8f5ed ("rcu: Don't invoke try_invoke_on_locked_down_task() with irqs disabled")
> > Signed-off-by: Yanfei Xu <yanfei.xu@xxxxxxxxxxxxx>
>
> Apologies for that bug, and thank you for the fix!  Queued for testing
> and review.  I wordsmithed as usual, so could you please check to make
> sure that I did not mess anything up?

Ah, this new commit message is more clear. Thank you!

Regards,
Yanfei

>                                                          Thanx, Paul
>
> ------------------------------------------------------------------------
>
> commit 9855fdb508e2fa136551294861682d83b71daded
> Author: Yanfei Xu <yanfei.xu@xxxxxxxxxxxxx>
> Date:   Sun May 16 00:45:11 2021 +0800
>
>      rcu: Fix to include first blocked task in stall warning
>
>      The for loop in rcu_print_task_stall() always omits ts[0], which points
>      to the first task blocking the stalled grace period.  This in turn fails
>      to count this first task, which means that ndetected will be equal to
>      zero when all CPUs have passed through their quiescent states and only
>      one task is blocking the stalled grace period.  This zero value for
>      ndetected will in turn result in an incorrect "All QSes seen" message:
>
>      rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
>      rcu:    Tasks blocked on level-1 rcu_node (CPUs 12-23):
>              (detected by 15, t=6504 jiffies, g=164777, q=9011209)
>      rcu: All QSes seen, last rcu_preempt kthread activity 1 (4295252379-4295252378), jiffies_till_next_fqs=1, root ->qsmask 0x2
>      BUG: sleeping function called from invalid context at include/linux/uaccess.h:156
>      in_atomic(): 1, irqs_disabled(): 0, non_block: 0, pid: 70613, name: msgstress04
>      INFO: lockdep is turned off.
>      Preemption disabled at:
>      [<ffff8000104031a4>] create_object.isra.0+0x204/0x4b0
>      CPU: 15 PID: 70613 Comm: msgstress04 Kdump: loaded Not tainted
>      5.12.2-yoctodev-standard #1
>      Hardware name: Marvell OcteonTX CN96XX board (DT)
>      Call trace:
>       dump_backtrace+0x0/0x2cc
>       show_stack+0x24/0x30
>       dump_stack+0x110/0x188
>       ___might_sleep+0x214/0x2d0
>       __might_sleep+0x7c/0xe0
>
>      This commit therefore fixes the loop to include ts[0].
>
>      Fixes: c583bcb8f5ed ("rcu: Don't invoke try_invoke_on_locked_down_task() with irqs disabled")
>      Signed-off-by: Yanfei Xu <yanfei.xu@xxxxxxxxxxxxx>
>      Signed-off-by: Paul E. McKenney <paulmck@xxxxxxxxxx>
>
> diff --git a/kernel/rcu/tree_stall.h b/kernel/rcu/tree_stall.h
> index f4152aa18f48..a10ea1f1f81f 100644
> --- a/kernel/rcu/tree_stall.h
> +++ b/kernel/rcu/tree_stall.h
> @@ -280,8 +280,8 @@ static int rcu_print_task_stall(struct rcu_node *rnp, unsigned long flags)
>                          break;
>          }
>          raw_spin_unlock_irqrestore_rcu_node(rnp, flags);
> -       for (i--; i; i--) {
> -               t = ts[i];
> +       while (i) {
> +               t = ts[--i];
>                  if (!try_invoke_on_locked_down_task(t, check_slow_task, &rscr))
>                          pr_cont(" P%d", t->pid);
>                  else