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

["Leizhen (ThunderTown)" <thunder.leizhen@huawei.com>]

On 2022/11/9 23:08, Frederic Weisbecker wrote:
> 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?

Since the last snapshot. See the diagram below:

+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
                    |
                    |
                    Take the snapshot at this time

> 
>> 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.
> .
> 

-- 
Regards,
  Zhen Lei