RE: [PATCH v4 4/4] rcu: Add RCU stall diagnosis information

From: "Elliott, Robert (Servers)" <elliott@hpe.com>
To: "Leizhen (ThunderTown)" <thunder.leizhen@huawei.com>,
	"paulmck@kernel.org" <paulmck@kernel.org>
Cc: Frederic Weisbecker <frederic@kernel.org>,
	Neeraj Upadhyay <quic_neeraju@quicinc.com>,
	Josh Triplett <josh@joshtriplett.org>,
	"Steven Rostedt" <rostedt@goodmis.org>,
	Mathieu Desnoyers <mathieu.desnoyers@efficios.com>,
	Lai Jiangshan <jiangshanlai@gmail.com>,
	Joel Fernandes <joel@joelfernandes.org>,
	"rcu@vger.kernel.org" <rcu@vger.kernel.org>,
	"linux-kernel@vger.kernel.org" <linux-kernel@vger.kernel.org>
Subject: RE: [PATCH v4 4/4] rcu: Add RCU stall diagnosis information
Date: Tue, 8 Nov 2022 05:53:06 +0000	[thread overview]
Message-ID: <MW5PR84MB1842F64C2019065948048B92AB3F9@MW5PR84MB1842.NAMPRD84.PROD.OUTLOOK.COM> (raw)
In-Reply-To: <ac89012c-c9c8-aed1-2007-d5cc93433db7@huawei.com>

> -----Original Message-----
> From: Leizhen (ThunderTown) <thunder.leizhen@huawei.com>
> Sent: Monday, November 7, 2022 9:07 PM
> Subject: Re: [PATCH v4 4/4] rcu: Add RCU stall diagnosis information
> 
> On 2022/11/8 5:57, Elliott, Robert (Servers) wrote:
> > I created a 22 second stall, which triggered two self-detected stall
> > messages. The second one covers 18 seconds (and reports 17444 ms
> > of system cputime), but still reports the half_timeout of 2.5 s on
> 
> Because I have not updated rsrp->gp_seq in print_cpu_stat_info().
> 
> Please add rsrp->gp_seq-- at the bottom of print_cpu_stat_info()
> and try again.
> 
> diff --git a/kernel/rcu/tree_stall.h b/kernel/rcu/tree_stall.h
> index 2e560a70d88fd87..6f6c95d599e6436 100644
> --- a/kernel/rcu/tree_stall.h
> +++ b/kernel/rcu/tree_stall.h
> @@ -455,6 +455,7 @@ static void print_cpu_stat_info(int cpu)
>                 div_u64(cpustat[CPUTIME_SOFTIRQ] - rsrp->cputime_softirq,
> NSEC_PER_MSEC),
>                 div_u64(cpustat[CPUTIME_SYSTEM] - rsrp->cputime_system,
> NSEC_PER_MSEC),
>                 jiffies64_to_msecs(half_timeout));
> +       rsrp->gp_seq--;
>  }

That causes a lot more expedited stall messages to be printed (52 of them).
[   80.709572] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: { 22-.... } 3 jiffies s: 481 root: 0x2/.
[   80.743724] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: { 22-.... } 311 jiffies s: 481 root: 0x2/.
[   81.028028] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: { 22-.... } 620 jiffies s: 481 root: 0x2/.
[   81.313255] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: { 22-.... } 929 jiffies s: 481 root: 0x2/.
[   81.598483] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: { 22-.... } 1238 jiffies s: 481 root: 0x2/.
[   81.883710] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: { 22-.... } 1547 jiffies s: 481 root: 0x2/.
...
[   95.077093] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: { 22-.... } 15840 jiffies s: 481 root: 0x2/.
[   95.362327] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: { 22-.... } 16149 jiffies s: 481 root: 0x2/.
[   95.647549] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: {

Of the three self-detected prints, the second and third system cputimes 
of 8809 and 8655 are still greater than 1500.

[   73.774167] tcrypt: rcu testing - kernel_fpu_disable for rude 22 s
[   76.540071] rcu: INFO: rcu_preempt self-detected stall on CPU 22
[   76.546118] rcu:     22-....: (2994 ticks this GP) idle=716c/1/0x4000000000000000 softirq=2095/2095 fqs=751
[   76.555661] rcu:     CPU 22          hardirqs   softirqs          csw     system  cond_resched
[   76.564067] rcu:     CPU 22   count:        0          4             0                        0
[   76.572560] rcu:     CPU 22 cputime:        3          0                     1493               ==> 1500 (ms)
[   76.582277] rcu:     CPU 22 current: in_kernel_fpu_begin=1 this_cpu_preemptible=0
[   76.589546] rcu:     (self-detected stall on CPU 22 t=3054 jiffies g=13897 q=274 ncpus=56)
...
[   85.021211] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: {
[   85.158741] rcu: INFO: rcu_preempt self-detected stall on CPU 22
[   85.159351]  22-....
[   85.163204] rcu:     22-....: (11839 ticks this GP) idle=716c/1/0x4000000000000000 softirq=2095/2095 fqs=2959
[   85.163207] rcu:     CPU 22          hardirqs   softirqs          csw     system  cond_resched
[   85.163208] rcu:     CPU 22   count:        0         43             0                        0
[   85.163210] rcu:     CPU 22 cputime:      491          0                     8809               ==> 1500 (ms)
[   85.166980]  } 4831 jiffies s: 481 root: 0x2/.
[   85.170745] rcu:     CPU 22 current: in_kernel_fpu_begin=1 this_cpu_preemptible=0
[   85.170747] rcu:     (self-detected stall on CPU 22 t=12351 jiffies g=13897 q=2542 ncpus=56)
...
[   93.899261] rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: {
[   93.920482] rcu: INFO: rcu_preempt self-detected stall on CPU 22
[   93.933812]  22-....
[   93.939063] rcu:     22-....: (20543 ticks this GP) idle=716c/1/0x4000000000000000 softirq=2095/2095 fqs=5216
[   93.939066] rcu:     CPU 22          hardirqs   softirqs          csw     system  cond_resched
[   93.939067] rcu:     CPU 22   count:        0         59             0                        0
[   93.946245]  } 14342 jiffies s: 481 root: 0x2/.
[   93.953415] rcu:     CPU 22 cputime:      777          0                     8655               ==> 1500 (ms)
[   93.953418] rcu:     CPU 22 current: in_kernel_fpu_begin=1 this_cpu_preemptible=0
[   93.953419] rcu:     (self-detected stall on CPU 22 t=21865 jiffies g=13897 q=6284 ncpus=56)
[   93.953421] CPU: 22 PID: 2604 Comm: modprobe Not tainted 6.0.0+ #13
[   93.960598] rcu: blocking rcu_node structures (internal RCU debug):

(I added "CPU %d" to all the self-detected lines to try to help the interleaving)