Commit | Line | Data |
---|---|---|
64db4cff PM |
1 | CONFIG_RCU_TRACE debugfs Files and Formats |
2 | ||
3 | ||
4 | The rcupreempt and rcutree 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 | Note that the rcuclassic implementation of RCU does not provide debugfs | |
8 | trace output. | |
9 | ||
10 | The following sections describe the debugfs files and formats for | |
11 | preemptable RCU (rcupreempt) and hierarchical RCU (rcutree). | |
12 | ||
13 | ||
14 | Preemptable RCU debugfs Files and Formats | |
15 | ||
16 | This implementation of RCU provides three debugfs files under the | |
17 | top-level directory RCU: rcu/rcuctrs (which displays the per-CPU | |
18 | counters used by preemptable RCU) rcu/rcugp (which displays grace-period | |
19 | counters), and rcu/rcustats (which internal counters for debugging RCU). | |
20 | ||
21 | The output of "cat rcu/rcuctrs" looks as follows: | |
22 | ||
23 | CPU last cur F M | |
24 | 0 5 -5 0 0 | |
25 | 1 -1 0 0 0 | |
26 | 2 0 1 0 0 | |
27 | 3 0 1 0 0 | |
28 | 4 0 1 0 0 | |
29 | 5 0 1 0 0 | |
30 | 6 0 2 0 0 | |
31 | 7 0 -1 0 0 | |
32 | 8 0 1 0 0 | |
33 | ggp = 26226, state = waitzero | |
34 | ||
35 | The per-CPU fields are as follows: | |
36 | ||
37 | o "CPU" gives the CPU number. Offline CPUs are not displayed. | |
38 | ||
39 | o "last" gives the value of the counter that is being decremented | |
40 | for the current grace period phase. In the example above, | |
41 | the counters sum to 4, indicating that there are still four | |
42 | RCU read-side critical sections still running that started | |
43 | before the last counter flip. | |
44 | ||
45 | o "cur" gives the value of the counter that is currently being | |
46 | both incremented (by rcu_read_lock()) and decremented (by | |
47 | rcu_read_unlock()). In the example above, the counters sum to | |
48 | 1, indicating that there is only one RCU read-side critical section | |
49 | still running that started after the last counter flip. | |
50 | ||
51 | o "F" indicates whether RCU is waiting for this CPU to acknowledge | |
52 | a counter flip. In the above example, RCU is not waiting on any, | |
53 | which is consistent with the state being "waitzero" rather than | |
54 | "waitack". | |
55 | ||
56 | o "M" indicates whether RCU is waiting for this CPU to execute a | |
57 | memory barrier. In the above example, RCU is not waiting on any, | |
58 | which is consistent with the state being "waitzero" rather than | |
59 | "waitmb". | |
60 | ||
61 | o "ggp" is the global grace-period counter. | |
62 | ||
63 | o "state" is the RCU state, which can be one of the following: | |
64 | ||
65 | o "idle": there is no grace period in progress. | |
66 | ||
67 | o "waitack": RCU just incremented the global grace-period | |
68 | counter, which has the effect of reversing the roles of | |
69 | the "last" and "cur" counters above, and is waiting for | |
70 | all the CPUs to acknowledge the flip. Once the flip has | |
71 | been acknowledged, CPUs will no longer be incrementing | |
72 | what are now the "last" counters, so that their sum will | |
73 | decrease monotonically down to zero. | |
74 | ||
75 | o "waitzero": RCU is waiting for the sum of the "last" counters | |
76 | to decrease to zero. | |
77 | ||
78 | o "waitmb": RCU is waiting for each CPU to execute a memory | |
79 | barrier, which ensures that instructions from a given CPU's | |
80 | last RCU read-side critical section cannot be reordered | |
81 | with instructions following the memory-barrier instruction. | |
82 | ||
83 | The output of "cat rcu/rcugp" looks as follows: | |
84 | ||
85 | oldggp=48870 newggp=48873 | |
86 | ||
87 | Note that reading from this file provokes a synchronize_rcu(). The | |
88 | "oldggp" value is that of "ggp" from rcu/rcuctrs above, taken before | |
89 | executing the synchronize_rcu(), and the "newggp" value is also the | |
90 | "ggp" value, but taken after the synchronize_rcu() command returns. | |
91 | ||
92 | ||
93 | The output of "cat rcu/rcugp" looks as follows: | |
94 | ||
95 | na=1337955 nl=40 wa=1337915 wl=44 da=1337871 dl=0 dr=1337871 di=1337871 | |
96 | 1=50989 e1=6138 i1=49722 ie1=82 g1=49640 a1=315203 ae1=265563 a2=49640 | |
97 | z1=1401244 ze1=1351605 z2=49639 m1=5661253 me1=5611614 m2=49639 | |
98 | ||
99 | These are counters tracking internal preemptable-RCU events, however, | |
100 | some of them may be useful for debugging algorithms using RCU. In | |
101 | particular, the "nl", "wl", and "dl" values track the number of RCU | |
102 | callbacks in various states. The fields are as follows: | |
103 | ||
104 | o "na" is the total number of RCU callbacks that have been enqueued | |
105 | since boot. | |
106 | ||
107 | o "nl" is the number of RCU callbacks waiting for the previous | |
108 | grace period to end so that they can start waiting on the next | |
109 | grace period. | |
110 | ||
111 | o "wa" is the total number of RCU callbacks that have started waiting | |
112 | for a grace period since boot. "na" should be roughly equal to | |
113 | "nl" plus "wa". | |
114 | ||
115 | o "wl" is the number of RCU callbacks currently waiting for their | |
116 | grace period to end. | |
117 | ||
118 | o "da" is the total number of RCU callbacks whose grace periods | |
119 | have completed since boot. "wa" should be roughly equal to | |
120 | "wl" plus "da". | |
121 | ||
122 | o "dr" is the total number of RCU callbacks that have been removed | |
123 | from the list of callbacks ready to invoke. "dr" should be roughly | |
124 | equal to "da". | |
125 | ||
126 | o "di" is the total number of RCU callbacks that have been invoked | |
127 | since boot. "di" should be roughly equal to "da", though some | |
128 | early versions of preemptable RCU had a bug so that only the | |
129 | last CPU's count of invocations was displayed, rather than the | |
130 | sum of all CPU's counts. | |
131 | ||
132 | o "1" is the number of calls to rcu_try_flip(). This should be | |
133 | roughly equal to the sum of "e1", "i1", "a1", "z1", and "m1" | |
134 | described below. In other words, the number of times that | |
135 | the state machine is visited should be equal to the sum of the | |
136 | number of times that each state is visited plus the number of | |
137 | times that the state-machine lock acquisition failed. | |
138 | ||
139 | o "e1" is the number of times that rcu_try_flip() was unable to | |
140 | acquire the fliplock. | |
141 | ||
142 | o "i1" is the number of calls to rcu_try_flip_idle(). | |
143 | ||
144 | o "ie1" is the number of times rcu_try_flip_idle() exited early | |
145 | due to the calling CPU having no work for RCU. | |
146 | ||
147 | o "g1" is the number of times that rcu_try_flip_idle() decided | |
148 | to start a new grace period. "i1" should be roughly equal to | |
149 | "ie1" plus "g1". | |
150 | ||
151 | o "a1" is the number of calls to rcu_try_flip_waitack(). | |
152 | ||
153 | o "ae1" is the number of times that rcu_try_flip_waitack() found | |
154 | that at least one CPU had not yet acknowledge the new grace period | |
155 | (AKA "counter flip"). | |
156 | ||
157 | o "a2" is the number of time rcu_try_flip_waitack() found that | |
158 | all CPUs had acknowledged. "a1" should be roughly equal to | |
159 | "ae1" plus "a2". (This particular output was collected on | |
160 | a 128-CPU machine, hence the smaller-than-usual fraction of | |
161 | calls to rcu_try_flip_waitack() finding all CPUs having already | |
162 | acknowledged.) | |
163 | ||
164 | o "z1" is the number of calls to rcu_try_flip_waitzero(). | |
165 | ||
166 | o "ze1" is the number of times that rcu_try_flip_waitzero() found | |
167 | that not all of the old RCU read-side critical sections had | |
168 | completed. | |
169 | ||
170 | o "z2" is the number of times that rcu_try_flip_waitzero() finds | |
171 | the sum of the counters equal to zero, in other words, that | |
172 | all of the old RCU read-side critical sections had completed. | |
173 | The value of "z1" should be roughly equal to "ze1" plus | |
174 | "z2". | |
175 | ||
176 | o "m1" is the number of calls to rcu_try_flip_waitmb(). | |
177 | ||
178 | o "me1" is the number of times that rcu_try_flip_waitmb() finds | |
179 | that at least one CPU has not yet executed a memory barrier. | |
180 | ||
181 | o "m2" is the number of times that rcu_try_flip_waitmb() finds that | |
182 | all CPUs have executed a memory barrier. | |
183 | ||
184 | ||
185 | Hierarchical RCU debugfs Files and Formats | |
186 | ||
187 | This implementation of RCU provides three debugfs files under the | |
188 | top-level directory RCU: rcu/rcudata (which displays fields in struct | |
189 | rcu_data), rcu/rcugp (which displays grace-period counters), and | |
190 | rcu/rcuhier (which displays the struct rcu_node hierarchy). | |
191 | ||
192 | The output of "cat rcu/rcudata" looks as follows: | |
193 | ||
194 | rcu: | |
195 | 0 c=4011 g=4012 pq=1 pqc=4011 qp=0 rpfq=1 rp=3c2a dt=23301/73 dn=2 df=1882 of=0 ri=2126 ql=2 b=10 | |
196 | 1 c=4011 g=4012 pq=1 pqc=4011 qp=0 rpfq=3 rp=39a6 dt=78073/1 dn=2 df=1402 of=0 ri=1875 ql=46 b=10 | |
197 | 2 c=4010 g=4010 pq=1 pqc=4010 qp=0 rpfq=-5 rp=1d12 dt=16646/0 dn=2 df=3140 of=0 ri=2080 ql=0 b=10 | |
198 | 3 c=4012 g=4013 pq=1 pqc=4012 qp=1 rpfq=3 rp=2b50 dt=21159/1 dn=2 df=2230 of=0 ri=1923 ql=72 b=10 | |
199 | 4 c=4012 g=4013 pq=1 pqc=4012 qp=1 rpfq=3 rp=1644 dt=5783/1 dn=2 df=3348 of=0 ri=2805 ql=7 b=10 | |
200 | 5 c=4012 g=4013 pq=0 pqc=4011 qp=1 rpfq=3 rp=1aac dt=5879/1 dn=2 df=3140 of=0 ri=2066 ql=10 b=10 | |
201 | 6 c=4012 g=4013 pq=1 pqc=4012 qp=1 rpfq=3 rp=ed8 dt=5847/1 dn=2 df=3797 of=0 ri=1266 ql=10 b=10 | |
202 | 7 c=4012 g=4013 pq=1 pqc=4012 qp=1 rpfq=3 rp=1fa2 dt=6199/1 dn=2 df=2795 of=0 ri=2162 ql=28 b=10 | |
203 | rcu_bh: | |
204 | 0 c=-268 g=-268 pq=1 pqc=-268 qp=0 rpfq=-145 rp=21d6 dt=23301/73 dn=2 df=0 of=0 ri=0 ql=0 b=10 | |
205 | 1 c=-268 g=-268 pq=1 pqc=-268 qp=1 rpfq=-170 rp=20ce dt=78073/1 dn=2 df=26 of=0 ri=5 ql=0 b=10 | |
206 | 2 c=-268 g=-268 pq=1 pqc=-268 qp=1 rpfq=-83 rp=fbd dt=16646/0 dn=2 df=28 of=0 ri=4 ql=0 b=10 | |
207 | 3 c=-268 g=-268 pq=1 pqc=-268 qp=0 rpfq=-105 rp=178c dt=21159/1 dn=2 df=28 of=0 ri=2 ql=0 b=10 | |
208 | 4 c=-268 g=-268 pq=1 pqc=-268 qp=1 rpfq=-30 rp=b54 dt=5783/1 dn=2 df=32 of=0 ri=0 ql=0 b=10 | |
209 | 5 c=-268 g=-268 pq=1 pqc=-268 qp=1 rpfq=-29 rp=df5 dt=5879/1 dn=2 df=30 of=0 ri=3 ql=0 b=10 | |
210 | 6 c=-268 g=-268 pq=1 pqc=-268 qp=1 rpfq=-28 rp=788 dt=5847/1 dn=2 df=32 of=0 ri=0 ql=0 b=10 | |
211 | 7 c=-268 g=-268 pq=1 pqc=-268 qp=1 rpfq=-53 rp=1098 dt=6199/1 dn=2 df=30 of=0 ri=3 ql=0 b=10 | |
212 | ||
213 | The first section lists the rcu_data structures for rcu, the second for | |
214 | rcu_bh. Each section has one line per CPU, or eight for this 8-CPU system. | |
215 | The fields are as follows: | |
216 | ||
217 | o The number at the beginning of each line is the CPU number. | |
218 | CPUs numbers followed by an exclamation mark are offline, | |
219 | but have been online at least once since boot. There will be | |
220 | no output for CPUs that have never been online, which can be | |
221 | a good thing in the surprisingly common case where NR_CPUS is | |
222 | substantially larger than the number of actual CPUs. | |
223 | ||
224 | o "c" is the count of grace periods that this CPU believes have | |
225 | completed. CPUs in dynticks idle mode may lag quite a ways | |
226 | behind, for example, CPU 4 under "rcu" above, which has slept | |
227 | through the past 25 RCU grace periods. It is not unusual to | |
228 | see CPUs lagging by thousands of grace periods. | |
229 | ||
230 | o "g" is the count of grace periods that this CPU believes have | |
231 | started. Again, CPUs in dynticks idle mode may lag behind. | |
232 | If the "c" and "g" values are equal, this CPU has already | |
233 | reported a quiescent state for the last RCU grace period that | |
234 | it is aware of, otherwise, the CPU believes that it owes RCU a | |
235 | quiescent state. | |
236 | ||
237 | o "pq" indicates that this CPU has passed through a quiescent state | |
238 | for the current grace period. It is possible for "pq" to be | |
239 | "1" and "c" different than "g", which indicates that although | |
240 | the CPU has passed through a quiescent state, either (1) this | |
241 | CPU has not yet reported that fact, (2) some other CPU has not | |
242 | yet reported for this grace period, or (3) both. | |
243 | ||
244 | o "pqc" indicates which grace period the last-observed quiescent | |
245 | state for this CPU corresponds to. This is important for handling | |
246 | the race between CPU 0 reporting an extended dynticks-idle | |
247 | quiescent state for CPU 1 and CPU 1 suddenly waking up and | |
248 | reporting its own quiescent state. If CPU 1 was the last CPU | |
249 | for the current grace period, then the CPU that loses this race | |
250 | will attempt to incorrectly mark CPU 1 as having checked in for | |
251 | the next grace period! | |
252 | ||
253 | o "qp" indicates that RCU still expects a quiescent state from | |
254 | this CPU. | |
255 | ||
256 | o "rpfq" is the number of rcu_pending() calls on this CPU required | |
257 | to induce this CPU to invoke force_quiescent_state(). | |
258 | ||
259 | o "rp" is low-order four hex digits of the count of how many times | |
260 | rcu_pending() has been invoked on this CPU. | |
261 | ||
262 | o "dt" is the current value of the dyntick counter that is incremented | |
263 | when entering or leaving dynticks idle state, either by the | |
264 | scheduler or by irq. The number after the "/" is the interrupt | |
265 | nesting depth when in dyntick-idle state, or one greater than | |
266 | the interrupt-nesting depth otherwise. | |
267 | ||
268 | This field is displayed only for CONFIG_NO_HZ kernels. | |
269 | ||
270 | o "dn" is the current value of the dyntick counter that is incremented | |
271 | when entering or leaving dynticks idle state via NMI. If both | |
272 | the "dt" and "dn" values are even, then this CPU is in dynticks | |
273 | idle mode and may be ignored by RCU. If either of these two | |
274 | counters is odd, then RCU must be alert to the possibility of | |
275 | an RCU read-side critical section running on this CPU. | |
276 | ||
277 | This field is displayed only for CONFIG_NO_HZ kernels. | |
278 | ||
279 | o "df" is the number of times that some other CPU has forced a | |
280 | quiescent state on behalf of this CPU due to this CPU being in | |
281 | dynticks-idle state. | |
282 | ||
283 | This field is displayed only for CONFIG_NO_HZ kernels. | |
284 | ||
285 | o "of" is the number of times that some other CPU has forced a | |
286 | quiescent state on behalf of this CPU due to this CPU being | |
287 | offline. In a perfect world, this might neve happen, but it | |
288 | turns out that offlining and onlining a CPU can take several grace | |
289 | periods, and so there is likely to be an extended period of time | |
290 | when RCU believes that the CPU is online when it really is not. | |
291 | Please note that erring in the other direction (RCU believing a | |
292 | CPU is offline when it is really alive and kicking) is a fatal | |
293 | error, so it makes sense to err conservatively. | |
294 | ||
295 | o "ri" is the number of times that RCU has seen fit to send a | |
296 | reschedule IPI to this CPU in order to get it to report a | |
297 | quiescent state. | |
298 | ||
299 | o "ql" is the number of RCU callbacks currently residing on | |
300 | this CPU. This is the total number of callbacks, regardless | |
301 | of what state they are in (new, waiting for grace period to | |
302 | start, waiting for grace period to end, ready to invoke). | |
303 | ||
304 | o "b" is the batch limit for this CPU. If more than this number | |
305 | of RCU callbacks is ready to invoke, then the remainder will | |
306 | be deferred. | |
307 | ||
308 | ||
309 | The output of "cat rcu/rcugp" looks as follows: | |
310 | ||
311 | rcu: completed=33062 gpnum=33063 | |
312 | rcu_bh: completed=464 gpnum=464 | |
313 | ||
314 | Again, this output is for both "rcu" and "rcu_bh". The fields are | |
315 | taken from the rcu_state structure, and are as follows: | |
316 | ||
317 | o "completed" is the number of grace periods that have completed. | |
318 | It is comparable to the "c" field from rcu/rcudata in that a | |
319 | CPU whose "c" field matches the value of "completed" is aware | |
320 | that the corresponding RCU grace period has completed. | |
321 | ||
322 | o "gpnum" is the number of grace periods that have started. It is | |
323 | comparable to the "g" field from rcu/rcudata in that a CPU | |
324 | whose "g" field matches the value of "gpnum" is aware that the | |
325 | corresponding RCU grace period has started. | |
326 | ||
327 | If these two fields are equal (as they are for "rcu_bh" above), | |
328 | then there is no grace period in progress, in other words, RCU | |
329 | is idle. On the other hand, if the two fields differ (as they | |
330 | do for "rcu" above), then an RCU grace period is in progress. | |
331 | ||
332 | ||
333 | The output of "cat rcu/rcuhier" looks as follows, with very long lines: | |
334 | ||
335 | c=6902 g=6903 s=2 jfq=3 j=72c7 nfqs=13142/nfqsng=0(13142) fqlh=6 | |
336 | 1/1 0:127 ^0 | |
337 | 3/3 0:35 ^0 0/0 36:71 ^1 0/0 72:107 ^2 0/0 108:127 ^3 | |
338 | 3/3f 0:5 ^0 2/3 6:11 ^1 0/0 12:17 ^2 0/0 18:23 ^3 0/0 24:29 ^4 0/0 30:35 ^5 0/0 36:41 ^0 0/0 42:47 ^1 0/0 48:53 ^2 0/0 54:59 ^3 0/0 60:65 ^4 0/0 66:71 ^5 0/0 72:77 ^0 0/0 78:83 ^1 0/0 84:89 ^2 0/0 90:95 ^3 0/0 96:101 ^4 0/0 102:107 ^5 0/0 108:113 ^0 0/0 114:119 ^1 0/0 120:125 ^2 0/0 126:127 ^3 | |
339 | rcu_bh: | |
340 | c=-226 g=-226 s=1 jfq=-5701 j=72c7 nfqs=88/nfqsng=0(88) fqlh=0 | |
341 | 0/1 0:127 ^0 | |
342 | 0/3 0:35 ^0 0/0 36:71 ^1 0/0 72:107 ^2 0/0 108:127 ^3 | |
343 | 0/3f 0:5 ^0 0/3 6:11 ^1 0/0 12:17 ^2 0/0 18:23 ^3 0/0 24:29 ^4 0/0 30:35 ^5 0/0 36:41 ^0 0/0 42:47 ^1 0/0 48:53 ^2 0/0 54:59 ^3 0/0 60:65 ^4 0/0 66:71 ^5 0/0 72:77 ^0 0/0 78:83 ^1 0/0 84:89 ^2 0/0 90:95 ^3 0/0 96:101 ^4 0/0 102:107 ^5 0/0 108:113 ^0 0/0 114:119 ^1 0/0 120:125 ^2 0/0 126:127 ^3 | |
344 | ||
345 | This is once again split into "rcu" and "rcu_bh" portions. The fields are | |
346 | as follows: | |
347 | ||
348 | o "c" is exactly the same as "completed" under rcu/rcugp. | |
349 | ||
350 | o "g" is exactly the same as "gpnum" under rcu/rcugp. | |
351 | ||
352 | o "s" is the "signaled" state that drives force_quiescent_state()'s | |
353 | state machine. | |
354 | ||
355 | o "jfq" is the number of jiffies remaining for this grace period | |
356 | before force_quiescent_state() is invoked to help push things | |
357 | along. Note that CPUs in dyntick-idle mode thoughout the grace | |
358 | period will not report on their own, but rather must be check by | |
359 | some other CPU via force_quiescent_state(). | |
360 | ||
361 | o "j" is the low-order four hex digits of the jiffies counter. | |
362 | Yes, Paul did run into a number of problems that turned out to | |
363 | be due to the jiffies counter no longer counting. Why do you ask? | |
364 | ||
365 | o "nfqs" is the number of calls to force_quiescent_state() since | |
366 | boot. | |
367 | ||
368 | o "nfqsng" is the number of useless calls to force_quiescent_state(), | |
369 | where there wasn't actually a grace period active. This can | |
370 | happen due to races. The number in parentheses is the difference | |
371 | between "nfqs" and "nfqsng", or the number of times that | |
372 | force_quiescent_state() actually did some real work. | |
373 | ||
374 | o "fqlh" is the number of calls to force_quiescent_state() that | |
375 | exited immediately (without even being counted in nfqs above) | |
376 | due to contention on ->fqslock. | |
377 | ||
378 | o Each element of the form "1/1 0:127 ^0" represents one struct | |
379 | rcu_node. Each line represents one level of the hierarchy, from | |
380 | root to leaves. It is best to think of the rcu_data structures | |
381 | as forming yet another level after the leaves. Note that there | |
382 | might be either one, two, or three levels of rcu_node structures, | |
383 | depending on the relationship between CONFIG_RCU_FANOUT and | |
384 | CONFIG_NR_CPUS. | |
385 | ||
386 | o The numbers separated by the "/" are the qsmask followed | |
387 | by the qsmaskinit. The qsmask will have one bit | |
388 | set for each entity in the next lower level that | |
389 | has not yet checked in for the current grace period. | |
390 | The qsmaskinit will have one bit for each entity that is | |
391 | currently expected to check in during each grace period. | |
392 | The value of qsmaskinit is assigned to that of qsmask | |
393 | at the beginning of each grace period. | |
394 | ||
395 | For example, for "rcu", the qsmask of the first entry | |
396 | of the lowest level is 0x14, meaning that we are still | |
397 | waiting for CPUs 2 and 4 to check in for the current | |
398 | grace period. | |
399 | ||
400 | o The numbers separated by the ":" are the range of CPUs | |
401 | served by this struct rcu_node. This can be helpful | |
402 | in working out how the hierarchy is wired together. | |
403 | ||
404 | For example, the first entry at the lowest level shows | |
405 | "0:5", indicating that it covers CPUs 0 through 5. | |
406 | ||
407 | o The number after the "^" indicates the bit in the | |
408 | next higher level rcu_node structure that this | |
409 | rcu_node structure corresponds to. | |
410 | ||
411 | For example, the first entry at the lowest level shows | |
412 | "^0", indicating that it corresponds to bit zero in | |
413 | the first entry at the middle level. |