]>
Commit | Line | Data |
---|---|---|
64db4cff PM |
1 | CONFIG_RCU_TRACE debugfs Files and Formats |
2 | ||
3 | ||
bd58b430 PM |
4 | The rcutree implementation of RCU provides debugfs trace output that |
5 | summarizes counters and state. This information is useful for debugging | |
6 | RCU itself, and can sometimes also help to debug abuses of RCU. | |
7 | The following sections describe the debugfs files and formats. | |
64db4cff PM |
8 | |
9 | ||
10 | Hierarchical RCU debugfs Files and Formats | |
11 | ||
12 | This implementation of RCU provides three debugfs files under the | |
13 | top-level directory RCU: rcu/rcudata (which displays fields in struct | |
14 | rcu_data), rcu/rcugp (which displays grace-period counters), and | |
15 | rcu/rcuhier (which displays the struct rcu_node hierarchy). | |
16 | ||
17 | The output of "cat rcu/rcudata" looks as follows: | |
18 | ||
d6714c22 | 19 | rcu_sched: |
6fd9b3a4 PM |
20 | 0 c=17829 g=17829 pq=1 pqc=17829 qp=0 dt=10951/1 dn=0 df=1101 of=0 ri=36 ql=0 b=10 |
21 | 1 c=17829 g=17829 pq=1 pqc=17829 qp=0 dt=16117/1 dn=0 df=1015 of=0 ri=0 ql=0 b=10 | |
22 | 2 c=17829 g=17829 pq=1 pqc=17829 qp=0 dt=1445/1 dn=0 df=1839 of=0 ri=0 ql=0 b=10 | |
23 | 3 c=17829 g=17829 pq=1 pqc=17829 qp=0 dt=6681/1 dn=0 df=1545 of=0 ri=0 ql=0 b=10 | |
24 | 4 c=17829 g=17829 pq=1 pqc=17829 qp=0 dt=1003/1 dn=0 df=1992 of=0 ri=0 ql=0 b=10 | |
25 | 5 c=17829 g=17830 pq=1 pqc=17829 qp=1 dt=3887/1 dn=0 df=3331 of=0 ri=4 ql=2 b=10 | |
26 | 6 c=17829 g=17829 pq=1 pqc=17829 qp=0 dt=859/1 dn=0 df=3224 of=0 ri=0 ql=0 b=10 | |
27 | 7 c=17829 g=17830 pq=0 pqc=17829 qp=1 dt=3761/1 dn=0 df=1818 of=0 ri=0 ql=2 b=10 | |
64db4cff | 28 | rcu_bh: |
6fd9b3a4 PM |
29 | 0 c=-275 g=-275 pq=1 pqc=-275 qp=0 dt=10951/1 dn=0 df=0 of=0 ri=0 ql=0 b=10 |
30 | 1 c=-275 g=-275 pq=1 pqc=-275 qp=0 dt=16117/1 dn=0 df=13 of=0 ri=0 ql=0 b=10 | |
31 | 2 c=-275 g=-275 pq=1 pqc=-275 qp=0 dt=1445/1 dn=0 df=15 of=0 ri=0 ql=0 b=10 | |
32 | 3 c=-275 g=-275 pq=1 pqc=-275 qp=0 dt=6681/1 dn=0 df=9 of=0 ri=0 ql=0 b=10 | |
33 | 4 c=-275 g=-275 pq=1 pqc=-275 qp=0 dt=1003/1 dn=0 df=15 of=0 ri=0 ql=0 b=10 | |
34 | 5 c=-275 g=-275 pq=1 pqc=-275 qp=0 dt=3887/1 dn=0 df=15 of=0 ri=0 ql=0 b=10 | |
35 | 6 c=-275 g=-275 pq=1 pqc=-275 qp=0 dt=859/1 dn=0 df=15 of=0 ri=0 ql=0 b=10 | |
36 | 7 c=-275 g=-275 pq=1 pqc=-275 qp=0 dt=3761/1 dn=0 df=15 of=0 ri=0 ql=0 b=10 | |
64db4cff | 37 | |
bd58b430 PM |
38 | The first section lists the rcu_data structures for rcu_sched, the second |
39 | for rcu_bh. Note that CONFIG_TREE_PREEMPT_RCU kernels will have an | |
40 | additional section for rcu_preempt. Each section has one line per CPU, | |
41 | or eight for this 8-CPU system. The fields are as follows: | |
64db4cff PM |
42 | |
43 | o The number at the beginning of each line is the CPU number. | |
44 | CPUs numbers followed by an exclamation mark are offline, | |
45 | but have been online at least once since boot. There will be | |
46 | no output for CPUs that have never been online, which can be | |
47 | a good thing in the surprisingly common case where NR_CPUS is | |
48 | substantially larger than the number of actual CPUs. | |
49 | ||
50 | o "c" is the count of grace periods that this CPU believes have | |
51 | completed. CPUs in dynticks idle mode may lag quite a ways | |
bd58b430 PM |
52 | behind, for example, CPU 4 under "rcu_sched" above, which has |
53 | slept through the past 25 RCU grace periods. It is not unusual | |
54 | to see CPUs lagging by thousands of grace periods. | |
64db4cff PM |
55 | |
56 | o "g" is the count of grace periods that this CPU believes have | |
57 | started. Again, CPUs in dynticks idle mode may lag behind. | |
58 | If the "c" and "g" values are equal, this CPU has already | |
59 | reported a quiescent state for the last RCU grace period that | |
60 | it is aware of, otherwise, the CPU believes that it owes RCU a | |
61 | quiescent state. | |
62 | ||
63 | o "pq" indicates that this CPU has passed through a quiescent state | |
64 | for the current grace period. It is possible for "pq" to be | |
65 | "1" and "c" different than "g", which indicates that although | |
66 | the CPU has passed through a quiescent state, either (1) this | |
67 | CPU has not yet reported that fact, (2) some other CPU has not | |
68 | yet reported for this grace period, or (3) both. | |
69 | ||
70 | o "pqc" indicates which grace period the last-observed quiescent | |
71 | state for this CPU corresponds to. This is important for handling | |
72 | the race between CPU 0 reporting an extended dynticks-idle | |
73 | quiescent state for CPU 1 and CPU 1 suddenly waking up and | |
74 | reporting its own quiescent state. If CPU 1 was the last CPU | |
75 | for the current grace period, then the CPU that loses this race | |
76 | will attempt to incorrectly mark CPU 1 as having checked in for | |
77 | the next grace period! | |
78 | ||
79 | o "qp" indicates that RCU still expects a quiescent state from | |
80 | this CPU. | |
81 | ||
64db4cff PM |
82 | o "dt" is the current value of the dyntick counter that is incremented |
83 | when entering or leaving dynticks idle state, either by the | |
84 | scheduler or by irq. The number after the "/" is the interrupt | |
85 | nesting depth when in dyntick-idle state, or one greater than | |
86 | the interrupt-nesting depth otherwise. | |
87 | ||
88 | This field is displayed only for CONFIG_NO_HZ kernels. | |
89 | ||
90 | o "dn" is the current value of the dyntick counter that is incremented | |
91 | when entering or leaving dynticks idle state via NMI. If both | |
92 | the "dt" and "dn" values are even, then this CPU is in dynticks | |
93 | idle mode and may be ignored by RCU. If either of these two | |
94 | counters is odd, then RCU must be alert to the possibility of | |
95 | an RCU read-side critical section running on this CPU. | |
96 | ||
97 | This field is displayed only for CONFIG_NO_HZ kernels. | |
98 | ||
99 | o "df" is the number of times that some other CPU has forced a | |
100 | quiescent state on behalf of this CPU due to this CPU being in | |
101 | dynticks-idle state. | |
102 | ||
103 | This field is displayed only for CONFIG_NO_HZ kernels. | |
104 | ||
105 | o "of" is the number of times that some other CPU has forced a | |
106 | quiescent state on behalf of this CPU due to this CPU being | |
107 | offline. In a perfect world, this might neve happen, but it | |
108 | turns out that offlining and onlining a CPU can take several grace | |
109 | periods, and so there is likely to be an extended period of time | |
110 | when RCU believes that the CPU is online when it really is not. | |
111 | Please note that erring in the other direction (RCU believing a | |
112 | CPU is offline when it is really alive and kicking) is a fatal | |
113 | error, so it makes sense to err conservatively. | |
114 | ||
115 | o "ri" is the number of times that RCU has seen fit to send a | |
116 | reschedule IPI to this CPU in order to get it to report a | |
117 | quiescent state. | |
118 | ||
119 | o "ql" is the number of RCU callbacks currently residing on | |
120 | this CPU. This is the total number of callbacks, regardless | |
121 | of what state they are in (new, waiting for grace period to | |
122 | start, waiting for grace period to end, ready to invoke). | |
123 | ||
124 | o "b" is the batch limit for this CPU. If more than this number | |
125 | of RCU callbacks is ready to invoke, then the remainder will | |
126 | be deferred. | |
127 | ||
6fd9b3a4 PM |
128 | There is also an rcu/rcudata.csv file with the same information in |
129 | comma-separated-variable spreadsheet format. | |
130 | ||
64db4cff PM |
131 | |
132 | The output of "cat rcu/rcugp" looks as follows: | |
133 | ||
d6714c22 | 134 | rcu_sched: completed=33062 gpnum=33063 |
64db4cff PM |
135 | rcu_bh: completed=464 gpnum=464 |
136 | ||
bd58b430 PM |
137 | Again, this output is for both "rcu_sched" and "rcu_bh". Note that |
138 | kernels built with CONFIG_TREE_PREEMPT_RCU will have an additional | |
139 | "rcu_preempt" line. The fields are taken from the rcu_state structure, | |
140 | and are as follows: | |
64db4cff PM |
141 | |
142 | o "completed" is the number of grace periods that have completed. | |
143 | It is comparable to the "c" field from rcu/rcudata in that a | |
144 | CPU whose "c" field matches the value of "completed" is aware | |
145 | that the corresponding RCU grace period has completed. | |
146 | ||
147 | o "gpnum" is the number of grace periods that have started. It is | |
148 | comparable to the "g" field from rcu/rcudata in that a CPU | |
149 | whose "g" field matches the value of "gpnum" is aware that the | |
150 | corresponding RCU grace period has started. | |
151 | ||
152 | If these two fields are equal (as they are for "rcu_bh" above), | |
153 | then there is no grace period in progress, in other words, RCU | |
154 | is idle. On the other hand, if the two fields differ (as they | |
bd58b430 | 155 | do for "rcu_sched" above), then an RCU grace period is in progress. |
64db4cff PM |
156 | |
157 | ||
158 | The output of "cat rcu/rcuhier" looks as follows, with very long lines: | |
159 | ||
bd58b430 | 160 | c=6902 g=6903 s=2 jfq=3 j=72c7 nfqs=13142/nfqsng=0(13142) fqlh=6 oqlen=0 |
0edf1a68 PM |
161 | 1/1 .>. 0:127 ^0 |
162 | 3/3 .>. 0:35 ^0 0/0 .>. 36:71 ^1 0/0 .>. 72:107 ^2 0/0 .>. 108:127 ^3 | |
163 | 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 | |
64db4cff | 164 | rcu_bh: |
bd58b430 | 165 | c=-226 g=-226 s=1 jfq=-5701 j=72c7 nfqs=88/nfqsng=0(88) fqlh=0 oqlen=0 |
0edf1a68 PM |
166 | 0/1 .>. 0:127 ^0 |
167 | 0/3 .>. 0:35 ^0 0/0 .>. 36:71 ^1 0/0 .>. 72:107 ^2 0/0 .>. 108:127 ^3 | |
168 | 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 | |
64db4cff | 169 | |
bd58b430 PM |
170 | This is once again split into "rcu_sched" and "rcu_bh" portions, |
171 | and CONFIG_TREE_PREEMPT_RCU kernels will again have an additional | |
172 | "rcu_preempt" section. The fields are as follows: | |
64db4cff PM |
173 | |
174 | o "c" is exactly the same as "completed" under rcu/rcugp. | |
175 | ||
176 | o "g" is exactly the same as "gpnum" under rcu/rcugp. | |
177 | ||
178 | o "s" is the "signaled" state that drives force_quiescent_state()'s | |
179 | state machine. | |
180 | ||
181 | o "jfq" is the number of jiffies remaining for this grace period | |
182 | before force_quiescent_state() is invoked to help push things | |
183 | along. Note that CPUs in dyntick-idle mode thoughout the grace | |
184 | period will not report on their own, but rather must be check by | |
185 | some other CPU via force_quiescent_state(). | |
186 | ||
187 | o "j" is the low-order four hex digits of the jiffies counter. | |
188 | Yes, Paul did run into a number of problems that turned out to | |
189 | be due to the jiffies counter no longer counting. Why do you ask? | |
190 | ||
191 | o "nfqs" is the number of calls to force_quiescent_state() since | |
192 | boot. | |
193 | ||
194 | o "nfqsng" is the number of useless calls to force_quiescent_state(), | |
195 | where there wasn't actually a grace period active. This can | |
196 | happen due to races. The number in parentheses is the difference | |
197 | between "nfqs" and "nfqsng", or the number of times that | |
198 | force_quiescent_state() actually did some real work. | |
199 | ||
200 | o "fqlh" is the number of calls to force_quiescent_state() that | |
201 | exited immediately (without even being counted in nfqs above) | |
202 | due to contention on ->fqslock. | |
203 | ||
bd58b430 PM |
204 | o "oqlen" is the number of callbacks on the "orphan" callback |
205 | list. RCU callbacks are placed on this list by CPUs going | |
206 | offline, and are "adopted" either by the CPU helping the outgoing | |
207 | CPU or by the next rcu_barrier*() call, whichever comes first. | |
208 | ||
64db4cff PM |
209 | o Each element of the form "1/1 0:127 ^0" represents one struct |
210 | rcu_node. Each line represents one level of the hierarchy, from | |
211 | root to leaves. It is best to think of the rcu_data structures | |
212 | as forming yet another level after the leaves. Note that there | |
213 | might be either one, two, or three levels of rcu_node structures, | |
214 | depending on the relationship between CONFIG_RCU_FANOUT and | |
215 | CONFIG_NR_CPUS. | |
0edf1a68 | 216 | |
64db4cff PM |
217 | o The numbers separated by the "/" are the qsmask followed |
218 | by the qsmaskinit. The qsmask will have one bit | |
219 | set for each entity in the next lower level that | |
220 | has not yet checked in for the current grace period. | |
221 | The qsmaskinit will have one bit for each entity that is | |
222 | currently expected to check in during each grace period. | |
223 | The value of qsmaskinit is assigned to that of qsmask | |
224 | at the beginning of each grace period. | |
225 | ||
bd58b430 PM |
226 | For example, for "rcu_sched", the qsmask of the first |
227 | entry of the lowest level is 0x14, meaning that we | |
228 | are still waiting for CPUs 2 and 4 to check in for the | |
229 | current grace period. | |
64db4cff | 230 | |
0edf1a68 PM |
231 | o The characters separated by the ">" indicate the state |
232 | of the blocked-tasks lists. A "T" preceding the ">" | |
233 | indicates that at least one task blocked in an RCU | |
234 | read-side critical section blocks the current grace | |
235 | period, while a "." preceding the ">" indicates otherwise. | |
236 | The character following the ">" indicates similarly for | |
237 | the next grace period. A "T" should appear in this | |
238 | field only for rcu-preempt. | |
239 | ||
64db4cff PM |
240 | o The numbers separated by the ":" are the range of CPUs |
241 | served by this struct rcu_node. This can be helpful | |
242 | in working out how the hierarchy is wired together. | |
243 | ||
244 | For example, the first entry at the lowest level shows | |
245 | "0:5", indicating that it covers CPUs 0 through 5. | |
246 | ||
247 | o The number after the "^" indicates the bit in the | |
248 | next higher level rcu_node structure that this | |
249 | rcu_node structure corresponds to. | |
250 | ||
251 | For example, the first entry at the lowest level shows | |
252 | "^0", indicating that it corresponds to bit zero in | |
253 | the first entry at the middle level. | |
6fd9b3a4 PM |
254 | |
255 | ||
256 | The output of "cat rcu/rcu_pending" looks as follows: | |
257 | ||
d6714c22 | 258 | rcu_sched: |
6fd9b3a4 PM |
259 | 0 np=255892 qsp=53936 cbr=0 cng=14417 gpc=10033 gps=24320 nf=6445 nn=146741 |
260 | 1 np=261224 qsp=54638 cbr=0 cng=25723 gpc=16310 gps=2849 nf=5912 nn=155792 | |
261 | 2 np=237496 qsp=49664 cbr=0 cng=2762 gpc=45478 gps=1762 nf=1201 nn=136629 | |
262 | 3 np=236249 qsp=48766 cbr=0 cng=286 gpc=48049 gps=1218 nf=207 nn=137723 | |
263 | 4 np=221310 qsp=46850 cbr=0 cng=26 gpc=43161 gps=4634 nf=3529 nn=123110 | |
264 | 5 np=237332 qsp=48449 cbr=0 cng=54 gpc=47920 gps=3252 nf=201 nn=137456 | |
265 | 6 np=219995 qsp=46718 cbr=0 cng=50 gpc=42098 gps=6093 nf=4202 nn=120834 | |
266 | 7 np=249893 qsp=49390 cbr=0 cng=72 gpc=38400 gps=17102 nf=41 nn=144888 | |
267 | rcu_bh: | |
268 | 0 np=146741 qsp=1419 cbr=0 cng=6 gpc=0 gps=0 nf=2 nn=145314 | |
269 | 1 np=155792 qsp=12597 cbr=0 cng=0 gpc=4 gps=8 nf=3 nn=143180 | |
270 | 2 np=136629 qsp=18680 cbr=0 cng=0 gpc=7 gps=6 nf=0 nn=117936 | |
271 | 3 np=137723 qsp=2843 cbr=0 cng=0 gpc=10 gps=7 nf=0 nn=134863 | |
272 | 4 np=123110 qsp=12433 cbr=0 cng=0 gpc=4 gps=2 nf=0 nn=110671 | |
273 | 5 np=137456 qsp=4210 cbr=0 cng=0 gpc=6 gps=5 nf=0 nn=133235 | |
274 | 6 np=120834 qsp=9902 cbr=0 cng=0 gpc=6 gps=3 nf=2 nn=110921 | |
275 | 7 np=144888 qsp=26336 cbr=0 cng=0 gpc=8 gps=2 nf=0 nn=118542 | |
276 | ||
bd58b430 PM |
277 | As always, this is once again split into "rcu_sched" and "rcu_bh" |
278 | portions, with CONFIG_TREE_PREEMPT_RCU kernels having an additional | |
279 | "rcu_preempt" section. The fields are as follows: | |
6fd9b3a4 PM |
280 | |
281 | o "np" is the number of times that __rcu_pending() has been invoked | |
282 | for the corresponding flavor of RCU. | |
283 | ||
284 | o "qsp" is the number of times that the RCU was waiting for a | |
285 | quiescent state from this CPU. | |
286 | ||
287 | o "cbr" is the number of times that this CPU had RCU callbacks | |
288 | that had passed through a grace period, and were thus ready | |
289 | to be invoked. | |
290 | ||
291 | o "cng" is the number of times that this CPU needed another | |
292 | grace period while RCU was idle. | |
293 | ||
294 | o "gpc" is the number of times that an old grace period had | |
295 | completed, but this CPU was not yet aware of it. | |
296 | ||
297 | o "gps" is the number of times that a new grace period had started, | |
298 | but this CPU was not yet aware of it. | |
299 | ||
300 | o "nf" is the number of times that this CPU suspected that the | |
301 | current grace period had run for too long, and thus needed to | |
302 | be forced. | |
303 | ||
304 | Please note that "forcing" consists of sending resched IPIs | |
305 | to holdout CPUs. If that CPU really still is in an old RCU | |
306 | read-side critical section, then we really do have to wait for it. | |
307 | The assumption behing "forcing" is that the CPU is not still in | |
308 | an old RCU read-side critical section, but has not yet responded | |
309 | for some other reason. | |
310 | ||
311 | o "nn" is the number of times that this CPU needed nothing. Alert | |
312 | readers will note that the rcu "nn" number for a given CPU very | |
313 | closely matches the rcu_bh "np" number for that same CPU. This | |
314 | is due to short-circuit evaluation in rcu_pending(). |