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.
