]>
Commit | Line | Data |
---|---|---|
4c54005c PM |
1 | Using RCU's CPU Stall Detector |
2 | ||
8e2a4397 PM |
3 | This document first discusses what sorts of issues RCU's CPU stall |
4 | detector can locate, and then discusses kernel parameters and Kconfig | |
5 | options that can be used to fine-tune the detector's operation. Finally, | |
6 | this document explains the stall detector's "splat" format. | |
7 | ||
8 | ||
9 | What Causes RCU CPU Stall Warnings? | |
10 | ||
11 | So your kernel printed an RCU CPU stall warning. The next question is | |
12 | "What caused it?" The following problems can result in RCU CPU stall | |
13 | warnings: | |
14 | ||
15 | o A CPU looping in an RCU read-side critical section. | |
16 | ||
17 | o A CPU looping with interrupts disabled. | |
18 | ||
19 | o A CPU looping with preemption disabled. This condition can | |
20 | result in RCU-sched stalls and, if ksoftirqd is in use, RCU-bh | |
21 | stalls. | |
22 | ||
23 | o A CPU looping with bottom halves disabled. This condition can | |
24 | result in RCU-sched and RCU-bh stalls. | |
25 | ||
26 | o For !CONFIG_PREEMPT kernels, a CPU looping anywhere in the | |
27 | kernel without invoking schedule(). Note that cond_resched() | |
28 | does not necessarily prevent RCU CPU stall warnings. Therefore, | |
29 | if the looping in the kernel is really expected and desirable | |
30 | behavior, you might need to replace some of the cond_resched() | |
31 | calls with calls to cond_resched_rcu_qs(). | |
32 | ||
33 | o Booting Linux using a console connection that is too slow to | |
34 | keep up with the boot-time console-message rate. For example, | |
35 | a 115Kbaud serial console can be -way- too slow to keep up | |
36 | with boot-time message rates, and will frequently result in | |
37 | RCU CPU stall warning messages. Especially if you have added | |
38 | debug printk()s. | |
39 | ||
40 | o Anything that prevents RCU's grace-period kthreads from running. | |
41 | This can result in the "All QSes seen" console-log message. | |
42 | This message will include information on when the kthread last | |
43 | ran and how often it should be expected to run. | |
44 | ||
45 | o A CPU-bound real-time task in a CONFIG_PREEMPT kernel, which might | |
46 | happen to preempt a low-priority task in the middle of an RCU | |
47 | read-side critical section. This is especially damaging if | |
48 | that low-priority task is not permitted to run on any other CPU, | |
49 | in which case the next RCU grace period can never complete, which | |
50 | will eventually cause the system to run out of memory and hang. | |
51 | While the system is in the process of running itself out of | |
52 | memory, you might see stall-warning messages. | |
53 | ||
54 | o A CPU-bound real-time task in a CONFIG_PREEMPT_RT kernel that | |
55 | is running at a higher priority than the RCU softirq threads. | |
56 | This will prevent RCU callbacks from ever being invoked, | |
57 | and in a CONFIG_PREEMPT_RCU kernel will further prevent | |
58 | RCU grace periods from ever completing. Either way, the | |
59 | system will eventually run out of memory and hang. In the | |
60 | CONFIG_PREEMPT_RCU case, you might see stall-warning | |
61 | messages. | |
62 | ||
63 | o A hardware or software issue shuts off the scheduler-clock | |
64 | interrupt on a CPU that is not in dyntick-idle mode. This | |
65 | problem really has happened, and seems to be most likely to | |
66 | result in RCU CPU stall warnings for CONFIG_NO_HZ_COMMON=n kernels. | |
67 | ||
68 | o A bug in the RCU implementation. | |
69 | ||
70 | o A hardware failure. This is quite unlikely, but has occurred | |
71 | at least once in real life. A CPU failed in a running system, | |
72 | becoming unresponsive, but not causing an immediate crash. | |
73 | This resulted in a series of RCU CPU stall warnings, eventually | |
74 | leading the realization that the CPU had failed. | |
75 | ||
76 | The RCU, RCU-sched, RCU-bh, and RCU-tasks implementations have CPU stall | |
77 | warning. Note that SRCU does -not- have CPU stall warnings. Please note | |
78 | that RCU only detects CPU stalls when there is a grace period in progress. | |
79 | No grace period, no CPU stall warnings. | |
80 | ||
81 | To diagnose the cause of the stall, inspect the stack traces. | |
82 | The offending function will usually be near the top of the stack. | |
83 | If you have a series of stall warnings from a single extended stall, | |
84 | comparing the stack traces can often help determine where the stall | |
85 | is occurring, which will usually be in the function nearest the top of | |
86 | that portion of the stack which remains the same from trace to trace. | |
87 | If you can reliably trigger the stall, ftrace can be quite helpful. | |
88 | ||
89 | RCU bugs can often be debugged with the help of CONFIG_RCU_TRACE | |
90 | and with RCU's event tracing. For information on RCU's event tracing, | |
91 | see include/trace/events/rcu.h. | |
92 | ||
93 | ||
94 | Fine-Tuning the RCU CPU Stall Detector | |
95 | ||
96 | The rcuupdate.rcu_cpu_stall_suppress module parameter disables RCU's | |
97 | CPU stall detector, which detects conditions that unduly delay RCU grace | |
98 | periods. This module parameter enables CPU stall detection by default, | |
99 | but may be overridden via boot-time parameter or at runtime via sysfs. | |
a00e0d71 PM |
100 | The stall detector's idea of what constitutes "unduly delayed" is |
101 | controlled by a set of kernel configuration variables and cpp macros: | |
4c54005c | 102 | |
a00e0d71 | 103 | CONFIG_RCU_CPU_STALL_TIMEOUT |
4c54005c | 104 | |
a00e0d71 PM |
105 | This kernel configuration parameter defines the period of time |
106 | that RCU will wait from the beginning of a grace period until it | |
107 | issues an RCU CPU stall warning. This time period is normally | |
64d3b7a1 | 108 | 21 seconds. |
4c54005c | 109 | |
24cd7fd0 | 110 | This configuration parameter may be changed at runtime via the |
84596ccb | 111 | /sys/module/rcupdate/parameters/rcu_cpu_stall_timeout, however |
24cd7fd0 | 112 | this parameter is checked only at the beginning of a cycle. |
64d3b7a1 | 113 | So if you are 10 seconds into a 40-second stall, setting this |
24cd7fd0 PM |
114 | sysfs parameter to (say) five will shorten the timeout for the |
115 | -next- stall, or the following warning for the current stall | |
116 | (assuming the stall lasts long enough). It will not affect the | |
117 | timing of the next warning for the current stall. | |
4c54005c | 118 | |
24cd7fd0 | 119 | Stall-warning messages may be enabled and disabled completely via |
96224daa | 120 | /sys/module/rcupdate/parameters/rcu_cpu_stall_suppress. |
24cd7fd0 | 121 | |
24cd7fd0 PM |
122 | RCU_STALL_DELAY_DELTA |
123 | ||
124 | Although the lockdep facility is extremely useful, it does add | |
125 | some overhead. Therefore, under CONFIG_PROVE_RCU, the | |
126 | RCU_STALL_DELAY_DELTA macro allows five extra seconds before | |
64d3b7a1 PM |
127 | giving an RCU CPU stall warning message. (This is a cpp |
128 | macro, not a kernel configuration parameter.) | |
4c54005c PM |
129 | |
130 | RCU_STALL_RAT_DELAY | |
131 | ||
f1d507be PM |
132 | The CPU stall detector tries to make the offending CPU print its |
133 | own warnings, as this often gives better-quality stack traces. | |
134 | However, if the offending CPU does not detect its own stall in | |
135 | the number of jiffies specified by RCU_STALL_RAT_DELAY, then | |
136 | some other CPU will complain. This delay is normally set to | |
64d3b7a1 PM |
137 | two jiffies. (This is a cpp macro, not a kernel configuration |
138 | parameter.) | |
4c54005c | 139 | |
37fe5f0e PM |
140 | rcupdate.rcu_task_stall_timeout |
141 | ||
142 | This boot/sysfs parameter controls the RCU-tasks stall warning | |
143 | interval. A value of zero or less suppresses RCU-tasks stall | |
144 | warnings. A positive value sets the stall-warning interval | |
14ef0575 | 145 | in jiffies. An RCU-tasks stall warning starts with the line: |
37fe5f0e PM |
146 | |
147 | INFO: rcu_tasks detected stalls on tasks: | |
148 | ||
149 | And continues with the output of sched_show_task() for each | |
150 | task stalling the current RCU-tasks grace period. | |
151 | ||
8e2a4397 PM |
152 | |
153 | Interpreting RCU's CPU Stall-Detector "Splats" | |
154 | ||
37fe5f0e PM |
155 | For non-RCU-tasks flavors of RCU, when a CPU detects that it is stalling, |
156 | it will print a message similar to the following: | |
f1d507be PM |
157 | |
158 | INFO: rcu_sched_state detected stall on CPU 5 (t=2500 jiffies) | |
159 | ||
160 | This message indicates that CPU 5 detected that it was causing a stall, | |
161 | and that the stall was affecting RCU-sched. This message will normally be | |
162 | followed by a stack dump of the offending CPU. On TREE_RCU kernel builds, | |
163 | RCU and RCU-sched are implemented by the same underlying mechanism, | |
28f6569a | 164 | while on PREEMPT_RCU kernel builds, RCU is instead implemented |
f1d507be PM |
165 | by rcu_preempt_state. |
166 | ||
167 | On the other hand, if the offending CPU fails to print out a stall-warning | |
168 | message quickly enough, some other CPU will print a message similar to | |
169 | the following: | |
170 | ||
171 | INFO: rcu_bh_state detected stalls on CPUs/tasks: { 3 5 } (detected by 2, 2502 jiffies) | |
172 | ||
173 | This message indicates that CPU 2 detected that CPUs 3 and 5 were both | |
174 | causing stalls, and that the stall was affecting RCU-bh. This message | |
175 | will normally be followed by stack dumps for each CPU. Please note that | |
28f6569a | 176 | PREEMPT_RCU builds can be stalled by tasks as well as by CPUs, |
f1d507be PM |
177 | and that the tasks will be indicated by PID, for example, "P3421". |
178 | It is even possible for a rcu_preempt_state stall to be caused by both | |
179 | CPUs -and- tasks, in which case the offending CPUs and tasks will all | |
180 | be called out in the list. | |
181 | ||
182 | Finally, if the grace period ends just as the stall warning starts | |
183 | printing, there will be a spurious stall-warning message: | |
184 | ||
185 | INFO: rcu_bh_state detected stalls on CPUs/tasks: { } (detected by 4, 2502 jiffies) | |
186 | ||
64d3b7a1 PM |
187 | This is rare, but does happen from time to time in real life. It is also |
188 | possible for a zero-jiffy stall to be flagged in this case, depending | |
189 | on how the stall warning and the grace-period initialization happen to | |
190 | interact. Please note that it is not possible to entirely eliminate this | |
191 | sort of false positive without resorting to things like stop_machine(), | |
192 | which is overkill for this sort of problem. | |
f1d507be | 193 | |
75c27f11 | 194 | Recent kernels will print a long form of the stall-warning message: |
24cd7fd0 PM |
195 | |
196 | INFO: rcu_preempt detected stall on CPU | |
6231069b | 197 | 0: (63959 ticks this GP) idle=241/3fffffffffffffff/0 softirq=82/543 |
24cd7fd0 PM |
198 | (t=65000 jiffies) |
199 | ||
75c27f11 | 200 | In kernels with CONFIG_RCU_FAST_NO_HZ, more information is printed: |
24cd7fd0 PM |
201 | |
202 | INFO: rcu_preempt detected stall on CPU | |
6231069b | 203 | 0: (64628 ticks this GP) idle=dd5/3fffffffffffffff/0 softirq=82/543 last_accelerate: a345/d342 nonlazy_posted: 25 .D |
24cd7fd0 PM |
204 | (t=65000 jiffies) |
205 | ||
206 | The "(64628 ticks this GP)" indicates that this CPU has taken more | |
207 | than 64,000 scheduling-clock interrupts during the current stalled | |
208 | grace period. If the CPU was not yet aware of the current grace | |
209 | period (for example, if it was offline), then this part of the message | |
210 | indicates how many grace periods behind the CPU is. | |
211 | ||
212 | The "idle=" portion of the message prints the dyntick-idle state. | |
213 | The hex number before the first "/" is the low-order 12 bits of the | |
214 | dynticks counter, which will have an even-numbered value if the CPU is | |
215 | in dyntick-idle mode and an odd-numbered value otherwise. The hex | |
216 | number between the two "/"s is the value of the nesting, which will | |
217 | be a small positive number if in the idle loop and a very large positive | |
218 | number (as shown above) otherwise. | |
219 | ||
6231069b PM |
220 | The "softirq=" portion of the message tracks the number of RCU softirq |
221 | handlers that the stalled CPU has executed. The number before the "/" | |
222 | is the number that had executed since boot at the time that this CPU | |
223 | last noted the beginning of a grace period, which might be the current | |
224 | (stalled) grace period, or it might be some earlier grace period (for | |
225 | example, if the CPU might have been in dyntick-idle mode for an extended | |
226 | time period. The number after the "/" is the number that have executed | |
227 | since boot until the current time. If this latter number stays constant | |
228 | across repeated stall-warning messages, it is possible that RCU's softirq | |
229 | handlers are no longer able to execute on this CPU. This can happen if | |
230 | the stalled CPU is spinning with interrupts are disabled, or, in -rt | |
231 | kernels, if a high-priority process is starving RCU's softirq handler. | |
232 | ||
233 | For CONFIG_RCU_FAST_NO_HZ kernels, the "last_accelerate:" prints the | |
234 | low-order 16 bits (in hex) of the jiffies counter when this CPU last | |
235 | invoked rcu_try_advance_all_cbs() from rcu_needs_cpu() or last invoked | |
236 | rcu_accelerate_cbs() from rcu_prepare_for_idle(). The "nonlazy_posted:" | |
237 | prints the number of non-lazy callbacks posted since the last call to | |
238 | rcu_needs_cpu(). Finally, an "L" indicates that there are currently | |
239 | no non-lazy callbacks ("." is printed otherwise, as shown above) and | |
240 | "D" indicates that dyntick-idle processing is enabled ("." is printed | |
241 | otherwise, for example, if disabled via the "nohz=" kernel boot parameter). | |
24cd7fd0 | 242 | |
fb81a44b PM |
243 | If the relevant grace-period kthread has been unable to run prior to |
244 | the stall warning, the following additional line is printed: | |
245 | ||
246 | rcu_preempt kthread starved for 2023 jiffies! | |
247 | ||
248 | Starving the grace-period kthreads of CPU time can of course result in | |
249 | RCU CPU stall warnings even when all CPUs and tasks have passed through | |
250 | the required quiescent states. | |
251 | ||
24cd7fd0 PM |
252 | |
253 | Multiple Warnings From One Stall | |
254 | ||
255 | If a stall lasts long enough, multiple stall-warning messages will be | |
256 | printed for it. The second and subsequent messages are printed at | |
257 | longer intervals, so that the time between (say) the first and second | |
258 | message will be about three times the interval between the beginning | |
259 | of the stall and the first message. | |
260 | ||
261 | ||
99a930b0 PM |
262 | Stall Warnings for Expedited Grace Periods |
263 | ||
264 | If an expedited grace period detects a stall, it will place a message | |
265 | like the following in dmesg: | |
266 | ||
267 | INFO: rcu_sched detected expedited stalls on CPUs: { 1 2 6 } 26009 jiffies s: 1043 | |
268 | ||
269 | This indicates that CPUs 1, 2, and 6 have failed to respond to a | |
270 | reschedule IPI, that the expedited grace period has been going on for | |
271 | 26,009 jiffies, and that the expedited grace-period sequence counter is | |
272 | 1043. The fact that this last value is odd indicates that an expedited | |
273 | grace period is in flight. | |
274 | ||
275 | It is entirely possible to see stall warnings from normal and from | |
276 | expedited grace periods at about the same time from the same run. |