]>
Commit | Line | Data |
---|---|---|
f2286ab9 MCC |
1 | .. SPDX-License-Identifier: GPL-2.0 |
2 | ||
3 | ============================== | |
4c54005c | 4 | Using RCU's CPU Stall Detector |
f2286ab9 | 5 | ============================== |
4c54005c | 6 | |
8e2a4397 PM |
7 | This document first discusses what sorts of issues RCU's CPU stall |
8 | detector can locate, and then discusses kernel parameters and Kconfig | |
9 | options that can be used to fine-tune the detector's operation. Finally, | |
10 | this document explains the stall detector's "splat" format. | |
11 | ||
12 | ||
13 | What Causes RCU CPU Stall Warnings? | |
f2286ab9 | 14 | =================================== |
8e2a4397 PM |
15 | |
16 | So your kernel printed an RCU CPU stall warning. The next question is | |
17 | "What caused it?" The following problems can result in RCU CPU stall | |
18 | warnings: | |
19 | ||
f2286ab9 | 20 | - A CPU looping in an RCU read-side critical section. |
8e2a4397 | 21 | |
f2286ab9 | 22 | - A CPU looping with interrupts disabled. |
8e2a4397 | 23 | |
f2286ab9 | 24 | - A CPU looping with preemption disabled. |
8e2a4397 | 25 | |
f2286ab9 | 26 | - A CPU looping with bottom halves disabled. |
8e2a4397 | 27 | |
81ad58be | 28 | - For !CONFIG_PREEMPTION kernels, a CPU looping anywhere in the kernel |
f2b1760a PM |
29 | without invoking schedule(). If the looping in the kernel is |
30 | really expected and desirable behavior, you might need to add | |
31 | some calls to cond_resched(). | |
8e2a4397 | 32 | |
f2286ab9 | 33 | - Booting Linux using a console connection that is too slow to |
8e2a4397 | 34 | keep up with the boot-time console-message rate. For example, |
e3879ecd | 35 | a 115Kbaud serial console can be *way* too slow to keep up |
8e2a4397 PM |
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 | ||
f2286ab9 | 40 | - Anything that prevents RCU's grace-period kthreads from running. |
8e2a4397 PM |
41 | This can result in the "All QSes seen" console-log message. |
42 | This message will include information on when the kthread last | |
dfa0ee48 | 43 | ran and how often it should be expected to run. It can also |
f2286ab9 | 44 | result in the ``rcu_.*kthread starved for`` console-log message, |
dfa0ee48 | 45 | which will include additional debugging information. |
8e2a4397 | 46 | |
81ad58be | 47 | - A CPU-bound real-time task in a CONFIG_PREEMPTION kernel, which might |
8e2a4397 PM |
48 | happen to preempt a low-priority task in the middle of an RCU |
49 | read-side critical section. This is especially damaging if | |
50 | that low-priority task is not permitted to run on any other CPU, | |
51 | in which case the next RCU grace period can never complete, which | |
52 | will eventually cause the system to run out of memory and hang. | |
53 | While the system is in the process of running itself out of | |
54 | memory, you might see stall-warning messages. | |
55 | ||
f2286ab9 | 56 | - A CPU-bound real-time task in a CONFIG_PREEMPT_RT kernel that |
8e2a4397 PM |
57 | is running at a higher priority than the RCU softirq threads. |
58 | This will prevent RCU callbacks from ever being invoked, | |
59 | and in a CONFIG_PREEMPT_RCU kernel will further prevent | |
60 | RCU grace periods from ever completing. Either way, the | |
61 | system will eventually run out of memory and hang. In the | |
62 | CONFIG_PREEMPT_RCU case, you might see stall-warning | |
63 | messages. | |
64 | ||
0500873d PM |
65 | You can use the rcutree.kthread_prio kernel boot parameter to |
66 | increase the scheduling priority of RCU's kthreads, which can | |
67 | help avoid this problem. However, please note that doing this | |
68 | can increase your system's context-switch rate and thus degrade | |
69 | performance. | |
70 | ||
f2286ab9 | 71 | - A periodic interrupt whose handler takes longer than the time |
dfa0ee48 PM |
72 | interval between successive pairs of interrupts. This can |
73 | prevent RCU's kthreads and softirq handlers from running. | |
74 | Note that certain high-overhead debugging options, for example | |
75 | the function_graph tracer, can result in interrupt handler taking | |
76 | considerably longer than normal, which can in turn result in | |
77 | RCU CPU stall warnings. | |
78 | ||
f2286ab9 | 79 | - Testing a workload on a fast system, tuning the stall-warning |
3d916a44 PM |
80 | timeout down to just barely avoid RCU CPU stall warnings, and then |
81 | running the same workload with the same stall-warning timeout on a | |
82 | slow system. Note that thermal throttling and on-demand governors | |
83 | can cause a single system to be sometimes fast and sometimes slow! | |
84 | ||
f2286ab9 | 85 | - A hardware or software issue shuts off the scheduler-clock |
8e2a4397 PM |
86 | interrupt on a CPU that is not in dyntick-idle mode. This |
87 | problem really has happened, and seems to be most likely to | |
88 | result in RCU CPU stall warnings for CONFIG_NO_HZ_COMMON=n kernels. | |
89 | ||
b81898e3 PM |
90 | - A hardware or software issue that prevents time-based wakeups |
91 | from occurring. These issues can range from misconfigured or | |
92 | buggy timer hardware through bugs in the interrupt or exception | |
93 | path (whether hardware, firmware, or software) through bugs | |
94 | in Linux's timer subsystem through bugs in the scheduler, and, | |
683954e5 NU |
95 | yes, even including bugs in RCU itself. It can also result in |
96 | the ``rcu_.*timer wakeup didn't happen for`` console-log message, | |
97 | which will include additional debugging information. | |
b81898e3 | 98 | |
f2286ab9 | 99 | - A bug in the RCU implementation. |
8e2a4397 | 100 | |
f2286ab9 | 101 | - A hardware failure. This is quite unlikely, but has occurred |
8e2a4397 PM |
102 | at least once in real life. A CPU failed in a running system, |
103 | becoming unresponsive, but not causing an immediate crash. | |
104 | This resulted in a series of RCU CPU stall warnings, eventually | |
105 | leading the realization that the CPU had failed. | |
106 | ||
77095901 | 107 | The RCU, RCU-sched, and RCU-tasks implementations have CPU stall warning. |
e3879ecd | 108 | Note that SRCU does *not* have CPU stall warnings. Please note that |
77095901 | 109 | RCU only detects CPU stalls when there is a grace period in progress. |
8e2a4397 PM |
110 | No grace period, no CPU stall warnings. |
111 | ||
112 | To diagnose the cause of the stall, inspect the stack traces. | |
113 | The offending function will usually be near the top of the stack. | |
114 | If you have a series of stall warnings from a single extended stall, | |
115 | comparing the stack traces can often help determine where the stall | |
116 | is occurring, which will usually be in the function nearest the top of | |
117 | that portion of the stack which remains the same from trace to trace. | |
118 | If you can reliably trigger the stall, ftrace can be quite helpful. | |
119 | ||
120 | RCU bugs can often be debugged with the help of CONFIG_RCU_TRACE | |
121 | and with RCU's event tracing. For information on RCU's event tracing, | |
122 | see include/trace/events/rcu.h. | |
123 | ||
124 | ||
125 | Fine-Tuning the RCU CPU Stall Detector | |
f2286ab9 | 126 | ====================================== |
8e2a4397 PM |
127 | |
128 | The rcuupdate.rcu_cpu_stall_suppress module parameter disables RCU's | |
129 | CPU stall detector, which detects conditions that unduly delay RCU grace | |
130 | periods. This module parameter enables CPU stall detection by default, | |
131 | but may be overridden via boot-time parameter or at runtime via sysfs. | |
a00e0d71 PM |
132 | The stall detector's idea of what constitutes "unduly delayed" is |
133 | controlled by a set of kernel configuration variables and cpp macros: | |
4c54005c | 134 | |
a00e0d71 | 135 | CONFIG_RCU_CPU_STALL_TIMEOUT |
f2286ab9 | 136 | ---------------------------- |
4c54005c | 137 | |
a00e0d71 PM |
138 | This kernel configuration parameter defines the period of time |
139 | that RCU will wait from the beginning of a grace period until it | |
140 | issues an RCU CPU stall warning. This time period is normally | |
64d3b7a1 | 141 | 21 seconds. |
4c54005c | 142 | |
24cd7fd0 | 143 | This configuration parameter may be changed at runtime via the |
84596ccb | 144 | /sys/module/rcupdate/parameters/rcu_cpu_stall_timeout, however |
24cd7fd0 | 145 | this parameter is checked only at the beginning of a cycle. |
64d3b7a1 | 146 | So if you are 10 seconds into a 40-second stall, setting this |
24cd7fd0 | 147 | sysfs parameter to (say) five will shorten the timeout for the |
e3879ecd | 148 | *next* stall, or the following warning for the current stall |
24cd7fd0 PM |
149 | (assuming the stall lasts long enough). It will not affect the |
150 | timing of the next warning for the current stall. | |
4c54005c | 151 | |
24cd7fd0 | 152 | Stall-warning messages may be enabled and disabled completely via |
96224daa | 153 | /sys/module/rcupdate/parameters/rcu_cpu_stall_suppress. |
24cd7fd0 | 154 | |
24cd7fd0 | 155 | RCU_STALL_DELAY_DELTA |
f2286ab9 | 156 | --------------------- |
24cd7fd0 PM |
157 | |
158 | Although the lockdep facility is extremely useful, it does add | |
159 | some overhead. Therefore, under CONFIG_PROVE_RCU, the | |
160 | RCU_STALL_DELAY_DELTA macro allows five extra seconds before | |
64d3b7a1 PM |
161 | giving an RCU CPU stall warning message. (This is a cpp |
162 | macro, not a kernel configuration parameter.) | |
4c54005c PM |
163 | |
164 | RCU_STALL_RAT_DELAY | |
f2286ab9 | 165 | ------------------- |
4c54005c | 166 | |
f1d507be PM |
167 | The CPU stall detector tries to make the offending CPU print its |
168 | own warnings, as this often gives better-quality stack traces. | |
169 | However, if the offending CPU does not detect its own stall in | |
170 | the number of jiffies specified by RCU_STALL_RAT_DELAY, then | |
171 | some other CPU will complain. This delay is normally set to | |
64d3b7a1 PM |
172 | two jiffies. (This is a cpp macro, not a kernel configuration |
173 | parameter.) | |
4c54005c | 174 | |
37fe5f0e | 175 | rcupdate.rcu_task_stall_timeout |
f2286ab9 | 176 | ------------------------------- |
37fe5f0e PM |
177 | |
178 | This boot/sysfs parameter controls the RCU-tasks stall warning | |
179 | interval. A value of zero or less suppresses RCU-tasks stall | |
180 | warnings. A positive value sets the stall-warning interval | |
588759a3 | 181 | in seconds. An RCU-tasks stall warning starts with the line: |
37fe5f0e PM |
182 | |
183 | INFO: rcu_tasks detected stalls on tasks: | |
184 | ||
185 | And continues with the output of sched_show_task() for each | |
186 | task stalling the current RCU-tasks grace period. | |
187 | ||
8e2a4397 PM |
188 | |
189 | Interpreting RCU's CPU Stall-Detector "Splats" | |
f2286ab9 | 190 | ============================================== |
8e2a4397 | 191 | |
99c0974f PM |
192 | For non-RCU-tasks flavors of RCU, when a CPU detects that some other |
193 | CPU is stalling, it will print a message similar to the following:: | |
f1d507be | 194 | |
d3cf5176 PM |
195 | INFO: rcu_sched detected stalls on CPUs/tasks: |
196 | 2-...: (3 GPs behind) idle=06c/0/0 softirq=1453/1455 fqs=0 | |
197 | 16-...: (0 ticks this GP) idle=81c/0/0 softirq=764/764 fqs=0 | |
e1333462 | 198 | (detected by 32, t=2603 jiffies, g=7075, q=625) |
f1d507be | 199 | |
d3cf5176 PM |
200 | This message indicates that CPU 32 detected that CPUs 2 and 16 were both |
201 | causing stalls, and that the stall was affecting RCU-sched. This message | |
f1d507be | 202 | will normally be followed by stack dumps for each CPU. Please note that |
d3cf5176 PM |
203 | PREEMPT_RCU builds can be stalled by tasks as well as by CPUs, and that |
204 | the tasks will be indicated by PID, for example, "P3421". It is even | |
e3879ecd | 205 | possible for an rcu_state stall to be caused by both CPUs *and* tasks, |
dd944caa | 206 | in which case the offending CPUs and tasks will all be called out in the list. |
99c0974f PM |
207 | In some cases, CPUs will detect themselves stalling, which will result |
208 | in a self-detected stall. | |
24cd7fd0 | 209 | |
d3cf5176 PM |
210 | CPU 2's "(3 GPs behind)" indicates that this CPU has not interacted with |
211 | the RCU core for the past three grace periods. In contrast, CPU 16's "(0 | |
212 | ticks this GP)" indicates that this CPU has not taken any scheduling-clock | |
213 | interrupts during the current stalled grace period. | |
24cd7fd0 PM |
214 | |
215 | The "idle=" portion of the message prints the dyntick-idle state. | |
216 | The hex number before the first "/" is the low-order 12 bits of the | |
d3cf5176 PM |
217 | dynticks counter, which will have an even-numbered value if the CPU |
218 | is in dyntick-idle mode and an odd-numbered value otherwise. The hex | |
219 | number between the two "/"s is the value of the nesting, which will be | |
220 | a small non-negative number if in the idle loop (as shown above) and a | |
221 | very large positive number otherwise. | |
24cd7fd0 | 222 | |
6231069b PM |
223 | The "softirq=" portion of the message tracks the number of RCU softirq |
224 | handlers that the stalled CPU has executed. The number before the "/" | |
225 | is the number that had executed since boot at the time that this CPU | |
226 | last noted the beginning of a grace period, which might be the current | |
227 | (stalled) grace period, or it might be some earlier grace period (for | |
228 | example, if the CPU might have been in dyntick-idle mode for an extended | |
9984fd7e | 229 | time period). The number after the "/" is the number that have executed |
6231069b PM |
230 | since boot until the current time. If this latter number stays constant |
231 | across repeated stall-warning messages, it is possible that RCU's softirq | |
232 | handlers are no longer able to execute on this CPU. This can happen if | |
233 | the stalled CPU is spinning with interrupts are disabled, or, in -rt | |
234 | kernels, if a high-priority process is starving RCU's softirq handler. | |
235 | ||
a78ad16c | 236 | The "fqs=" shows the number of force-quiescent-state idle/offline |
d3cf5176 PM |
237 | detection passes that the grace-period kthread has made across this |
238 | CPU since the last time that this CPU noted the beginning of a grace | |
239 | period. | |
240 | ||
241 | The "detected by" line indicates which CPU detected the stall (in this | |
e1333462 PM |
242 | case, CPU 32), how many jiffies have elapsed since the start of the grace |
243 | period (in this case 2603), the grace-period sequence number (7075), and | |
244 | an estimate of the total number of RCU callbacks queued across all CPUs | |
245 | (625 in this case). | |
d3cf5176 PM |
246 | |
247 | In kernels with CONFIG_RCU_FAST_NO_HZ, more information is printed | |
f2286ab9 | 248 | for each CPU:: |
d3cf5176 | 249 | |
77a40f97 | 250 | 0: (64628 ticks this GP) idle=dd5/3fffffffffffffff/0 softirq=82/543 last_accelerate: a345/d342 dyntick_enabled: 1 |
d3cf5176 PM |
251 | |
252 | The "last_accelerate:" prints the low-order 16 bits (in hex) of the | |
253 | jiffies counter when this CPU last invoked rcu_try_advance_all_cbs() | |
254 | from rcu_needs_cpu() or last invoked rcu_accelerate_cbs() from | |
77a40f97 JFG |
255 | rcu_prepare_for_idle(). "dyntick_enabled: 1" indicates that dyntick-idle |
256 | processing is enabled. | |
d3cf5176 PM |
257 | |
258 | If the grace period ends just as the stall warning starts printing, | |
259 | there will be a spurious stall-warning message, which will include | |
f2286ab9 | 260 | the following:: |
d3cf5176 PM |
261 | |
262 | INFO: Stall ended before state dump start | |
263 | ||
264 | This is rare, but does happen from time to time in real life. It is also | |
265 | possible for a zero-jiffy stall to be flagged in this case, depending | |
266 | on how the stall warning and the grace-period initialization happen to | |
267 | interact. Please note that it is not possible to entirely eliminate this | |
268 | sort of false positive without resorting to things like stop_machine(), | |
269 | which is overkill for this sort of problem. | |
270 | ||
271 | If all CPUs and tasks have passed through quiescent states, but the | |
272 | grace period has nevertheless failed to end, the stall-warning splat | |
f2286ab9 | 273 | will include something like the following:: |
d3cf5176 PM |
274 | |
275 | All QSes seen, last rcu_preempt kthread activity 23807 (4297905177-4297881370), jiffies_till_next_fqs=3, root ->qsmask 0x0 | |
276 | ||
277 | The "23807" indicates that it has been more than 23 thousand jiffies | |
278 | since the grace-period kthread ran. The "jiffies_till_next_fqs" | |
279 | indicates how frequently that kthread should run, giving the number | |
280 | of jiffies between force-quiescent-state scans, in this case three, | |
281 | which is way less than 23807. Finally, the root rcu_node structure's | |
282 | ->qsmask field is printed, which will normally be zero. | |
24cd7fd0 | 283 | |
fb81a44b | 284 | If the relevant grace-period kthread has been unable to run prior to |
d3cf5176 | 285 | the stall warning, as was the case in the "All QSes seen" line above, |
f2286ab9 | 286 | the following additional line is printed:: |
fb81a44b | 287 | |
99c0974f PM |
288 | rcu_sched kthread starved for 23807 jiffies! g7075 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1 ->cpu=5 |
289 | Unless rcu_sched kthread gets sufficient CPU time, OOM is now expected behavior. | |
fb81a44b | 290 | |
d3cf5176 PM |
291 | Starving the grace-period kthreads of CPU time can of course result |
292 | in RCU CPU stall warnings even when all CPUs and tasks have passed | |
e1333462 PM |
293 | through the required quiescent states. The "g" number shows the current |
294 | grace-period sequence number, the "f" precedes the ->gp_flags command | |
295 | to the grace-period kthread, the "RCU_GP_WAIT_FQS" indicates that the | |
296 | kthread is waiting for a short timeout, the "state" precedes value of the | |
297 | task_struct ->state field, and the "cpu" indicates that the grace-period | |
298 | kthread last ran on CPU 5. | |
fb81a44b | 299 | |
683954e5 NU |
300 | If the relevant grace-period kthread does not wake from FQS wait in a |
301 | reasonable time, then the following additional line is printed:: | |
302 | ||
303 | kthread timer wakeup didn't happen for 23804 jiffies! g7076 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402 | |
304 | ||
305 | The "23804" indicates that kthread's timer expired more than 23 thousand | |
306 | jiffies ago. The rest of the line has meaning similar to the kthread | |
307 | starvation case. | |
308 | ||
309 | Additionally, the following line is printed:: | |
310 | ||
311 | Possible timer handling issue on cpu=4 timer-softirq=11142 | |
312 | ||
313 | Here "cpu" indicates that the grace-period kthread last ran on CPU 4, | |
314 | where it queued the fqs timer. The number following the "timer-softirq" | |
315 | is the current ``TIMER_SOFTIRQ`` count on cpu 4. If this value does not | |
316 | change on successive RCU CPU stall warnings, there is further reason to | |
317 | suspect a timer problem. | |
318 | ||
99c0974f PM |
319 | These messages are usually followed by stack dumps of the CPUs and tasks |
320 | involved in the stall. These stack traces can help you locate the cause | |
321 | of the stall, keeping in mind that the CPU detecting the stall will have | |
322 | an interrupt frame that is mainly devoted to detecting the stall. | |
323 | ||
24cd7fd0 PM |
324 | |
325 | Multiple Warnings From One Stall | |
f2286ab9 | 326 | ================================ |
24cd7fd0 | 327 | |
99c0974f PM |
328 | If a stall lasts long enough, multiple stall-warning messages will |
329 | be printed for it. The second and subsequent messages are printed at | |
24cd7fd0 PM |
330 | longer intervals, so that the time between (say) the first and second |
331 | message will be about three times the interval between the beginning | |
99c0974f PM |
332 | of the stall and the first message. It can be helpful to compare the |
333 | stack dumps for the different messages for the same stalled grace period. | |
24cd7fd0 PM |
334 | |
335 | ||
99a930b0 | 336 | Stall Warnings for Expedited Grace Periods |
f2286ab9 | 337 | ========================================== |
99a930b0 PM |
338 | |
339 | If an expedited grace period detects a stall, it will place a message | |
f2286ab9 | 340 | like the following in dmesg:: |
99a930b0 | 341 | |
d3cf5176 PM |
342 | INFO: rcu_sched detected expedited stalls on CPUs/tasks: { 7-... } 21119 jiffies s: 73 root: 0x2/. |
343 | ||
344 | This indicates that CPU 7 has failed to respond to a reschedule IPI. | |
345 | The three periods (".") following the CPU number indicate that the CPU | |
346 | is online (otherwise the first period would instead have been "O"), | |
347 | that the CPU was online at the beginning of the expedited grace period | |
348 | (otherwise the second period would have instead been "o"), and that | |
349 | the CPU has been online at least once since boot (otherwise, the third | |
350 | period would instead have been "N"). The number before the "jiffies" | |
351 | indicates that the expedited grace period has been going on for 21,119 | |
352 | jiffies. The number following the "s:" indicates that the expedited | |
353 | grace-period sequence counter is 73. The fact that this last value is | |
354 | odd indicates that an expedited grace period is in flight. The number | |
355 | following "root:" is a bitmask that indicates which children of the root | |
356 | rcu_node structure correspond to CPUs and/or tasks that are blocking the | |
357 | current expedited grace period. If the tree had more than one level, | |
358 | additional hex numbers would be printed for the states of the other | |
359 | rcu_node structures in the tree. | |
360 | ||
361 | As with normal grace periods, PREEMPT_RCU builds can be stalled by | |
362 | tasks as well as by CPUs, and that the tasks will be indicated by PID, | |
363 | for example, "P3421". | |
99a930b0 PM |
364 | |
365 | It is entirely possible to see stall warnings from normal and from | |
d3cf5176 | 366 | expedited grace periods at about the same time during the same run. |