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. ]

diff --git a/include/linux/rcupdate.h b/include/linux/rcupdate.h
index 275aa3f1062d4b8db48be4f5201dce83b6c9bcb4..7f89cea596e1a3f8bcdad0bcb8db0002915b9aa5 100644 (file)
--- a/include/linux/rcupdate.h
+++ b/include/linux/rcupdate.h
@@ -53,7 +53,10 @@ extern int rcutorture_runnable; /* for sysctl */
 extern void rcutorture_record_test_transition(void);
 extern void rcutorture_record_progress(unsigned long vernum);
 extern void do_trace_rcu_torture_read(char *rcutorturename,
-                                     struct rcu_head *rhp);
+                                     struct rcu_head *rhp,
+                                     unsigned long secs,
+                                     unsigned long c_old,
+                                     unsigned long c);
 #else
 static inline void rcutorture_record_test_transition(void)
 {
@@ -63,9 +66,13 @@ static inline void rcutorture_record_progress(unsigned long vernum)
 }
 #ifdef CONFIG_RCU_TRACE
 extern void do_trace_rcu_torture_read(char *rcutorturename,
-                                     struct rcu_head *rhp);
+                                     struct rcu_head *rhp,
+                                     unsigned long secs,
+                                     unsigned long c_old,
+                                     unsigned long c);
 #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
 #endif
 

diff --git a/include/trace/events/rcu.h b/include/trace/events/rcu.h
index d4f559b1ec3444eada48e8e9e1d8bd85f36da5b6..09af021c8e96c061aae2c9c2a5e0bb199f7e9530 100644 (file)
--- a/include/trace/events/rcu.h
+++ b/include/trace/events/rcu.h
@@ -523,22 +523,30 @@ TRACE_EVENT(rcu_batch_end,
  */
 TRACE_EVENT(rcu_torture_read,
 
-       TP_PROTO(char *rcutorturename, struct rcu_head *rhp),
+       TP_PROTO(char *rcutorturename, struct rcu_head *rhp,
+                unsigned long secs, unsigned long c_old, unsigned long c),
 
-       TP_ARGS(rcutorturename, rhp),
+       TP_ARGS(rcutorturename, rhp, secs, c_old, c),
 
        TP_STRUCT__entry(
                __field(char *, rcutorturename)
                __field(struct rcu_head *, rhp)
+               __field(unsigned long, secs)
+               __field(unsigned long, c_old)
+               __field(unsigned long, c)
        ),
 
        TP_fast_assign(
                __entry->rcutorturename = rcutorturename;
                __entry->rhp = rhp;
+               __entry->secs = secs;
+               __entry->c_old = c_old;
+               __entry->c = c;
        ),
 
-       TP_printk("%s torture read %p",
-                 __entry->rcutorturename, __entry->rhp)
+       TP_printk("%s torture read %p %luus c: %lu %lu",
+                 __entry->rcutorturename, __entry->rhp,
+                 __entry->secs, __entry->c_old, __entry->c)
 );
 
 /*
@@ -608,7 +616,8 @@ TRACE_EVENT(rcu_barrier,
 #define trace_rcu_invoke_kfree_callback(rcuname, rhp, offset) do { } while (0)
 #define trace_rcu_batch_end(rcuname, callbacks_invoked, cb, nr, iit, risk) \
        do { } while (0)
-#define trace_rcu_torture_read(rcutorturename, rhp) do { } while (0)
+#define trace_rcu_torture_read(rcutorturename, rhp, secs, c_old, c) \
+       do { } while (0)
 #define trace_rcu_barrier(name, s, cpu, cnt, done) do { } while (0)
 
 #endif /* #else #ifdef CONFIG_RCU_TRACE */

diff --git a/kernel/rcupdate.c b/kernel/rcupdate.c
index a2cf76177b443d33bb30b19052524db385cb4fc9..303359d1ca88f04594275530e0be2482f122a553 100644 (file)
--- 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 31dea01c85fd50fb3297627dc81556a146f249c5..a583f1ce713dfcb9ae5ede5502efd4241655e328 100644 (file)
--- 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;

diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index 3a353091a90390f6b95b632408797d14908d57f3..7d83f52fbade53ea4a162951d91aceca105a804e 100644 (file)
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -1008,6 +1008,7 @@ config RCU_CPU_STALL_INFO
 config RCU_TRACE
        bool "Enable tracing for RCU"
        depends on DEBUG_KERNEL
+       select TRACE_CLOCK
        help
          This option provides tracing in RCU which presents stats
          in debugfs for debugging RCU implementation.