[RFC][PATCH] ftrace: Add internal recursive checks

[RFC][PATCH] ftrace: Add internal recursive checks

[Steven Rostedt]

Witold reported a reboot caused by the selftests of the dynamic function
tracer. He sent me a config and I used ktest to do a config_bisect on it
(as my config did not cause the crash). It pointed out that the problem
config was CONFIG_PROVE_RCU.

What happened was that if multiple callbacks are attached to the
function tracer, we iterate a list of callbacks. Because the list is
managed by synchronize_sched() and preempt_disable, the access to the
pointers uses rcu_dereference_raw().

When PROVE_RCU is enabled, the rcu_dereference_raw() calls some
debugging functions, which happen to be traced. The tracing of the debug
function would then call rcu_dereference_raw() which would then call the
debug function and then... well you get the idea.

I first wrote two different patches to solve this bug.

1) add a __rcu_dereference_raw() that would not do any checks.
2) add notrace to the offending debug functions.

Both of these patches worked.

Talking with Paul McKenney on IRC, he suggested to add recursion
detection instead. This seemed to be a better solution, so I decided to
implement it. As the task_struct already has a trace_recursion to detect
recursion in the ring buffer, and that has a very small number it
allows, I decided to use that same variable to add flags that can detect
the recursion inside the infrastructure of the function tracer.

I plan to change it so that the task struct bit can be checked in
mcount, but as that requires changes to all archs, I will hold that off
to the next merge window.

Reported-by: Witold Baryluk <baryluk@smp.if.uj.edu.pl>
Not-yet-signed-off-by: Steven Rostedt <rostedt@goodmis.org>

