tracing/ftrace: don't insert TRACE_PRINT during selftests

PATCH Applied Frederic Weisbecker 3 participants 7 messages Dec 4, 2008 – Dec 5, 2008 Tracing

lore

Share & tools

lore

Frederic Weisbecker

author

2008-12-04 22:47 UTC #0 lore raw

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

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 <[email protected]>

---
 kernel/trace/trace.c |   13 ++++++++++++-
 1 files changed, 12 insertions(+), 1 deletions(-)

kernel/trace/trace.c +12 -1

index ea38652..5dca6ef 100644
@@ -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();

Signature · 1 line

1.5.6.3

Steven Rostedt

maintainer

2008-12-04 22:56 UTC #1 lore raw

Quoted 23 lines · 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 <[email protected]>
---
 kernel/trace/trace.c |   13 ++++++++++++-
 1 files changed, 12 insertions(+), 1 deletions(-)
kernel/trace/trace.c +0 -0
index ea38652..5dca6ef 100644

kernel/trace/trace.c line 52

Quoted 9 lines

kernel/trace/trace.c +6 -0

@@ -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
*/

kernel/trace/trace.c line 53

Quoted 1 line

kernel/trace/trace.c +1 -0

+static atomic_t tracing_selftest_running = ATOMIC_INIT(0);

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

kernel/trace/trace.c int register_tracer(struct tracer *type) · line 601

Quoted 10 lines

kernel/trace/trace.c +3 -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);

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

Quoted 13 lines

kernel/trace/trace.c +1 -0

 		/*
 		 * 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) {

kernel/trace/trace.c int trace_vprintk(unsigned long ip, int depth, const char *fmt, va_list args) · line 3611

Quoted 8 lines

kernel/trace/trace.c +1 -1

@@ -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

Frédéric Weisbecker

author

2008-12-04 23:03 UTC #2 lore raw

2008/12/4 Steven Rostedt <[email protected]>:

Quoted 7 lines

The comment style should be:
/*
* comment
* comment
* comment
*/

Sorry, will fix it.

Quoted 4 lines

Quoted 2 lines
+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.

Quoted 4 lines

Quoted 4 lines
+
/* For tracers that don't implement custom flags */
 static struct tracer_opt dummy_tracer_opt[] = {
      { }

Quoted 9 lines

kernel/trace/trace.c int register_tracer(struct tracer *type) · line 601

Quoted 6 lines

kernel/trace/trace.c +2 -0

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

Quoted 25 lines

Quoted 12 lines

kernel/trace/trace.c +1 -0

              /*
               * 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) {

kernel/trace/trace.c int trace_vprintk(unsigned long ip, int depth, const char *fmt, va_list args)

Quoted 9 lines

kernel/trace/trace.c +1 -2

@@ -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

Frédéric Weisbecker

author

2008-12-04 23:05 UTC #3 lore raw

2008/12/5 Frédéric Weisbecker <[email protected]>:

Quoted 36 lines

2008/12/4 Steven Rostedt <[email protected]>:
Quoted 7 lines
The comment style should be:
/*
* comment
* comment
* comment
*/
Sorry, will fix it.
Quoted 4 lines
Quoted 2 lines
+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.
Quoted 4 lines
Quoted 4 lines
+
/* For tracers that don't implement custom flags */
 static struct tracer_opt dummy_tracer_opt[] = {
      { }
Quoted 9 lines
kernel/trace/trace.c int register_tracer(struct tracer *type) · line 601
Quoted 6 lines
kernel/trace/trace.c +2 -0
@@ -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.

Quoted 4 lines

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 :-)

Steven Rostedt

maintainer

2008-12-04 23:26 UTC #4 lore raw

In reply to Frédéric Weisbecker

Quoted 8 lines · Fr?d?ric Weisbecker

Quoted 3 lines
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

Quoted 28 lines

Quoted 26 lines

Quoted 13 lines

/*
* Run a selftest on this tracer.
* Here we reset the trace buffer, and set the current

kernel/trace/trace.c +1 -0

@@ -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) {

kernel/trace/trace.c int trace_vprintk(unsigned long ip, int depth, const char *fmt, va_list args)

Quoted 9 lines

kernel/trace/trace.c +1 -2

@@ -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

Ingo Molnar

Applied

2008-12-05 13:48 UTC #5 lore raw

In reply to Frederic Weisbecker

Quoted 10 lines · 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.

Quoted 7 lines

This patch prevent prevent from TRACE_PRINT entries insertion during selftests.
Signed-off-by Frederic Weisbecker <[email protected]>
---
 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

Frédéric Weisbecker

author

2008-12-05 14:01 UTC #6 lore raw

2008/12/5 Ingo Molnar <[email protected]>:

Quoted 16 lines · Frederic Weisbecker

Quoted 14 lines
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.

Quoted 8 lines

Quoted 4 lines
Signed-off-by Frederic Weisbecker <[email protected]>
---
 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 :-)