ftrace: preemptoff selftest not working

ftrace: preemptoff selftest not working

[Heiko Carstens]

Hi Steven,

I was wondering why the preemptoff and preemptirqsoff tracer selftests
don't work on s390. After all its just that they get called from
non-preemptible context:

kernel_init() will execute all initcalls, however the first line in
kernel_init() is lock_kernel(), which causes the preempt_count to be
increased. Any later calls to add_preempt_count() (especially those
from the selftests) will therefore not result in a call to
trace_preempt_off() since the check below in add_preempt_count()
will be false:

	if (preempt_count() == val)
		trace_preempt_off(CALLER_ADDR0, get_parent_ip(CALLER_ADDR1));

Hence the trace buffer will be empty.
The patch below makes the selftests working for me, since then they run
in preemptible context. But it is ugly and I'm not proposing it for
upstream ;)

Just wanted to make you aware that there is a bug.

---
 init/main.c                  |    4 ++++
 kernel/trace/trace_irqsoff.c |    3 +--
 2 files changed, 5 insertions(+), 2 deletions(-)

Index: linux-2.6/kernel/trace/trace_irqsoff.c
===================================================================
--- linux-2.6.orig/kernel/trace/trace_irqsoff.c
+++ linux-2.6/kernel/trace/trace_irqsoff.c
@@ -482,7 +482,7 @@ static struct tracer preemptirqsoff_trac
 # define register_preemptirqsoff(trace) do { } while (0)
 #endif
 
-__init static int init_irqsoff_tracer(void)
+int init_irqsoff_tracer(void)
 {
 	register_irqsoff(irqsoff_tracer);
 	register_preemptoff(preemptoff_tracer);
@@ -490,4 +490,3 @@ __init static int init_irqsoff_tracer(vo
 
 	return 0;
 }
-device_initcall(init_irqsoff_tracer);
Index: linux-2.6/init/main.c
===================================================================
--- linux-2.6.orig/init/main.c
+++ linux-2.6/init/main.c
@@ -789,6 +789,8 @@ static void run_init_process(char *init_
 	kernel_execve(init_filename, argv_init, envp_init);
 }
 
+extern int init_irqsoff_tracer(void);
+
 /* This is a non __init function. Force it to be noinline otherwise gcc
  * makes it inline to init() and it becomes part of init.text section
  */
@@ -800,6 +802,8 @@ static int noinline init_post(void)
 	system_state = SYSTEM_RUNNING;
 	numa_default_policy();
 
+	init_irqsoff_tracer();
+
 	if (sys_open((const char __user *) "/dev/console", O_RDWR, 0) < 0)
 		printk(KERN_WARNING "Warning: unable to open an initial console.\n");
 

Re: ftrace: preemptoff selftest not working

[Ingo Molnar]

* Heiko Carstens <heiko.carstens@de.ibm.com> wrote:

> Hi Steven,
> 
> I was wondering why the preemptoff and preemptirqsoff tracer 
> selftests don't work on s390. After all its just that they get 
> called from non-preemptible context:
> 
> kernel_init() will execute all initcalls, however the first line in 
> kernel_init() is lock_kernel(), which causes the preempt_count to be 
> increased. Any later calls to add_preempt_count() (especially those 
> from the selftests) will therefore not result in a call to 
> trace_preempt_off() since the check below in add_preempt_count() 
> will be false:
> 
> 	if (preempt_count() == val)
> 		trace_preempt_off(CALLER_ADDR0, get_parent_ip(CALLER_ADDR1));
> 
> Hence the trace buffer will be empty.

ah, indeed :-)

side-effect of the removal of CONFIG_PREEMPT_BKL - these things were 
written before that and nobody noticed that the self-test stopped 
working for real.

> The patch below makes the selftests working for me, since then they 
> run in preemptible context. But it is ugly and I'm not proposing it 
> for upstream ;)
> 
> Just wanted to make you aware that there is a bug.

indeed it's ugly. We could perhaps drop the BKL in the selftests?

	Ingo

Re: ftrace: preemptoff selftest not working

[Steven Rostedt]

On Tue, 18 Nov 2008, Heiko Carstens wrote:

