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