[PATCH 0/3] tracing: Enable tracepoints early and allow printk to use them

[PATCH 0/3] tracing: Enable tracepoints early and allow printk to use them

[Steven Rostedt]

As the merge window is still open, and this code was not as complex
as I thought it might be. I'm thinking of pushing this in now.

This will allow Thomas to debug his irq work for 3.20.

This code is not that intrusive and I'm currently running it through
all my tests (which caught the call_rcu_sched issue()). But I like to
have some more eyes on this, as I don't like to push something into
mainline this quickly. I'm doing this only because the code is simple
enough and is useful for work coming in 3.20.

I also feel that I could handle the fall out of this work over the
holidays if need be.

Steven Rostedt (Red Hat) (3):
      tracepoints: Do not use call_rcu_sched() before early_initcall()
      tracing: Move enabling tracepoints to just after mm_init()
      tracing: Add tp_printk cmdline to have tracepoints go to printk()

----
 Documentation/kernel-parameters.txt | 18 ++++++++++++++++
 include/linux/ftrace.h              |  7 +++++++
 init/main.c                         |  3 +++
 kernel/sysctl.c                     |  7 +++++++
 kernel/trace/trace.c                | 25 +++++++++++++++++++++-
 kernel/trace/trace.h                | 14 +++++++++++++
 kernel/trace/trace_events.c         | 42 +++++++++++++++++++++++++++++++++++--
 kernel/trace/trace_syscalls.c       |  7 ++-----
 kernel/tracepoint.c                 | 27 +++++++++++++++++++++++-
 9 files changed, 141 insertions(+), 9 deletions(-)

[PATCH 1/3] tracepoints: Do not use call_rcu_sched() before early_initcall()

[Steven Rostedt]

[-- Attachment #1: 0001-tracepoints-Do-not-use-call_rcu_sched-before-early_i.patch --]
[-- Type: text/plain, Size: 2497 bytes --]

From: "Steven Rostedt (Red Hat)" <rostedt@goodmis.org>

In order to move enabling of trace events to just after mm_init(), the
tracepoint enable code can not use call_rcu_sched() because rcu isn't
even initialized yet.  Since this can only happen before SMP is set up
(and even before interrupts are set up), there's no reason to use
call_rcu_sched() at this point.

Instead, create a variable called tracepoint_rcu_safe that gets enabled
via early_initcall() and if that is not set, free the code directly
instead of using call_rcu_sched().

This allows us to enable tracepoints early without issues.

Cc: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Cc: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
Cc: Thomas Gleixner <tglx@linutronix.de>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 kernel/tracepoint.c | 27 ++++++++++++++++++++++++++-
 1 file changed, 26 insertions(+), 1 deletion(-)

diff --git a/kernel/tracepoint.c b/kernel/tracepoint.c
index 3490407dc7b7..9b90ef0ac731 100644
--- a/kernel/tracepoint.c
+++ b/kernel/tracepoint.c
@@ -33,6 +33,15 @@ extern struct tracepoint * const __stop___tracepoints_ptrs[];
 /* Set to 1 to enable tracepoint debug output */
 static const int tracepoint_debug;
 
+/*
+ * traceoint_rcu_is_safe is set to true at early_initcall().
+ * Tracepoints can be enabled before rcu is initialized.
+ * When that happens, there's no reason to free via call_rcu()
+ * because the system isn't even in SMP mode yet, and rcu isn't
+ * initialized. Just directly free the old tracepoints instead.
+ */
+static bool tracepoint_rcu_is_safe;
+
 #ifdef CONFIG_MODULES
 /*
  * Tracepoint module list mutex protects the local module list.
@@ -76,7 +85,16 @@ static inline void release_probes(struct tracepoint_func *old)
 	if (old) {
 		struct tp_probes *tp_probes = container_of(old,
 			struct tp_probes, probes[0]);
-		call_rcu_sched(&tp_probes->rcu, rcu_free_old_probes);
+		/*
+		 * Tracepoints can be enabled before RCU is initialized
+		 * at boot up. If that is the case, do not bother using
+		 * call_rcu() (because that will fail), but instead just
+		 * free directly.
+		 */
+		if (likely(tracepoint_rcu_is_safe))
+			call_rcu_sched(&tp_probes->rcu, rcu_free_old_probes);
+		else
+			rcu_free_old_probes(&tp_probes->rcu);
 	}
 }
 
@@ -518,3 +536,10 @@ void syscall_unregfunc(void)
 	}
 }
 #endif
+
+static __init int init_tracepoint_rcu(void)
+{
+	tracepoint_rcu_is_safe = true;
+	return 0;
+}
+early_initcall(init_tracepoint_rcu);
-- 
2.1.3

Re: [PATCH 1/3] tracepoints: Do not use call_rcu_sched() before early_initcall()

[Steven Rostedt]

On Sun, 14 Dec 2014 11:41:05 -0500
Steven Rostedt <rostedt@goodmis.org> wrote:

> From: "Steven Rostedt (Red Hat)" <rostedt@goodmis.org>
> 
> In order to move enabling of trace events to just after mm_init(), the
> tracepoint enable code can not use call_rcu_sched() because rcu isn't
> even initialized yet.  Since this can only happen before SMP is set up
> (and even before interrupts are set up), there's no reason to use
> call_rcu_sched() at this point.
> 
> Instead, create a variable called tracepoint_rcu_safe that gets enabled
> via early_initcall() and if that is not set, free the code directly
> instead of using call_rcu_sched().
> 
> This allows us to enable tracepoints early without issues.
> 
> Cc: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
> Cc: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
> Cc: Thomas Gleixner <tglx@linutronix.de>
> Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
> ---
>  kernel/tracepoint.c | 27 ++++++++++++++++++++++++++-
>  1 file changed, 26 insertions(+), 1 deletion(-)
> 
> diff --git a/kernel/tracepoint.c b/kernel/tracepoint.c
> index 3490407dc7b7..9b90ef0ac731 100644
> --- a/kernel/tracepoint.c
> +++ b/kernel/tracepoint.c
> @@ -33,6 +33,15 @@ extern struct tracepoint * const __stop___tracepoints_ptrs[];
>  /* Set to 1 to enable tracepoint debug output */
>  static const int tracepoint_debug;
>  
> +/*
> + * traceoint_rcu_is_safe is set to true at early_initcall().
> + * Tracepoints can be enabled before rcu is initialized.
> + * When that happens, there's no reason to free via call_rcu()
> + * because the system isn't even in SMP mode yet, and rcu isn't
> + * initialized. Just directly free the old tracepoints instead.
> + */
> +static bool tracepoint_rcu_is_safe;

Hmm, I probably should make this read_mostly.

Although, it's not a hot path. Still, it gets set once at boot up and
never touched again. Yeah, that deserves a read_mostly.

-- Steve