> Hi Steven,
> 
> I was wondering why the preemptoff and preemptirqsoff tracer selftests
> don't work on s390. After all its just that they get called from
> non-preemptible context:
> 
> kernel_init() will execute all initcalls, however the first line in
> kernel_init() is lock_kernel(), which causes the preempt_count to be
> increased. Any later calls to add_preempt_count() (especially those
> from the selftests) will therefore not result in a call to
> trace_preempt_off() since the check below in add_preempt_count()
> will be false:
> 
> 	if (preempt_count() == val)
> 		trace_preempt_off(CALLER_ADDR0, get_parent_ip(CALLER_ADDR1));
> 
> Hence the trace buffer will be empty.
> The patch below makes the selftests working for me, since then they run
> in preemptible context. But it is ugly and I'm not proposing it for
> upstream ;)
> 
> Just wanted to make you aware that there is a bug.

Yep, this might be a better answer than what I put into linux-tip (and my 
git repo).

See:

  ftrace: force pass of preemptoff selftest

The cause of the bug was the conversion of the BKL back to a spinlock, and 
making it non preempt.  The initcall code is called with the BKL applied 
which now means it can not preempt. This breaks the preempt tracer 
selftest.

My solution was to just force a pass if this is detected. Perhaps moving 
the test might be better.

-- Steve

