All of lore.kernel.org
 help / color / mirror / Atom feed
* [PATCH] ftrace: disable function tracing bringing up new CPU
@ 2008-06-05 20:54 Steven Rostedt
  2008-06-05 23:19 ` [PATCH -v2] " Steven Rostedt
  0 siblings, 1 reply; 3+ messages in thread
From: Steven Rostedt @ 2008-06-05 20:54 UTC (permalink / raw)
  To: Ingo Molnar; +Cc: LKML, Thomas Gleixner, Peter Zijlstra, Rusty Russell, akpm


Peter Zijlstra found that taking down and bringing up a new CPU caused
ftrace to crash the kernel. This was due to some arch calls that were
being traced by the function tracer before the smp_processor_id was set
up. Since the function tracer uses smp_processor_id it caused a triple
fault.

Instead of adding notrace all over the architecture code to prevent
this problem, it is easier to simply disable the function tracer
when bringing up a new CPU.

Signed-off-by: Steven Rostedt <srostedt@redhat.com>
---
 include/linux/ftrace.h            |   11 ++++++++---
 kernel/cpu.c                      |    9 +++++++++
 kernel/trace/ftrace.c             |   28 ++++++++++++++++++++++++++++
 kernel/trace/trace_irqsoff.c      |    3 +++
 kernel/trace/trace_sched_wakeup.c |    2 +-
 5 files changed, 49 insertions(+), 4 deletions(-)

Index: linux-tip.git/include/linux/ftrace.h
===================================================================
--- linux-tip.git.orig/include/linux/ftrace.h	2008-06-05 14:51:47.000000000 -0400
+++ linux-tip.git/include/linux/ftrace.h	2008-06-05 16:52:32.000000000 -0400
@@ -33,10 +33,15 @@ void clear_ftrace_function(void);
 extern void ftrace_stub(unsigned long a0, unsigned long a1);
 extern void mcount(void);

+void ftrace_enable(void);
+void ftrace_disable(void);
+
 #else /* !CONFIG_FTRACE */
-# define register_ftrace_function(ops) do { } while (0)
-# define unregister_ftrace_function(ops) do { } while (0)
-# define clear_ftrace_function(ops) do { } while (0)
+# define register_ftrace_function(ops)		do { } while (0)
+# define unregister_ftrace_function(ops)	do { } while (0)
+# define clear_ftrace_function(ops)		do { } while (0)
+# define ftrace_enable()			do { } while (0)
+# define ftrace_disable()			do { } while (0)
 #endif /* CONFIG_FTRACE */

 #ifdef CONFIG_DYNAMIC_FTRACE
Index: linux-tip.git/kernel/cpu.c
===================================================================
--- linux-tip.git.orig/kernel/cpu.c	2008-06-05 14:50:44.000000000 -0400
+++ linux-tip.git/kernel/cpu.c	2008-06-05 14:51:50.000000000 -0400
@@ -14,6 +14,7 @@
 #include <linux/kthread.h>
 #include <linux/stop_machine.h>
 #include <linux/mutex.h>
+#include <linux/ftrace.h>

 /* Serializes the updates to cpu_online_map, cpu_present_map */
 static DEFINE_MUTEX(cpu_add_remove_lock);
@@ -300,8 +301,16 @@ static int __cpuinit _cpu_up(unsigned in
 		goto out_notify;
 	}

+	/*
+	 * Disable function tracing while bringing up a new CPU.
+	 * We don't want to trace functions that can not handle a
+	 * smp_processor_id() call.
+	 */
+	ftrace_disable();
+
 	/* Arch-specific enabling code. */
 	ret = __cpu_up(cpu);
+	ftrace_enable();
 	if (ret != 0)
 		goto out_notify;
 	BUG_ON(!cpu_online(cpu));
Index: linux-tip.git/kernel/trace/ftrace.c
===================================================================
--- linux-tip.git.orig/kernel/trace/ftrace.c	2008-06-05 14:50:44.000000000 -0400
+++ linux-tip.git/kernel/trace/ftrace.c	2008-06-05 16:41:09.000000000 -0400
@@ -148,6 +148,34 @@ static int __unregister_ftrace_function(
 	return ret;
 }

+static int ftrace_disabled_count;
+static int save_ftrace_enabled;
+
+void ftrace_disable(void)
+{
+	unsigned long flags;
+
+	mutex_lock(&ftrace_sysctl_lock);
+
+	save_ftrace_enabled = ftrace_enabled;
+	ftrace_enabled = 0;
+}
+
+void ftrace_enable(void)
+{
+	unsigned long flags;
+
+	/* ftrace_enable must be paired with ftrace_disable */
+	if (!mutex_is_locked(&ftrace_sysctl_lock)) {
+		WARN_ON(1);
+		return;
+	}
+
+	ftrace_enabled = save_ftrace_enabled;
+
+	mutex_unlock(&ftrace_sysctl_lock);
+}
+
 #ifdef CONFIG_DYNAMIC_FTRACE

 static struct task_struct *ftraced_task;
Index: linux-tip.git/kernel/trace/trace_irqsoff.c
===================================================================
--- linux-tip.git.orig/kernel/trace/trace_irqsoff.c	2008-06-05 14:50:44.000000000 -0400
+++ linux-tip.git/kernel/trace/trace_irqsoff.c	2008-06-05 14:51:50.000000000 -0400
@@ -76,6 +76,9 @@ irqsoff_tracer_call(unsigned long ip, un
 	long disabled;
 	int cpu;

+	if (unlikely(!ftrace_enabled))
+		return;
+
 	/*
 	 * Does not matter if we preempt. We test the flags
 	 * afterward, to see if irqs are disabled or not.
Index: linux-tip.git/kernel/trace/trace_sched_wakeup.c
===================================================================
--- linux-tip.git.orig/kernel/trace/trace_sched_wakeup.c	2008-06-05 14:50:44.000000000 -0400
+++ linux-tip.git/kernel/trace/trace_sched_wakeup.c	2008-06-05 14:51:50.000000000 -0400
@@ -44,7 +44,7 @@ wakeup_tracer_call(unsigned long ip, uns
 	int resched;
 	int cpu;

-	if (likely(!wakeup_task))
+	if (likely(!wakeup_task) || !ftrace_enabled)
 		return;

 	resched = need_resched();

^ permalink raw reply	[flat|nested] 3+ messages in thread

* [PATCH -v2] ftrace: disable function tracing bringing up new CPU
  2008-06-05 20:54 [PATCH] ftrace: disable function tracing bringing up new CPU Steven Rostedt
@ 2008-06-05 23:19 ` Steven Rostedt
  2008-06-18  8:25   ` Ingo Molnar
  0 siblings, 1 reply; 3+ messages in thread
From: Steven Rostedt @ 2008-06-05 23:19 UTC (permalink / raw)
  To: Ingo Molnar; +Cc: LKML, Thomas Gleixner, Peter Zijlstra, Rusty Russell, akpm

[
  I noticed that I left a "unsigned long flags" in the version I sent out.
  That was due to my first faulty implementation that used a spin lock.
  Please use this patch instead. The only difference between this patch
  and the one I sent out is that I removed the unused flags variables
  from ftrace_enable() and ftrace_disable().
]

Peter Zijlstra found that taking down and bringing up a new CPU caused
ftrace to crash the kernel. This was due to some arch calls that were
being traced by the function tracer before the smp_processor_id was set
up. Since the function tracer uses smp_processor_id it caused a triple
fault.

Instead of adding notrace all over the architecture code to prevent
this problem, it is easier to simply disable the function tracer
when bringing up a new CPU.

Signed-off-by: Steven Rostedt <srostedt@redhat.com>
---
 include/linux/ftrace.h            |   11 ++++++++---
 kernel/cpu.c                      |    9 +++++++++
 kernel/trace/ftrace.c             |   24 ++++++++++++++++++++++++
 kernel/trace/trace_irqsoff.c      |    3 +++
 kernel/trace/trace_sched_wakeup.c |    2 +-
 5 files changed, 45 insertions(+), 4 deletions(-)

Index: linux-tip.git/include/linux/ftrace.h
===================================================================
--- linux-tip.git.orig/include/linux/ftrace.h	2008-06-05 14:51:47.000000000 -0400
+++ linux-tip.git/include/linux/ftrace.h	2008-06-05 16:52:32.000000000 -0400
@@ -33,10 +33,15 @@ void clear_ftrace_function(void);
 extern void ftrace_stub(unsigned long a0, unsigned long a1);
 extern void mcount(void);

+void ftrace_enable(void);
+void ftrace_disable(void);
+
 #else /* !CONFIG_FTRACE */
-# define register_ftrace_function(ops) do { } while (0)
-# define unregister_ftrace_function(ops) do { } while (0)
-# define clear_ftrace_function(ops) do { } while (0)
+# define register_ftrace_function(ops)		do { } while (0)
+# define unregister_ftrace_function(ops)	do { } while (0)
+# define clear_ftrace_function(ops)		do { } while (0)
+# define ftrace_enable()			do { } while (0)
+# define ftrace_disable()			do { } while (0)
 #endif /* CONFIG_FTRACE */

 #ifdef CONFIG_DYNAMIC_FTRACE
Index: linux-tip.git/kernel/cpu.c
===================================================================
--- linux-tip.git.orig/kernel/cpu.c	2008-06-05 14:50:44.000000000 -0400
+++ linux-tip.git/kernel/cpu.c	2008-06-05 14:51:50.000000000 -0400
@@ -14,6 +14,7 @@
 #include <linux/kthread.h>
 #include <linux/stop_machine.h>
 #include <linux/mutex.h>
+#include <linux/ftrace.h>

 /* Serializes the updates to cpu_online_map, cpu_present_map */
 static DEFINE_MUTEX(cpu_add_remove_lock);
@@ -300,8 +301,16 @@ static int __cpuinit _cpu_up(unsigned in
 		goto out_notify;
 	}

+	/*
+	 * Disable function tracing while bringing up a new CPU.
+	 * We don't want to trace functions that can not handle a
+	 * smp_processor_id() call.
+	 */
+	ftrace_disable();
+
 	/* Arch-specific enabling code. */
 	ret = __cpu_up(cpu);
+	ftrace_enable();
 	if (ret != 0)
 		goto out_notify;
 	BUG_ON(!cpu_online(cpu));
Index: linux-tip.git/kernel/trace/ftrace.c
===================================================================
--- linux-tip.git.orig/kernel/trace/ftrace.c	2008-06-05 14:50:44.000000000 -0400
+++ linux-tip.git/kernel/trace/ftrace.c	2008-06-05 18:17:14.000000000 -0400
@@ -148,6 +148,30 @@ static int __unregister_ftrace_function(
 	return ret;
 }

+static int ftrace_disabled_count;
+static int save_ftrace_enabled;
+
+void ftrace_disable(void)
+{
+	mutex_lock(&ftrace_sysctl_lock);
+
+	save_ftrace_enabled = ftrace_enabled;
+	ftrace_enabled = 0;
+}
+
+void ftrace_enable(void)
+{
+	/* ftrace_enable must be paired with ftrace_disable */
+	if (!mutex_is_locked(&ftrace_sysctl_lock)) {
+		WARN_ON(1);
+		return;
+	}
+
+	ftrace_enabled = save_ftrace_enabled;
+
+	mutex_unlock(&ftrace_sysctl_lock);
+}
+
 #ifdef CONFIG_DYNAMIC_FTRACE

 static struct task_struct *ftraced_task;
Index: linux-tip.git/kernel/trace/trace_irqsoff.c
===================================================================
--- linux-tip.git.orig/kernel/trace/trace_irqsoff.c	2008-06-05 14:50:44.000000000 -0400
+++ linux-tip.git/kernel/trace/trace_irqsoff.c	2008-06-05 14:51:50.000000000 -0400
@@ -76,6 +76,9 @@ irqsoff_tracer_call(unsigned long ip, un
 	long disabled;
 	int cpu;

+	if (unlikely(!ftrace_enabled))
+		return;
+
 	/*
 	 * Does not matter if we preempt. We test the flags
 	 * afterward, to see if irqs are disabled or not.
Index: linux-tip.git/kernel/trace/trace_sched_wakeup.c
===================================================================
--- linux-tip.git.orig/kernel/trace/trace_sched_wakeup.c	2008-06-05 14:50:44.000000000 -0400
+++ linux-tip.git/kernel/trace/trace_sched_wakeup.c	2008-06-05 14:51:50.000000000 -0400
@@ -44,7 +44,7 @@ wakeup_tracer_call(unsigned long ip, uns
 	int resched;
 	int cpu;

-	if (likely(!wakeup_task))
+	if (likely(!wakeup_task) || !ftrace_enabled)
 		return;

 	resched = need_resched();



^ permalink raw reply	[flat|nested] 3+ messages in thread

* Re: [PATCH -v2] ftrace: disable function tracing bringing up new CPU
  2008-06-05 23:19 ` [PATCH -v2] " Steven Rostedt
