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@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?
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