> 
> ---
>  init/main.c                  |    4 ++++
>  kernel/trace/trace_irqsoff.c |    3 +--
>  2 files changed, 5 insertions(+), 2 deletions(-)
> 
> Index: linux-2.6/kernel/trace/trace_irqsoff.c
> ===================================================================
> --- linux-2.6.orig/kernel/trace/trace_irqsoff.c
> +++ linux-2.6/kernel/trace/trace_irqsoff.c
> @@ -482,7 +482,7 @@ static struct tracer preemptirqsoff_trac
>  # define register_preemptirqsoff(trace) do { } while (0)
>  #endif
>  
> -__init static int init_irqsoff_tracer(void)
> +int init_irqsoff_tracer(void)
>  {
>  	register_irqsoff(irqsoff_tracer);
>  	register_preemptoff(preemptoff_tracer);
> @@ -490,4 +490,3 @@ __init static int init_irqsoff_tracer(vo
>  
>  	return 0;
>  }
> -device_initcall(init_irqsoff_tracer);
> Index: linux-2.6/init/main.c
> ===================================================================
> --- linux-2.6.orig/init/main.c
> +++ linux-2.6/init/main.c
> @@ -789,6 +789,8 @@ static void run_init_process(char *init_
>  	kernel_execve(init_filename, argv_init, envp_init);
>  }
>  
> +extern int init_irqsoff_tracer(void);
> +
>  /* This is a non __init function. Force it to be noinline otherwise gcc
>   * makes it inline to init() and it becomes part of init.text section
>   */
> @@ -800,6 +802,8 @@ static int noinline init_post(void)
>  	system_state = SYSTEM_RUNNING;
>  	numa_default_policy();
>  
> +	init_irqsoff_tracer();
> +
>  	if (sys_open((const char __user *) "/dev/console", O_RDWR, 0) < 0)
>  		printk(KERN_WARNING "Warning: unable to open an initial console.\n");
>  
> 
> 

Re: ftrace: preemptoff selftest not working

[Ingo Molnar]

* Steven Rostedt <rostedt@goodmis.org> wrote:

> > Hence the trace buffer will be empty. The patch below makes the 
> > selftests working for me, since then they run in preemptible 
> > context. But it is ugly and I'm not proposing it for upstream ;)
> > 
> > Just wanted to make you aware that there is a bug.
> 
> Yep, this might be a better answer than what I put into linux-tip 
> (and my git repo).
> 
> See:
> 
>   ftrace: force pass of preemptoff selftest
> 
> The cause of the bug was the conversion of the BKL back to a 
> spinlock, and making it non preempt.  The initcall code is called 
> with the BKL applied which now means it can not preempt. This breaks 
> the preempt tracer selftest.
> 
> My solution was to just force a pass if this is detected. Perhaps 
> moving the test might be better.

it would be better to just drop the BKL in that selftest. (or in all 
selftests - an elevated preempt count will skew a number of things)

	Ingo

Re: ftrace: preemptoff selftest not working

[Steven Rostedt]

On Tue, 18 Nov 2008, Ingo Molnar wrote:
> 
> * Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > > Hence the trace buffer will be empty. The patch below makes the 
> > > selftests working for me, since then they run in preemptible 
> > > context. But it is ugly and I'm not proposing it for upstream ;)
> > > 
> > > Just wanted to make you aware that there is a bug.
> > 
> > Yep, this might be a better answer than what I put into linux-tip 
> > (and my git repo).
> > 
> > See:
> > 
> >   ftrace: force pass of preemptoff selftest
> > 
> > The cause of the bug was the conversion of the BKL back to a 
> > spinlock, and making it non preempt.  The initcall code is called 
> > with the BKL applied which now means it can not preempt. This breaks 
> > the preempt tracer selftest.
> > 
> > My solution was to just force a pass if this is detected. Perhaps 
> > moving the test might be better.
> 
> it would be better to just drop the BKL in that selftest. (or in all 
> selftests - an elevated preempt count will skew a number of things)

I have no problem with that, but does the BKL play any role for being 
held? I have no idea why it is taken in boot up, so I'm hestiant to touch 
it.

-- Steve

Re: ftrace: preemptoff selftest not working

[Ingo Molnar]

* Steven Rostedt <rostedt@goodmis.org> wrote:

> 
> On Tue, 18 Nov 2008, Ingo Molnar wrote:
> > 
> > * Steven Rostedt <rostedt@goodmis.org> wrote:
> > 
> > > > Hence the trace buffer will be empty. The patch below makes the 
> > > > selftests working for me, since then they run in preemptible 
> > > > context. But it is ugly and I'm not proposing it for upstream ;)
> > > > 
> > > > Just wanted to make you aware that there is a bug.
> > > 
> > > Yep, this might be a better answer than what I put into linux-tip 
> > > (and my git repo).
> > > 
> > > See:
> > > 
> > >   ftrace: force pass of preemptoff selftest
> > > 
> > > The cause of the bug was the conversion of the BKL back to a 
> > > spinlock, and making it non preempt.  The initcall code is called 
> > > with the BKL applied which now means it can not preempt. This breaks 
> > > the preempt tracer selftest.
> > > 
> > > My solution was to just force a pass if this is detected. Perhaps 
> > > moving the test might be better.
> > 
> > it would be better to just drop the BKL in that selftest. (or in all 
> > selftests - an elevated preempt count will skew a number of things)
> 
> I have no problem with that, but does the BKL play any role for 
> being held? I have no idea why it is taken in boot up, so I'm 
> hestiant to touch it.

we can drop it in selected initcalls just fine. Its only role is 
old-style init functions racing with other async contexts of 
themselves.

	Ingo

Re: ftrace: preemptoff selftest not working

[Heiko Carstens]

On Tue, Nov 18, 2008 at 03:47:51PM +0100, Ingo Molnar wrote:
> 
> * Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > 
> > On Tue, 18 Nov 2008, Ingo Molnar wrote:
> > > 
> > > * Steven Rostedt <rostedt@goodmis.org> wrote:
> > > 
> > > > > Hence the trace buffer will be empty. The patch below makes the 
> > > > > selftests working for me, since then they run in preemptible 
> > > > > context. But it is ugly and I'm not proposing it for upstream ;)
> > > > > 
> > > > > Just wanted to make you aware that there is a bug.
> > > > 
> > > > Yep, this might be a better answer than what I put into linux-tip 
> > > > (and my git repo).
> > > > 
> > > > See:
> > > > 
> > > >   ftrace: force pass of preemptoff selftest
> > > > 
> > > > The cause of the bug was the conversion of the BKL back to a 
> > > > spinlock, and making it non preempt.  The initcall code is called 
> > > > with the BKL applied which now means it can not preempt. This breaks 
> > > > the preempt tracer selftest.
> > > > 
> > > > My solution was to just force a pass if this is detected. Perhaps 
> > > > moving the test might be better.
> > > 
> > > it would be better to just drop the BKL in that selftest. (or in all 
> > > selftests - an elevated preempt count will skew a number of things)
> > 
> > I have no problem with that, but does the BKL play any role for 
> > being held? I have no idea why it is taken in boot up, so I'm 
> > hestiant to touch it.
> 
> we can drop it in selected initcalls just fine. Its only role is 
> old-style init functions racing with other async contexts of 
> themselves.

Something like below works fine for me...

Signed-off-by: Heiko Carstens <heiko.carstens@de.ibm.com>
---

 kernel/trace/trace.c |    8 ++++++++
 1 file changed, 8 insertions(+)

Index: linux-2.6/kernel/trace/trace.c
===================================================================
--- linux-2.6.orig/kernel/trace/trace.c
+++ linux-2.6/kernel/trace/trace.c
@@ -482,6 +482,13 @@ int register_tracer(struct tracer *type)
 	}
 
 #ifdef CONFIG_FTRACE_STARTUP_TEST
