Re: [PATCH] rcu: Illustrate the stall information of CONFIG_RCU_CPU_STALL_CPUTIME=y

[Leizhen (ThunderTown)]

On 2022/11/9 4:46, Paul E. McKenney wrote:
> On Mon, Nov 07, 2022 at 11:29:35PM +0800, Zhen Lei wrote:
>> Describes how to quickly determine the RCU stall fault type based on the
>> extra output information during CONFIG_RCU_CPU_STALL_CPUTIME=y.
>>
>> Signed-off-by: Zhen Lei <thunder.leizhen@xxxxxxxxxx>
> 
> Hearing no objections, I queued the following for further review.
> 
> This commit might of course need to change based on your ongoing
> discussion with Robert.  I that case, please feel free to send me a
> replacment patch or to send me an incremental patch that I can fold into
> this patch.  Either way works.

I'll issue incremental patches on the basis of your adjustment! This will
make it clearer and save your time in reviewing.

Thanks for your help. I really admire your verbal skills. Your improved
description is much better than mine.

> 
> 							Thanx, Paul
> 
> ------------------------------------------------------------------------
> 
> commit b05c2a06ff8a1267b7e8dc812e3944119535d6b6
> Author: Zhen Lei <thunder.leizhen@xxxxxxxxxx>
> Date:   Mon Nov 7 23:29:35 2022 +0800
> 
>     doc: Document CONFIG_RCU_CPU_STALL_CPUTIME=y stall information
>     
>     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>
> 
> diff --git a/Documentation/RCU/stallwarn.rst b/Documentation/RCU/stallwarn.rst
> index dfa4db8c0931e..bd8cf6c640984 100644
> --- a/Documentation/RCU/stallwarn.rst
> +++ b/Documentation/RCU/stallwarn.rst
> @@ -390,3 +390,82 @@ 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 second half of the rcu stall
> +timeout. 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.  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 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.
> +
> +2. A CPU looping with bottom halves disabled.
> +
> +   This is similar to the previous example, but with non-zero number of
> +   and CPU time consumed by hard interrupts, along with non-zero CPU
> +   time consumed by in-kernel execution.::
> +
> +   rcu:          hardirqs   softirqs   csw/system
> +   rcu:  number:      624          0            0
> +   rcu: cputime:       49          0         2446   ==> 2500(ms)
> +
> +   The fact that there are zero softirqs gives a hint that these were
> +   disabled, perhaps via local_bh_disable().  It is of course possible
> +   that there were no softirqs, perhaps because all events that would
> +   result in softirq execution are confined to other CPUs.  In this case,
> +   the diagnosis should continue as shown in the next example.
> +
> +3. A CPU looping with preemption disabled.
> +
> +   Here, only the number of context switches is zero.::
> +
> +   rcu:          hardirqs   softirqs   csw/system
> +   rcu:  number:      624         45            0
> +   rcu: cputime:       69          1         2425   ==> 2500(ms)
> +
> +   This situation hints that the stalled CPU was looping with preemption
> +   disabled.
> +
> +4. No looping, but massive hard and soft interrupts.::
> +
> +   rcu:          hardirqs   softirqs   csw/system
> +   rcu:  number:       xx         xx            0
> +   rcu: cputime:       xx         xx            0   ==> 2500(ms)
> +
> +   Here, the number and CPU time of hard interrupts are all non-zero,
> +   but the number of context switches and the in-kernel CPU time consumed
> +   are zero. The number and cputime of soft interrupts will usually be
> +   non-zero, but could be zero, for example, if the CPU was spinning
> +   within a single hard interrupt handler.
> +
> +   If this type of RCU CPU stall warning can be reproduced, you can
> +   narrow it down by looking at /proc/interrupts or by writing code to
> +   trace each interrupt, for example, by referring to show_interrupts().
> .
> 

-- 
Regards,
  Zhen Lei