diff --git a/include/linux/sched.h b/include/linux/sched.h
index 885c4f2..54484e0 100644
--- a/include/linux/sched.h
+++ b/include/linux/sched.h
@@ -1514,8 +1514,20 @@ struct task_struct {
 #ifdef CONFIG_TRACING
 	/* state flags for use by tracers */
 	unsigned long trace;
-	/* bitmask of trace recursion */
+	/* bitmask and counter of trace recursion */
 	unsigned long trace_recursion;
+
+	/* Only current can touch these values */
+#define trace_recursion_inc() (current)->trace_recursion++
+#define trace_recursion_dec() (current)->trace_recursion--
+	/* Ring buffer has the 10 LSB bits to count */
+#define trace_recursion_buffer() ((current)->trace_recursion & 0x3ff)
+#define TRACE_INTERNAL_BIT		(1<<11)
+#define TRACE_GLOBAL_BIT		(1<<12)
+#define trace_recursion_set(bit)	(current)->trace_recursion |= (bit)
+#define trace_recursion_clear(bit)	(current)->trace_recursion &= ~(bit)
+#define trace_recursion_test(bit)	((current)->trace_recursion & (bit))
+
 #endif /* CONFIG_TRACING */
 #ifdef CONFIG_CGROUP_MEM_RES_CTLR /* memcg uses this to do batch job */
 	struct memcg_batch_info {
diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
index d017c2c..33b00d8 100644
--- a/kernel/trace/ftrace.c
+++ b/kernel/trace/ftrace.c
@@ -109,12 +109,18 @@ ftrace_ops_list_func(unsigned long ip, unsigned long parent_ip);
 static void ftrace_global_list_func(unsigned long ip,
 				    unsigned long parent_ip)
 {
-	struct ftrace_ops *op = rcu_dereference_raw(ftrace_global_list); /*see above*/
+	struct ftrace_ops *op;
+
+	if (unlikely(trace_recursion_test(TRACE_GLOBAL_BIT)))
+		return;
 
+	trace_recursion_set(TRACE_GLOBAL_BIT);
+	op = rcu_dereference_raw(ftrace_global_list); /*see above*/
 	while (op != &ftrace_list_end) {
 		op->func(ip, parent_ip);
 		op = rcu_dereference_raw(op->next); /*see above*/
 	};
+	trace_recursion_clear(TRACE_GLOBAL_BIT);
 }
 
 static void ftrace_pid_func(unsigned long ip, unsigned long parent_ip)
@@ -3484,6 +3490,10 @@ ftrace_ops_list_func(unsigned long ip, unsigned long parent_ip)
 {
 	struct ftrace_ops *op;
 
+	if (unlikely(trace_recursion_test(TRACE_INTERNAL_BIT)))
+		return;
+
+	trace_recursion_set(TRACE_INTERNAL_BIT);
 	/*
 	 * Some of the ops may be dynamically allocated,
 	 * they must be freed after a synchronize_sched().
@@ -3496,6 +3506,7 @@ ftrace_ops_list_func(unsigned long ip, unsigned long parent_ip)
 		op = rcu_dereference_raw(op->next);
 	};
 	preempt_enable_notrace();
+	trace_recursion_clear(TRACE_INTERNAL_BIT);
 }
 
 static void clear_ftrace_swapper(void)
diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
index 0ef7b4b..b0c7aa4 100644
--- a/kernel/trace/ring_buffer.c
+++ b/kernel/trace/ring_buffer.c
@@ -2216,7 +2216,7 @@ static noinline void trace_recursive_fail(void)
 
 	printk_once(KERN_WARNING "Tracing recursion: depth[%ld]:"
 		    "HC[%lu]:SC[%lu]:NMI[%lu]\n",
-		    current->trace_recursion,
+		    trace_recursion_buffer(),
 		    hardirq_count() >> HARDIRQ_SHIFT,
 		    softirq_count() >> SOFTIRQ_SHIFT,
 		    in_nmi());
@@ -2226,9 +2226,9 @@ static noinline void trace_recursive_fail(void)
 
 static inline int trace_recursive_lock(void)
 {
-	current->trace_recursion++;
+	trace_recursion_inc();
 
-	if (likely(current->trace_recursion < TRACE_RECURSIVE_DEPTH))
+	if (likely(trace_recursion_buffer() < TRACE_RECURSIVE_DEPTH))
 		return 0;
 
 	trace_recursive_fail();
@@ -2238,9 +2238,9 @@ static inline int trace_recursive_lock(void)
 
 static inline void trace_recursive_unlock(void)
 {
-	WARN_ON_ONCE(!current->trace_recursion);
+	WARN_ON_ONCE(!trace_recursion_buffer());
 
-	current->trace_recursion--;
+	trace_recursion_dec();
 }
 
 #else

Re: [RFC][PATCH] ftrace: Add internal recursive checks

[Thomas Gleixner]

On Wed, 25 May 2011, Steven Rostedt wrote:
> +
> +	/* Only current can touch these values */
> +#define trace_recursion_inc() (current)->trace_recursion++
> +#define trace_recursion_dec() (current)->trace_recursion--
> +	/* Ring buffer has the 10 LSB bits to count */
> +#define trace_recursion_buffer() ((current)->trace_recursion & 0x3ff)
> +#define TRACE_INTERNAL_BIT		(1<<11)
> +#define TRACE_GLOBAL_BIT		(1<<12)
> +#define trace_recursion_set(bit)	(current)->trace_recursion |= (bit)
> +#define trace_recursion_clear(bit)	(current)->trace_recursion &= ~(bit)
> +#define trace_recursion_test(bit)	((current)->trace_recursion & (bit))
> +
>  #endif /* CONFIG_TRACING */

Bah, these are only used in kernel/trace/. So can you please add them
to a kernel/trace local header file instead of cramming it mindlessly
into task_struct just because you're lazy?

Thanks,

	tglx

Re: [RFC][PATCH] ftrace: Add internal recursive checks

[Steven Rostedt]

On Wed, 2011-05-25 at 20:57 +0200, Thomas Gleixner wrote:
> On Wed, 25 May 2011, Steven Rostedt wrote:
> > +
> > +	/* Only current can touch these values */
> > +#define trace_recursion_inc() (current)->trace_recursion++
> > +#define trace_recursion_dec() (current)->trace_recursion--
> > +	/* Ring buffer has the 10 LSB bits to count */
> > +#define trace_recursion_buffer() ((current)->trace_recursion & 0x3ff)
> > +#define TRACE_INTERNAL_BIT		(1<<11)
> > +#define TRACE_GLOBAL_BIT		(1<<12)
> > +#define trace_recursion_set(bit)	(current)->trace_recursion |= (bit)
> > +#define trace_recursion_clear(bit)	(current)->trace_recursion &= ~(bit)
> > +#define trace_recursion_test(bit)	((current)->trace_recursion & (bit))
> > +
> >  #endif /* CONFIG_TRACING */
> 
> Bah, these are only used in kernel/trace/. So can you please add them
> to a kernel/trace local header file instead of cramming it mindlessly
> into task_struct just because you're lazy?

Actually the lazy thing to do was to include it only in
kernel/trace/trace.h BUT...

Any user of the function tracer (callbacks) may need to do the same
thing, because the callbacks could be called without going though the
list lookup and may need their own bit set.

But that said, I'll move these over to include/linux/ftrace.h as that is
probably the better location for it.

-- Steve

Re: [RFC][PATCH] ftrace: Add internal recursive checks

[Thomas Gleixner]

On Wed, 25 May 2011, Steven Rostedt wrote:

> On Wed, 2011-05-25 at 20:57 +0200, Thomas Gleixner wrote:
> > On Wed, 25 May 2011, Steven Rostedt wrote:
> > > +
> > > +	/* Only current can touch these values */
> > > +#define trace_recursion_inc() (current)->trace_recursion++
> > > +#define trace_recursion_dec() (current)->trace_recursion--
> > > +	/* Ring buffer has the 10 LSB bits to count */
> > > +#define trace_recursion_buffer() ((current)->trace_recursion & 0x3ff)
> > > +#define TRACE_INTERNAL_BIT		(1<<11)
> > > +#define TRACE_GLOBAL_BIT		(1<<12)
> > > +#define trace_recursion_set(bit)	(current)->trace_recursion |= (bit)
> > > +#define trace_recursion_clear(bit)	(current)->trace_recursion &= ~(bit)
> > > +#define trace_recursion_test(bit)	((current)->trace_recursion & (bit))
> > > +
> > >  #endif /* CONFIG_TRACING */
> > 
> > Bah, these are only used in kernel/trace/. So can you please add them
> > to a kernel/trace local header file instead of cramming it mindlessly
> > into task_struct just because you're lazy?
> 
> Actually the lazy thing to do was to include it only in
> kernel/trace/trace.h BUT...
> 
> Any user of the function tracer (callbacks) may need to do the same
> thing, because the callbacks could be called without going though the
> list lookup and may need their own bit set.

Errm, what means _MAY_? There are no users outside of kernel/trace/
for this right now. Are you saying that you forgot to update some code
or is this about random out of tree users?
 
Thanks,

	tglx

Re: [RFC][PATCH] ftrace: Add internal recursive checks

[Steven Rostedt]

On Thu, 2011-05-26 at 00:54 +0200, Thomas Gleixner wrote:
> On Wed, 25 May 2011, Steven Rostedt wrote:

> > Any user of the function tracer (callbacks) may need to do the same
> > thing, because the callbacks could be called without going though the
> > list lookup and may need their own bit set.
> 
> Errm, what means _MAY_? There are no users outside of kernel/trace/
> for this right now. Are you saying that you forgot to update some code
> or is this about random out of tree users?

Actually, I was thinking about perf, not some random out of tree user.
But if this is needed, I hate to have to move the code then. It's not
like it's modifying some internal to ftrace variable. It is modifying a
variable in the task_struct. If there are other users that need it. Why
not expose it in a core header? And it's not like ftrace.h is a bad
location for this. ftrace.h is in fact made for function tracing.

This would not even work for out of tree users, as any bit they chose,
could someday conflict with an internal user.

-- Steve

Re: [RFC][PATCH] ftrace: Add internal recursive checks

[Steven Rostedt]

On Wed, 2011-05-25 at 19:41 -0400, Steven Rostedt wrote:
> On Thu, 2011-05-26 at 00:54 +0200, Thomas Gleixner wrote:
> > On Wed, 25 May 2011, Steven Rostedt wrote:

> > Errm, what means _MAY_? There are no users outside of kernel/trace/
> > for this right now. Are you saying that you forgot to update some code
> > or is this about random out of tree users?
> 
> Actually, I was thinking about perf, not some random out of tree user.
> But if this is needed, I hate to have to move the code then. It's not
> like it's modifying some internal to ftrace variable. It is modifying a
> variable in the task_struct. If there are other users that need it. Why
> not expose it in a core header? And it's not like ftrace.h is a bad
> location for this. ftrace.h is in fact made for function tracing.

Thinking about this a little more. I think I will put this in
kernel/trace/trace.h. Not for the reasons you give, but because the next
change in this area (for the next merge window) I want to have mcount do
the work, and then we only need one recursive bit set, and it will
handle function recursion by all users, and then we don't need to worry
about recursions due to the function tracer anymore :)

-- Steve

[tip:perf/urgent] ftrace: Add internal recursive checks

[tip-bot for Steven Rostedt]

Commit-ID:  b1cff0ad1062621ae63cb6c5dc4165191fe2e9f1
Gitweb:     http://git.kernel.org/tip/b1cff0ad1062621ae63cb6c5dc4165191fe2e9f1
Author:     Steven Rostedt <rostedt@goodmis.org>
AuthorDate: Wed, 25 May 2011 14:27:43 -0400
Committer:  Steven Rostedt <rostedt@goodmis.org>
CommitDate: Wed, 25 May 2011 22:13:49 -0400

ftrace: Add internal recursive checks

Witold reported a reboot caused by the selftests of the dynamic function
tracer. He sent me a config and I used ktest to do a config_bisect on it
(as my config did not cause the crash). It pointed out that the problem
config was CONFIG_PROVE_RCU.

What happened was that if multiple callbacks are attached to the
function tracer, we iterate a list of callbacks. Because the list is
managed by synchronize_sched() and preempt_disable, the access to the
pointers uses rcu_dereference_raw().

When PROVE_RCU is enabled, the rcu_dereference_raw() calls some
debugging functions, which happen to be traced. The tracing of the debug
function would then call rcu_dereference_raw() which would then call the
debug function and then... well you get the idea.

I first wrote two different patches to solve this bug.

1) add a __rcu_dereference_raw() that would not do any checks.
2) add notrace to the offending debug functions.

