* [PATCH] rcu: Illustrate the stall information of CONFIG_RCU_CPU_STALL_CPUTIME=y
@ 2022-11-07 15:29 Zhen Lei
2022-11-08 20:46 ` Paul E. McKenney
0 siblings, 1 reply; 5+ messages in thread
From: Zhen Lei @ 2022-11-07 15:29 UTC (permalink / raw)
To: Paul E . McKenney, Frederic Weisbecker, Neeraj Upadhyay,
Josh Triplett, Steven Rostedt, Mathieu Desnoyers, Lai Jiangshan,
Joel Fernandes, rcu, linux-kernel
Cc: Zhen Lei, Robert Elliott
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@huawei.com>
---
Documentation/RCU/stallwarn.rst | 56 +++++++++++++++++++++++++++++++++
1 file changed, 56 insertions(+)
diff --git a/Documentation/RCU/stallwarn.rst b/Documentation/RCU/stallwarn.rst
index dfa4db8c0931eaf..40748bff8b8186e 100644
--- a/Documentation/RCU/stallwarn.rst
+++ b/Documentation/RCU/stallwarn.rst
@@ -390,3 +390,59 @@ 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
+=====================
+If CONFIG_RCU_CPU_STALL_CPUTIME=y or rcupdate.rcu_cpu_stall_cputime=1,
+some statistics related to interrupts and tasks are shown additionally
+as follows:
+rcu: hardirqs softirqs csw/system
+rcu: number: 624 45 0
+rcu: cputime: 69 1 2425 ==> 2500(ms)
+
+These statistics are collected in 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. The values in
+row "cputime:" are the cputime of hard interrupts, cputime of soft
+interrupts, cputime of tasks, and sampling period. Because user-mode tasks
+do not cause rcu stall, these tasks can only be kernel tasks, that's why
+only the cputime of system 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)
+ The start time of the interrupt processing is marked when the handler
+ is entered, and the end time is marked when the handler is exited. The
+ cputime of hard interrupts is zero because the current processing time
+ of current interrupt has not been calculated. Since the irq is disabled,
+ all other counts must be zero in the second half of rcu stall timeout.
+
+2. A CPU looping with bottom halves disabled.
+ Similar to the former, but the number and cputime of hard interrupts
+ are non-zero.
+ rcu: hardirqs softirqs csw/system
+ rcu: number: 624 0 0
+ rcu: cputime: 49 0 2446 ==> 2500(ms)
+ The cputime of system is non-zero, so local_bh_disable() is called in
+ current task. Otherwise, the cputime of softirqs should be non-zero.
+ Note, in this case, the number of soft interrupts is always zero.
+
+3. A CPU looping with preemption disabled.
+ The number and cputime of hard interrupts and soft interrupts are all
+ non-zero. 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)
+
+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)
+ The number and cputime of hard interrupts are all non-zero. The number
+ of context switches and the cputime of system are zero. The number and
+ cputime of soft interrupts depends on the cputime of hard interrupts,
+ either all zeros or all non-zeros.
+ If it can be reproduced, cat /proc/interrupts or write code to trace
+ each interrupt by referring to show_interrupts().
--
2.25.1
^ permalink raw reply related [flat|nested] 5+ messages in thread
* Re: [PATCH] rcu: Illustrate the stall information of CONFIG_RCU_CPU_STALL_CPUTIME=y
2022-11-07 15:29 [PATCH] rcu: Illustrate the stall information of CONFIG_RCU_CPU_STALL_CPUTIME=y Zhen Lei
@ 2022-11-08 20:46 ` Paul E. McKenney
2022-11-09 2:09 ` Leizhen (ThunderTown)
0 siblings, 1 reply; 5+ messages in thread
From: Paul E. McKenney @ 2022-11-08 20:46 UTC (permalink / raw)
To: Zhen Lei
Cc: Frederic Weisbecker, Neeraj Upadhyay, Josh Triplett,
Steven Rostedt, Mathieu Desnoyers, Lai Jiangshan, Joel Fernandes,
rcu, linux-kernel, Robert Elliott
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@huawei.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@huawei.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@huawei.com>
Signed-off-by: Paul E. McKenney <paulmck@kernel.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().
^ permalink raw reply related [flat|nested] 5+ messages in thread
* Re: [PATCH] rcu: Illustrate the stall information of CONFIG_RCU_CPU_STALL_CPUTIME=y
2022-11-08 20:46 ` Paul E. McKenney
@ 2022-11-09 2:09 ` Leizhen (ThunderTown)
2022-11-09 8:46 ` Leizhen (ThunderTown)
0 siblings, 1 reply; 5+ messages in thread
From: Leizhen (ThunderTown) @ 2022-11-09 2:09 UTC (permalink / raw)
To: paulmck
Cc: Frederic Weisbecker, Neeraj Upadhyay, Josh Triplett,
Steven Rostedt, Mathieu Desnoyers, Lai Jiangshan, Joel Fernandes,
rcu, linux-kernel, Robert Elliott
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@huawei.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.
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@huawei.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@huawei.com>
> Signed-off-by: Paul E. McKenney <paulmck@kernel.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().
> .
>
--
Regards,
Zhen Lei
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: [PATCH] rcu: Illustrate the stall information of CONFIG_RCU_CPU_STALL_CPUTIME=y
2022-11-09 2:09 ` Leizhen (ThunderTown)
@ 2022-11-09 8:46 ` Leizhen (ThunderTown)
2022-11-09 15:56 ` Paul E. McKenney
0 siblings, 1 reply; 5+ messages in thread
From: Leizhen (ThunderTown) @ 2022-11-09 8:46 UTC (permalink / raw)
To: paulmck
Cc: Frederic Weisbecker, Neeraj Upadhyay, Josh Triplett,
Steven Rostedt, Mathieu Desnoyers, Lai Jiangshan, Joel Fernandes,
rcu, linux-kernel, Robert Elliott
On 2022/11/9 10:09, Leizhen (ThunderTown) wrote:
>
>
> 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@huawei.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.
>
> I'll issue incremental patches on the basis of your adjustment! This will
> make it clearer and save your time in reviewing.
I found that Patch 4/4 had one line of description that needed to be changed,
so I had to switch to method 1.
>
> 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@huawei.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@huawei.com>
>> Signed-off-by: Paul E. McKenney <paulmck@kernel.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().
>> .
>>
>
--
Regards,
Zhen Lei
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: [PATCH] rcu: Illustrate the stall information of CONFIG_RCU_CPU_STALL_CPUTIME=y
2022-11-09 8:46 ` Leizhen (ThunderTown)
@ 2022-11-09 15:56 ` Paul E. McKenney
0 siblings, 0 replies; 5+ messages in thread
From: Paul E. McKenney @ 2022-11-09 15:56 UTC (permalink / raw)
To: Leizhen (ThunderTown)
Cc: Frederic Weisbecker, Neeraj Upadhyay, Josh Triplett,
Steven Rostedt, Mathieu Desnoyers, Lai Jiangshan, Joel Fernandes,
rcu, linux-kernel, Robert Elliott
On Wed, Nov 09, 2022 at 04:46:01PM +0800, Leizhen (ThunderTown) wrote:
>
>
> On 2022/11/9 10:09, Leizhen (ThunderTown) wrote:
> >
> >
> > 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@huawei.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.
> >
> > I'll issue incremental patches on the basis of your adjustment! This will
> > make it clearer and save your time in reviewing.
>
> I found that Patch 4/4 had one line of description that needed to be changed,
> so I had to switch to method 1.
Sounds good! I will drop what I have (five patches) and take the next
series with Frederic's feedback addressed.
Thanx, Paul
> > 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@huawei.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@huawei.com>
> >> Signed-off-by: Paul E. McKenney <paulmck@kernel.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().
> >> .
> >>
> >
>
> --
> Regards,
> Zhen Lei
^ permalink raw reply [flat|nested] 5+ messages in thread
end of thread, other threads:[~2022-11-09 15:57 UTC | newest]
Thread overview: 5+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2022-11-07 15:29 [PATCH] rcu: Illustrate the stall information of CONFIG_RCU_CPU_STALL_CPUTIME=y Zhen Lei
2022-11-08 20:46 ` Paul E. McKenney
2022-11-09 2:09 ` Leizhen (ThunderTown)
2022-11-09 8:46 ` Leizhen (ThunderTown)
2022-11-09 15:56 ` Paul E. McKenney
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.