Paul E. McKenney | 4c54005 | 2010-01-14 16:10:57 -0800 | [diff] [blame] | 1 | Using RCU's CPU Stall Detector |
| 2 | |
Paul E. McKenney | a00e0d71 | 2011-02-08 17:14:39 -0800 | [diff] [blame] | 3 | The rcu_cpu_stall_suppress module parameter enables RCU's CPU stall |
| 4 | detector, which detects conditions that unduly delay RCU grace periods. |
| 5 | This module parameter enables CPU stall detection by default, but |
| 6 | may be overridden via boot-time parameter or at runtime via sysfs. |
| 7 | The stall detector's idea of what constitutes "unduly delayed" is |
| 8 | controlled by a set of kernel configuration variables and cpp macros: |
Paul E. McKenney | 4c54005 | 2010-01-14 16:10:57 -0800 | [diff] [blame] | 9 | |
Paul E. McKenney | a00e0d71 | 2011-02-08 17:14:39 -0800 | [diff] [blame] | 10 | CONFIG_RCU_CPU_STALL_TIMEOUT |
Paul E. McKenney | 4c54005 | 2010-01-14 16:10:57 -0800 | [diff] [blame] | 11 | |
Paul E. McKenney | a00e0d71 | 2011-02-08 17:14:39 -0800 | [diff] [blame] | 12 | This kernel configuration parameter defines the period of time |
| 13 | that RCU will wait from the beginning of a grace period until it |
| 14 | issues an RCU CPU stall warning. This time period is normally |
Paul E. McKenney | 24cd7fd | 2012-01-20 17:35:55 -0800 | [diff] [blame] | 15 | sixty seconds. |
Paul E. McKenney | 4c54005 | 2010-01-14 16:10:57 -0800 | [diff] [blame] | 16 | |
Paul E. McKenney | 24cd7fd | 2012-01-20 17:35:55 -0800 | [diff] [blame] | 17 | This configuration parameter may be changed at runtime via the |
| 18 | /sys/module/rcutree/parameters/rcu_cpu_stall_timeout, however |
| 19 | this parameter is checked only at the beginning of a cycle. |
| 20 | So if you are 30 seconds into a 70-second stall, setting this |
| 21 | sysfs parameter to (say) five will shorten the timeout for the |
| 22 | -next- stall, or the following warning for the current stall |
| 23 | (assuming the stall lasts long enough). It will not affect the |
| 24 | timing of the next warning for the current stall. |
Paul E. McKenney | 4c54005 | 2010-01-14 16:10:57 -0800 | [diff] [blame] | 25 | |
Paul E. McKenney | 24cd7fd | 2012-01-20 17:35:55 -0800 | [diff] [blame] | 26 | Stall-warning messages may be enabled and disabled completely via |
| 27 | /sys/module/rcutree/parameters/rcu_cpu_stall_suppress. |
| 28 | |
| 29 | CONFIG_RCU_CPU_STALL_VERBOSE |
| 30 | |
| 31 | This kernel configuration parameter causes the stall warning to |
| 32 | also dump the stacks of any tasks that are blocking the current |
| 33 | RCU-preempt grace period. |
| 34 | |
| 35 | RCU_CPU_STALL_INFO |
| 36 | |
| 37 | This kernel configuration parameter causes the stall warning to |
| 38 | print out additional per-CPU diagnostic information, including |
| 39 | information on scheduling-clock ticks and RCU's idle-CPU tracking. |
| 40 | |
| 41 | RCU_STALL_DELAY_DELTA |
| 42 | |
| 43 | Although the lockdep facility is extremely useful, it does add |
| 44 | some overhead. Therefore, under CONFIG_PROVE_RCU, the |
| 45 | RCU_STALL_DELAY_DELTA macro allows five extra seconds before |
| 46 | giving an RCU CPU stall warning message. |
Paul E. McKenney | 4c54005 | 2010-01-14 16:10:57 -0800 | [diff] [blame] | 47 | |
| 48 | RCU_STALL_RAT_DELAY |
| 49 | |
Paul E. McKenney | f1d507b | 2010-04-15 15:49:46 -0700 | [diff] [blame] | 50 | The CPU stall detector tries to make the offending CPU print its |
| 51 | own warnings, as this often gives better-quality stack traces. |
| 52 | However, if the offending CPU does not detect its own stall in |
| 53 | the number of jiffies specified by RCU_STALL_RAT_DELAY, then |
| 54 | some other CPU will complain. This delay is normally set to |
| 55 | two jiffies. |
Paul E. McKenney | 4c54005 | 2010-01-14 16:10:57 -0800 | [diff] [blame] | 56 | |
Paul E. McKenney | f1d507b | 2010-04-15 15:49:46 -0700 | [diff] [blame] | 57 | When a CPU detects that it is stalling, it will print a message similar |
| 58 | to the following: |
| 59 | |
| 60 | INFO: rcu_sched_state detected stall on CPU 5 (t=2500 jiffies) |
| 61 | |
| 62 | This message indicates that CPU 5 detected that it was causing a stall, |
| 63 | and that the stall was affecting RCU-sched. This message will normally be |
| 64 | followed by a stack dump of the offending CPU. On TREE_RCU kernel builds, |
| 65 | RCU and RCU-sched are implemented by the same underlying mechanism, |
| 66 | while on TREE_PREEMPT_RCU kernel builds, RCU is instead implemented |
| 67 | by rcu_preempt_state. |
| 68 | |
| 69 | On the other hand, if the offending CPU fails to print out a stall-warning |
| 70 | message quickly enough, some other CPU will print a message similar to |
| 71 | the following: |
| 72 | |
| 73 | INFO: rcu_bh_state detected stalls on CPUs/tasks: { 3 5 } (detected by 2, 2502 jiffies) |
| 74 | |
| 75 | This message indicates that CPU 2 detected that CPUs 3 and 5 were both |
| 76 | causing stalls, and that the stall was affecting RCU-bh. This message |
| 77 | will normally be followed by stack dumps for each CPU. Please note that |
| 78 | TREE_PREEMPT_RCU builds can be stalled by tasks as well as by CPUs, |
| 79 | and that the tasks will be indicated by PID, for example, "P3421". |
| 80 | It is even possible for a rcu_preempt_state stall to be caused by both |
| 81 | CPUs -and- tasks, in which case the offending CPUs and tasks will all |
| 82 | be called out in the list. |
| 83 | |
| 84 | Finally, if the grace period ends just as the stall warning starts |
| 85 | printing, there will be a spurious stall-warning message: |
| 86 | |
| 87 | INFO: rcu_bh_state detected stalls on CPUs/tasks: { } (detected by 4, 2502 jiffies) |
| 88 | |
| 89 | This is rare, but does happen from time to time in real life. |
| 90 | |
Paul E. McKenney | 24cd7fd | 2012-01-20 17:35:55 -0800 | [diff] [blame] | 91 | If the CONFIG_RCU_CPU_STALL_INFO kernel configuration parameter is set, |
| 92 | more information is printed with the stall-warning message, for example: |
| 93 | |
| 94 | INFO: rcu_preempt detected stall on CPU |
| 95 | 0: (63959 ticks this GP) idle=241/3fffffffffffffff/0 |
| 96 | (t=65000 jiffies) |
| 97 | |
| 98 | In kernels with CONFIG_RCU_FAST_NO_HZ, even more information is |
| 99 | printed: |
| 100 | |
| 101 | INFO: rcu_preempt detected stall on CPU |
| 102 | 0: (64628 ticks this GP) idle=dd5/3fffffffffffffff/0 drain=0 . timer=-1 |
| 103 | (t=65000 jiffies) |
| 104 | |
| 105 | The "(64628 ticks this GP)" indicates that this CPU has taken more |
| 106 | than 64,000 scheduling-clock interrupts during the current stalled |
| 107 | grace period. If the CPU was not yet aware of the current grace |
| 108 | period (for example, if it was offline), then this part of the message |
| 109 | indicates how many grace periods behind the CPU is. |
| 110 | |
| 111 | The "idle=" portion of the message prints the dyntick-idle state. |
| 112 | The hex number before the first "/" is the low-order 12 bits of the |
| 113 | dynticks counter, which will have an even-numbered value if the CPU is |
| 114 | in dyntick-idle mode and an odd-numbered value otherwise. The hex |
| 115 | number between the two "/"s is the value of the nesting, which will |
| 116 | be a small positive number if in the idle loop and a very large positive |
| 117 | number (as shown above) otherwise. |
| 118 | |
| 119 | For CONFIG_RCU_FAST_NO_HZ kernels, the "drain=0" indicates that the |
| 120 | CPU is not in the process of trying to force itself into dyntick-idle |
| 121 | state, the "." indicates that the CPU has not given up forcing RCU |
| 122 | into dyntick-idle mode (it would be "H" otherwise), and the "timer=-1" |
| 123 | indicates that the CPU has not recented forced RCU into dyntick-idle |
| 124 | mode (it would otherwise indicate the number of microseconds remaining |
| 125 | in this forced state). |
| 126 | |
| 127 | |
| 128 | Multiple Warnings From One Stall |
| 129 | |
| 130 | If a stall lasts long enough, multiple stall-warning messages will be |
| 131 | printed for it. The second and subsequent messages are printed at |
| 132 | longer intervals, so that the time between (say) the first and second |
| 133 | message will be about three times the interval between the beginning |
| 134 | of the stall and the first message. |
| 135 | |
| 136 | |
| 137 | What Causes RCU CPU Stall Warnings? |
| 138 | |
Paul E. McKenney | f1d507b | 2010-04-15 15:49:46 -0700 | [diff] [blame] | 139 | So your kernel printed an RCU CPU stall warning. The next question is |
| 140 | "What caused it?" The following problems can result in RCU CPU stall |
| 141 | warnings: |
Paul E. McKenney | 4c54005 | 2010-01-14 16:10:57 -0800 | [diff] [blame] | 142 | |
| 143 | o A CPU looping in an RCU read-side critical section. |
| 144 | |
Paul E. McKenney | f1d507b | 2010-04-15 15:49:46 -0700 | [diff] [blame] | 145 | o A CPU looping with interrupts disabled. This condition can |
| 146 | result in RCU-sched and RCU-bh stalls. |
Paul E. McKenney | 4c54005 | 2010-01-14 16:10:57 -0800 | [diff] [blame] | 147 | |
Paul E. McKenney | f1d507b | 2010-04-15 15:49:46 -0700 | [diff] [blame] | 148 | o A CPU looping with preemption disabled. This condition can |
| 149 | result in RCU-sched stalls and, if ksoftirqd is in use, RCU-bh |
| 150 | stalls. |
| 151 | |
| 152 | o A CPU looping with bottom halves disabled. This condition can |
| 153 | result in RCU-sched and RCU-bh stalls. |
Paul E. McKenney | 4c54005 | 2010-01-14 16:10:57 -0800 | [diff] [blame] | 154 | |
| 155 | o For !CONFIG_PREEMPT kernels, a CPU looping anywhere in the kernel |
| 156 | without invoking schedule(). |
| 157 | |
Paul E. McKenney | 2c96c77 | 2010-08-23 16:34:02 -0700 | [diff] [blame] | 158 | o A CPU-bound real-time task in a CONFIG_PREEMPT kernel, which might |
| 159 | happen to preempt a low-priority task in the middle of an RCU |
| 160 | read-side critical section. This is especially damaging if |
| 161 | that low-priority task is not permitted to run on any other CPU, |
| 162 | in which case the next RCU grace period can never complete, which |
| 163 | will eventually cause the system to run out of memory and hang. |
| 164 | While the system is in the process of running itself out of |
| 165 | memory, you might see stall-warning messages. |
| 166 | |
| 167 | o A CPU-bound real-time task in a CONFIG_PREEMPT_RT kernel that |
| 168 | is running at a higher priority than the RCU softirq threads. |
| 169 | This will prevent RCU callbacks from ever being invoked, |
| 170 | and in a CONFIG_TREE_PREEMPT_RCU kernel will further prevent |
| 171 | RCU grace periods from ever completing. Either way, the |
| 172 | system will eventually run out of memory and hang. In the |
| 173 | CONFIG_TREE_PREEMPT_RCU case, you might see stall-warning |
| 174 | messages. |
| 175 | |
Paul E. McKenney | 2c01531 | 2011-10-02 17:21:18 -0700 | [diff] [blame] | 176 | o A hardware or software issue shuts off the scheduler-clock |
| 177 | interrupt on a CPU that is not in dyntick-idle mode. This |
| 178 | problem really has happened, and seems to be most likely to |
| 179 | result in RCU CPU stall warnings for CONFIG_NO_HZ=n kernels. |
| 180 | |
Paul E. McKenney | 4c54005 | 2010-01-14 16:10:57 -0800 | [diff] [blame] | 181 | o A bug in the RCU implementation. |
| 182 | |
| 183 | o A hardware failure. This is quite unlikely, but has occurred |
Paul E. McKenney | f1d507b | 2010-04-15 15:49:46 -0700 | [diff] [blame] | 184 | at least once in real life. A CPU failed in a running system, |
Paul E. McKenney | 4c54005 | 2010-01-14 16:10:57 -0800 | [diff] [blame] | 185 | becoming unresponsive, but not causing an immediate crash. |
| 186 | This resulted in a series of RCU CPU stall warnings, eventually |
| 187 | leading the realization that the CPU had failed. |
| 188 | |
Paul E. McKenney | 9ceae0e | 2011-11-03 13:43:24 -0700 | [diff] [blame] | 189 | The RCU, RCU-sched, and RCU-bh implementations have CPU stall warning. |
| 190 | SRCU does not have its own CPU stall warnings, but its calls to |
| 191 | synchronize_sched() will result in RCU-sched detecting RCU-sched-related |
| 192 | CPU stalls. Please note that RCU only detects CPU stalls when there is |
| 193 | a grace period in progress. No grace period, no CPU stall warnings. |
Paul E. McKenney | 4c54005 | 2010-01-14 16:10:57 -0800 | [diff] [blame] | 194 | |
Paul E. McKenney | f1d507b | 2010-04-15 15:49:46 -0700 | [diff] [blame] | 195 | To diagnose the cause of the stall, inspect the stack traces. |
| 196 | The offending function will usually be near the top of the stack. |
| 197 | If you have a series of stall warnings from a single extended stall, |
| 198 | comparing the stack traces can often help determine where the stall |
| 199 | is occurring, which will usually be in the function nearest the top of |
| 200 | that portion of the stack which remains the same from trace to trace. |
| 201 | If you can reliably trigger the stall, ftrace can be quite helpful. |
Paul E. McKenney | 4c54005 | 2010-01-14 16:10:57 -0800 | [diff] [blame] | 202 | |
Paul E. McKenney | 24cd7fd | 2012-01-20 17:35:55 -0800 | [diff] [blame] | 203 | RCU bugs can often be debugged with the help of CONFIG_RCU_TRACE |
| 204 | and with RCU's event tracing. |