> +
>  #ifdef CONFIG_MODULES
>  /*
>   * Tracepoint module list mutex protects the local module list.
> @@ -76,7 +85,16 @@ static inline void release_probes(struct tracepoint_func *old)
>  	if (old) {
>  		struct tp_probes *tp_probes = container_of(old,
>  			struct tp_probes, probes[0]);
> -		call_rcu_sched(&tp_probes->rcu, rcu_free_old_probes);
> +		/*
> +		 * Tracepoints can be enabled before RCU is initialized
> +		 * at boot up. If that is the case, do not bother using
> +		 * call_rcu() (because that will fail), but instead just
> +		 * free directly.
> +		 */
> +		if (likely(tracepoint_rcu_is_safe))
> +			call_rcu_sched(&tp_probes->rcu, rcu_free_old_probes);
> +		else
> +			rcu_free_old_probes(&tp_probes->rcu);
>  	}
>  }
>  
> @@ -518,3 +536,10 @@ void syscall_unregfunc(void)
>  	}
>  }
>  #endif
> +
> +static __init int init_tracepoint_rcu(void)
> +{
> +	tracepoint_rcu_is_safe = true;
> +	return 0;
> +}
> +early_initcall(init_tracepoint_rcu);

Re: [PATCH 1/3] tracepoints: Do not use call_rcu_sched() before early_initcall()

[Paul E. McKenney]

On Sun, Dec 14, 2014 at 11:53:32AM -0500, Steven Rostedt wrote:
> On Sun, 14 Dec 2014 11:41:05 -0500
> Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > From: "Steven Rostedt (Red Hat)" <rostedt@goodmis.org>
> > 
> > In order to move enabling of trace events to just after mm_init(), the
> > tracepoint enable code can not use call_rcu_sched() because rcu isn't
> > even initialized yet.  Since this can only happen before SMP is set up
> > (and even before interrupts are set up), there's no reason to use
> > call_rcu_sched() at this point.
> > 
> > Instead, create a variable called tracepoint_rcu_safe that gets enabled
> > via early_initcall() and if that is not set, free the code directly
> > instead of using call_rcu_sched().
> > 
> > This allows us to enable tracepoints early without issues.
> > 
> > Cc: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
> > Cc: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
> > Cc: Thomas Gleixner <tglx@linutronix.de>
> > Signed-off-by: Steven Rostedt <rostedt@goodmis.org>

With the addition of read_mostly, and given that I am not going to mess
with call_rcu() this late in the 3.19 process without a blazingly good
reason:

Reviewed-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>

Please note that you can use call_rcu() and friends as soon as rcu_init()
returns.  The callbacks won't be invoked until early_initcall() time,
but they will be properly queued.

Please note also that there are places where turning a call_rcu() into
a direct function call don't work, even at times when preemption is
disabled and there is only one CPU.  One example is where single-threaded
code uses call_rcu() on a list element of a list that it is traversing
within an RCU read-side critical section.  A direct call to the RCU
callback could potentially destroy the pointers that the traversal was
going to use to find the next element.  This means that we cannot make
call_rcu() do direct calls to the callback, as that would break quite
a bit of existing code.

Is there some definite point during boot before which you won't need to
invoke call_rcu_sched() for tracing?  I am guessing "no", but have to ask.
I can probably make call_rcu_sched() work arbitrarily early, but it is a
bit uglier.  And this assumes that irqs_disabled_flags(local_irq_save())
returns true during early boot.  I would -hope- this would be true!  ;-)

							Thanx, Paul

> > ---
> >  kernel/tracepoint.c | 27 ++++++++++++++++++++++++++-
> >  1 file changed, 26 insertions(+), 1 deletion(-)
> > 
> > diff --git a/kernel/tracepoint.c b/kernel/tracepoint.c
> > index 3490407dc7b7..9b90ef0ac731 100644
> > --- a/kernel/tracepoint.c
> > +++ b/kernel/tracepoint.c
> > @@ -33,6 +33,15 @@ extern struct tracepoint * const __stop___tracepoints_ptrs[];
> >  /* Set to 1 to enable tracepoint debug output */
> >  static const int tracepoint_debug;
> >  
> > +/*
> > + * traceoint_rcu_is_safe is set to true at early_initcall().
> > + * Tracepoints can be enabled before rcu is initialized.
> > + * When that happens, there's no reason to free via call_rcu()
> > + * because the system isn't even in SMP mode yet, and rcu isn't
> > + * initialized. Just directly free the old tracepoints instead.
> > + */
> > +static bool tracepoint_rcu_is_safe;
> 
> Hmm, I probably should make this read_mostly.
> 
> Although, it's not a hot path. Still, it gets set once at boot up and
> never touched again. Yeah, that deserves a read_mostly.
> 
> -- Steve
> 
> > +
> >  #ifdef CONFIG_MODULES
> >  /*
> >   * Tracepoint module list mutex protects the local module list.
> > @@ -76,7 +85,16 @@ static inline void release_probes(struct tracepoint_func *old)
> >  	if (old) {
> >  		struct tp_probes *tp_probes = container_of(old,
> >  			struct tp_probes, probes[0]);
> > -		call_rcu_sched(&tp_probes->rcu, rcu_free_old_probes);
> > +		/*
> > +		 * Tracepoints can be enabled before RCU is initialized
> > +		 * at boot up. If that is the case, do not bother using
> > +		 * call_rcu() (because that will fail), but instead just
> > +		 * free directly.
> > +		 */
> > +		if (likely(tracepoint_rcu_is_safe))
> > +			call_rcu_sched(&tp_probes->rcu, rcu_free_old_probes);
> > +		else
> > +			rcu_free_old_probes(&tp_probes->rcu);
> >  	}
> >  }
> >  
> > @@ -518,3 +536,10 @@ void syscall_unregfunc(void)
> >  	}
> >  }
> >  #endif
> > +
> > +static __init int init_tracepoint_rcu(void)
> > +{
> > +	tracepoint_rcu_is_safe = true;
> > +	return 0;
> > +}
> > +early_initcall(init_tracepoint_rcu);
> 

Re: [PATCH 1/3] tracepoints: Do not use call_rcu_sched() before early_initcall()

[Steven Rostedt]

On Sun, 14 Dec 2014 10:08:54 -0800
"Paul E. McKenney" <paulmck@linux.vnet.ibm.com> wrote:

