linux-kernel - Re: [PATCH 2/3] rcu: print first CPU on expedited stall line

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Date:   Wed, 21 Dec 2022 11:02:07 -0800
From:   "Paul E. McKenney" <paulmck@...nel.org>
To:     Robert Elliott <elliott@....com>
Cc:     herbert@...dor.apana.org.au, davem@...emloft.net,
        frederic@...nel.org, quic_neeraju@...cinc.com,
        josh@...htriplett.org, linux-crypto@...r.kernel.org,
        rcu@...r.kernel.org, linux-kernel@...r.kernel.org
Subject: Re: [PATCH 2/3] rcu: print first CPU on expedited stall line

On Mon, Dec 19, 2022 at 02:29:09PM -0600, Robert Elliott wrote:
> Include the first CPU number in the first pr_err() call reporting
> an expedited stall warning.
> 
> Printing the CPU numbers with subsequent pr_cont() calls can
> result in the prints being many lines away or being dropped entirely
> in a busy system. This change ensures there is indication of at
> least one of the CPUs with the problem with the original message.
> 
> Before (if prints are interspersed with other prints):
>   rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: {
>   13-....
>   } 32 jiffies s: 6685 root: 0x1/.
> 
> After:
>   rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: {13-....
>   } 32 jiffies s: 6685 root: 0x1/.
> 
> Signed-off-by: Robert Elliott <elliott@....com>

A couple of questions below.

> ---
>  kernel/rcu/tree_exp.h | 22 +++++++++++++++-------
>  1 file changed, 15 insertions(+), 7 deletions(-)
> 
> diff --git a/kernel/rcu/tree_exp.h b/kernel/rcu/tree_exp.h
> index ed6c3cce28f2..ade6a18e6c07 100644
> --- a/kernel/rcu/tree_exp.h
> +++ b/kernel/rcu/tree_exp.h
> @@ -624,8 +624,6 @@ static void synchronize_rcu_expedited_wait(void)
>  		if (rcu_stall_is_suppressed())
>  			continue;
>  		trace_rcu_stall_warning(rcu_state.name, TPS("ExpeditedStall"));
> -		pr_err("INFO: %s detected expedited stalls on CPUs/tasks: {",
> -		       rcu_state.name);
>  		ndetected = 0;
>  		rcu_for_each_leaf_node(rnp) {
>  			ndetected += rcu_print_task_exp_stall(rnp);
> @@ -637,11 +635,21 @@ static void synchronize_rcu_expedited_wait(void)
>  					continue;
>  				ndetected++;
>  				rdp = per_cpu_ptr(&rcu_data, cpu);
> -				pr_cont(" %d-%c%c%c%c", cpu,
> -					"O."[!!cpu_online(cpu)],
> -					"o."[!!(rdp->grpmask & rnp->expmaskinit)],
> -					"N."[!!(rdp->grpmask & rnp->expmaskinitnext)],
> -					"D."[!!(rdp->cpu_no_qs.b.exp)]);
> +				// print the prefix and the first CPU number together
> +				// under heavy load, the pr_cont prints can be far away or dropped
> +				if (ndetected == 1)

Is the purpose here to print the header only on the first detected task?
If so, what if there is more than one task blocking the first rcu_node
structure?  Wouldn't that omit the header entirely?

> +					pr_err("INFO: %s detected expedited stalls on CPUs/tasks: {%d-%c%c%c%c",

We can of course get other console output interspersed at this point.
This might be OK in practice, but the commit log should clearly spell
out the reasons.

> +					       rcu_state.name, cpu,
> +					       "O."[!!cpu_online(cpu)],
> +					       "o."[!!(rdp->grpmask & rnp->expmaskinit)],
> +					       "N."[!!(rdp->grpmask & rnp->expmaskinitnext)],
> +					       "D."[!!(rdp->cpu_no_qs.b.exp)]);
> +				else
> +					pr_cont(" %d-%c%c%c%c", cpu,
> +						"O."[!!cpu_online(cpu)],
> +						"o."[!!(rdp->grpmask & rnp->expmaskinit)],
> +						"N."[!!(rdp->grpmask & rnp->expmaskinitnext)],
> +						"D."[!!(rdp->cpu_no_qs.b.exp)]);
>  			}
>  		}
>  		pr_cont(" } %lu jiffies s: %lu root: %#lx/%c\n",
> -- 
> 2.38.1
>