rcu: Reduce rcutorture tracing

Currently, rcutorture traces every read-side access.  This can be
problematic because even a two-minute rcutorture run on a two-CPU system
can generate 28,853,363 reads.  Normally, only a failing read is of
interest, so this commit traces adjusts rcutorture's tracing to only
trace failing reads.  The resulting event tracing records the time
and the ->completed value captured at the beginning of the RCU read-side
critical section, allowing correlation with other event-tracing messages.

Signed-off-by: Paul E. McKenney <paul.mckenney@linaro.org>
Signed-off-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
Reviewed-by: Josh Triplett <josh@joshtriplett.org>
[ paulmck: Add fix to build problem located by Randy Dunlap based on
  diagnosis by Steven Rostedt. ]

2 files changed, 30 insertions, 10 deletions

diff --git a/kernel/rcupdate.c b/kernel/rcupdate.c
index a2cf76177b44..303359d1ca88 100644
--- a/kernel/rcupdate.c
+++ b/kernel/rcupdate.c
@@ -404,11 +404,14 @@ EXPORT_SYMBOL_GPL(rcuhead_debug_descr);
 #endif /* #ifdef CONFIG_DEBUG_OBJECTS_RCU_HEAD */
 
 #if defined(CONFIG_TREE_RCU) || defined(CONFIG_TREE_PREEMPT_RCU) || defined(CONFIG_RCU_TRACE)
-void do_trace_rcu_torture_read(char *rcutorturename, struct rcu_head *rhp)
+void do_trace_rcu_torture_read(char *rcutorturename, struct rcu_head *rhp,
+                               unsigned long secs,
+                               unsigned long c_old, unsigned long c)
 {
-        trace_rcu_torture_read(rcutorturename, rhp);
+        trace_rcu_torture_read(rcutorturename, rhp, secs, c_old, c);
 }
 EXPORT_SYMBOL_GPL(do_trace_rcu_torture_read);
 #else
-#define do_trace_rcu_torture_read(rcutorturename, rhp) do { } while (0)
+#define do_trace_rcu_torture_read(rcutorturename, rhp, secs, c_old, c) \
+        do { } while (0)
 #endif
diff --git a/kernel/rcutorture.c b/kernel/rcutorture.c
index 31dea01c85fd..a583f1ce713d 100644
--- a/kernel/rcutorture.c
+++ b/kernel/rcutorture.c
@@ -46,6 +46,7 @@
 #include <linux/stat.h>
 #include <linux/srcu.h>
 #include <linux/slab.h>
+#include <linux/trace_clock.h>
 #include <asm/byteorder.h>
 
 MODULE_LICENSE("GPL");
@@ -1028,7 +1029,6 @@ void rcutorture_trace_dump(void)
                 return;
         if (atomic_xchg(&beenhere, 1) != 0)
                 return;
-        do_trace_rcu_torture_read(cur_ops->name, (struct rcu_head *)~0UL);
         ftrace_dump(DUMP_ALL);
 }
 
@@ -1042,13 +1042,16 @@ static void rcu_torture_timer(unsigned long unused)
 {
         int idx;
         int completed;
+        int completed_end;
         static DEFINE_RCU_RANDOM(rand);
         static DEFINE_SPINLOCK(rand_lock);
         struct rcu_torture *p;
         int pipe_count;
+        unsigned long long ts;
 
         idx = cur_ops->readlock();
         completed = cur_ops->completed();
+        ts = trace_clock_local();
         p = rcu_dereference_check(rcu_torture_current,
                                   rcu_read_lock_bh_held() ||
                                   rcu_read_lock_sched_held() ||
@@ -1058,7 +1061,6 @@ static void rcu_torture_timer(unsigned long unused)
                 cur_ops->readunlock(idx);
                 return;
         }
-        do_trace_rcu_torture_read(cur_ops->name, &p->rtort_rcu);
         if (p->rtort_mbtest == 0)
                 atomic_inc(&n_rcu_torture_mberror);
         spin_lock(&rand_lock);
@@ -1071,10 +1073,16 @@ static void rcu_torture_timer(unsigned long unused)
                 /* Should not happen, but... */
                 pipe_count = RCU_TORTURE_PIPE_LEN;
         }
-        if (pipe_count > 1)
+        completed_end = cur_ops->completed();
+        if (pipe_count > 1) {
+                unsigned long __maybe_unused ts_rem = do_div(ts, NSEC_PER_USEC);
+
+                do_trace_rcu_torture_read(cur_ops->name, &p->rtort_rcu, ts,
+                                          completed, completed_end);
                 rcutorture_trace_dump();
+        }
         __this_cpu_inc(rcu_torture_count[pipe_count]);
-        completed = cur_ops->completed() - completed;
+        completed = completed_end - completed;
         if (completed > RCU_TORTURE_PIPE_LEN) {
                 /* Should not happen, but... */
                 completed = RCU_TORTURE_PIPE_LEN;
@@ -1094,11 +1102,13 @@ static int
 rcu_torture_reader(void *arg)
 {
         int completed;
+        int completed_end;
         int idx;
         DEFINE_RCU_RANDOM(rand);
         struct rcu_torture *p;
         int pipe_count;
         struct timer_list t;
+        unsigned long long ts;
 
         VERBOSE_PRINTK_STRING("rcu_torture_reader task started");
         set_user_nice(current, 19);
@@ -1112,6 +1122,7 @@ rcu_torture_reader(void *arg)
                 }
                 idx = cur_ops->readlock();
                 completed = cur_ops->completed();
+                ts = trace_clock_local();
                 p = rcu_dereference_check(rcu_torture_current,
                                           rcu_read_lock_bh_held() ||
                                           rcu_read_lock_sched_held() ||
@@ -1122,7 +1133,6 @@ rcu_torture_reader(void *arg)
                         schedule_timeout_interruptible(HZ);
                         continue;
                 }
-                do_trace_rcu_torture_read(cur_ops->name, &p->rtort_rcu);
                 if (p->rtort_mbtest == 0)
                         atomic_inc(&n_rcu_torture_mberror);
                 cur_ops->read_delay(&rand);
@@ -1132,10 +1142,17 @@ rcu_torture_reader(void *arg)
                         /* Should not happen, but... */
                         pipe_count = RCU_TORTURE_PIPE_LEN;
                 }
-                if (pipe_count > 1)
+                completed_end = cur_ops->completed();
+                if (pipe_count > 1) {
+                        unsigned long __maybe_unused ts_rem =
+                                        do_div(ts, NSEC_PER_USEC);
+
+                        do_trace_rcu_torture_read(cur_ops->name, &p->rtort_rcu,
+                                                  ts, completed, completed_end);
                         rcutorture_trace_dump();
+                }
                 __this_cpu_inc(rcu_torture_count[pipe_count]);
-                completed = cur_ops->completed() - completed;
+                completed = completed_end - completed;
                 if (completed > RCU_TORTURE_PIPE_LEN) {
                         /* Should not happen, but... */
                         completed = RCU_TORTURE_PIPE_LEN;