> On Sun, Dec 14, 2014 at 11:53:32AM -0500, Steven Rostedt wrote:
> > On Sun, 14 Dec 2014 11:41:05 -0500
> > Steven Rostedt <rostedt@goodmis.org> wrote:
> > 
> > > From: "Steven Rostedt (Red Hat)" <rostedt@goodmis.org>
> > > 
> > > In order to move enabling of trace events to just after mm_init(), the
> > > tracepoint enable code can not use call_rcu_sched() because rcu isn't
> > > even initialized yet.  Since this can only happen before SMP is set up
> > > (and even before interrupts are set up), there's no reason to use
> > > call_rcu_sched() at this point.
> > > 
> > > Instead, create a variable called tracepoint_rcu_safe that gets enabled
> > > via early_initcall() and if that is not set, free the code directly
> > > instead of using call_rcu_sched().
> > > 
> > > This allows us to enable tracepoints early without issues.
> > > 
> > > Cc: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
> > > Cc: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
> > > Cc: Thomas Gleixner <tglx@linutronix.de>
> > > Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
> 
> With the addition of read_mostly, and given that I am not going to mess
> with call_rcu() this late in the 3.19 process without a blazingly good
> reason:
> 
> Reviewed-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>

Thanks!

> 
> Please note that you can use call_rcu() and friends as soon as rcu_init()
> returns.  The callbacks won't be invoked until early_initcall() time,
> but they will be properly queued.
> 
> Please note also that there are places where turning a call_rcu() into
> a direct function call don't work, even at times when preemption is
> disabled and there is only one CPU.  One example is where single-threaded
> code uses call_rcu() on a list element of a list that it is traversing
> within an RCU read-side critical section.  A direct call to the RCU
> callback could potentially destroy the pointers that the traversal was
> going to use to find the next element.  This means that we cannot make
> call_rcu() do direct calls to the callback, as that would break quite
> a bit of existing code.
> 
> Is there some definite point during boot before which you won't need to
> invoke call_rcu_sched() for tracing?  I am guessing "no", but have to ask.
> I can probably make call_rcu_sched() work arbitrarily early, but it is a
> bit uglier.  And this assumes that irqs_disabled_flags(local_irq_save())
> returns true during early boot.  I would -hope- this would be true!  ;-)
> 

With your feed back, and because I would like this to go into 3.19, I
would like to keep the current patch as is (with the read_mostly
update, which I'm currently testing). We can always change it later
after call_rcu() has been changed.

-- Steve

Re: [PATCH 1/3] tracepoints: Do not use call_rcu_sched() before early_initcall()

[Paul E. McKenney]

On Sun, Dec 14, 2014 at 01:15:38PM -0500, Steven Rostedt wrote:
> On Sun, 14 Dec 2014 10:08:54 -0800
> "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> wrote:
> 
> > On Sun, Dec 14, 2014 at 11:53:32AM -0500, Steven Rostedt wrote:
> > > On Sun, 14 Dec 2014 11:41:05 -0500
> > > Steven Rostedt <rostedt@goodmis.org> wrote:
> > > 
> > > > From: "Steven Rostedt (Red Hat)" <rostedt@goodmis.org>
> > > > 
> > > > In order to move enabling of trace events to just after mm_init(), the
> > > > tracepoint enable code can not use call_rcu_sched() because rcu isn't
> > > > even initialized yet.  Since this can only happen before SMP is set up
> > > > (and even before interrupts are set up), there's no reason to use
> > > > call_rcu_sched() at this point.
> > > > 
> > > > Instead, create a variable called tracepoint_rcu_safe that gets enabled
> > > > via early_initcall() and if that is not set, free the code directly
> > > > instead of using call_rcu_sched().
> > > > 
> > > > This allows us to enable tracepoints early without issues.
> > > > 
> > > > Cc: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
> > > > Cc: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
> > > > Cc: Thomas Gleixner <tglx@linutronix.de>
> > > > Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
> > 
> > With the addition of read_mostly, and given that I am not going to mess
> > with call_rcu() this late in the 3.19 process without a blazingly good
> > reason:
> > 
> > Reviewed-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
> 
> Thanks!
> 
> > Please note that you can use call_rcu() and friends as soon as rcu_init()
> > returns.  The callbacks won't be invoked until early_initcall() time,
> > but they will be properly queued.
> > 
> > Please note also that there are places where turning a call_rcu() into
> > a direct function call don't work, even at times when preemption is
> > disabled and there is only one CPU.  One example is where single-threaded
> > code uses call_rcu() on a list element of a list that it is traversing
> > within an RCU read-side critical section.  A direct call to the RCU
> > callback could potentially destroy the pointers that the traversal was
> > going to use to find the next element.  This means that we cannot make
> > call_rcu() do direct calls to the callback, as that would break quite
> > a bit of existing code.
> > 
> > Is there some definite point during boot before which you won't need to
> > invoke call_rcu_sched() for tracing?  I am guessing "no", but have to ask.
> > I can probably make call_rcu_sched() work arbitrarily early, but it is a
> > bit uglier.  And this assumes that irqs_disabled_flags(local_irq_save())
> > returns true during early boot.  I would -hope- this would be true!  ;-)
> 
> With your feed back, and because I would like this to go into 3.19, I
> would like to keep the current patch as is (with the read_mostly
> update, which I'm currently testing). We can always change it later
> after call_rcu() has been changed.

Completely agreed!  ;-)

							Thanx, Paul

Re: [PATCH 1/3] tracepoints: Do not use call_rcu_sched() before early_initcall()

[Steven Rostedt]

On Sun, 14 Dec 2014 10:18:35 -0800
"Paul E. McKenney" <paulmck@linux.vnet.ibm.com> wrote:

> > With your feed back, and because I would like this to go into 3.19, I
> > would like to keep the current patch as is (with the read_mostly
> > update, which I'm currently testing). We can always change it later
> > after call_rcu() has been changed.
> 
> Completely agreed!  ;-)

For this late in the game, we need to play it safe.

I got rid of my tracepoint patch and moved trace_init() to after
rcu_init(), which I think is good enough for Thomas. Thomas?

I'll start testing that now.

Later, if you could add a rcu_init() version that lets us call
call_rcu_sched() just after mm_init() then we could move trace_init()
up a bit more.

Thanks,

-- Steve

Re: [PATCH 1/3] tracepoints: Do not use call_rcu_sched() before early_initcall()

[Paul E. McKenney]

On Sun, Dec 14, 2014 at 01:25:56PM -0500, Steven Rostedt wrote:
> On Sun, 14 Dec 2014 10:18:35 -0800
> "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> wrote:
> 
> > > With your feed back, and because I would like this to go into 3.19, I
> > > would like to keep the current patch as is (with the read_mostly
> > > update, which I'm currently testing). We can always change it later
> > > after call_rcu() has been changed.
> > 
> > Completely agreed!  ;-)
> 
> For this late in the game, we need to play it safe.
> 
> I got rid of my tracepoint patch and moved trace_init() to after
> rcu_init(), which I think is good enough for Thomas. Thomas?
> 
> I'll start testing that now.

That should work as well.

> Later, if you could add a rcu_init() version that lets us call
> call_rcu_sched() just after mm_init() then we could move trace_init()
> up a bit more.

OK, will put something together for that.  Good to hear that this is
not needed indefinitely early -- that would be a bit harder.  ;-)

							Thanx, Paul

Re: [PATCH 1/3] tracepoints: Do not use call_rcu_sched() before early_initcall()

[Mathieu Desnoyers]

----- Original Message -----
> From: "Steven Rostedt" <rostedt@goodmis.org>
> To: linux-kernel@vger.kernel.org
> Cc: "Linus Torvalds" <torvalds@linux-foundation.org>, "Ingo Molnar" <mingo@kernel.org>, "Andrew Morton"
> <akpm@linux-foundation.org>, "Thomas Gleixner" <tglx@linutronix.de>, "Mathieu Desnoyers"
> <mathieu.desnoyers@efficios.com>, "Paul E. McKenney" <paulmck@linux.vnet.ibm.com>
> Sent: Sunday, December 14, 2014 11:41:05 AM
> Subject: [PATCH 1/3] tracepoints: Do not use call_rcu_sched() before early_initcall()
> 
> From: "Steven Rostedt (Red Hat)" <rostedt@goodmis.org>
> 
> In order to move enabling of trace events to just after mm_init(), the
> tracepoint enable code can not use call_rcu_sched() because rcu isn't
> even initialized yet.  Since this can only happen before SMP is set up
> (and even before interrupts are set up), there's no reason to use
> call_rcu_sched() at this point.
> 
> Instead, create a variable called tracepoint_rcu_safe that gets enabled
> via early_initcall() and if that is not set, free the code directly
> instead of using call_rcu_sched().
> 
> This allows us to enable tracepoints early without issues.
> 
> Cc: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
> Cc: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
> Cc: Thomas Gleixner <tglx@linutronix.de>
> Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
> ---
>  kernel/tracepoint.c | 27 ++++++++++++++++++++++++++-
>  1 file changed, 26 insertions(+), 1 deletion(-)
> 
> diff --git a/kernel/tracepoint.c b/kernel/tracepoint.c
> index 3490407dc7b7..9b90ef0ac731 100644
> --- a/kernel/tracepoint.c
> +++ b/kernel/tracepoint.c
> @@ -33,6 +33,15 @@ extern struct tracepoint * const
> __stop___tracepoints_ptrs[];
>  /* Set to 1 to enable tracepoint debug output */
>  static const int tracepoint_debug;
>  
> +/*
> + * traceoint_rcu_is_safe is set to true at early_initcall().
> + * Tracepoints can be enabled before rcu is initialized.
> + * When that happens, there's no reason to free via call_rcu()
> + * because the system isn't even in SMP mode yet, and rcu isn't
> + * initialized. Just directly free the old tracepoints instead.
> + */
> +static bool tracepoint_rcu_is_safe;
> +
>  #ifdef CONFIG_MODULES
>  /*
>   * Tracepoint module list mutex protects the local module list.
> @@ -76,7 +85,16 @@ static inline void release_probes(struct tracepoint_func
> *old)
>  	if (old) {
>  		struct tp_probes *tp_probes = container_of(old,
>  			struct tp_probes, probes[0]);
> -		call_rcu_sched(&tp_probes->rcu, rcu_free_old_probes);
> +		/*
> +		 * Tracepoints can be enabled before RCU is initialized
> +		 * at boot up. If that is the case, do not bother using
> +		 * call_rcu() (because that will fail), but instead just
> +		 * free directly.
> +		 */
> +		if (likely(tracepoint_rcu_is_safe))
> +			call_rcu_sched(&tp_probes->rcu, rcu_free_old_probes);
> +		else
> +			rcu_free_old_probes(&tp_probes->rcu);

Would it makes sense to have call_rcu() and call_rcu_sched()
provide this "direct call" fallback at early boot instead
of having this in the caller ?

Thanks,

Mathieu

>  	}
>  }
>  
> @@ -518,3 +536,10 @@ void syscall_unregfunc(void)
>  	}
>  }
>  #endif
> +
> +static __init int init_tracepoint_rcu(void)
> +{
> +	tracepoint_rcu_is_safe = true;
> +	return 0;
> +}
> +early_initcall(init_tracepoint_rcu);
> --
> 2.1.3
> 
> 
> 

-- 
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com

Re: [PATCH 1/3] tracepoints: Do not use call_rcu_sched() before early_initcall()

[Steven Rostedt]

On Sun, 14 Dec 2014 17:05:49 +0000 (UTC)
Mathieu Desnoyers <mathieu.desnoyers@efficios.com> wrote:


> >  #ifdef CONFIG_MODULES
> >  /*
> >   * Tracepoint module list mutex protects the local module list.
> > @@ -76,7 +85,16 @@ static inline void release_probes(struct tracepoint_func
> > *old)
> >  	if (old) {
> >  		struct tp_probes *tp_probes = container_of(old,
> >  			struct tp_probes, probes[0]);
> > -		call_rcu_sched(&tp_probes->rcu, rcu_free_old_probes);
> > +		/*
> > +		 * Tracepoints can be enabled before RCU is initialized
> > +		 * at boot up. If that is the case, do not bother using
> > +		 * call_rcu() (because that will fail), but instead just
> > +		 * free directly.
> > +		 */
> > +		if (likely(tracepoint_rcu_is_safe))
> > +			call_rcu_sched(&tp_probes->rcu, rcu_free_old_probes);
> > +		else
> > +			rcu_free_old_probes(&tp_probes->rcu);
> 
> Would it makes sense to have call_rcu() and call_rcu_sched()
> provide this "direct call" fallback at early boot instead
> of having this in the caller ?
> 

That was my original thought, and I even started down that path. But
then I realized that tracepoints are very unique, and this is really
special for tracepoints. Then I thought, why touch a complex system like
RCU for the one off case of tracepoints? I don't really see any other
user needing this feature (well, maybe lockdep, perf or ftrace, but
still they too are special). I decided the simplest and safest approach
was to just touch the tracepoint code. Other users shouldn't need this.

If IRQ setup, or other core pieces of code can use this, then I would
agree that rcu should be changed. But until then, I rather not add
another conditional to the core RCU code.

-- Steve

Re: [PATCH 1/3] tracepoints: Do not use call_rcu_sched() before early_initcall()

[Steven Rostedt]

On Sun, 14 Dec 2014 12:14:57 -0500
Steven Rostedt <rostedt@goodmis.org> wrote:

> If IRQ setup, or other core pieces of code can use this, then I would
> agree that rcu should be changed. But until then, I rather not add
> another conditional to the core RCU code.

Also, call_rcu*() is called from several hot paths. This location is
not a hot path, and actually, it is in fact rather slow. That's another
reason not to add the logic into the RCU code if just adding it to
tracepoints is sufficient.

-- Steve

Re: [PATCH 1/3] tracepoints: Do not use call_rcu_sched() before early_initcall()

[Mathieu Desnoyers]

