* [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 [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 [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 a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox
all inboxes | Powered by JetHome®