From dfa0ee48ef86f79430d2be9d1e2e1b509abb3cce Mon Sep 17 00:00:00 2001 From: "Paul E. McKenney" Date: Wed, 9 Aug 2017 10:16:29 -0700 Subject: documentation: Long-running irq handlers can stall RCU grace periods If a periodic interrupt's handler takes longer to execute than the period between successive interrupts, RCU's kthreads and softirq handlers can be prevented from executing, resulting in otherwise inexplicable RCU CPU stall warnings. This commit therefore calls out this possibility in Documentation/RCU/stallwarn.txt. Reported-by: Daniel Lezcano Signed-off-by: Paul E. McKenney --- Documentation/RCU/stallwarn.txt | 12 +++++++++++- 1 file changed, 11 insertions(+), 1 deletion(-) (limited to 'Documentation/RCU/stallwarn.txt') diff --git a/Documentation/RCU/stallwarn.txt b/Documentation/RCU/stallwarn.txt index 96a3d81837e1..21b8913acbdf 100644 --- a/Documentation/RCU/stallwarn.txt +++ b/Documentation/RCU/stallwarn.txt @@ -40,7 +40,9 @@ o Booting Linux using a console connection that is too slow to o Anything that prevents RCU's grace-period kthreads from running. This can result in the "All QSes seen" console-log message. This message will include information on when the kthread last - ran and how often it should be expected to run. + ran and how often it should be expected to run. It can also + result in the "rcu_.*kthread starved for" console-log message, + which will include additional debugging information. o A CPU-bound real-time task in a CONFIG_PREEMPT kernel, which might happen to preempt a low-priority task in the middle of an RCU @@ -60,6 +62,14 @@ o A CPU-bound real-time task in a CONFIG_PREEMPT_RT kernel that CONFIG_PREEMPT_RCU case, you might see stall-warning messages. +o A periodic interrupt whose handler takes longer than the time + interval between successive pairs of interrupts. This can + prevent RCU's kthreads and softirq handlers from running. + Note that certain high-overhead debugging options, for example + the function_graph tracer, can result in interrupt handler taking + considerably longer than normal, which can in turn result in + RCU CPU stall warnings. + o A hardware or software issue shuts off the scheduler-clock interrupt on a CPU that is not in dyntick-idle mode. This problem really has happened, and seems to be most likely to -- cgit From 3d916a443e97169a3d88765c4e0b07ac813f439f Mon Sep 17 00:00:00 2001 From: "Paul E. McKenney" Date: Thu, 10 Aug 2017 14:33:17 -0700 Subject: documentation: Slow systems can stall RCU grace periods If a fast system has a worst-case grace-period duration of (say) ten seconds, then running the same workload on a system ten times as slow will get you an RCU CPU stall warning given default stall-warning timeout settings. This commit therefore adds this possibility to stallwarn.txt. Reported-by: Daniel Lezcano Signed-off-by: Paul E. McKenney --- Documentation/RCU/stallwarn.txt | 6 ++++++ 1 file changed, 6 insertions(+) (limited to 'Documentation/RCU/stallwarn.txt') diff --git a/Documentation/RCU/stallwarn.txt b/Documentation/RCU/stallwarn.txt index 21b8913acbdf..238acbd94917 100644 --- a/Documentation/RCU/stallwarn.txt +++ b/Documentation/RCU/stallwarn.txt @@ -70,6 +70,12 @@ o A periodic interrupt whose handler takes longer than the time considerably longer than normal, which can in turn result in RCU CPU stall warnings. +o Testing a workload on a fast system, tuning the stall-warning + timeout down to just barely avoid RCU CPU stall warnings, and then + running the same workload with the same stall-warning timeout on a + slow system. Note that thermal throttling and on-demand governors + can cause a single system to be sometimes fast and sometimes slow! + o A hardware or software issue shuts off the scheduler-clock interrupt on a CPU that is not in dyntick-idle mode. This problem really has happened, and seems to be most likely to -- cgit From d3cf5176d0b17610b7c7f1562e496ec401fe01f8 Mon Sep 17 00:00:00 2001 From: "Paul E. McKenney" Date: Thu, 17 Aug 2017 12:29:22 -0700 Subject: documentation: Update RCU CPU stall warning messages The RCU CPU stall warnings have morphed significantly since the last update, so this commit brings the documentation up to date. Signed-off-by: Paul E. McKenney --- Documentation/RCU/stallwarn.txt | 182 +++++++++++++++++++++++----------------- 1 file changed, 105 insertions(+), 77 deletions(-) (limited to 'Documentation/RCU/stallwarn.txt') diff --git a/Documentation/RCU/stallwarn.txt b/Documentation/RCU/stallwarn.txt index 238acbd94917..a08f928c8557 100644 --- a/Documentation/RCU/stallwarn.txt +++ b/Documentation/RCU/stallwarn.txt @@ -171,67 +171,32 @@ Interpreting RCU's CPU Stall-Detector "Splats" For non-RCU-tasks flavors of RCU, when a CPU detects that it is stalling, it will print a message similar to the following: -INFO: rcu_sched_state detected stall on CPU 5 (t=2500 jiffies) + INFO: rcu_sched detected stalls on CPUs/tasks: + 2-...: (3 GPs behind) idle=06c/0/0 softirq=1453/1455 fqs=0 + 16-...: (0 ticks this GP) idle=81c/0/0 softirq=764/764 fqs=0 + (detected by 32, t=2603 jiffies, g=7073, c=7072, q=625) -This message indicates that CPU 5 detected that it was causing a stall, -and that the stall was affecting RCU-sched. This message will normally be -followed by a stack dump of the offending CPU. On TREE_RCU kernel builds, -RCU and RCU-sched are implemented by the same underlying mechanism, -while on PREEMPT_RCU kernel builds, RCU is instead implemented -by rcu_preempt_state. - -On the other hand, if the offending CPU fails to print out a stall-warning -message quickly enough, some other CPU will print a message similar to -the following: - -INFO: rcu_bh_state detected stalls on CPUs/tasks: { 3 5 } (detected by 2, 2502 jiffies) - -This message indicates that CPU 2 detected that CPUs 3 and 5 were both -causing stalls, and that the stall was affecting RCU-bh. This message +This message indicates that CPU 32 detected that CPUs 2 and 16 were both +causing stalls, and that the stall was affecting RCU-sched. This message will normally be followed by stack dumps for each CPU. Please note that -PREEMPT_RCU builds can be stalled by tasks as well as by CPUs, -and that the tasks will be indicated by PID, for example, "P3421". -It is even possible for a rcu_preempt_state stall to be caused by both -CPUs -and- tasks, in which case the offending CPUs and tasks will all -be called out in the list. - -Finally, if the grace period ends just as the stall warning starts -printing, there will be a spurious stall-warning message: - -INFO: rcu_bh_state detected stalls on CPUs/tasks: { } (detected by 4, 2502 jiffies) - -This is rare, but does happen from time to time in real life. It is also -possible for a zero-jiffy stall to be flagged in this case, depending -on how the stall warning and the grace-period initialization happen to -interact. Please note that it is not possible to entirely eliminate this -sort of false positive without resorting to things like stop_machine(), -which is overkill for this sort of problem. - -Recent kernels will print a long form of the stall-warning message: - - INFO: rcu_preempt detected stall on CPU - 0: (63959 ticks this GP) idle=241/3fffffffffffffff/0 softirq=82/543 - (t=65000 jiffies) - -In kernels with CONFIG_RCU_FAST_NO_HZ, more information is printed: - - INFO: rcu_preempt detected stall on CPU - 0: (64628 ticks this GP) idle=dd5/3fffffffffffffff/0 softirq=82/543 last_accelerate: a345/d342 nonlazy_posted: 25 .D - (t=65000 jiffies) +PREEMPT_RCU builds can be stalled by tasks as well as by CPUs, and that +the tasks will be indicated by PID, for example, "P3421". It is even +possible for a rcu_preempt_state stall to be caused by both CPUs -and- +tasks, in which case the offending CPUs and tasks will all be called +out in the list. -The "(64628 ticks this GP)" indicates that this CPU has taken more -than 64,000 scheduling-clock interrupts during the current stalled -grace period. If the CPU was not yet aware of the current grace -period (for example, if it was offline), then this part of the message -indicates how many grace periods behind the CPU is. +CPU 2's "(3 GPs behind)" indicates that this CPU has not interacted with +the RCU core for the past three grace periods. In contrast, CPU 16's "(0 +ticks this GP)" indicates that this CPU has not taken any scheduling-clock +interrupts during the current stalled grace period. The "idle=" portion of the message prints the dyntick-idle state. The hex number before the first "/" is the low-order 12 bits of the -dynticks counter, which will have an even-numbered value if the CPU is -in dyntick-idle mode and an odd-numbered value otherwise. The hex -number between the two "/"s is the value of the nesting, which will -be a small positive number if in the idle loop and a very large positive -number (as shown above) otherwise. +dynticks counter, which will have an even-numbered value if the CPU +is in dyntick-idle mode and an odd-numbered value otherwise. The hex +number between the two "/"s is the value of the nesting, which will be +a small non-negative number if in the idle loop (as shown above) and a +very large positive number otherwise. The "softirq=" portion of the message tracks the number of RCU softirq handlers that the stalled CPU has executed. The number before the "/" @@ -246,24 +211,72 @@ handlers are no longer able to execute on this CPU. This can happen if the stalled CPU is spinning with interrupts are disabled, or, in -rt kernels, if a high-priority process is starving RCU's softirq handler. -For CONFIG_RCU_FAST_NO_HZ kernels, the "last_accelerate:" prints the -low-order 16 bits (in hex) of the jiffies counter when this CPU last -invoked rcu_try_advance_all_cbs() from rcu_needs_cpu() or last invoked -rcu_accelerate_cbs() from rcu_prepare_for_idle(). The "nonlazy_posted:" -prints the number of non-lazy callbacks posted since the last call to -rcu_needs_cpu(). Finally, an "L" indicates that there are currently -no non-lazy callbacks ("." is printed otherwise, as shown above) and -"D" indicates that dyntick-idle processing is enabled ("." is printed -otherwise, for example, if disabled via the "nohz=" kernel boot parameter). +The "fps=" shows the number of force-quiescent-state idle/offline +detection passes that the grace-period kthread has made across this +CPU since the last time that this CPU noted the beginning of a grace +period. + +The "detected by" line indicates which CPU detected the stall (in this +case, CPU 32), how many jiffies have elapsed since the start of the +grace period (in this case 2603), the number of the last grace period +to start and to complete (7073 and 7072, respectively), and an estimate +of the total number of RCU callbacks queued across all CPUs (625 in +this case). + +In kernels with CONFIG_RCU_FAST_NO_HZ, more information is printed +for each CPU: + + 0: (64628 ticks this GP) idle=dd5/3fffffffffffffff/0 softirq=82/543 last_accelerate: a345/d342 nonlazy_posted: 25 .D + +The "last_accelerate:" prints the low-order 16 bits (in hex) of the +jiffies counter when this CPU last invoked rcu_try_advance_all_cbs() +from rcu_needs_cpu() or last invoked rcu_accelerate_cbs() from +rcu_prepare_for_idle(). The "nonlazy_posted:" prints the number +of non-lazy callbacks posted since the last call to rcu_needs_cpu(). +Finally, an "L" indicates that there are currently no non-lazy callbacks +("." is printed otherwise, as shown above) and "D" indicates that +dyntick-idle processing is enabled ("." is printed otherwise, for example, +if disabled via the "nohz=" kernel boot parameter). + +If the grace period ends just as the stall warning starts printing, +there will be a spurious stall-warning message, which will include +the following: + + INFO: Stall ended before state dump start + +This is rare, but does happen from time to time in real life. It is also +possible for a zero-jiffy stall to be flagged in this case, depending +on how the stall warning and the grace-period initialization happen to +interact. Please note that it is not possible to entirely eliminate this +sort of false positive without resorting to things like stop_machine(), +which is overkill for this sort of problem. + +If all CPUs and tasks have passed through quiescent states, but the +grace period has nevertheless failed to end, the stall-warning splat +will include something like the following: + + All QSes seen, last rcu_preempt kthread activity 23807 (4297905177-4297881370), jiffies_till_next_fqs=3, root ->qsmask 0x0 + +The "23807" indicates that it has been more than 23 thousand jiffies +since the grace-period kthread ran. The "jiffies_till_next_fqs" +indicates how frequently that kthread should run, giving the number +of jiffies between force-quiescent-state scans, in this case three, +which is way less than 23807. Finally, the root rcu_node structure's +->qsmask field is printed, which will normally be zero. If the relevant grace-period kthread has been unable to run prior to -the stall warning, the following additional line is printed: +the stall warning, as was the case in the "All QSes seen" line above, +the following additional line is printed: - rcu_preempt kthread starved for 2023 jiffies! + kthread starved for 23807 jiffies! g7073 c7072 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1 -Starving the grace-period kthreads of CPU time can of course result in -RCU CPU stall warnings even when all CPUs and tasks have passed through -the required quiescent states. +Starving the grace-period kthreads of CPU time can of course result +in RCU CPU stall warnings even when all CPUs and tasks have passed +through the required quiescent states. The "g" and "c" numbers flag the +number of the last grace period started and completed, respectively, +the "f" precedes the ->gp_flags command to the grace-period kthread, +the "RCU_GP_WAIT_FQS" indicates that the kthread is waiting for a short +timeout, and the "state" precedes value of the task_struct ->state field. Multiple Warnings From One Stall @@ -280,13 +293,28 @@ Stall Warnings for Expedited Grace Periods If an expedited grace period detects a stall, it will place a message like the following in dmesg: - INFO: rcu_sched detected expedited stalls on CPUs: { 1 2 6 } 26009 jiffies s: 1043 - -This indicates that CPUs 1, 2, and 6 have failed to respond to a -reschedule IPI, that the expedited grace period has been going on for -26,009 jiffies, and that the expedited grace-period sequence counter is -1043. The fact that this last value is odd indicates that an expedited -grace period is in flight. + INFO: rcu_sched detected expedited stalls on CPUs/tasks: { 7-... } 21119 jiffies s: 73 root: 0x2/. + +This indicates that CPU 7 has failed to respond to a reschedule IPI. +The three periods (".") following the CPU number indicate that the CPU +is online (otherwise the first period would instead have been "O"), +that the CPU was online at the beginning of the expedited grace period +(otherwise the second period would have instead been "o"), and that +the CPU has been online at least once since boot (otherwise, the third +period would instead have been "N"). The number before the "jiffies" +indicates that the expedited grace period has been going on for 21,119 +jiffies. The number following the "s:" indicates that the expedited +grace-period sequence counter is 73. The fact that this last value is +odd indicates that an expedited grace period is in flight. The number +following "root:" is a bitmask that indicates which children of the root +rcu_node structure correspond to CPUs and/or tasks that are blocking the +current expedited grace period. If the tree had more than one level, +additional hex numbers would be printed for the states of the other +rcu_node structures in the tree. + +As with normal grace periods, PREEMPT_RCU builds can be stalled by +tasks as well as by CPUs, and that the tasks will be indicated by PID, +for example, "P3421". It is entirely possible to see stall warnings from normal and from -expedited grace periods at about the same time from the same run. +expedited grace periods at about the same time during the same run. -- cgit