----- Original Message -----
> From: "Steven Rostedt" <rostedt@goodmis.org>
> To: "Mathieu Desnoyers" <mathieu.desnoyers@efficios.com>
> Cc: linux-kernel@vger.kernel.org, "Linus Torvalds" <torvalds@linux-foundation.org>, "Ingo Molnar" <mingo@kernel.org>,
> "Andrew Morton" <akpm@linux-foundation.org>, "Thomas Gleixner" <tglx@linutronix.de>, "Paul E. McKenney"
> <paulmck@linux.vnet.ibm.com>
> Sent: Sunday, December 14, 2014 12:21:36 PM
> Subject: Re: [PATCH 1/3] tracepoints: Do not use call_rcu_sched() before early_initcall()
> 
> On Sun, 14 Dec 2014 12:14:57 -0500
> Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > If IRQ setup, or other core pieces of code can use this, then I would
> > agree that rcu should be changed. But until then, I rather not add
> > another conditional to the core RCU code.
> 
> Also, call_rcu*() is called from several hot paths. This location is
> not a hot path, and actually, it is in fact rather slow. That's another
> reason not to add the logic into the RCU code if just adding it to
> tracepoints is sufficient.

Given that your reason for having this RCU-specific logic in tracepoint.c
rather than within call_rcu*() is not slowing down a fast-path, how about
creating a new call_rcu_early() and call_rcu_sched_early() which can be
called in normal operation and at early boot ?

This would allow us to keep the RCU logic within the RCU implementation
rather than strongly coupling it with the tracepoint code.

Thanks,

Mathieu

-- 
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com

Re: [PATCH 1/3] tracepoints: Do not use call_rcu_sched() before early_initcall()

[Steven Rostedt]

On Sun, 14 Dec 2014 17:29:28 +0000 (UTC)
Mathieu Desnoyers <mathieu.desnoyers@efficios.com> wrote:

> Given that your reason for having this RCU-specific logic in tracepoint.c
> rather than within call_rcu*() is not slowing down a fast-path, how about
> creating a new call_rcu_early() and call_rcu_sched_early() which can be
> called in normal operation and at early boot ?

That's a possibility.

> 
> This would allow us to keep the RCU logic within the RCU implementation
> rather than strongly coupling it with the tracepoint code.
> 

It's not that strong of a coupling to RCU. It's more coupled to being
called really early (which needs special care).

It just happened that RCU failed for being called that early. Other
things could possible fail too (if added to the tracepoint logic).
Maybe I should rename the variable to "tracepoint_earlyboot" instead.

But as RCU is the only thing that failed (so far in my testing), I'll
think about adding a call_rcu_sched_early(). But then, this does make
things more complex, and me more nervous about adding it.

-- Steve

Re: [PATCH 1/3] tracepoints: Do not use call_rcu_sched() before early_initcall()

[Paul E. McKenney]

On Sun, Dec 14, 2014 at 12:44:31PM -0500, Steven Rostedt wrote:
> On Sun, 14 Dec 2014 17:29:28 +0000 (UTC)
> Mathieu Desnoyers <mathieu.desnoyers@efficios.com> wrote:
> 
> > Given that your reason for having this RCU-specific logic in tracepoint.c
> > rather than within call_rcu*() is not slowing down a fast-path, how about
> > creating a new call_rcu_early() and call_rcu_sched_early() which can be
> > called in normal operation and at early boot ?
> 
> That's a possibility.
> 
> > 
> > This would allow us to keep the RCU logic within the RCU implementation
> > rather than strongly coupling it with the tracepoint code.
> > 
> 
> It's not that strong of a coupling to RCU. It's more coupled to being
> called really early (which needs special care).
> 
> It just happened that RCU failed for being called that early. Other
> things could possible fail too (if added to the tracepoint logic).
> Maybe I should rename the variable to "tracepoint_earlyboot" instead.

But you do have to call this quite early.  After rcu_init() is invoked,
things should work fine.

> But as RCU is the only thing that failed (so far in my testing), I'll
> think about adding a call_rcu_sched_early(). But then, this does make
> things more complex, and me more nervous about adding it.

I really am nervous about a call_rcu_sched_early() that immediately
invokes the specified callback.  That is just begging for someone to
invoke it while traversing a list in an RCU read-side critical section,
which will break.

My thought is to make the compiler initialize the pieces of RCU that
are needed.  That said, this initialization includes per-CPU variables,
so the question then becomes "when do per-CPU variables get initialized?"

							Thanx, Paul

[PATCH 2/3] tracing: Move enabling tracepoints to just after mm_init()

[Steven Rostedt]

[-- Attachment #1: 0002-tracing-Move-enabling-tracepoints-to-just-after-mm_i.patch --]
[-- Type: text/plain, Size: 4373 bytes --]

From: "Steven Rostedt (Red Hat)" <rostedt@goodmis.org>

Enabling tracepoints at boot up can be very useful. The tracepoint
can be initialized right after memory has been. There's no need to
wait for the early_initcall() to be called. That's too late for some
things that can use tracepoints for debugging. Move the logic to
enable tracepoints out of the initcalls and into init/main.c to
right after mm_init().

This also allows trace_printk() to be used early too.

Link: http://lkml.kernel.org/r/alpine.DEB.2.11.1412121539300.16494@nanos

Suggested-by: Thomas Gleixner <tglx@linutronix.de>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 include/linux/ftrace.h        |  6 ++++++
 init/main.c                   |  3 +++
 kernel/trace/trace.c          |  8 +++++++-
 kernel/trace/trace.h          | 13 +++++++++++++
 kernel/trace/trace_events.c   | 10 ++++++++--
 kernel/trace/trace_syscalls.c |  7 ++-----
 6 files changed, 39 insertions(+), 8 deletions(-)

diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
index ed501953f0b2..f4bc14b7d444 100644
--- a/include/linux/ftrace.h
+++ b/include/linux/ftrace.h
@@ -39,6 +39,12 @@
 # define FTRACE_FORCE_LIST_FUNC 0
 #endif
 
+/* Main tracing buffer and events set up */
+#ifdef CONFIG_TRACING
+void trace_init(void);
+#else
+static inline void trace_init(void) { }
+#endif
 
 struct module;
 struct ftrace_hash;
diff --git a/init/main.c b/init/main.c
index 800a0daede7e..060e60b6aa59 100644
--- a/init/main.c
+++ b/init/main.c
@@ -561,6 +561,9 @@ asmlinkage __visible void __init start_kernel(void)
 	trap_init();
 	mm_init();
 
+	/* trace_printk() and trace points may be used after this */
+	trace_init();
+
 	/*
 	 * Set up the scheduler prior starting any interrupts (such as the
 	 * timer interrupt). Full topology setup happens at smp_init()
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 4ceb2546c7ef..ec3ca694665f 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -6876,6 +6876,13 @@ out:
 	return ret;
 }
 
+void __init trace_init(void)
+{
+	tracer_alloc_buffers();
+	init_ftrace_syscalls();
+	trace_event_init();	
+}
+
 __init static int clear_boot_tracer(void)
 {
 	/*
@@ -6895,6 +6902,5 @@ __init static int clear_boot_tracer(void)
 	return 0;
 }
 
-early_initcall(tracer_alloc_buffers);
 fs_initcall(tracer_init_debugfs);
 late_initcall(clear_boot_tracer);
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 3255dfb054a0..c138c149d6ef 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -1301,4 +1301,17 @@ int perf_ftrace_event_register(struct ftrace_event_call *call,
 #define perf_ftrace_event_register NULL
 #endif
 
+#ifdef CONFIG_FTRACE_SYSCALLS
+void init_ftrace_syscalls(void);
+#else
+static inline void init_ftrace_syscalls(void) { }
+#endif
+
+#ifdef CONFIG_EVENT_TRACING
+void trace_event_init(void);
+#else
+static inline void __init trace_event_init(void) { }
+#endif
+
+
 #endif /* _LINUX_KERNEL_TRACE_H */
diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index f9d0cbe014b7..fd9deb0e03f0 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -2477,8 +2477,14 @@ static __init int event_trace_init(void)
 #endif
 	return 0;
 }
