Commit 52494535 authored by Paul E. McKenney's avatar Paul E. McKenney Committed by Paul E. McKenney

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: default avatarPaul E. McKenney <paul.mckenney@linaro.org>
Signed-off-by: default avatarPaul E. McKenney <paulmck@linux.vnet.ibm.com>
Reviewed-by: default avatarJosh Triplett <josh@joshtriplett.org>
[ paulmck: Add fix to build problem located by Randy Dunlap based on
  diagnosis by Steven Rostedt. ]
parent dc975e94
...@@ -53,7 +53,10 @@ extern int rcutorture_runnable; /* for sysctl */ ...@@ -53,7 +53,10 @@ extern int rcutorture_runnable; /* for sysctl */
extern void rcutorture_record_test_transition(void); extern void rcutorture_record_test_transition(void);
extern void rcutorture_record_progress(unsigned long vernum); extern void rcutorture_record_progress(unsigned long vernum);
extern void do_trace_rcu_torture_read(char *rcutorturename, 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 #else
static inline void rcutorture_record_test_transition(void) static inline void rcutorture_record_test_transition(void)
{ {
...@@ -63,9 +66,13 @@ static inline void rcutorture_record_progress(unsigned long vernum) ...@@ -63,9 +66,13 @@ static inline void rcutorture_record_progress(unsigned long vernum)
} }
#ifdef CONFIG_RCU_TRACE #ifdef CONFIG_RCU_TRACE
extern void do_trace_rcu_torture_read(char *rcutorturename, 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 #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
#endif #endif
......
...@@ -523,22 +523,30 @@ TRACE_EVENT(rcu_batch_end, ...@@ -523,22 +523,30 @@ TRACE_EVENT(rcu_batch_end,
*/ */
TRACE_EVENT(rcu_torture_read, 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( TP_STRUCT__entry(
__field(char *, rcutorturename) __field(char *, rcutorturename)
__field(struct rcu_head *, rhp) __field(struct rcu_head *, rhp)
__field(unsigned long, secs)
__field(unsigned long, c_old)
__field(unsigned long, c)
), ),
TP_fast_assign( TP_fast_assign(
__entry->rcutorturename = rcutorturename; __entry->rcutorturename = rcutorturename;
__entry->rhp = rhp; __entry->rhp = rhp;
__entry->secs = secs;
__entry->c_old = c_old;
__entry->c = c;
), ),
TP_printk("%s torture read %p", TP_printk("%s torture read %p %luus c: %lu %lu",
__entry->rcutorturename, __entry->rhp) __entry->rcutorturename, __entry->rhp,
__entry->secs, __entry->c_old, __entry->c)
); );
/* /*
...@@ -608,7 +616,8 @@ TRACE_EVENT(rcu_barrier, ...@@ -608,7 +616,8 @@ TRACE_EVENT(rcu_barrier,
#define trace_rcu_invoke_kfree_callback(rcuname, rhp, offset) do { } while (0) #define trace_rcu_invoke_kfree_callback(rcuname, rhp, offset) do { } while (0)
#define trace_rcu_batch_end(rcuname, callbacks_invoked, cb, nr, iit, risk) \ #define trace_rcu_batch_end(rcuname, callbacks_invoked, cb, nr, iit, risk) \
do { } while (0) 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) #define trace_rcu_barrier(name, s, cpu, cnt, done) do { } while (0)
#endif /* #else #ifdef CONFIG_RCU_TRACE */ #endif /* #else #ifdef CONFIG_RCU_TRACE */
......
...@@ -404,11 +404,14 @@ EXPORT_SYMBOL_GPL(rcuhead_debug_descr); ...@@ -404,11 +404,14 @@ EXPORT_SYMBOL_GPL(rcuhead_debug_descr);
#endif /* #ifdef CONFIG_DEBUG_OBJECTS_RCU_HEAD */ #endif /* #ifdef CONFIG_DEBUG_OBJECTS_RCU_HEAD */
#if defined(CONFIG_TREE_RCU) || defined(CONFIG_TREE_PREEMPT_RCU) || defined(CONFIG_RCU_TRACE) #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); EXPORT_SYMBOL_GPL(do_trace_rcu_torture_read);
#else #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
...@@ -46,6 +46,7 @@ ...@@ -46,6 +46,7 @@
#include <linux/stat.h> #include <linux/stat.h>
#include <linux/srcu.h> #include <linux/srcu.h>
#include <linux/slab.h> #include <linux/slab.h>
#include <linux/trace_clock.h>
#include <asm/byteorder.h> #include <asm/byteorder.h>
MODULE_LICENSE("GPL"); MODULE_LICENSE("GPL");
...@@ -1028,7 +1029,6 @@ void rcutorture_trace_dump(void) ...@@ -1028,7 +1029,6 @@ void rcutorture_trace_dump(void)
return; return;
if (atomic_xchg(&beenhere, 1) != 0) if (atomic_xchg(&beenhere, 1) != 0)
return; return;
do_trace_rcu_torture_read(cur_ops->name, (struct rcu_head *)~0UL);
ftrace_dump(DUMP_ALL); ftrace_dump(DUMP_ALL);
} }
...@@ -1042,13 +1042,16 @@ static void rcu_torture_timer(unsigned long unused) ...@@ -1042,13 +1042,16 @@ static void rcu_torture_timer(unsigned long unused)
{ {
int idx; int idx;
int completed; int completed;
int completed_end;
static DEFINE_RCU_RANDOM(rand); static DEFINE_RCU_RANDOM(rand);
static DEFINE_SPINLOCK(rand_lock); static DEFINE_SPINLOCK(rand_lock);
struct rcu_torture *p; struct rcu_torture *p;
int pipe_count; int pipe_count;
unsigned long long ts;
idx = cur_ops->readlock(); idx = cur_ops->readlock();
completed = cur_ops->completed(); completed = cur_ops->completed();
ts = trace_clock_local();
p = rcu_dereference_check(rcu_torture_current, p = rcu_dereference_check(rcu_torture_current,
rcu_read_lock_bh_held() || rcu_read_lock_bh_held() ||
rcu_read_lock_sched_held() || rcu_read_lock_sched_held() ||
...@@ -1058,7 +1061,6 @@ static void rcu_torture_timer(unsigned long unused) ...@@ -1058,7 +1061,6 @@ static void rcu_torture_timer(unsigned long unused)
cur_ops->readunlock(idx); cur_ops->readunlock(idx);
return; return;
} }
do_trace_rcu_torture_read(cur_ops->name, &p->rtort_rcu);
if (p->rtort_mbtest == 0) if (p->rtort_mbtest == 0)
atomic_inc(&n_rcu_torture_mberror); atomic_inc(&n_rcu_torture_mberror);
spin_lock(&rand_lock); spin_lock(&rand_lock);
...@@ -1071,10 +1073,16 @@ static void rcu_torture_timer(unsigned long unused) ...@@ -1071,10 +1073,16 @@ static void rcu_torture_timer(unsigned long unused)
/* Should not happen, but... */ /* Should not happen, but... */
pipe_count = RCU_TORTURE_PIPE_LEN; 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(); rcutorture_trace_dump();
}
__this_cpu_inc(rcu_torture_count[pipe_count]); __this_cpu_inc(rcu_torture_count[pipe_count]);
completed = cur_ops->completed() - completed; completed = completed_end - completed;
if (completed > RCU_TORTURE_PIPE_LEN) { if (completed > RCU_TORTURE_PIPE_LEN) {
/* Should not happen, but... */ /* Should not happen, but... */
completed = RCU_TORTURE_PIPE_LEN; completed = RCU_TORTURE_PIPE_LEN;
...@@ -1094,11 +1102,13 @@ static int ...@@ -1094,11 +1102,13 @@ static int
rcu_torture_reader(void *arg) rcu_torture_reader(void *arg)
{ {
int completed; int completed;
int completed_end;
int idx; int idx;
DEFINE_RCU_RANDOM(rand); DEFINE_RCU_RANDOM(rand);
struct rcu_torture *p; struct rcu_torture *p;
int pipe_count; int pipe_count;
struct timer_list t; struct timer_list t;
unsigned long long ts;
VERBOSE_PRINTK_STRING("rcu_torture_reader task started"); VERBOSE_PRINTK_STRING("rcu_torture_reader task started");
set_user_nice(current, 19); set_user_nice(current, 19);
...@@ -1112,6 +1122,7 @@ rcu_torture_reader(void *arg) ...@@ -1112,6 +1122,7 @@ rcu_torture_reader(void *arg)
} }
idx = cur_ops->readlock(); idx = cur_ops->readlock();
completed = cur_ops->completed(); completed = cur_ops->completed();
ts = trace_clock_local();
p = rcu_dereference_check(rcu_torture_current, p = rcu_dereference_check(rcu_torture_current,
rcu_read_lock_bh_held() || rcu_read_lock_bh_held() ||
rcu_read_lock_sched_held() || rcu_read_lock_sched_held() ||
...@@ -1122,7 +1133,6 @@ rcu_torture_reader(void *arg) ...@@ -1122,7 +1133,6 @@ rcu_torture_reader(void *arg)
schedule_timeout_interruptible(HZ); schedule_timeout_interruptible(HZ);
continue; continue;
} }
do_trace_rcu_torture_read(cur_ops->name, &p->rtort_rcu);
if (p->rtort_mbtest == 0) if (p->rtort_mbtest == 0)
atomic_inc(&n_rcu_torture_mberror); atomic_inc(&n_rcu_torture_mberror);
cur_ops->read_delay(&rand); cur_ops->read_delay(&rand);
...@@ -1132,10 +1142,17 @@ rcu_torture_reader(void *arg) ...@@ -1132,10 +1142,17 @@ rcu_torture_reader(void *arg)
/* Should not happen, but... */ /* Should not happen, but... */
pipe_count = RCU_TORTURE_PIPE_LEN; 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(); rcutorture_trace_dump();
}
__this_cpu_inc(rcu_torture_count[pipe_count]); __this_cpu_inc(rcu_torture_count[pipe_count]);
completed = cur_ops->completed() - completed; completed = completed_end - completed;
if (completed > RCU_TORTURE_PIPE_LEN) { if (completed > RCU_TORTURE_PIPE_LEN) {
/* Should not happen, but... */ /* Should not happen, but... */
completed = RCU_TORTURE_PIPE_LEN; completed = RCU_TORTURE_PIPE_LEN;
......
...@@ -1008,6 +1008,7 @@ config RCU_CPU_STALL_INFO ...@@ -1008,6 +1008,7 @@ config RCU_CPU_STALL_INFO
config RCU_TRACE config RCU_TRACE
bool "Enable tracing for RCU" bool "Enable tracing for RCU"
depends on DEBUG_KERNEL depends on DEBUG_KERNEL
select TRACE_CLOCK
help help
This option provides tracing in RCU which presents stats This option provides tracing in RCU which presents stats
in debugfs for debugging RCU implementation. in debugfs for debugging RCU implementation.
......
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment