Commit 269dcc1c2ec25864308ee03a3fa26ea819d9f5d0

Authored by Paul E. McKenney
1 parent 0ddea0ead2

rcu: Add tracing data to support queueing models

The current tracing data is not sufficient to deduce the average time
that a callback spends waiting for a grace period to end.  Add three
per-CPU counters recording the number of callbacks invoked (ci), the
number of callbacks orphaned (co), and the number of callbacks adopted
(ca).  Given the existing callback queue length (ql), the average wait
time in absence of CPU hotplug operations is ql/ci.  The units of wait
time will be in terms of the duration over which ci was measured.

In the presence of CPU hotplug operations, there is room for argument,
but ql/(ci-co+ca) won't steer you too far wrong.

Also fixes a typo called out by Lucas De Marchi <lucas.de.marchi@gmail.com>.

Signed-off-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>

Showing 4 changed files with 25 additions and 4 deletions Side-by-side Diff

Documentation/RCU/trace.txt
... ... @@ -125,6 +125,17 @@
125 125 of RCU callbacks is ready to invoke, then the remainder will
126 126 be deferred.
127 127  
  128 +o "ci" is the number of RCU callbacks that have been invoked for
  129 + this CPU. Note that ci+ql is the number of callbacks that have
  130 + been registered in absence of CPU-hotplug activity.
  131 +
  132 +o "co" is the number of RCU callbacks that have been orphaned due to
  133 + this CPU going offline.
  134 +
  135 +o "ca" is the number of RCU callbacks that have been adopted due to
  136 + other CPUs going offline. Note that ci+co-ca+ql is the number of
  137 + RCU callbacks registered on this CPU.
  138 +
128 139 There is also an rcu/rcudata.csv file with the same information in
129 140 comma-separated-variable spreadsheet format.
130 141  
... ... @@ -180,7 +191,7 @@
180 191  
181 192 o "jfq" is the number of jiffies remaining for this grace period
182 193 before force_quiescent_state() is invoked to help push things
183   - along. Note that CPUs in dyntick-idle mode thoughout the grace
  194 + along. Note that CPUs in dyntick-idle mode throughout the grace
184 195 period will not report on their own, but rather must be check by
185 196 some other CPU via force_quiescent_state().
186 197  
... ... @@ -1004,6 +1004,7 @@
1004 1004 for (i = 0; i < RCU_NEXT_SIZE; i++)
1005 1005 rdp->nxttail[i] = &rdp->nxtlist;
1006 1006 rsp->orphan_qlen += rdp->qlen;
  1007 + rdp->n_cbs_orphaned += rdp->qlen;
1007 1008 rdp->qlen = 0;
1008 1009 raw_spin_unlock(&rsp->onofflock); /* irqs remain disabled. */
1009 1010 }
... ... @@ -1025,6 +1026,7 @@
1025 1026 *rdp->nxttail[RCU_NEXT_TAIL] = rsp->orphan_cbs_list;
1026 1027 rdp->nxttail[RCU_NEXT_TAIL] = rsp->orphan_cbs_tail;
1027 1028 rdp->qlen += rsp->orphan_qlen;
  1029 + rdp->n_cbs_adopted += rsp->orphan_qlen;
1028 1030 rsp->orphan_cbs_list = NULL;
1029 1031 rsp->orphan_cbs_tail = &rsp->orphan_cbs_list;
1030 1032 rsp->orphan_qlen = 0;
... ... @@ -1156,6 +1158,7 @@
1156 1158  
1157 1159 /* Update count, and requeue any remaining callbacks. */
1158 1160 rdp->qlen -= count;
  1161 + rdp->n_cbs_invoked += count;
1159 1162 if (list != NULL) {
1160 1163 *tail = rdp->nxtlist;
1161 1164 rdp->nxtlist = list;
... ... @@ -202,6 +202,9 @@
202 202 long qlen; /* # of queued callbacks */
203 203 long qlen_last_fqs_check;
204 204 /* qlen at last check for QS forcing */
  205 + unsigned long n_cbs_invoked; /* count of RCU cbs invoked. */
  206 + unsigned long n_cbs_orphaned; /* RCU cbs sent to orphanage. */
  207 + unsigned long n_cbs_adopted; /* RCU cbs adopted from orphanage. */
205 208 unsigned long n_force_qs_snap;
206 209 /* did other CPU force QS recently? */
207 210 long blimit; /* Upper limit on a processed batch */
kernel/rcutree_trace.c
... ... @@ -64,7 +64,9 @@
64 64 rdp->dynticks_fqs);
65 65 #endif /* #ifdef CONFIG_NO_HZ */
66 66 seq_printf(m, " of=%lu ri=%lu", rdp->offline_fqs, rdp->resched_ipi);
67   - seq_printf(m, " ql=%ld b=%ld\n", rdp->qlen, rdp->blimit);
  67 + seq_printf(m, " ql=%ld b=%ld", rdp->qlen, rdp->blimit);
  68 + seq_printf(m, " ci=%lu co=%lu ca=%lu\n",
  69 + rdp->n_cbs_invoked, rdp->n_cbs_orphaned, rdp->n_cbs_adopted);
68 70 }
69 71  
70 72 #define PRINT_RCU_DATA(name, func, m) \
... ... @@ -119,7 +121,9 @@
119 121 rdp->dynticks_fqs);
120 122 #endif /* #ifdef CONFIG_NO_HZ */
121 123 seq_printf(m, ",%lu,%lu", rdp->offline_fqs, rdp->resched_ipi);
122   - seq_printf(m, ",%ld,%ld\n", rdp->qlen, rdp->blimit);
  124 + seq_printf(m, ",%ld,%ld", rdp->qlen, rdp->blimit);
  125 + seq_printf(m, ",%lu,%lu,%lu\n",
  126 + rdp->n_cbs_invoked, rdp->n_cbs_orphaned, rdp->n_cbs_adopted);
123 127 }
124 128  
125 129 static int show_rcudata_csv(struct seq_file *m, void *unused)
... ... @@ -128,7 +132,7 @@
128 132 #ifdef CONFIG_NO_HZ
129 133 seq_puts(m, "\"dt\",\"dt nesting\",\"dn\",\"df\",");
130 134 #endif /* #ifdef CONFIG_NO_HZ */
131   - seq_puts(m, "\"of\",\"ri\",\"ql\",\"b\"\n");
  135 + seq_puts(m, "\"of\",\"ri\",\"ql\",\"b\",\"ci\",\"co\",\"ca\"\n");
132 136 #ifdef CONFIG_TREE_PREEMPT_RCU
133 137 seq_puts(m, "\"rcu_preempt:\"\n");
134 138 PRINT_RCU_DATA(rcu_preempt_data, print_one_rcu_data_csv, m);