-early_initcall(event_trace_memsetup);
-core_initcall(event_trace_enable);
+
+void __init trace_event_init(void)
+{
+	event_trace_memsetup();
+	init_ftrace_syscalls();
+	event_trace_enable();
+}
+
 fs_initcall(event_trace_init);
 
 #ifdef CONFIG_FTRACE_STARTUP_TEST
diff --git a/kernel/trace/trace_syscalls.c b/kernel/trace/trace_syscalls.c
index a72f3d8d813e..ec239771c175 100644
--- a/kernel/trace/trace_syscalls.c
+++ b/kernel/trace/trace_syscalls.c
@@ -514,7 +514,7 @@ unsigned long __init __weak arch_syscall_addr(int nr)
 	return (unsigned long)sys_call_table[nr];
 }
 
-static int __init init_ftrace_syscalls(void)
+void __init init_ftrace_syscalls(void)
 {
 	struct syscall_metadata *meta;
 	unsigned long addr;
@@ -524,7 +524,7 @@ static int __init init_ftrace_syscalls(void)
 				    GFP_KERNEL);
 	if (!syscalls_metadata) {
 		WARN_ON(1);
-		return -ENOMEM;
+		return;
 	}
 
 	for (i = 0; i < NR_syscalls; i++) {
@@ -536,10 +536,7 @@ static int __init init_ftrace_syscalls(void)
 		meta->syscall_nr = i;
 		syscalls_metadata[i] = meta;
 	}
-
-	return 0;
 }
-early_initcall(init_ftrace_syscalls);
 
 #ifdef CONFIG_PERF_EVENTS
 
-- 
2.1.3

Re: [PATCH 2/3] tracing: Move enabling tracepoints to just after mm_init()

[Paul E. McKenney]

On Sun, Dec 14, 2014 at 11:41:06AM -0500, Steven Rostedt wrote:
> From: "Steven Rostedt (Red Hat)" <rostedt@goodmis.org>
> 
> Enabling tracepoints at boot up can be very useful. The tracepoint
> can be initialized right after memory has been. There's no need to
> wait for the early_initcall() to be called. That's too late for some
> things that can use tracepoints for debugging. Move the logic to
> enable tracepoints out of the initcalls and into init/main.c to
> right after mm_init().
> 
> This also allows trace_printk() to be used early too.
> 
> Link: http://lkml.kernel.org/r/alpine.DEB.2.11.1412121539300.16494@nanos
> 
> Suggested-by: Thomas Gleixner <tglx@linutronix.de>
> Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
> ---
>  include/linux/ftrace.h        |  6 ++++++
>  init/main.c                   |  3 +++
>  kernel/trace/trace.c          |  8 +++++++-
>  kernel/trace/trace.h          | 13 +++++++++++++
>  kernel/trace/trace_events.c   | 10 ++++++++--
>  kernel/trace/trace_syscalls.c |  7 ++-----
>  6 files changed, 39 insertions(+), 8 deletions(-)
> 
> diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
> index ed501953f0b2..f4bc14b7d444 100644
> --- a/include/linux/ftrace.h
> +++ b/include/linux/ftrace.h
> @@ -39,6 +39,12 @@
>  # define FTRACE_FORCE_LIST_FUNC 0
>  #endif
> 
> +/* Main tracing buffer and events set up */
> +#ifdef CONFIG_TRACING
> +void trace_init(void);
> +#else
> +static inline void trace_init(void) { }
> +#endif
> 
>  struct module;
>  struct ftrace_hash;
> diff --git a/init/main.c b/init/main.c
> index 800a0daede7e..060e60b6aa59 100644
> --- a/init/main.c
> +++ b/init/main.c
> @@ -561,6 +561,9 @@ asmlinkage __visible void __init start_kernel(void)
>  	trap_init();
>  	mm_init();
> 
> +	/* trace_printk() and trace points may be used after this */
> +	trace_init();

Or if you aren't going to use call_rcu_sched() before this point, I could
move the call_rcu_sched()-relevant initialization to this point.  Or make
the compiler do it -- I am pretty sure that the per-CPU variables are in
place at this point.

							Thanx, Paul

