Message-ID: <20221108204640.GJ3907045@paulmck-ThinkPad-P17-Gen-1>
Date:   Tue, 8 Nov 2022 12:46:40 -0800
From:   "Paul E. McKenney" <paulmck@...nel.org>
To:     Zhen Lei <thunder.leizhen@...wei.com>
Cc:     Frederic Weisbecker <frederic@...nel.org>,
        Neeraj Upadhyay <quic_neeraju@...cinc.com>,
        Josh Triplett <josh@...htriplett.org>,
        Steven Rostedt <rostedt@...dmis.org>,
        Mathieu Desnoyers <mathieu.desnoyers@...icios.com>,
        Lai Jiangshan <jiangshanlai@...il.com>,
        Joel Fernandes <joel@...lfernandes.org>, rcu@...r.kernel.org,
        linux-kernel@...r.kernel.org, Robert Elliott <elliott@....com>
Subject: Re: [PATCH] rcu: Illustrate the stall information of
 CONFIG_RCU_CPU_STALL_CPUTIME=y

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@...wei.com>

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.

							Thanx, Paul

------------------------------------------------------------------------

commit b05c2a06ff8a1267b7e8dc812e3944119535d6b6
Author: Zhen Lei <thunder.leizhen@...wei.com>
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@...wei.com>
    Signed-off-by: Paul E. McKenney <paulmck@...nel.org>

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

Powered by blists - more mailing lists