[PATCH 1/3] tracing/ftrace: don't insert TRACE_PRINT during selftests

[PATCH 1/3] tracing/ftrace: don't insert TRACE_PRINT during selftests

[Frederic Weisbecker]

Impact: fix tracer selfstests false results

After setting a ftrace_printk somewhere in th kernel, I saw the
Function tracer selftest failing.

When a selftest occurs, the ring buffer is lurked to see if
some entries were inserted. But concurrent insertion such as
ftrace_printk could occured at the same time and could give
false positive or negative results.

This patch prevent prevent from TRACE_PRINT entries insertion
during selftests.

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
---
 kernel/trace/trace.c |   13 ++++++++++++-
 1 files changed, 12 insertions(+), 1 deletions(-)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index ea38652..5dca6ef 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -44,6 +44,14 @@
 unsigned long __read_mostly	tracing_max_latency = (cycle_t)ULONG_MAX;
 unsigned long __read_mostly	tracing_thresh;
 
+/* We need to change this state when a selftest is running.
+ * A selftest will lurk into the ring-buffer to count the
+ * entries inserted during the selftest although some concurrent
+ * insertions into the ring-buffer such as ftrace_printk could occurred
+ * at the same time, giving false positive or negative results.
+ */
+static atomic_t tracing_selftest_running = ATOMIC_INIT(0);
+
 /* For tracers that don't implement custom flags */
 static struct tracer_opt dummy_tracer_opt[] = {
 	{ }
@@ -589,6 +597,8 @@ int register_tracer(struct tracer *type)
 		struct tracer *saved_tracer = current_trace;
 		struct trace_array *tr = &global_trace;
 		int i;
+
+		atomic_set(&tracing_selftest_running, 1);
 		/*
 		 * Run a selftest on this tracer.
 		 * Here we reset the trace buffer, and set the current
@@ -603,6 +613,7 @@ int register_tracer(struct tracer *type)
 		/* the test is responsible for initializing and enabling */
 		pr_info("Testing tracer %s: ", type->name);
 		ret = type->selftest(type, tr);
+		atomic_set(&tracing_selftest_running, 0);
 		/* the test is responsible for resetting too */
 		current_trace = saved_tracer;
 		if (ret) {
@@ -3594,7 +3605,7 @@ int trace_vprintk(unsigned long ip, int depth, const char *fmt, va_list args)
 	unsigned long flags, irq_flags;
 	int cpu, len = 0, size, pc;
 
-	if (tracing_disabled)
+	if (tracing_disabled || atomic_read(&tracing_selftest_running))
 		return 0;
 
 	pc = preempt_count();
-- 
1.5.6.3

Re: [PATCH 1/3] tracing/ftrace: don't insert TRACE_PRINT during selftests

[Steven Rostedt]

On Thu, 4 Dec 2008, Frederic Weisbecker wrote:
> Impact: fix tracer selfstests false results
> 
> After setting a ftrace_printk somewhere in th kernel, I saw the
> Function tracer selftest failing.
> 
> When a selftest occurs, the ring buffer is lurked to see if
> some entries were inserted. But concurrent insertion such as
> ftrace_printk could occured at the same time and could give
> false positive or negative results.
> 
> This patch prevent prevent from TRACE_PRINT entries insertion
> during selftests.
> 
> Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
> ---
>  kernel/trace/trace.c |   13 ++++++++++++-
>  1 files changed, 12 insertions(+), 1 deletions(-)
> 
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index ea38652..5dca6ef 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -44,6 +44,14 @@
>  unsigned long __read_mostly	tracing_max_latency = (cycle_t)ULONG_MAX;
>  unsigned long __read_mostly	tracing_thresh;
>  
> +/* We need to change this state when a selftest is running.
> + * A selftest will lurk into the ring-buffer to count the
> + * entries inserted during the selftest although some concurrent
> + * insertions into the ring-buffer such as ftrace_printk could occurred
> + * at the same time, giving false positive or negative results.
> + */

The comment style should be:

/*
 * comment
 * comment
 * comment
 */


> +static atomic_t tracing_selftest_running = ATOMIC_INIT(0);

Do we need that is atomic? Also, it needs to be __read_mostly.

> +
>  /* For tracers that don't implement custom flags */
>  static struct tracer_opt dummy_tracer_opt[] = {
>  	{ }
> @@ -589,6 +597,8 @@ int register_tracer(struct tracer *type)
>  		struct tracer *saved_tracer = current_trace;
>  		struct trace_array *tr = &global_trace;
>  		int i;
> +
> +		atomic_set(&tracing_selftest_running, 1);

Enable this in the mutex lock, and we could make it a normal int.

>  		/*
>  		 * Run a selftest on this tracer.
>  		 * Here we reset the trace buffer, and set the current
> @@ -603,6 +613,7 @@ int register_tracer(struct tracer *type)
>  		/* the test is responsible for initializing and enabling */
>  		pr_info("Testing tracer %s: ", type->name);
>  		ret = type->selftest(type, tr);
> +		atomic_set(&tracing_selftest_running, 0);
>  		/* the test is responsible for resetting too */
>  		current_trace = saved_tracer;
>  		if (ret) {
> @@ -3594,7 +3605,7 @@ int trace_vprintk(unsigned long ip, int depth, const char *fmt, va_list args)
>  	unsigned long flags, irq_flags;
>  	int cpu, len = 0, size, pc;
>  
> -	if (tracing_disabled)
> +	if (tracing_disabled || atomic_read(&tracing_selftest_running))
>  		return 0;
>  
>  	pc = preempt_count();
> -- 

-- Steve

Re: [PATCH 1/3] tracing/ftrace: don't insert TRACE_PRINT during selftests

[Frédéric Weisbecker]

2008/12/4 Steven Rostedt <rostedt@goodmis.org>:
> The comment style should be:
>
> /*
>  * comment
>  * comment
>  * comment
>  */

Sorry, will fix it.

>
>> +static atomic_t tracing_selftest_running = ATOMIC_INIT(0);
>
> Do we need that is atomic? Also, it needs to be __read_mostly.


I thought it should be atomic to be sure the value is synchronized
on smp when read. But actually that should have been more likely an
int with smp_wb after writing it.

>> +
>>  /* For tracers that don't implement custom flags */
>>  static struct tracer_opt dummy_tracer_opt[] = {
>>       { }
>> @@ -589,6 +597,8 @@ int register_tracer(struct tracer *type)
>>               struct tracer *saved_tracer = current_trace;
>>               struct trace_array *tr = &global_trace;
>>               int i;
>> +
>> +             atomic_set(&tracing_selftest_running, 1);
>
> Enable this in the mutex lock, and we could make it a normal int.
>


But ftrace_printk can be called from interrupt context. I think we can loose
some TRACE_PRINT entries at the selftests time since the tracer are not enabled
by the user at this time, except the boot tracer...

>>               /*
>>                * Run a selftest on this tracer.
>>                * Here we reset the trace buffer, and set the current
>> @@ -603,6 +613,7 @@ int register_tracer(struct tracer *type)
>>               /* the test is responsible for initializing and enabling */
>>               pr_info("Testing tracer %s: ", type->name);
>>               ret = type->selftest(type, tr);
>> +             atomic_set(&tracing_selftest_running, 0);
>>               /* the test is responsible for resetting too */
>>               current_trace = saved_tracer;
>>               if (ret) {
>> @@ -3594,7 +3605,7 @@ int trace_vprintk(unsigned long ip, int depth, const char *fmt, va_list args)
>>       unsigned long flags, irq_flags;
>>       int cpu, len = 0, size, pc;
>>
>> -     if (tracing_disabled)
>> +     if (tracing_disabled || atomic_read(&tracing_selftest_running))
>>               return 0;
>>
>>       pc = preempt_count();
>> --
>
> -- Steve
>
>

Re: [PATCH 1/3] tracing/ftrace: don't insert TRACE_PRINT during selftests

[Frédéric Weisbecker]

2008/12/5 Frédéric Weisbecker <fweisbec@gmail.com>:
> 2008/12/4 Steven Rostedt <rostedt@goodmis.org>:
>> The comment style should be:
>>
>> /*
>>  * comment
>>  * comment
>>  * comment
>>  */
>
> Sorry, will fix it.
>
>>
>>> +static atomic_t tracing_selftest_running = ATOMIC_INIT(0);
>>
>> Do we need that is atomic? Also, it needs to be __read_mostly.
>
>
> I thought it should be atomic to be sure the value is synchronized
> on smp when read. But actually that should have been more likely an
> int with smp_wb after writing it.
>
>>> +
>>>  /* For tracers that don't implement custom flags */
>>>  static struct tracer_opt dummy_tracer_opt[] = {
>>>       { }
>>> @@ -589,6 +597,8 @@ int register_tracer(struct tracer *type)
>>>               struct tracer *saved_tracer = current_trace;
>>>               struct trace_array *tr = &global_trace;
>>>               int i;
>>> +
>>> +             atomic_set(&tracing_selftest_running, 1);
>>
>> Enable this in the mutex lock, and we could make it a normal int.
>>
>
>
> But ftrace_printk can be called from interrupt context. I think we can loose
> some TRACE_PRINT entries at the selftests time since the tracer are not enabled
> by the user at this time, except the boot tracer...
>

But with the boot tracer enabled, there is no selftest actually :-)

Re: [PATCH 1/3] tracing/ftrace: don't insert TRACE_PRINT during selftests

[Steven Rostedt]

On Fri, 5 Dec 2008, Fr?d?ric Weisbecker wrote:
> >
> > Enable this in the mutex lock, and we could make it a normal int.
> >
> 
> 
> But ftrace_printk can be called from interrupt context. I think we can loose
> some TRACE_PRINT entries at the selftests time since the tracer are not enabled
> by the user at this time, except the boot tracer...

I mean, move it down farther after we acquire the mutex. Should be fine.

-- Steve

> 
> >>               /*
> >>                * Run a selftest on this tracer.
> >>                * Here we reset the trace buffer, and set the current
> >> @@ -603,6 +613,7 @@ int register_tracer(struct tracer *type)
> >>               /* the test is responsible for initializing and enabling */
> >>               pr_info("Testing tracer %s: ", type->name);
> >>               ret = type->selftest(type, tr);
> >> +             atomic_set(&tracing_selftest_running, 0);
> >>               /* the test is responsible for resetting too */
> >>               current_trace = saved_tracer;
> >>               if (ret) {
> >> @@ -3594,7 +3605,7 @@ int trace_vprintk(unsigned long ip, int depth, const char *fmt, va_list args)
> >>       unsigned long flags, irq_flags;
> >>       int cpu, len = 0, size, pc;
> >>
> >> -     if (tracing_disabled)
> >> +     if (tracing_disabled || atomic_read(&tracing_selftest_running))
> >>               return 0;
> >>
> >>       pc = preempt_count();
> >> --
> >
> > -- Steve
> >
> >
> 
> 

Re: [PATCH 1/3] tracing/ftrace: don't insert TRACE_PRINT during selftests

[Ingo Molnar]

* Frederic Weisbecker <fweisbec@gmail.com> wrote:

> Impact: fix tracer selfstests false results
> 
> After setting a ftrace_printk somewhere in th kernel, I saw the
> Function tracer selftest failing.
> 
> When a selftest occurs, the ring buffer is lurked to see if
> some entries were inserted. But concurrent insertion such as
> ftrace_printk could occured at the same time and could give
> false positive or negative results.
> 
> This patch prevent prevent from TRACE_PRINT entries insertion
> during selftests.
> 
> Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
> ---
>  kernel/trace/trace.c |   13 ++++++++++++-
>  1 files changed, 12 insertions(+), 1 deletions(-)

applied to tip/tracing/ftrace, thanks.

I suspect you'll also fix the things Steve pointed out?

	Ingo

Re: [PATCH 1/3] tracing/ftrace: don't insert TRACE_PRINT during selftests

[Frédéric Weisbecker]

2008/12/5 Ingo Molnar <mingo@elte.hu>:
>
> * Frederic Weisbecker <fweisbec@gmail.com> wrote:
>
>> Impact: fix tracer selfstests false results
>>
>> After setting a ftrace_printk somewhere in th kernel, I saw the
>> Function tracer selftest failing.
>>
>> When a selftest occurs, the ring buffer is lurked to see if
>> some entries were inserted. But concurrent insertion such as
>> ftrace_printk could occured at the same time and could give
>> false positive or negative results.
>>
>> This patch prevent prevent from TRACE_PRINT entries insertion
>> during selftests.
>>
>> Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
>> ---
>>  kernel/trace/trace.c |   13 ++++++++++++-
>>  1 files changed, 12 insertions(+), 1 deletions(-)
>
> applied to tip/tracing/ftrace, thanks.
>
> I suspect you'll also fix the things Steve pointed out?


Yes of course :-)