@ 2008-06-18  8:25   ` Ingo Molnar
  0 siblings, 0 replies; 3+ messages in thread
From: Ingo Molnar @ 2008-06-18  8:25 UTC (permalink / raw)
  To: Steven Rostedt; +Cc: LKML, Thomas Gleixner, Peter Zijlstra, Rusty Russell, akpm


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

> Peter Zijlstra found that taking down and bringing up a new CPU caused 
> ftrace to crash the kernel. This was due to some arch calls that were 
> being traced by the function tracer before the smp_processor_id was 
> set up. Since the function tracer uses smp_processor_id it caused a 
> triple fault.
> 
> Instead of adding notrace all over the architecture code to prevent 
> this problem, it is easier to simply disable the function tracer when 
> bringing up a new CPU.

this patch brought lockdep trouble - see below.

	Ingo

------------------->
calling  pcibios_irq_init+0x0/0x449
PCI: Using IRQ router PIIX/ICH [8086/2440] at 0000:00:1f.0

=======================================================
[ INFO: possible circular locking dependency detected ]
2.6.26-rc5-00070-g53ec472-dirty #697
-------------------------------------------------------
ftraced/27 is trying to acquire lock:
 (&cpu_hotplug.lock){--..}, at: [<c0125d44>] get_online_cpus+0x31/0x43

but task is already holding lock:
 (ftraced_lock){--..}, at: [<c014f6ad>] ftraced+0x47/0x136

which lock already depends on the new lock.


the existing dependency chain (in reverse order) is:

-> #2 (ftraced_lock){--..}:
       [<c01412ff>] __lock_acquire+0x9f8/0xb5f
       [<c0141872>] lock_acquire+0x6a/0x90
       [<c06efb64>] mutex_lock_nested+0xdd/0x27a
       [<c014f6ad>] ftraced+0x47/0x136
       [<c0135820>] kthread+0x40/0x68
       [<c0103c27>] kernel_thread_helper+0x7/0x10
       [<ffffffff>] 0xffffffff

-> #1 (ftrace_sysctl_lock){--..}:
       [<c01412ff>] __lock_acquire+0x9f8/0xb5f
       [<c0141872>] lock_acquire+0x6a/0x90
       [<c06efb64>] mutex_lock_nested+0xdd/0x27a
       [<c014e7ea>] ftrace_disable+0xf/0x25
       [<c06edb43>] _cpu_up+0x8a/0xf1
       [<c06edbf3>] cpu_up+0x49/0x59
       [<c0a3d599>] kernel_init+0x8e/0x264
       [<c0103c27>] kernel_thread_helper+0x7/0x10
       [<ffffffff>] 0xffffffff

-> #0 (&cpu_hotplug.lock){--..}:
       [<c0141226>] __lock_acquire+0x91f/0xb5f
       [<c0141872>] lock_acquire+0x6a/0x90
       [<c06efb64>] mutex_lock_nested+0xdd/0x27a
       [<c0125d44>] get_online_cpus+0x31/0x43
       [<c0147c34>] stop_machine_run+0x16/0x3d
       [<c014f00a>] ftrace_update_code+0x2f/0x3a
       [<c014f6cc>] ftraced+0x66/0x136
       [<c0135820>] kthread+0x40/0x68
       [<c0103c27>] kernel_thread_helper+0x7/0x10
       [<ffffffff>] 0xffffffff

other info that might help us debug this:

2 locks held by ftraced/27:
 #0:  (ftrace_sysctl_lock){--..}, at: [<c014f6a1>] ftraced+0x3b/0x136
 #1:  (ftraced_lock){--..}, at: [<c014f6ad>] ftraced+0x47/0x136

stack backtrace:
Pid: 27, comm: ftraced Not tainted 2.6.26-rc5-00070-g53ec472-dirty #697
 [<c013f6b1>] print_circular_bug_tail+0x5b/0x66
 [<c013ef59>] ? print_circular_bug_entry+0x39/0x43
 [<c0141226>] __lock_acquire+0x91f/0xb5f
 [<c0141872>] lock_acquire+0x6a/0x90
 [<c0125d44>] ? get_online_cpus+0x31/0x43
 [<c06efb64>] mutex_lock_nested+0xdd/0x27a
 [<c0125d44>] ? get_online_cpus+0x31/0x43
 [<c0125d44>] ? get_online_cpus+0x31/0x43
 [<c014ec54>] ? __ftrace_update_code+0x0/0x12e
 [<c0125d44>] get_online_cpus+0x31/0x43
 [<c0147c34>] stop_machine_run+0x16/0x3d
 [<c014f666>] ? ftraced+0x0/0x136
 [<c014f00a>] ftrace_update_code+0x2f/0x3a
 [<c014f6cc>] ftraced+0x66/0x136
 [<c014f666>] ? ftraced+0x0/0x136
 [<c0135820>] kthread+0x40/0x68
 [<c01357e0>] ? kthread+0x0/0x68
 [<c0103c27>] kernel_thread_helper+0x7/0x10
 =======================
PCI->APIC IRQ transform: 0000:00:1f.2[D] -> IRQ 19
PCI->APIC IRQ transform: 0000:00:1f.3[B] -> IRQ 17
PCI->APIC IRQ transform: 0000:00:1f.4[C] -> IRQ 23
PCI->APIC IRQ transform: 0000:00:1f.5[B] -> IRQ 17
PCI->APIC IRQ transform: 0000:01:00.0[A] -> IRQ 22
PCI->APIC IRQ transform: 0000:03:04.0[A] -> IRQ 18

^ permalink raw reply	[flat|nested] 3+ messages in thread

end of thread, other threads:[~2008-06-18  8:25 UTC | newest]

Thread overview: 3+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2008-06-05 20:54 [PATCH] ftrace: disable function tracing bringing up new CPU Steven Rostedt
2008-06-05 23:19 ` [PATCH -v2] " Steven Rostedt
2008-06-18  8:25   ` Ingo Molnar

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.