> +
>  	/*
>  	 * Set up the scheduler prior starting any interrupts (such as the
>  	 * timer interrupt). Full topology setup happens at smp_init()
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index 4ceb2546c7ef..ec3ca694665f 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -6876,6 +6876,13 @@ out:
>  	return ret;
>  }
> 
> +void __init trace_init(void)
> +{
> +	tracer_alloc_buffers();
> +	init_ftrace_syscalls();
> +	trace_event_init();	
> +}
> +
>  __init static int clear_boot_tracer(void)
>  {
>  	/*
> @@ -6895,6 +6902,5 @@ __init static int clear_boot_tracer(void)
>  	return 0;
>  }
> 
> -early_initcall(tracer_alloc_buffers);
>  fs_initcall(tracer_init_debugfs);
>  late_initcall(clear_boot_tracer);
> diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
> index 3255dfb054a0..c138c149d6ef 100644
> --- a/kernel/trace/trace.h
> +++ b/kernel/trace/trace.h
> @@ -1301,4 +1301,17 @@ int perf_ftrace_event_register(struct ftrace_event_call *call,
>  #define perf_ftrace_event_register NULL
>  #endif
> 
> +#ifdef CONFIG_FTRACE_SYSCALLS
> +void init_ftrace_syscalls(void);
> +#else
> +static inline void init_ftrace_syscalls(void) { }
> +#endif
> +
> +#ifdef CONFIG_EVENT_TRACING
> +void trace_event_init(void);
> +#else
> +static inline void __init trace_event_init(void) { }
> +#endif
> +
> +
>  #endif /* _LINUX_KERNEL_TRACE_H */
> diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
> index f9d0cbe014b7..fd9deb0e03f0 100644
> --- a/kernel/trace/trace_events.c
> +++ b/kernel/trace/trace_events.c
> @@ -2477,8 +2477,14 @@ static __init int event_trace_init(void)
>  #endif
>  	return 0;
>  }
> -early_initcall(event_trace_memsetup);
> -core_initcall(event_trace_enable);
> +
> +void __init trace_event_init(void)
> +{
> +	event_trace_memsetup();
> +	init_ftrace_syscalls();
> +	event_trace_enable();
> +}
> +
>  fs_initcall(event_trace_init);
> 
>  #ifdef CONFIG_FTRACE_STARTUP_TEST
> diff --git a/kernel/trace/trace_syscalls.c b/kernel/trace/trace_syscalls.c
> index a72f3d8d813e..ec239771c175 100644
> --- a/kernel/trace/trace_syscalls.c
> +++ b/kernel/trace/trace_syscalls.c
> @@ -514,7 +514,7 @@ unsigned long __init __weak arch_syscall_addr(int nr)
>  	return (unsigned long)sys_call_table[nr];
>  }
> 
> -static int __init init_ftrace_syscalls(void)
> +void __init init_ftrace_syscalls(void)
>  {
>  	struct syscall_metadata *meta;
>  	unsigned long addr;
> @@ -524,7 +524,7 @@ static int __init init_ftrace_syscalls(void)
>  				    GFP_KERNEL);
>  	if (!syscalls_metadata) {
>  		WARN_ON(1);
> -		return -ENOMEM;
> +		return;
>  	}
> 
>  	for (i = 0; i < NR_syscalls; i++) {
> @@ -536,10 +536,7 @@ static int __init init_ftrace_syscalls(void)
>  		meta->syscall_nr = i;
>  		syscalls_metadata[i] = meta;
>  	}
> -
> -	return 0;
>  }
> -early_initcall(init_ftrace_syscalls);
> 
>  #ifdef CONFIG_PERF_EVENTS
> 
> -- 
> 2.1.3
> 
> 

Re: [PATCH 2/3] tracing: Move enabling tracepoints to just after mm_init()

[Steven Rostedt]

On Sun, 14 Dec 2014 10:14:44 -0800
"Paul E. McKenney" <paulmck@linux.vnet.ibm.com> wrote:


> > diff --git a/init/main.c b/init/main.c
> > index 800a0daede7e..060e60b6aa59 100644
> > --- a/init/main.c
> > +++ b/init/main.c
> > @@ -561,6 +561,9 @@ asmlinkage __visible void __init start_kernel(void)
> >  	trap_init();
> >  	mm_init();
> > 
> > +	/* trace_printk() and trace points may be used after this */
> > +	trace_init();
> 
> Or if you aren't going to use call_rcu_sched() before this point, I could
> move the call_rcu_sched()-relevant initialization to this point.  Or make
> the compiler do it -- I am pretty sure that the per-CPU variables are in
> place at this point.
> 

Well, we could move trace_init() after rcu_init() for now too, and
remove my tracepoint patch. But I'd like to have trace_init() go before
sched_init() since that could possibly use debugging tracepoints as
well.

So if you could add a rcu_partial_init() that makes calling
call_rcu_sched() work, that would be great. That could be for 3.20
then, and for now, I just move trace_init() after rcu_init() which is
still before irq_init() that Thomas needs for his work.

-- Steve

Re: [PATCH 2/3] tracing: Move enabling tracepoints to just after mm_init()

[Paul E. McKenney]

On Sun, Dec 14, 2014 at 01:20:20PM -0500, Steven Rostedt wrote:
> On Sun, 14 Dec 2014 10:14:44 -0800
> "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> wrote:
> 
> 
> > > diff --git a/init/main.c b/init/main.c
> > > index 800a0daede7e..060e60b6aa59 100644
> > > --- a/init/main.c
> > > +++ b/init/main.c
> > > @@ -561,6 +561,9 @@ asmlinkage __visible void __init start_kernel(void)
> > >  	trap_init();
> > >  	mm_init();
> > > 
> > > +	/* trace_printk() and trace points may be used after this */
> > > +	trace_init();
> > 
> > Or if you aren't going to use call_rcu_sched() before this point, I could
> > move the call_rcu_sched()-relevant initialization to this point.  Or make
> > the compiler do it -- I am pretty sure that the per-CPU variables are in
> > place at this point.
> 
> Well, we could move trace_init() after rcu_init() for now too, and
> remove my tracepoint patch. But I'd like to have trace_init() go before
> sched_init() since that could possibly use debugging tracepoints as
> well.
> 
> So if you could add a rcu_partial_init() that makes calling
> call_rcu_sched() work, that would be great. That could be for 3.20
> then, and for now, I just move trace_init() after rcu_init() which is
> still before irq_init() that Thomas needs for his work.

Sounds like a good approach.  I also need to check up on documentation of
which RCU primitives can be used where, I suspect.

							Thanx, Paul

[PATCH 3/3] tracing: Add tp_printk cmdline to have tracepoints go to printk()

[Steven Rostedt]

