Paul E. McKenney | 64db4cf | 2008-12-18 21:55:32 +0100 | [diff] [blame] | 1 | CONFIG_RCU_TRACE debugfs Files and Formats |
| 2 | |
| 3 | |
Paul E. McKenney | 8e79e1f | 2010-11-04 14:31:19 -0700 | [diff] [blame] | 4 | The rcutree and rcutiny implementations of RCU provide debugfs trace |
| 5 | output that summarizes counters and state. This information is useful for |
| 6 | debugging RCU itself, and can sometimes also help to debug abuses of RCU. |
| 7 | The following sections describe the debugfs files and formats, first |
| 8 | for rcutree and next for rcutiny. |
Paul E. McKenney | 64db4cf | 2008-12-18 21:55:32 +0100 | [diff] [blame] | 9 | |
| 10 | |
Paul E. McKenney | 8e79e1f | 2010-11-04 14:31:19 -0700 | [diff] [blame] | 11 | CONFIG_TREE_RCU and CONFIG_TREE_PREEMPT_RCU debugfs Files and Formats |
Paul E. McKenney | 64db4cf | 2008-12-18 21:55:32 +0100 | [diff] [blame] | 12 | |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 13 | These implementations of RCU provide several debugfs directories under the |
Paul E. McKenney | 90e6ac3 | 2011-04-06 15:20:47 -0700 | [diff] [blame] | 14 | top-level directory "rcu": |
| 15 | |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 16 | rcu/rcu_bh |
| 17 | rcu/rcu_preempt |
| 18 | rcu/rcu_sched |
| 19 | |
| 20 | Each directory contains files for the corresponding flavor of RCU. |
| 21 | Note that rcu/rcu_preempt is only present for CONFIG_TREE_PREEMPT_RCU. |
| 22 | For CONFIG_TREE_RCU, the RCU flavor maps onto the RCU-sched flavor, |
| 23 | so that activity for both appears in rcu/rcu_sched. |
| 24 | |
| 25 | In addition, the following file appears in the top-level directory: |
| 26 | rcu/rcutorture. This file displays rcutorture test progress. The output |
| 27 | of "cat rcu/rcutorture" looks as follows: |
| 28 | |
| 29 | rcutorture test sequence: 0 (test in progress) |
| 30 | rcutorture update version number: 615 |
| 31 | |
| 32 | The first line shows the number of rcutorture tests that have completed |
| 33 | since boot. If a test is currently running, the "(test in progress)" |
| 34 | string will appear as shown above. The second line shows the number of |
| 35 | update cycles that the current test has started, or zero if there is |
| 36 | no test in progress. |
| 37 | |
| 38 | |
| 39 | Within each flavor directory (rcu/rcu_bh, rcu/rcu_sched, and possibly |
| 40 | also rcu/rcu_preempt) the following files will be present: |
| 41 | |
| 42 | rcudata: |
Paul E. McKenney | 90e6ac3 | 2011-04-06 15:20:47 -0700 | [diff] [blame] | 43 | Displays fields in struct rcu_data. |
Paul E. McKenney | d484a21 | 2012-10-31 13:22:08 -0700 | [diff] [blame] | 44 | rcuexp: |
| 45 | Displays statistics for expedited grace periods. |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 46 | rcugp: |
Paul E. McKenney | 90e6ac3 | 2011-04-06 15:20:47 -0700 | [diff] [blame] | 47 | Displays grace-period counters. |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 48 | rcuhier: |
Paul E. McKenney | 90e6ac3 | 2011-04-06 15:20:47 -0700 | [diff] [blame] | 49 | Displays the struct rcu_node hierarchy. |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 50 | rcu_pending: |
Paul E. McKenney | 90e6ac3 | 2011-04-06 15:20:47 -0700 | [diff] [blame] | 51 | Displays counts of the reasons rcu_pending() decided that RCU had |
| 52 | work to do. |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 53 | rcuboost: |
Paul E. McKenney | 90e6ac3 | 2011-04-06 15:20:47 -0700 | [diff] [blame] | 54 | Displays RCU boosting statistics. Only present if |
| 55 | CONFIG_RCU_BOOST=y. |
Paul E. McKenney | 64db4cf | 2008-12-18 21:55:32 +0100 | [diff] [blame] | 56 | |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 57 | The output of "cat rcu/rcu_preempt/rcudata" looks as follows: |
Paul E. McKenney | 64db4cf | 2008-12-18 21:55:32 +0100 | [diff] [blame] | 58 | |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 59 | 0!c=30455 g=30456 pq=1 qp=1 dt=126535/140000000000000/0 df=2002 of=4 ql=0/0 qs=N... b=10 ci=74572 nci=0 co=1131 ca=716 |
| 60 | 1!c=30719 g=30720 pq=1 qp=0 dt=132007/140000000000000/0 df=1874 of=10 ql=0/0 qs=N... b=10 ci=123209 nci=0 co=685 ca=982 |
| 61 | 2!c=30150 g=30151 pq=1 qp=1 dt=138537/140000000000000/0 df=1707 of=8 ql=0/0 qs=N... b=10 ci=80132 nci=0 co=1328 ca=1458 |
| 62 | 3 c=31249 g=31250 pq=1 qp=0 dt=107255/140000000000000/0 df=1749 of=6 ql=0/450 qs=NRW. b=10 ci=151700 nci=0 co=509 ca=622 |
| 63 | 4!c=29502 g=29503 pq=1 qp=1 dt=83647/140000000000000/0 df=965 of=5 ql=0/0 qs=N... b=10 ci=65643 nci=0 co=1373 ca=1521 |
| 64 | 5 c=31201 g=31202 pq=1 qp=1 dt=70422/0/0 df=535 of=7 ql=0/0 qs=.... b=10 ci=58500 nci=0 co=764 ca=698 |
| 65 | 6!c=30253 g=30254 pq=1 qp=1 dt=95363/140000000000000/0 df=780 of=5 ql=0/0 qs=N... b=10 ci=100607 nci=0 co=1414 ca=1353 |
| 66 | 7 c=31178 g=31178 pq=1 qp=0 dt=91536/0/0 df=547 of=4 ql=0/0 qs=.... b=10 ci=109819 nci=0 co=1115 ca=969 |
Paul E. McKenney | 64db4cf | 2008-12-18 21:55:32 +0100 | [diff] [blame] | 67 | |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 68 | This file has one line per CPU, or eight for this 8-CPU system. |
| 69 | The fields are as follows: |
Paul E. McKenney | 64db4cf | 2008-12-18 21:55:32 +0100 | [diff] [blame] | 70 | |
| 71 | o The number at the beginning of each line is the CPU number. |
| 72 | CPUs numbers followed by an exclamation mark are offline, |
| 73 | but have been online at least once since boot. There will be |
| 74 | no output for CPUs that have never been online, which can be |
| 75 | a good thing in the surprisingly common case where NR_CPUS is |
| 76 | substantially larger than the number of actual CPUs. |
| 77 | |
| 78 | o "c" is the count of grace periods that this CPU believes have |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 79 | completed. Offlined CPUs and CPUs in dynticks idle mode may lag |
| 80 | quite a ways behind, for example, CPU 4 under "rcu_sched" above, |
| 81 | which has been offline through 16 RCU grace periods. It is not |
| 82 | unusual to see offline CPUs lagging by thousands of grace periods. |
| 83 | Note that although the grace-period number is an unsigned long, |
| 84 | it is printed out as a signed long to allow more human-friendly |
| 85 | representation near boot time. |
Paul E. McKenney | 64db4cf | 2008-12-18 21:55:32 +0100 | [diff] [blame] | 86 | |
| 87 | o "g" is the count of grace periods that this CPU believes have |
Paul E. McKenney | 2fa218d | 2011-03-27 21:37:58 -0700 | [diff] [blame] | 88 | started. Again, offlined CPUs and CPUs in dynticks idle mode |
| 89 | may lag behind. If the "c" and "g" values are equal, this CPU |
| 90 | has already reported a quiescent state for the last RCU grace |
| 91 | period that it is aware of, otherwise, the CPU believes that it |
| 92 | owes RCU a quiescent state. |
Paul E. McKenney | 64db4cf | 2008-12-18 21:55:32 +0100 | [diff] [blame] | 93 | |
| 94 | o "pq" indicates that this CPU has passed through a quiescent state |
| 95 | for the current grace period. It is possible for "pq" to be |
| 96 | "1" and "c" different than "g", which indicates that although |
| 97 | the CPU has passed through a quiescent state, either (1) this |
| 98 | CPU has not yet reported that fact, (2) some other CPU has not |
| 99 | yet reported for this grace period, or (3) both. |
| 100 | |
Paul E. McKenney | 64db4cf | 2008-12-18 21:55:32 +0100 | [diff] [blame] | 101 | o "qp" indicates that RCU still expects a quiescent state from |
Paul E. McKenney | 2fa218d | 2011-03-27 21:37:58 -0700 | [diff] [blame] | 102 | this CPU. Offlined CPUs and CPUs in dyntick idle mode might |
| 103 | well have qp=1, which is OK: RCU is still ignoring them. |
Paul E. McKenney | 64db4cf | 2008-12-18 21:55:32 +0100 | [diff] [blame] | 104 | |
Paul E. McKenney | 64db4cf | 2008-12-18 21:55:32 +0100 | [diff] [blame] | 105 | o "dt" is the current value of the dyntick counter that is incremented |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 106 | when entering or leaving idle, either due to a context switch or |
| 107 | due to an interrupt. This number is even if the CPU is in idle |
| 108 | from RCU's viewpoint and odd otherwise. The number after the |
| 109 | first "/" is the interrupt nesting depth when in idle state, |
| 110 | or a large number added to the interrupt-nesting depth when |
| 111 | running a non-idle task. Some architectures do not accurately |
| 112 | count interrupt nesting when running in non-idle kernel context, |
| 113 | which can result in interesting anomalies such as negative |
| 114 | interrupt-nesting levels. The number after the second "/" |
| 115 | is the NMI nesting depth. |
Paul E. McKenney | 64db4cf | 2008-12-18 21:55:32 +0100 | [diff] [blame] | 116 | |
Paul E. McKenney | 64db4cf | 2008-12-18 21:55:32 +0100 | [diff] [blame] | 117 | o "df" is the number of times that some other CPU has forced a |
| 118 | quiescent state on behalf of this CPU due to this CPU being in |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 119 | idle state. |
Paul E. McKenney | 64db4cf | 2008-12-18 21:55:32 +0100 | [diff] [blame] | 120 | |
Paul E. McKenney | 64db4cf | 2008-12-18 21:55:32 +0100 | [diff] [blame] | 121 | o "of" is the number of times that some other CPU has forced a |
| 122 | quiescent state on behalf of this CPU due to this CPU being |
Paul E. McKenney | 2fa218d | 2011-03-27 21:37:58 -0700 | [diff] [blame] | 123 | offline. In a perfect world, this might never happen, but it |
Paul E. McKenney | 64db4cf | 2008-12-18 21:55:32 +0100 | [diff] [blame] | 124 | turns out that offlining and onlining a CPU can take several grace |
| 125 | periods, and so there is likely to be an extended period of time |
| 126 | when RCU believes that the CPU is online when it really is not. |
| 127 | Please note that erring in the other direction (RCU believing a |
| 128 | CPU is offline when it is really alive and kicking) is a fatal |
| 129 | error, so it makes sense to err conservatively. |
| 130 | |
Paul E. McKenney | 64db4cf | 2008-12-18 21:55:32 +0100 | [diff] [blame] | 131 | o "ql" is the number of RCU callbacks currently residing on |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 132 | this CPU. The first number is the number of "lazy" callbacks |
| 133 | that are known to RCU to only be freeing memory, and the number |
| 134 | after the "/" is the total number of callbacks, lazy or not. |
| 135 | These counters count callbacks regardless of what phase of |
| 136 | grace-period processing that they are in (new, waiting for |
| 137 | grace period to start, waiting for grace period to end, ready |
| 138 | to invoke). |
Paul E. McKenney | 64db4cf | 2008-12-18 21:55:32 +0100 | [diff] [blame] | 139 | |
Paul E. McKenney | 0ac3d13 | 2011-03-28 15:47:07 -0700 | [diff] [blame] | 140 | o "qs" gives an indication of the state of the callback queue |
| 141 | with four characters: |
| 142 | |
| 143 | "N" Indicates that there are callbacks queued that are not |
| 144 | ready to be handled by the next grace period, and thus |
| 145 | will be handled by the grace period following the next |
| 146 | one. |
| 147 | |
| 148 | "R" Indicates that there are callbacks queued that are |
| 149 | ready to be handled by the next grace period. |
| 150 | |
| 151 | "W" Indicates that there are callbacks queued that are |
| 152 | waiting on the current grace period. |
| 153 | |
| 154 | "D" Indicates that there are callbacks queued that have |
| 155 | already been handled by a prior grace period, and are |
| 156 | thus waiting to be invoked. Note that callbacks in |
| 157 | the process of being invoked are not counted here. |
| 158 | Callbacks in the process of being invoked are those |
| 159 | that have been removed from the rcu_data structures |
| 160 | queues by rcu_do_batch(), but which have not yet been |
| 161 | invoked. |
| 162 | |
| 163 | If there are no callbacks in a given one of the above states, |
| 164 | the corresponding character is replaced by ".". |
| 165 | |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 166 | o "b" is the batch limit for this CPU. If more than this number |
| 167 | of RCU callbacks is ready to invoke, then the remainder will |
| 168 | be deferred. |
| 169 | |
| 170 | o "ci" is the number of RCU callbacks that have been invoked for |
| 171 | this CPU. Note that ci+nci+ql is the number of callbacks that have |
| 172 | been registered in absence of CPU-hotplug activity. |
| 173 | |
| 174 | o "nci" is the number of RCU callbacks that have been offloaded from |
| 175 | this CPU. This will always be zero unless the kernel was built |
| 176 | with CONFIG_RCU_NOCB_CPU=y and the "rcu_nocbs=" kernel boot |
| 177 | parameter was specified. |
| 178 | |
| 179 | o "co" is the number of RCU callbacks that have been orphaned due to |
| 180 | this CPU going offline. These orphaned callbacks have been moved |
| 181 | to an arbitrarily chosen online CPU. |
| 182 | |
| 183 | o "ca" is the number of RCU callbacks that have been adopted by this |
| 184 | CPU due to other CPUs going offline. Note that ci+co-ca+ql is |
| 185 | the number of RCU callbacks registered on this CPU. |
| 186 | |
| 187 | |
| 188 | Kernels compiled with CONFIG_RCU_BOOST=y display the following from |
| 189 | /debug/rcu/rcu_preempt/rcudata: |
| 190 | |
| 191 | 0!c=12865 g=12866 pq=1 qp=1 dt=83113/140000000000000/0 df=288 of=11 ql=0/0 qs=N... kt=0/O ktl=944 b=10 ci=60709 nci=0 co=748 ca=871 |
| 192 | 1 c=14407 g=14408 pq=1 qp=0 dt=100679/140000000000000/0 df=378 of=7 ql=0/119 qs=NRW. kt=0/W ktl=9b6 b=10 ci=109740 nci=0 co=589 ca=485 |
| 193 | 2 c=14407 g=14408 pq=1 qp=0 dt=105486/0/0 df=90 of=9 ql=0/89 qs=NRW. kt=0/W ktl=c0c b=10 ci=83113 nci=0 co=533 ca=490 |
| 194 | 3 c=14407 g=14408 pq=1 qp=0 dt=107138/0/0 df=142 of=8 ql=0/188 qs=NRW. kt=0/W ktl=b96 b=10 ci=121114 nci=0 co=426 ca=290 |
| 195 | 4 c=14405 g=14406 pq=1 qp=1 dt=50238/0/0 df=706 of=7 ql=0/0 qs=.... kt=0/W ktl=812 b=10 ci=34929 nci=0 co=643 ca=114 |
| 196 | 5!c=14168 g=14169 pq=1 qp=0 dt=45465/140000000000000/0 df=161 of=11 ql=0/0 qs=N... kt=0/O ktl=b4d b=10 ci=47712 nci=0 co=677 ca=722 |
| 197 | 6 c=14404 g=14405 pq=1 qp=0 dt=59454/0/0 df=94 of=6 ql=0/0 qs=.... kt=0/W ktl=e57 b=10 ci=55597 nci=0 co=701 ca=811 |
| 198 | 7 c=14407 g=14408 pq=1 qp=1 dt=68850/0/0 df=31 of=8 ql=0/0 qs=.... kt=0/W ktl=14bd b=10 ci=77475 nci=0 co=508 ca=1042 |
| 199 | |
| 200 | This is similar to the output discussed above, but contains the following |
| 201 | additional fields: |
| 202 | |
Paul E. McKenney | 90e6ac3 | 2011-04-06 15:20:47 -0700 | [diff] [blame] | 203 | o "kt" is the per-CPU kernel-thread state. The digit preceding |
Paul E. McKenney | 15ba0ba | 2011-04-06 16:01:16 -0700 | [diff] [blame] | 204 | the first slash is zero if there is no work pending and 1 |
Paul E. McKenney | 5ece5ba | 2011-04-22 18:08:51 -0700 | [diff] [blame] | 205 | otherwise. The character between the first pair of slashes is |
| 206 | as follows: |
Paul E. McKenney | 90e6ac3 | 2011-04-06 15:20:47 -0700 | [diff] [blame] | 207 | |
| 208 | "S" The kernel thread is stopped, in other words, all |
| 209 | CPUs corresponding to this rcu_node structure are |
| 210 | offline. |
| 211 | |
| 212 | "R" The kernel thread is running. |
| 213 | |
| 214 | "W" The kernel thread is waiting because there is no work |
| 215 | for it to do. |
| 216 | |
Paul E. McKenney | 15ba0ba | 2011-04-06 16:01:16 -0700 | [diff] [blame] | 217 | "O" The kernel thread is waiting because it has been |
| 218 | forced off of its designated CPU or because its |
| 219 | ->cpus_allowed mask permits it to run on other than |
| 220 | its designated CPU. |
| 221 | |
Paul E. McKenney | 90e6ac3 | 2011-04-06 15:20:47 -0700 | [diff] [blame] | 222 | "Y" The kernel thread is yielding to avoid hogging CPU. |
| 223 | |
| 224 | "?" Unknown value, indicates a bug. |
| 225 | |
Paul E. McKenney | 15ba0ba | 2011-04-06 16:01:16 -0700 | [diff] [blame] | 226 | The number after the final slash is the CPU that the kthread |
| 227 | is actually running on. |
| 228 | |
Paul E. McKenney | d5988af | 2011-06-15 23:07:55 -0700 | [diff] [blame] | 229 | This field is displayed only for CONFIG_RCU_BOOST kernels. |
| 230 | |
Paul E. McKenney | 5ece5ba | 2011-04-22 18:08:51 -0700 | [diff] [blame] | 231 | o "ktl" is the low-order 16 bits (in hexadecimal) of the count of |
| 232 | the number of times that this CPU's per-CPU kthread has gone |
| 233 | through its loop servicing invoke_rcu_cpu_kthread() requests. |
| 234 | |
Paul E. McKenney | d5988af | 2011-06-15 23:07:55 -0700 | [diff] [blame] | 235 | This field is displayed only for CONFIG_RCU_BOOST kernels. |
| 236 | |
Paul E. McKenney | 64db4cf | 2008-12-18 21:55:32 +0100 | [diff] [blame] | 237 | |
Paul E. McKenney | d484a21 | 2012-10-31 13:22:08 -0700 | [diff] [blame] | 238 | The output of "cat rcu/rcu_preempt/rcuexp" looks as follows: |
| 239 | |
| 240 | s=21872 d=21872 w=0 tf=0 wd1=0 wd2=0 n=0 sc=21872 dt=21872 dl=0 dx=21872 |
| 241 | |
| 242 | These fields are as follows: |
| 243 | |
| 244 | o "s" is the starting sequence number. |
| 245 | |
| 246 | o "d" is the ending sequence number. When the starting and ending |
| 247 | numbers differ, there is an expedited grace period in progress. |
| 248 | |
| 249 | o "w" is the number of times that the sequence numbers have been |
| 250 | in danger of wrapping. |
| 251 | |
| 252 | o "tf" is the number of times that contention has resulted in a |
| 253 | failure to begin an expedited grace period. |
| 254 | |
| 255 | o "wd1" and "wd2" are the number of times that an attempt to |
| 256 | start an expedited grace period found that someone else had |
| 257 | completed an expedited grace period that satisfies the |
| 258 | attempted request. "Our work is done." |
| 259 | |
| 260 | o "n" is number of times that contention was so great that |
| 261 | the request was demoted from an expedited grace period to |
| 262 | a normal grace period. |
| 263 | |
| 264 | o "sc" is the number of times that the attempt to start a |
| 265 | new expedited grace period succeeded. |
| 266 | |
| 267 | o "dt" is the number of times that we attempted to update |
| 268 | the "d" counter. |
| 269 | |
| 270 | o "dl" is the number of times that we failed to update the "d" |
| 271 | counter. |
| 272 | |
| 273 | o "dx" is the number of times that we succeeded in updating |
| 274 | the "d" counter. |
| 275 | |
| 276 | |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 277 | The output of "cat rcu/rcu_preempt/rcugp" looks as follows: |
Paul E. McKenney | 269dcc1 | 2010-09-07 14:23:09 -0700 | [diff] [blame] | 278 | |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 279 | completed=31249 gpnum=31250 age=1 max=18 |
Paul E. McKenney | 269dcc1 | 2010-09-07 14:23:09 -0700 | [diff] [blame] | 280 | |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 281 | These fields are taken from the rcu_state structure, and are as follows: |
Paul E. McKenney | 64db4cf | 2008-12-18 21:55:32 +0100 | [diff] [blame] | 282 | |
| 283 | o "completed" is the number of grace periods that have completed. |
| 284 | It is comparable to the "c" field from rcu/rcudata in that a |
| 285 | CPU whose "c" field matches the value of "completed" is aware |
| 286 | that the corresponding RCU grace period has completed. |
| 287 | |
| 288 | o "gpnum" is the number of grace periods that have started. It is |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 289 | similarly comparable to the "g" field from rcu/rcudata in that |
| 290 | a CPU whose "g" field matches the value of "gpnum" is aware that |
| 291 | the corresponding RCU grace period has started. |
Paul E. McKenney | 64db4cf | 2008-12-18 21:55:32 +0100 | [diff] [blame] | 292 | |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 293 | If these two fields are equal, then there is no grace period |
| 294 | in progress, in other words, RCU is idle. On the other hand, |
| 295 | if the two fields differ (as they are above), then an RCU grace |
| 296 | period is in progress. |
Paul E. McKenney | 64db4cf | 2008-12-18 21:55:32 +0100 | [diff] [blame] | 297 | |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 298 | o "age" is the number of jiffies that the current grace period |
| 299 | has extended for, or zero if there is no grace period currently |
| 300 | in effect. |
Paul E. McKenney | 64db4cf | 2008-12-18 21:55:32 +0100 | [diff] [blame] | 301 | |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 302 | o "max" is the age in jiffies of the longest-duration grace period |
| 303 | thus far. |
Paul E. McKenney | 64db4cf | 2008-12-18 21:55:32 +0100 | [diff] [blame] | 304 | |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 305 | The output of "cat rcu/rcu_preempt/rcuhier" looks as follows: |
Paul E. McKenney | 64db4cf | 2008-12-18 21:55:32 +0100 | [diff] [blame] | 306 | |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 307 | c=14407 g=14408 s=0 jfq=2 j=c863 nfqs=12040/nfqsng=0(12040) fqlh=1051 oqlen=0/0 |
| 308 | 3/3 ..>. 0:7 ^0 |
| 309 | e/e ..>. 0:3 ^0 d/d ..>. 4:7 ^1 |
Paul E. McKenney | 64db4cf | 2008-12-18 21:55:32 +0100 | [diff] [blame] | 310 | |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 311 | The fields are as follows: |
Paul E. McKenney | 64db4cf | 2008-12-18 21:55:32 +0100 | [diff] [blame] | 312 | |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 313 | o "c" is exactly the same as "completed" under rcu/rcu_preempt/rcugp. |
Paul E. McKenney | 64db4cf | 2008-12-18 21:55:32 +0100 | [diff] [blame] | 314 | |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 315 | o "g" is exactly the same as "gpnum" under rcu/rcu_preempt/rcugp. |
| 316 | |
| 317 | o "s" is the current state of the force_quiescent_state() |
Paul E. McKenney | 64db4cf | 2008-12-18 21:55:32 +0100 | [diff] [blame] | 318 | state machine. |
| 319 | |
| 320 | o "jfq" is the number of jiffies remaining for this grace period |
| 321 | before force_quiescent_state() is invoked to help push things |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 322 | along. Note that CPUs in idle mode throughout the grace period |
| 323 | will not report on their own, but rather must be check by some |
| 324 | other CPU via force_quiescent_state(). |
Paul E. McKenney | 64db4cf | 2008-12-18 21:55:32 +0100 | [diff] [blame] | 325 | |
| 326 | o "j" is the low-order four hex digits of the jiffies counter. |
| 327 | Yes, Paul did run into a number of problems that turned out to |
| 328 | be due to the jiffies counter no longer counting. Why do you ask? |
| 329 | |
| 330 | o "nfqs" is the number of calls to force_quiescent_state() since |
| 331 | boot. |
| 332 | |
| 333 | o "nfqsng" is the number of useless calls to force_quiescent_state(), |
| 334 | where there wasn't actually a grace period active. This can |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 335 | no longer happen due to grace-period processing being pushed |
| 336 | into a kthread. The number in parentheses is the difference |
Paul E. McKenney | 64db4cf | 2008-12-18 21:55:32 +0100 | [diff] [blame] | 337 | between "nfqs" and "nfqsng", or the number of times that |
| 338 | force_quiescent_state() actually did some real work. |
| 339 | |
| 340 | o "fqlh" is the number of calls to force_quiescent_state() that |
| 341 | exited immediately (without even being counted in nfqs above) |
| 342 | due to contention on ->fqslock. |
| 343 | |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 344 | o Each element of the form "3/3 ..>. 0:7 ^0" represents one rcu_node |
| 345 | structure. Each line represents one level of the hierarchy, |
| 346 | from root to leaves. It is best to think of the rcu_data |
| 347 | structures as forming yet another level after the leaves. |
| 348 | Note that there might be either one, two, three, or even four |
| 349 | levels of rcu_node structures, depending on the relationship |
| 350 | between CONFIG_RCU_FANOUT, CONFIG_RCU_FANOUT_LEAF (possibly |
| 351 | adjusted using the rcu_fanout_leaf kernel boot parameter), and |
| 352 | CONFIG_NR_CPUS (possibly adjusted using the nr_cpu_ids count of |
| 353 | possible CPUs for the booting hardware). |
Paul E. McKenney | 0edf1a6 | 2009-10-14 10:15:59 -0700 | [diff] [blame] | 354 | |
Paul E. McKenney | 64db4cf | 2008-12-18 21:55:32 +0100 | [diff] [blame] | 355 | o The numbers separated by the "/" are the qsmask followed |
| 356 | by the qsmaskinit. The qsmask will have one bit |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 357 | set for each entity in the next lower level that has |
| 358 | not yet checked in for the current grace period ("e" |
| 359 | indicating CPUs 5, 6, and 7 in the example above). |
Paul E. McKenney | 64db4cf | 2008-12-18 21:55:32 +0100 | [diff] [blame] | 360 | The qsmaskinit will have one bit for each entity that is |
| 361 | currently expected to check in during each grace period. |
| 362 | The value of qsmaskinit is assigned to that of qsmask |
| 363 | at the beginning of each grace period. |
| 364 | |
Paul E. McKenney | 0edf1a6 | 2009-10-14 10:15:59 -0700 | [diff] [blame] | 365 | o The characters separated by the ">" indicate the state |
Paul E. McKenney | 12f5f52 | 2010-11-29 21:56:39 -0800 | [diff] [blame] | 366 | of the blocked-tasks lists. A "G" preceding the ">" |
Paul E. McKenney | 0edf1a6 | 2009-10-14 10:15:59 -0700 | [diff] [blame] | 367 | indicates that at least one task blocked in an RCU |
| 368 | read-side critical section blocks the current grace |
Paul E. McKenney | 12f5f52 | 2010-11-29 21:56:39 -0800 | [diff] [blame] | 369 | period, while a "E" preceding the ">" indicates that |
| 370 | at least one task blocked in an RCU read-side critical |
| 371 | section blocks the current expedited grace period. |
| 372 | A "T" character following the ">" indicates that at |
| 373 | least one task is blocked within an RCU read-side |
| 374 | critical section, regardless of whether any current |
| 375 | grace period (expedited or normal) is inconvenienced. |
| 376 | A "." character appears if the corresponding condition |
| 377 | does not hold, so that "..>." indicates that no tasks |
| 378 | are blocked. In contrast, "GE>T" indicates maximal |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 379 | inconvenience from blocked tasks. CONFIG_TREE_RCU |
| 380 | builds of the kernel will always show "..>.". |
Paul E. McKenney | 0edf1a6 | 2009-10-14 10:15:59 -0700 | [diff] [blame] | 381 | |
Paul E. McKenney | 64db4cf | 2008-12-18 21:55:32 +0100 | [diff] [blame] | 382 | o The numbers separated by the ":" are the range of CPUs |
| 383 | served by this struct rcu_node. This can be helpful |
| 384 | in working out how the hierarchy is wired together. |
| 385 | |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 386 | For example, the example rcu_node structure shown above |
| 387 | has "0:7", indicating that it covers CPUs 0 through 7. |
Paul E. McKenney | 64db4cf | 2008-12-18 21:55:32 +0100 | [diff] [blame] | 388 | |
| 389 | o The number after the "^" indicates the bit in the |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 390 | next higher level rcu_node structure that this rcu_node |
| 391 | structure corresponds to. For example, the "d/d ..>. 4:7 |
| 392 | ^1" has a "1" in this position, indicating that it |
| 393 | corresponds to the "1" bit in the "3" shown in the |
| 394 | "3/3 ..>. 0:7 ^0" entry on the next level up. |
Paul E. McKenney | 6fd9b3a | 2009-04-13 21:31:18 -0700 | [diff] [blame] | 395 | |
| 396 | |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 397 | The output of "cat rcu/rcu_sched/rcu_pending" looks as follows: |
Paul E. McKenney | 6fd9b3a | 2009-04-13 21:31:18 -0700 | [diff] [blame] | 398 | |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 399 | 0!np=26111 qsp=29 rpq=5386 cbr=1 cng=570 gpc=3674 gps=577 nn=15903 |
| 400 | 1!np=28913 qsp=35 rpq=6097 cbr=1 cng=448 gpc=3700 gps=554 nn=18113 |
| 401 | 2!np=32740 qsp=37 rpq=6202 cbr=0 cng=476 gpc=4627 gps=546 nn=20889 |
| 402 | 3 np=23679 qsp=22 rpq=5044 cbr=1 cng=415 gpc=3403 gps=347 nn=14469 |
| 403 | 4!np=30714 qsp=4 rpq=5574 cbr=0 cng=528 gpc=3931 gps=639 nn=20042 |
| 404 | 5 np=28910 qsp=2 rpq=5246 cbr=0 cng=428 gpc=4105 gps=709 nn=18422 |
| 405 | 6!np=38648 qsp=5 rpq=7076 cbr=0 cng=840 gpc=4072 gps=961 nn=25699 |
| 406 | 7 np=37275 qsp=2 rpq=6873 cbr=0 cng=868 gpc=3416 gps=971 nn=25147 |
Paul E. McKenney | 6fd9b3a | 2009-04-13 21:31:18 -0700 | [diff] [blame] | 407 | |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 408 | The fields are as follows: |
| 409 | |
| 410 | o The leading number is the CPU number, with "!" indicating |
| 411 | an offline CPU. |
Paul E. McKenney | 6fd9b3a | 2009-04-13 21:31:18 -0700 | [diff] [blame] | 412 | |
| 413 | o "np" is the number of times that __rcu_pending() has been invoked |
| 414 | for the corresponding flavor of RCU. |
| 415 | |
| 416 | o "qsp" is the number of times that the RCU was waiting for a |
| 417 | quiescent state from this CPU. |
| 418 | |
Paul E. McKenney | d21670a | 2010-04-14 17:39:26 -0700 | [diff] [blame] | 419 | o "rpq" is the number of times that the CPU had passed through |
| 420 | a quiescent state, but not yet reported it to RCU. |
| 421 | |
Paul E. McKenney | 6fd9b3a | 2009-04-13 21:31:18 -0700 | [diff] [blame] | 422 | o "cbr" is the number of times that this CPU had RCU callbacks |
| 423 | that had passed through a grace period, and were thus ready |
| 424 | to be invoked. |
| 425 | |
| 426 | o "cng" is the number of times that this CPU needed another |
| 427 | grace period while RCU was idle. |
| 428 | |
| 429 | o "gpc" is the number of times that an old grace period had |
| 430 | completed, but this CPU was not yet aware of it. |
| 431 | |
| 432 | o "gps" is the number of times that a new grace period had started, |
| 433 | but this CPU was not yet aware of it. |
| 434 | |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 435 | o "nn" is the number of times that this CPU needed nothing. |
Paul E. McKenney | 90e6ac3 | 2011-04-06 15:20:47 -0700 | [diff] [blame] | 436 | |
| 437 | |
| 438 | The output of "cat rcu/rcuboost" looks as follows: |
| 439 | |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 440 | 0:3 tasks=.... kt=W ntb=0 neb=0 nnb=0 j=c864 bt=c894 |
| 441 | balk: nt=0 egt=4695 bt=0 nb=0 ny=56 nos=0 |
| 442 | 4:7 tasks=.... kt=W ntb=0 neb=0 nnb=0 j=c864 bt=c894 |
| 443 | balk: nt=0 egt=6541 bt=0 nb=0 ny=126 nos=0 |
Paul E. McKenney | 90e6ac3 | 2011-04-06 15:20:47 -0700 | [diff] [blame] | 444 | |
| 445 | This information is output only for rcu_preempt. Each two-line entry |
| 446 | corresponds to a leaf rcu_node strcuture. The fields are as follows: |
| 447 | |
| 448 | o "n:m" is the CPU-number range for the corresponding two-line |
| 449 | entry. In the sample output above, the first entry covers |
Paul E. McKenney | 40e80c4 | 2012-10-31 13:00:15 -0700 | [diff] [blame] | 450 | CPUs zero through three and the second entry covers CPUs four |
| 451 | through seven. |
Paul E. McKenney | 90e6ac3 | 2011-04-06 15:20:47 -0700 | [diff] [blame] | 452 | |
| 453 | o "tasks=TNEB" gives the state of the various segments of the |
| 454 | rnp->blocked_tasks list: |
| 455 | |
| 456 | "T" This indicates that there are some tasks that blocked |
| 457 | while running on one of the corresponding CPUs while |
| 458 | in an RCU read-side critical section. |
| 459 | |
| 460 | "N" This indicates that some of the blocked tasks are preventing |
| 461 | the current normal (non-expedited) grace period from |
| 462 | completing. |
| 463 | |
| 464 | "E" This indicates that some of the blocked tasks are preventing |
| 465 | the current expedited grace period from completing. |
| 466 | |
| 467 | "B" This indicates that some of the blocked tasks are in |
| 468 | need of RCU priority boosting. |
| 469 | |
| 470 | Each character is replaced with "." if the corresponding |
| 471 | condition does not hold. |
| 472 | |
| 473 | o "kt" is the state of the RCU priority-boosting kernel |
| 474 | thread associated with the corresponding rcu_node structure. |
| 475 | The state can be one of the following: |
| 476 | |
| 477 | "S" The kernel thread is stopped, in other words, all |
| 478 | CPUs corresponding to this rcu_node structure are |
| 479 | offline. |
| 480 | |
| 481 | "R" The kernel thread is running. |
| 482 | |
| 483 | "W" The kernel thread is waiting because there is no work |
| 484 | for it to do. |
| 485 | |
| 486 | "Y" The kernel thread is yielding to avoid hogging CPU. |
| 487 | |
| 488 | "?" Unknown value, indicates a bug. |
| 489 | |
| 490 | o "ntb" is the number of tasks boosted. |
| 491 | |
| 492 | o "neb" is the number of tasks boosted in order to complete an |
| 493 | expedited grace period. |
| 494 | |
| 495 | o "nnb" is the number of tasks boosted in order to complete a |
| 496 | normal (non-expedited) grace period. When boosting a task |
| 497 | that was blocking both an expedited and a normal grace period, |
| 498 | it is counted against the expedited total above. |
| 499 | |
| 500 | o "j" is the low-order 16 bits of the jiffies counter in |
| 501 | hexadecimal. |
| 502 | |
| 503 | o "bt" is the low-order 16 bits of the value that the jiffies |
| 504 | counter will have when we next start boosting, assuming that |
| 505 | the current grace period does not end beforehand. This is |
| 506 | also in hexadecimal. |
| 507 | |
| 508 | o "balk: nt" counts the number of times we didn't boost (in |
| 509 | other words, we balked) even though it was time to boost because |
| 510 | there were no blocked tasks to boost. This situation occurs |
| 511 | when there is one blocked task on one rcu_node structure and |
| 512 | none on some other rcu_node structure. |
| 513 | |
| 514 | o "egt" counts the number of times we balked because although |
| 515 | there were blocked tasks, none of them were blocking the |
| 516 | current grace period, whether expedited or otherwise. |
| 517 | |
| 518 | o "bt" counts the number of times we balked because boosting |
| 519 | had already been initiated for the current grace period. |
| 520 | |
| 521 | o "nb" counts the number of times we balked because there |
| 522 | was at least one task blocking the current non-expedited grace |
| 523 | period that never had blocked. If it is already running, it |
| 524 | just won't help to boost its priority! |
| 525 | |
| 526 | o "ny" counts the number of times we balked because it was |
| 527 | not yet time to start boosting. |
| 528 | |
| 529 | o "nos" counts the number of times we balked for other |
| 530 | reasons, e.g., the grace period ended first. |
| 531 | |
| 532 | |
Paul E. McKenney | 8e79e1f | 2010-11-04 14:31:19 -0700 | [diff] [blame] | 533 | CONFIG_TINY_RCU and CONFIG_TINY_PREEMPT_RCU debugfs Files and Formats |
| 534 | |
| 535 | These implementations of RCU provides a single debugfs file under the |
| 536 | top-level directory RCU, namely rcu/rcudata, which displays fields in |
| 537 | rcu_bh_ctrlblk, rcu_sched_ctrlblk and, for CONFIG_TINY_PREEMPT_RCU, |
| 538 | rcu_preempt_ctrlblk. |
| 539 | |
| 540 | The output of "cat rcu/rcudata" is as follows: |
| 541 | |
| 542 | rcu_preempt: qlen=24 gp=1097669 g197/p197/c197 tasks=... |
| 543 | ttb=. btg=no ntb=184 neb=0 nnb=183 j=01f7 bt=0274 |
| 544 | normal balk: nt=1097669 gt=0 bt=371 b=0 ny=25073378 nos=0 |
| 545 | exp balk: bt=0 nos=0 |
| 546 | rcu_sched: qlen: 0 |
| 547 | rcu_bh: qlen: 0 |
| 548 | |
| 549 | This is split into rcu_preempt, rcu_sched, and rcu_bh sections, with the |
| 550 | rcu_preempt section appearing only in CONFIG_TINY_PREEMPT_RCU builds. |
| 551 | The last three lines of the rcu_preempt section appear only in |
| 552 | CONFIG_RCU_BOOST kernel builds. The fields are as follows: |
| 553 | |
| 554 | o "qlen" is the number of RCU callbacks currently waiting either |
| 555 | for an RCU grace period or waiting to be invoked. This is the |
| 556 | only field present for rcu_sched and rcu_bh, due to the |
| 557 | short-circuiting of grace period in those two cases. |
| 558 | |
| 559 | o "gp" is the number of grace periods that have completed. |
| 560 | |
| 561 | o "g197/p197/c197" displays the grace-period state, with the |
| 562 | "g" number being the number of grace periods that have started |
| 563 | (mod 256), the "p" number being the number of grace periods |
| 564 | that the CPU has responded to (also mod 256), and the "c" |
| 565 | number being the number of grace periods that have completed |
| 566 | (once again mode 256). |
| 567 | |
| 568 | Why have both "gp" and "g"? Because the data flowing into |
| 569 | "gp" is only present in a CONFIG_RCU_TRACE kernel. |
| 570 | |
| 571 | o "tasks" is a set of bits. The first bit is "T" if there are |
| 572 | currently tasks that have recently blocked within an RCU |
| 573 | read-side critical section, the second bit is "N" if any of the |
| 574 | aforementioned tasks are blocking the current RCU grace period, |
| 575 | and the third bit is "E" if any of the aforementioned tasks are |
| 576 | blocking the current expedited grace period. Each bit is "." |
| 577 | if the corresponding condition does not hold. |
| 578 | |
| 579 | o "ttb" is a single bit. It is "B" if any of the blocked tasks |
| 580 | need to be priority boosted and "." otherwise. |
| 581 | |
| 582 | o "btg" indicates whether boosting has been carried out during |
| 583 | the current grace period, with "exp" indicating that boosting |
| 584 | is in progress for an expedited grace period, "no" indicating |
| 585 | that boosting has not yet started for a normal grace period, |
| 586 | "begun" indicating that boosting has bebug for a normal grace |
| 587 | period, and "done" indicating that boosting has completed for |
| 588 | a normal grace period. |
| 589 | |
| 590 | o "ntb" is the total number of tasks subjected to RCU priority boosting |
| 591 | periods since boot. |
| 592 | |
| 593 | o "neb" is the number of expedited grace periods that have had |
| 594 | to resort to RCU priority boosting since boot. |
| 595 | |
| 596 | o "nnb" is the number of normal grace periods that have had |
| 597 | to resort to RCU priority boosting since boot. |
| 598 | |
Paul E. McKenney | 90e6ac3 | 2011-04-06 15:20:47 -0700 | [diff] [blame] | 599 | o "j" is the low-order 16 bits of the jiffies counter in hexadecimal. |
Paul E. McKenney | 8e79e1f | 2010-11-04 14:31:19 -0700 | [diff] [blame] | 600 | |
Paul E. McKenney | 90e6ac3 | 2011-04-06 15:20:47 -0700 | [diff] [blame] | 601 | o "bt" is the low-order 16 bits of the value that the jiffies counter |
Paul E. McKenney | 8e79e1f | 2010-11-04 14:31:19 -0700 | [diff] [blame] | 602 | will have at the next time that boosting is scheduled to begin. |
| 603 | |
| 604 | o In the line beginning with "normal balk", the fields are as follows: |
| 605 | |
| 606 | o "nt" is the number of times that the system balked from |
| 607 | boosting because there were no blocked tasks to boost. |
| 608 | Note that the system will balk from boosting even if the |
| 609 | grace period is overdue when the currently running task |
| 610 | is looping within an RCU read-side critical section. |
| 611 | There is no point in boosting in this case, because |
| 612 | boosting a running task won't make it run any faster. |
| 613 | |
| 614 | o "gt" is the number of times that the system balked |
| 615 | from boosting because, although there were blocked tasks, |
| 616 | none of them were preventing the current grace period |
| 617 | from completing. |
| 618 | |
| 619 | o "bt" is the number of times that the system balked |
| 620 | from boosting because boosting was already in progress. |
| 621 | |
| 622 | o "b" is the number of times that the system balked from |
| 623 | boosting because boosting had already completed for |
| 624 | the grace period in question. |
| 625 | |
| 626 | o "ny" is the number of times that the system balked from |
| 627 | boosting because it was not yet time to start boosting |
| 628 | the grace period in question. |
| 629 | |
| 630 | o "nos" is the number of times that the system balked from |
| 631 | boosting for inexplicable ("not otherwise specified") |
| 632 | reasons. This can actually happen due to races involving |
| 633 | increments of the jiffies counter. |
| 634 | |
| 635 | o In the line beginning with "exp balk", the fields are as follows: |
| 636 | |
| 637 | o "bt" is the number of times that the system balked from |
| 638 | boosting because there were no blocked tasks to boost. |
| 639 | |
| 640 | o "nos" is the number of times that the system balked from |
| 641 | boosting for inexplicable ("not otherwise specified") |
| 642 | reasons. |