+	/*
+	 * When this gets called we hold the BKL which means that preemption
+	 * is disabled. Various trace selftests however need to disable
+	 * and enable preemption for successful tests. So we drop the BKL here
+	 * and grab it after the tests again.
+	 */
+	unlock_kernel();
 	if (type->selftest) {
 		struct tracer *saved_tracer = current_trace;
 		struct trace_array *tr = &global_trace;
@@ -515,6 +522,7 @@ int register_tracer(struct tracer *type)
 		}
 		printk(KERN_CONT "PASSED\n");
 	}
+	lock_kernel();
 #endif
 
 	type->next = trace_types;

Re: ftrace: preemptoff selftest not working

[Steven Rostedt]

On Tue, 18 Nov 2008, Heiko Carstens wrote:
> > 
> > we can drop it in selected initcalls just fine. Its only role is 
> > old-style init functions racing with other async contexts of 
> > themselves.
> 
> Something like below works fine for me...
> 
> Signed-off-by: Heiko Carstens <heiko.carstens@de.ibm.com>

Acked-by: Steven Rostedt <srostedt@redhat.com>

-- Steve

> ---
> 
>  kernel/trace/trace.c |    8 ++++++++
>  1 file changed, 8 insertions(+)
> 
> Index: linux-2.6/kernel/trace/trace.c
> ===================================================================
> --- linux-2.6.orig/kernel/trace/trace.c
> +++ linux-2.6/kernel/trace/trace.c
> @@ -482,6 +482,13 @@ int register_tracer(struct tracer *type)
>  	}
>  
>  #ifdef CONFIG_FTRACE_STARTUP_TEST
> +	/*
> +	 * When this gets called we hold the BKL which means that preemption
> +	 * is disabled. Various trace selftests however need to disable
> +	 * and enable preemption for successful tests. So we drop the BKL here
> +	 * and grab it after the tests again.
> +	 */
> +	unlock_kernel();
>  	if (type->selftest) {
>  		struct tracer *saved_tracer = current_trace;
>  		struct trace_array *tr = &global_trace;
> @@ -515,6 +522,7 @@ int register_tracer(struct tracer *type)
>  		}
>  		printk(KERN_CONT "PASSED\n");
>  	}
> +	lock_kernel();
>  #endif
>  
>  	type->next = trace_types;
> 
> 

Re: ftrace: preemptoff selftest not working

[Ingo Molnar]

* Steven Rostedt <rostedt@goodmis.org> wrote:

> 
> On Tue, 18 Nov 2008, Heiko Carstens wrote:
> > > 
> > > we can drop it in selected initcalls just fine. Its only role is 
> > > old-style init functions racing with other async contexts of 
> > > themselves.
> > 
> > Something like below works fine for me...
> > 
> > Signed-off-by: Heiko Carstens <heiko.carstens@de.ibm.com>
> 
> Acked-by: Steven Rostedt <srostedt@redhat.com>

i've applied it in the form below to tip/tracing/ftrace, thanks guys!

Since it's only about the self-test, and since they have not been 
working for a long time, i'm punting this to v2.6.29, not .28.

	Ingo

------------->
>From a22506347d038a66506c6f57e9b97104128e280d Mon Sep 17 00:00:00 2001
From: Heiko Carstens <heiko.carstens@de.ibm.com>
Date: Tue, 18 Nov 2008 18:06:35 +0100
Subject: [PATCH] ftrace: preemptoff selftest not working

Impact: fix preemptoff and preemptirqsoff tracer self-tests

I was wondering why the preemptoff and preemptirqsoff tracer selftests
don't work on s390. After all its just that they get called from
non-preemptible context:

