Re: [PATCH v6 2/2] doc: Document CONFIG_RCU_CPU_STALL_CPUTIME=y stall information

[Frederic Weisbecker]

On Wed, Nov 09, 2022 at 05:37:38PM +0800, Zhen Lei wrote:
> This commit doucments how to quickly determine the bug causing a given
> RCU CPU stall fault warning based on the output information provided
> by CONFIG_RCU_CPU_STALL_CPUTIME=y.
> 
> [ paulmck: Apply wordsmithing. ]
> 
> Signed-off-by: Zhen Lei <thunder.leizhen@xxxxxxxxxx>
> Signed-off-by: Paul E. McKenney <paulmck@xxxxxxxxxx>
> ---
>  Documentation/RCU/stallwarn.rst | 88 +++++++++++++++++++++++++++++++++
>  1 file changed, 88 insertions(+)
> 
> diff --git a/Documentation/RCU/stallwarn.rst b/Documentation/RCU/stallwarn.rst
> index dfa4db8c0931eaf..5e24e849290a286 100644
> --- a/Documentation/RCU/stallwarn.rst
> +++ b/Documentation/RCU/stallwarn.rst
> @@ -390,3 +390,91 @@ for example, "P3421".
>  
>  It is entirely possible to see stall warnings from normal and from
>  expedited grace periods at about the same time during the same run.
> +
> +RCU_CPU_STALL_CPUTIME
> +=====================
> +
> +In kernels built with CONFIG_RCU_CPU_STALL_CPUTIME=y or booted with
> +rcupdate.rcu_cpu_stall_cputime=1, the following additional information
> +is supplied with each RCU CPU stall warning::
> +
> +rcu:          hardirqs   softirqs   csw/system
> +rcu:  number:      624         45            0
> +rcu: cputime:       69          1         2425   ==> 2500(ms)
> +
> +These statistics are collected during the sampling period. The values
> +in row "number:" are the number of hard interrupts, number of soft
> +interrupts, and number of context switches on the stalled CPU. The
> +first three values in row "cputime:" indicate the CPU time in
> +milliseconds consumed by hard interrupts, soft interrupts, and tasks
> +on the stalled CPU.

Is that since the boot or since the last snapshot?

> The last number is the measurement interval, again
> +in milliseconds.  Because user-mode tasks normally do not cause RCU CPU
> +stalls, these tasks are typically kernel tasks, which is why only the
> +system CPU time are considered.
> +
> +The sampling period is shown as follows:
> +|<------------first timeout---------->|<-----second timeout----->|
> +|<--half timeout-->|<--half timeout-->|                          |
> +|                  |<--first period-->|                          |
> +|                  |<-----------second sampling period---------->|
> +|                  |                  |                          |
> +|          sampling time point    1st-stall                  2nd-stall
> +
> +
> +The following describes four typical scenarios:
> +
> +1. A CPU looping with interrupts disabled.::
> +
> +   rcu:          hardirqs   softirqs   csw/system
> +   rcu:  number:        0          0            0
> +   rcu: cputime:        0          0            0   ==> 2500(ms)
> +
> +   Because interrupts have been disabled throughout the measurement
> +   interval, there are no interrupts and no context switches.
> +   Furthermore, because CPU time consumption was measured using interrupt
> +   handlers, the system CPU consumption is misleadingly measured as zero.
> +   This scenario will normally also have "(0 ticks this GP)" printed on
> +   this CPU's summary line.

Right, unless you're running with CONFIG_NO_HZ_FULL=y and the target CPU
is nohz_full=, in that case you should see a delta in stime because the
cputime is measured with the CPU clock.

Thanks.