[-- Attachment #1: 0003-tracing-Add-tp_printk-cmdline-to-have-tracepoints-go.patch --]
[-- Type: text/plain, Size: 6230 bytes --]

From: "Steven Rostedt (Red Hat)" <rostedt@goodmis.org>

Add the kernel command line tp_printk option that will have tracepoints
that are active sent to printk() as well as to the trace buffer.

Passing "tp_printk" will activate this. To turn it off, the sysctl
/proc/sys/kernel/tracepoint_printk can have '0' echoed into it. Note,
this only works if the cmdline option is used. Echoing 1 into the sysctl
file without the cmdline option will have no affect.

Note, this is a dangerous option. Having high frequency tracepoints send
their data to printk() can possibly cause a live lock. This is another
reason why this is only active if the command line option is used.

Link: http://lkml.kernel.org/r/alpine.DEB.2.11.1412121539300.16494@nanos

Suggested-by: Thomas Gleixner <tglx@linutronix.de>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 Documentation/kernel-parameters.txt | 18 ++++++++++++++++++
 include/linux/ftrace.h              |  1 +
 kernel/sysctl.c                     |  7 +++++++
 kernel/trace/trace.c                | 17 +++++++++++++++++
 kernel/trace/trace.h                |  1 +
 kernel/trace/trace_events.c         | 32 ++++++++++++++++++++++++++++++++
 6 files changed, 76 insertions(+)

diff --git a/Documentation/kernel-parameters.txt b/Documentation/kernel-parameters.txt
index 1d09eb37c562..ae41f1181e9a 100644
--- a/Documentation/kernel-parameters.txt
+++ b/Documentation/kernel-parameters.txt
@@ -3500,6 +3500,24 @@ bytes respectively. Such letter suffixes can also be entirely omitted.
 			See also Documentation/trace/ftrace.txt "trace options"
 			section.
 
+	tp_printk[FTRACE]
+			Have the tracepoints sent to printk as well as the
+			tracing ring buffer. This is useful for early boot up
+			where the system hangs or reboots and does not give the
+			option for reading the tracing buffer or performing a
+			ftrace_dump_on_oops.
+
+			To turn off having tracepoints sent to printk,
+			 echo 0 > /proc/sys/kernel/tracepoint_printk
+			Note, echoing 1 into this file without the
+			tracepoint_printk kernel cmdline option has no effect.
+
+			** CAUTION **
+
+			Having tracepoints sent to printk() and activating high
+			frequency tracepoints such as irq or sched, can cause
+			the system to live lock.
+
 	traceoff_on_warning
 			[FTRACE] enable this option to disable tracing when a
 			warning is hit. This turns off "tracing_on". Tracing can
diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
index f4bc14b7d444..1da602982cf9 100644
--- a/include/linux/ftrace.h
+++ b/include/linux/ftrace.h
@@ -879,6 +879,7 @@ static inline int test_tsk_trace_graph(struct task_struct *tsk)
 enum ftrace_dump_mode;
 
 extern enum ftrace_dump_mode ftrace_dump_on_oops;
+extern int tracepoint_printk;
 
 extern void disable_trace_on_warning(void);
 extern int __disable_trace_on_warning;
diff --git a/kernel/sysctl.c b/kernel/sysctl.c
index 4aada6d9fe74..bb50c2187194 100644
--- a/kernel/sysctl.c
+++ b/kernel/sysctl.c
@@ -622,6 +622,13 @@ static struct ctl_table kern_table[] = {
 		.mode		= 0644,
 		.proc_handler	= proc_dointvec,
 	},
+	{
+		.procname	= "tracepoint_printk",
+		.data		= &tracepoint_printk,
+		.maxlen		= sizeof(tracepoint_printk),
+		.mode		= 0644,
+		.proc_handler	= proc_dointvec,
+	},
 #endif
 #ifdef CONFIG_KEXEC
 	{
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index ec3ca694665f..e890d2d4ec89 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -63,6 +63,10 @@ static bool __read_mostly tracing_selftest_running;
  */
 bool __read_mostly tracing_selftest_disabled;
 
+/* Pipe tracepoints to printk */
+struct trace_iterator *tracepoint_print_iter;
+int tracepoint_printk;
+
 /* For tracers that don't implement custom flags */
 static struct tracer_opt dummy_tracer_opt[] = {
 	{ }
@@ -193,6 +197,13 @@ static int __init set_trace_boot_clock(char *str)
 }
 __setup("trace_clock=", set_trace_boot_clock);
 
+static int __init set_tracepoint_printk(char *str)
+{
+	if ((strcmp(str, "=0") != 0 && strcmp(str, "=off") != 0))
+		tracepoint_printk = 1;
+	return 1;
+}
+__setup("tp_printk", set_tracepoint_printk);
 
 unsigned long long ns2usecs(cycle_t nsec)
 {
@@ -6878,6 +6889,12 @@ out:
 
 void __init trace_init(void)
 {
+	if (tracepoint_printk) {
+		tracepoint_print_iter =
+			kmalloc(sizeof(*tracepoint_print_iter), GFP_KERNEL);
+		if (WARN_ON(!tracepoint_print_iter))
+			tracepoint_printk = 0;
+	}
 	tracer_alloc_buffers();
 	init_ftrace_syscalls();
 	trace_event_init();	
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index c138c149d6ef..8de48bac1ce2 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -1313,5 +1313,6 @@ void trace_event_init(void);
 static inline void __init trace_event_init(void) { }
 #endif
 
+extern struct trace_iterator *tracepoint_print_iter;
 
 #endif /* _LINUX_KERNEL_TRACE_H */
diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index fd9deb0e03f0..9f7175a3df71 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -212,8 +212,40 @@ void *ftrace_event_buffer_reserve(struct ftrace_event_buffer *fbuffer,
 }
 EXPORT_SYMBOL_GPL(ftrace_event_buffer_reserve);
 
+static DEFINE_SPINLOCK(tracepoint_iter_lock);
+
+static void output_printk(struct ftrace_event_buffer *fbuffer)
+{
+	struct ftrace_event_call *event_call;
+	struct trace_event *event;
+	unsigned long flags;
+	struct trace_iterator *iter = tracepoint_print_iter;
+
+	if (!iter)
+		return;
+
+	event_call = fbuffer->ftrace_file->event_call;
+	if (!event_call || !event_call->event.funcs ||
+	    !event_call->event.funcs->trace)
+		return;
+
+	event = &fbuffer->ftrace_file->event_call->event;
+
+	spin_lock_irqsave(&tracepoint_iter_lock, flags);
+	trace_seq_init(&iter->seq);
+	iter->ent = fbuffer->entry;
+	event_call->event.funcs->trace(iter, 0, event);
+	trace_seq_putc(&iter->seq, 0);
+	printk("%s", iter->seq.buffer);
+
+	spin_unlock_irqrestore(&tracepoint_iter_lock, flags);
+}
+
 void ftrace_event_buffer_commit(struct ftrace_event_buffer *fbuffer)
 {
+	if (tracepoint_printk)
+		output_printk(fbuffer);
+
 	event_trigger_unlock_commit(fbuffer->ftrace_file, fbuffer->buffer,
 				    fbuffer->event, fbuffer->entry,
 				    fbuffer->flags, fbuffer->pc);
-- 
2.1.3

Re: [PATCH 0/3] tracing: Enable tracepoints early and allow printk to use them

[Steven Rostedt]

On Sun, 14 Dec 2014 11:41:04 -0500
Steven Rostedt <rostedt@goodmis.org> wrote:

> As the merge window is still open, and this code was not as complex
> as I thought it might be. I'm thinking of pushing this in now.
> 
> This will allow Thomas to debug his irq work for 3.20.

Bah, my cover letters have sucked lately. Let me explain what this
patch set does.


It basically adds two new features.

1) Allow traceopoints to be enabled right after mm_init(). By passing
in the trace_event= kernel command line parameter, tracepoints can be
enabled at boot up. For debugging things like the initialization of
interrupts, it is needed to have tracepoints enabled very early. People
have asked about this before and this has been on my todo list. As it
can be helpful for Thomas to debug his upcoming 3.20 IRQ work, I'm
pushing this now. This way he can add tracepoints into the IRQ set up
and have have users enable them when things go wrong.

2) Have the tracepoints printed via printk() (the console) when they
are triggered. If the irq code locks up or reboots the box, having the
tracepoint output go into the kernel ring buffer is useless for
debugging. But being able to add the tp_printk kernel command line
option along with the trace_event= option will have these tracepoints
printed as they occur, and that can be really useful for debugging
early lock up or reboot problems.

-- Steve