kernel_init() will execute all initcalls, however the first line in
kernel_init() is lock_kernel(), which causes the preempt_count to be
increased. Any later calls to add_preempt_count() (especially those
from the selftests) will therefore not result in a call to
trace_preempt_off() since the check below in add_preempt_count()
will be false:

        if (preempt_count() == val)
                trace_preempt_off(CALLER_ADDR0, get_parent_ip(CALLER_ADDR1));

Hence the trace buffer will be empty.

Fix this by releasing the BKL during the self-tests.

Signed-off-by: Heiko Carstens <heiko.carstens@de.ibm.com>
Acked-by: Steven Rostedt <rostedt@goodmis.org>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
---
 kernel/trace/trace.c |    8 ++++++++
 1 files changed, 8 insertions(+), 0 deletions(-)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 396fda0..1689212 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -532,6 +532,13 @@ int register_tracer(struct tracer *type)
 	}
 
 #ifdef CONFIG_FTRACE_STARTUP_TEST
+	/*
+	 * When this gets called we hold the BKL which means that preemption
+	 * is disabled. Various trace selftests however need to disable
+	 * and enable preemption for successful tests. So we drop the BKL here
+	 * and grab it after the tests again.
+	 */
+	unlock_kernel();
 	if (type->selftest) {
 		struct tracer *saved_tracer = current_trace;
 		struct trace_array *tr = &global_trace;
@@ -562,6 +569,7 @@ int register_tracer(struct tracer *type)
 		}
 		printk(KERN_CONT "PASSED\n");
 	}
+	lock_kernel();
 #endif
 
 	type->next = trace_types;

Re: ftrace: preemptoff selftest not working

[Ingo Molnar]

>  #ifdef CONFIG_FTRACE_STARTUP_TEST
> +	/*
> +	 * When this gets called we hold the BKL which means that preemption
> +	 * is disabled. Various trace selftests however need to disable
> +	 * and enable preemption for successful tests. So we drop the BKL here
> +	 * and grab it after the tests again.
> +	 */
> +	unlock_kernel();
>  	if (type->selftest) {
>  		struct tracer *saved_tracer = current_trace;
>  		struct trace_array *tr = &global_trace;
> @@ -562,6 +569,7 @@ int register_tracer(struct tracer *type)
>  		}
>  		printk(KERN_CONT "PASSED\n");
>  	}
> +	lock_kernel();

dropping the BKL was a good idea, but the code flow was not 
investigated thoroughly enough, which caused this crash to trigger in 
-tip testing:

calling  utsname_sysctl_init+0x0/0x11 @ 1
initcall utsname_sysctl_init+0x0/0x11 returned 0 after 0 usecs
calling  init_sched_switch_trace+0x0/0xf @ 1
Testing tracer sched_switch: PASSED
initcall init_sched_switch_trace+0x0/0xf returned 0 after 101562 usecs
calling  init_stack_trace+0x0/0xf @ 1
Testing tracer sysprof: PASSED
initcall init_stack_trace+0x0/0xf returned 0 after 105468 usecs
calling  init_irqsoff_tracer+0x0/0x11 @ 1
Testing tracer irqsoff: .. no entries found ..FAILED!
initcall init_irqsoff_tracer+0x0/0x11 returned 0 after 3906 usecs
calling  init_mmio_trace+0x0/0xf @ 1
------------[ cut here ]------------
Kernel BUG at c0c0a915 [verbose debug info unavailable]
invalid opcode: 0000 [#1] SMP DEBUG_PAGEALLOC
last sysfs file: 

Pid: 1, comm: swapper Not tainted (2.6.28-rc5-tip #53704) 
EIP: 0060:[<c0c0a915>] EFLAGS: 00010286 CPU: 1
EIP is at unlock_kernel+0x10/0x2b
EAX: ffffffff EBX: 00000000 ECX: 00000000 EDX: f7030000
ESI: c12da19c EDI: 00000000 EBP: f7039f54 ESP: f7039f54
 DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
Process swapper (pid: 1, ti=f7038000 task=f7030000 task.ti=f7038000)
Stack:
 f7039f6c c0164d30 c013fed8 a7d8d7b4 00000000 00000000 f7039f74 c12fb78a
 f7039fd0 c0101132 c12fb77d 00000000 6f727200 6f632072 2d206564 c1002031
 0000000f f7039fa2 f7039fb0 3531b171 00000000 00000000 0000002f c12ca480
Call Trace:
 [<c0164d30>] ? register_tracer+0x66/0x13f
 [<c013fed8>] ? ktime_get+0x19/0x1b
 [<c12fb78a>] ? init_mmio_trace+0xd/0xf
 [<c0101132>] ? do_one_initcall+0x4a/0x111
 [<c12fb77d>] ? init_mmio_trace+0x0/0xf
 [<c015c7e6>] ? init_irq_proc+0x46/0x59
 [<c12e851d>] ? kernel_init+0x104/0x152
 [<c12e8419>] ? kernel_init+0x0/0x152
 [<c01038b7>] ? kernel_thread_helper+0x7/0x10
Code: 58 14 43 75 0a b8 00 9b 2d c1 e8 51 43 7a ff 64 a1 00 a0 37 c1 89 58 14 5b 5d c3 55 64 8b 15 00 a0 37 c1 83 7a 14 00 89 e5 79 04 <0f> 0b eb fe 8b 42 14 48 85 c0 89 42 14 79 0a b8 00 9b 2d c1 e8 
EIP: [<c0c0a915>] unlock_kernel+0x10/0x2b SS:ESP 0068:f7039f54
---[ end trace a7919e7f17c0a725 ]---
Kernel panic - not syncing: Attempted to kill init!

the patch below fixes it.

	Ingo

-------------------->
>From 86fa2f60674540df0b34f5c547ed0c1cf3a8f212 Mon Sep 17 00:00:00 2001
From: Ingo Molnar <mingo@elte.hu>
Date: Wed, 19 Nov 2008 10:00:15 +0100
Subject: [PATCH] ftrace: fix selftest locking

Impact: fix self-test boot crash

Self-test failure forgot to re-lock the BKL - crashing the next
initcall:

Testing tracer irqsoff: .. no entries found ..FAILED!
initcall init_irqsoff_tracer+0x0/0x11 returned 0 after 3906 usecs
calling  init_mmio_trace+0x0/0xf @ 1
------------[ cut here ]------------
Kernel BUG at c0c0a915 [verbose debug info unavailable]
invalid opcode: 0000 [#1] SMP DEBUG_PAGEALLOC
last sysfs file:

Pid: 1, comm: swapper Not tainted (2.6.28-rc5-tip #53704)
EIP: 0060:[<c0c0a915>] EFLAGS: 00010286 CPU: 1
EIP is at unlock_kernel+0x10/0x2b
EAX: ffffffff EBX: 00000000 ECX: 00000000 EDX: f7030000
ESI: c12da19c EDI: 00000000 EBP: f7039f54 ESP: f7039f54
 DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
Process swapper (pid: 1, ti=f7038000 task=f7030000 task.ti=f7038000)
Stack:
 f7039f6c c0164d30 c013fed8 a7d8d7b4 00000000 00000000 f7039f74 c12fb78a
 f7039fd0 c0101132 c12fb77d 00000000 6f727200 6f632072 2d206564 c1002031
 0000000f f7039fa2 f7039fb0 3531b171 00000000 00000000 0000002f c12ca480
Call Trace:
 [<c0164d30>] ? register_tracer+0x66/0x13f
 [<c013fed8>] ? ktime_get+0x19/0x1b
 [<c12fb78a>] ? init_mmio_trace+0xd/0xf
 [<c0101132>] ? do_one_initcall+0x4a/0x111
 [<c12fb77d>] ? init_mmio_trace+0x0/0xf
 [<c015c7e6>] ? init_irq_proc+0x46/0x59
 [<c12e851d>] ? kernel_init+0x104/0x152
 [<c12e8419>] ? kernel_init+0x0/0x152
 [<c01038b7>] ? kernel_thread_helper+0x7/0x10
Code: 58 14 43 75 0a b8 00 9b 2d c1 e8 51 43 7a ff 64 a1 00 a0 37 c1 89 58 14 5b 5d c3 55 64 8b 15 00 a0 37 c1 83 7a 14 00 89 e5 79 04 <0f> 0b eb fe 8b 42 14 48 85 c0 89 42 14 79 0a b8 00 9b 2d c1 e8
EIP: [<c0c0a915>] unlock_kernel+0x10/0x2b SS:ESP 0068:f7039f54
---[ end trace a7919e7f17c0a725 ]---
Kernel panic - not syncing: Attempted to kill init!

So clean up the flow a bit.

Signed-off-by: Ingo Molnar <mingo@elte.hu>
---
 kernel/trace/trace.c |   25 +++++++++++++------------
 1 files changed, 13 insertions(+), 12 deletions(-)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 1689212..24b6238 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -520,7 +520,15 @@ int register_tracer(struct tracer *type)
 		return -1;
 	}
 
+	/*
+	 * When this gets called we hold the BKL which means that
+	 * preemption is disabled. Various trace selftests however
+	 * need to disable and enable preemption for successful tests.
+	 * So we drop the BKL here and grab it after the tests again.
+	 */
+	unlock_kernel();
 	mutex_lock(&trace_types_lock);
+
 	for (t = trace_types; t; t = t->next) {
 		if (strcmp(type->name, t->name) == 0) {
 			/* already found */
@@ -532,13 +540,6 @@ int register_tracer(struct tracer *type)
 	}
 
 #ifdef CONFIG_FTRACE_STARTUP_TEST
-	/*
-	 * When this gets called we hold the BKL which means that preemption
-	 * is disabled. Various trace selftests however need to disable
-	 * and enable preemption for successful tests. So we drop the BKL here
-	 * and grab it after the tests again.
-	 */
-	unlock_kernel();
 	if (type->selftest) {
 		struct tracer *saved_tracer = current_trace;
 		struct trace_array *tr = &global_trace;
@@ -550,9 +551,9 @@ int register_tracer(struct tracer *type)
 		 * internal tracing to verify that everything is in order.
 		 * If we fail, we do not register this tracer.
 		 */
-		for_each_tracing_cpu(i) {
+		for_each_tracing_cpu(i)
 			tracing_reset(tr, i);
-		}
+
 		current_trace = type;
 		/* the test is responsible for initializing and enabling */
 		pr_info("Testing tracer %s: ", type->name);
@@ -564,12 +565,11 @@ int register_tracer(struct tracer *type)
 			goto out;
 		}
 		/* Only reset on passing, to avoid touching corrupted buffers */
-		for_each_tracing_cpu(i) {
+		for_each_tracing_cpu(i)
 			tracing_reset(tr, i);
-		}
+
 		printk(KERN_CONT "PASSED\n");
 	}
-	lock_kernel();
 #endif
 
 	type->next = trace_types;
@@ -580,6 +580,7 @@ int register_tracer(struct tracer *type)
 
  out:
 	mutex_unlock(&trace_types_lock);
+	lock_kernel();
 
 	return ret;
 }

Re: ftrace: preemptoff selftest not working

[Heiko Carstens]

On Wed, Nov 19, 2008 at 10:02:23AM +0100, Ingo Molnar wrote:
> 
> >  #ifdef CONFIG_FTRACE_STARTUP_TEST
> > +	/*
> > +	 * When this gets called we hold the BKL which means that preemption
> > +	 * is disabled. Various trace selftests however need to disable
> > +	 * and enable preemption for successful tests. So we drop the BKL here
> > +	 * and grab it after the tests again.
> > +	 */
> > +	unlock_kernel();
> >  	if (type->selftest) {
> >  		struct tracer *saved_tracer = current_trace;
> >  		struct trace_array *tr = &global_trace;
> > @@ -562,6 +569,7 @@ int register_tracer(struct tracer *type)
> >  		}
> >  		printk(KERN_CONT "PASSED\n");
> >  	}
> > +	lock_kernel();
> 
> dropping the BKL was a good idea, but the code flow was not 
> investigated thoroughly enough, which caused this crash to trigger in 
> -tip testing:

Yes, I came to the same conlcusion this morning after reading the patch
again and wanted to send a follow-up patch. But you were faster ;)

Anyway, what bothers me more is the question if the idea to drop the BKL
in register_tracer is good. It's probably just a question of time until
the first tracers come in modules. And then the unlock_kernel()/lock_kernel()
sequence would be broken.
So it probably might make more sense to drop and grab the BKL in the
init functions that register a tracer?

But.. maybe the BKL is gone until this is an issue ;)