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

Frederic Weisbecker
2022-11-09T15:08:46Z

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@huawei.com>
> Signed-off-by: Paul E. McKenney <paulmck@kernel.org>
> ---
> 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.