Both of these patches worked.

Talking with Paul McKenney on IRC, he suggested to add recursion
detection instead. This seemed to be a better solution, so I decided to
implement it. As the task_struct already has a trace_recursion to detect
recursion in the ring buffer, and that has a very small number it
allows, I decided to use that same variable to add flags that can detect
the recursion inside the infrastructure of the function tracer.

I plan to change it so that the task struct bit can be checked in
mcount, but as that requires changes to all archs, I will hold that off
to the next merge window.

Cc: Ingo Molnar <mingo@elte.hu>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
Link: http://lkml.kernel.org/r/1306348063.1465.116.camel@gandalf.stny.rr.com
Reported-by: Witold Baryluk <baryluk@smp.if.uj.edu.pl>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 include/linux/sched.h      |    2 +-
 kernel/trace/ftrace.c      |   13 ++++++++++++-
 kernel/trace/ring_buffer.c |   10 +++++-----
 kernel/trace/trace.h       |   15 +++++++++++++++
 4 files changed, 33 insertions(+), 7 deletions(-)

diff --git a/include/linux/sched.h b/include/linux/sched.h
index d8b2d0b..7b78d9c 100644
--- a/include/linux/sched.h
+++ b/include/linux/sched.h
@@ -1513,7 +1513,7 @@ struct task_struct {
 #ifdef CONFIG_TRACING
 	/* state flags for use by tracers */
 	unsigned long trace;
-	/* bitmask of trace recursion */
+	/* bitmask and counter of trace recursion */
 	unsigned long trace_recursion;
 #endif /* CONFIG_TRACING */
 #ifdef CONFIG_CGROUP_MEM_RES_CTLR /* memcg uses this to do batch job */
diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
index 25949b3..1ee417f 100644
--- a/kernel/trace/ftrace.c
+++ b/kernel/trace/ftrace.c
@@ -109,12 +109,18 @@ ftrace_ops_list_func(unsigned long ip, unsigned long parent_ip);
 static void ftrace_global_list_func(unsigned long ip,
 				    unsigned long parent_ip)
 {
-	struct ftrace_ops *op = rcu_dereference_raw(ftrace_global_list); /*see above*/
+	struct ftrace_ops *op;
+
+	if (unlikely(trace_recursion_test(TRACE_GLOBAL_BIT)))
+		return;
 
+	trace_recursion_set(TRACE_GLOBAL_BIT);
+	op = rcu_dereference_raw(ftrace_global_list); /*see above*/
 	while (op != &ftrace_list_end) {
 		op->func(ip, parent_ip);
 		op = rcu_dereference_raw(op->next); /*see above*/
 	};
+	trace_recursion_clear(TRACE_GLOBAL_BIT);
 }
 
 static void ftrace_pid_func(unsigned long ip, unsigned long parent_ip)
@@ -3490,6 +3496,10 @@ ftrace_ops_list_func(unsigned long ip, unsigned long parent_ip)
 {
 	struct ftrace_ops *op;
 
+	if (unlikely(trace_recursion_test(TRACE_INTERNAL_BIT)))
+		return;
+
+	trace_recursion_set(TRACE_INTERNAL_BIT);
 	/*
 	 * Some of the ops may be dynamically allocated,
 	 * they must be freed after a synchronize_sched().
@@ -3502,6 +3512,7 @@ ftrace_ops_list_func(unsigned long ip, unsigned long parent_ip)
 		op = rcu_dereference_raw(op->next);
 	};
 	preempt_enable_notrace();
+	trace_recursion_clear(TRACE_INTERNAL_BIT);
 }
 
 static void clear_ftrace_swapper(void)
diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
index 0ef7b4b..b0c7aa4 100644
--- a/kernel/trace/ring_buffer.c
+++ b/kernel/trace/ring_buffer.c
@@ -2216,7 +2216,7 @@ static noinline void trace_recursive_fail(void)
 
 	printk_once(KERN_WARNING "Tracing recursion: depth[%ld]:"
 		    "HC[%lu]:SC[%lu]:NMI[%lu]\n",
-		    current->trace_recursion,
+		    trace_recursion_buffer(),
 		    hardirq_count() >> HARDIRQ_SHIFT,
 		    softirq_count() >> SOFTIRQ_SHIFT,
 		    in_nmi());
@@ -2226,9 +2226,9 @@ static noinline void trace_recursive_fail(void)
 
 static inline int trace_recursive_lock(void)
 {
-	current->trace_recursion++;
+	trace_recursion_inc();
 
-	if (likely(current->trace_recursion < TRACE_RECURSIVE_DEPTH))
+	if (likely(trace_recursion_buffer() < TRACE_RECURSIVE_DEPTH))
 		return 0;
 
 	trace_recursive_fail();
@@ -2238,9 +2238,9 @@ static inline int trace_recursive_lock(void)
 
 static inline void trace_recursive_unlock(void)
 {
-	WARN_ON_ONCE(!current->trace_recursion);
+	WARN_ON_ONCE(!trace_recursion_buffer());
 
-	current->trace_recursion--;
+	trace_recursion_dec();
 }
 
 #else
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 6b69c4b..229f859 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -784,4 +784,19 @@ extern const char *__stop___trace_bprintk_fmt[];
 	FTRACE_ENTRY(call, struct_name, id, PARAMS(tstruct), PARAMS(print))
 #include "trace_entries.h"
 
+/* Only current can touch trace_recursion */
+#define trace_recursion_inc() do { (current)->trace_recursion++; } while (0)
+#define trace_recursion_dec() do { (current)->trace_recursion--; } while (0)
+
+/* Ring buffer has the 10 LSB bits to count */
+#define trace_recursion_buffer() ((current)->trace_recursion & 0x3ff)
+
+/* for function tracing recursion */
+#define TRACE_INTERNAL_BIT		(1<<11)
+#define TRACE_GLOBAL_BIT		(1<<12)
+
+#define trace_recursion_set(bit)	do { (current)->trace_recursion |= (bit); } while (0)
+#define trace_recursion_clear(bit)	do { (current)->trace_recursion &= ~(bit); } while (0)
+#define trace_recursion_test(bit)	((current)->trace_recursion & (bit))
+
 #endif /* _LINUX_KERNEL_TRACE_H */