[PATCH] tracing: annotate emit_log_char() notrace

[PATCH] tracing: annotate emit_log_char() notrace

[Thomas Gleixner]

printk calls emit_log_char() in a loop which is cluttering the trace
buffer. Make it notrace.

Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
---
 kernel/printk.c |    2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

Index: linux-2.6-tip/kernel/printk.c
===================================================================
--- linux-2.6-tip.orig/kernel/printk.c
+++ linux-2.6-tip/kernel/printk.c
@@ -499,7 +499,7 @@ static void call_console_drivers(unsigne
 	_call_console_drivers(start_print, end, msg_level);
 }
 
-static void emit_log_char(char c)
+static void notrace emit_log_char(char c)
 {
 	LOG_BUF(log_end) = c;
 	log_end++;

Re: [PATCH] tracing: annotate emit_log_char() notrace

[Frederic Weisbecker]

On Wed, May 27, 2009 at 05:00:44PM +0200, Thomas Gleixner wrote:
> printk calls emit_log_char() in a loop which is cluttering the trace
> buffer. Make it notrace.
> 
> Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
> ---


Does it produce that much annoying traces?
I mean, printk() are usually rare events.

Do you have a particular debugging workflow that makes this
function invasive in the trace?

May be it's because you are debugging using ftrace and other
debugging options that use a lot of printk()
In such case, it would indeed be good to apply this patch.

Thanks,
Frederic.



>  kernel/printk.c |    2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
> 
> Index: linux-2.6-tip/kernel/printk.c
> ===================================================================
> --- linux-2.6-tip.orig/kernel/printk.c
> +++ linux-2.6-tip/kernel/printk.c
> @@ -499,7 +499,7 @@ static void call_console_drivers(unsigne
>  	_call_console_drivers(start_print, end, msg_level);
>  }
>  
> -static void emit_log_char(char c)
> +static void notrace emit_log_char(char c)
>  {
>  	LOG_BUF(log_end) = c;
>  	log_end++;

Re: [PATCH] tracing: annotate emit_log_char() notrace

[Thomas Gleixner]

On Thu, 28 May 2009, Frederic Weisbecker wrote:
> On Wed, May 27, 2009 at 05:00:44PM +0200, Thomas Gleixner wrote:
> > printk calls emit_log_char() in a loop which is cluttering the trace
> > buffer. Make it notrace.
> > 
> > Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
> > ---
> 
> 
> Does it produce that much annoying traces?
> I mean, printk() are usually rare events.
> 
> Do you have a particular debugging workflow that makes this
> function invasive in the trace?
> 
> May be it's because you are debugging using ftrace and other
> debugging options that use a lot of printk()
> In such case, it would indeed be good to apply this patch.

I noticed when I chased a boot up problem, half of the trace was full
of

   0.540550: emit_log_char <-vprintk
   0.540550: emit_log_char <-vprintk
   ...

though there is another annoyance in the same code path:

   0.540557: vgacon_set_cursor_size <-vgacon_cursor
   0.540558: __rcu_read_lock <-__atomic_notifier_call_chain
   0.540558: __rcu_read_unlock <-__atomic_notifier_call_chain
   0.540558: __rcu_read_lock <-__atomic_notifier_call_chain
   ...

It's actually the same number of times as we have emit_log_char()
there. __atomic_notifier_call_chain() itself is marked notrace but the
rcu calls inside are not. :(

IIRC the same happens with a serial console, but that can be worse as
you busy wait during the character output.

It'd be nice if we could inherit the notrace from the caller :)

Thanks,

	tglx

Re: [PATCH] tracing: annotate emit_log_char() notrace

[Steven Rostedt]

On Thu, 28 May 2009, Thomas Gleixner wrote:

> On Thu, 28 May 2009, Frederic Weisbecker wrote:
> > On Wed, May 27, 2009 at 05:00:44PM +0200, Thomas Gleixner wrote:
> > > printk calls emit_log_char() in a loop which is cluttering the trace
> > > buffer. Make it notrace.
> > > 
> > > Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
> > > ---
> > 
> > 
> > Does it produce that much annoying traces?
> > I mean, printk() are usually rare events.
> > 
> > Do you have a particular debugging workflow that makes this
> > function invasive in the trace?
> > 
> > May be it's because you are debugging using ftrace and other
> > debugging options that use a lot of printk()
> > In such case, it would indeed be good to apply this patch.
> 
> I noticed when I chased a boot up problem, half of the trace was full
> of
> 
>    0.540550: emit_log_char <-vprintk
>    0.540550: emit_log_char <-vprintk
>    ...
> 
> though there is another annoyance in the same code path:
> 
>    0.540557: vgacon_set_cursor_size <-vgacon_cursor
>    0.540558: __rcu_read_lock <-__atomic_notifier_call_chain
>    0.540558: __rcu_read_unlock <-__atomic_notifier_call_chain
>    0.540558: __rcu_read_lock <-__atomic_notifier_call_chain
>    ...
> 
> It's actually the same number of times as we have emit_log_char()
> there. __atomic_notifier_call_chain() itself is marked notrace but the
> rcu calls inside are not. :(
> 
> IIRC the same happens with a serial console, but that can be worse as
> you busy wait during the character output.
> 
> It'd be nice if we could inherit the notrace from the caller :)
> 

I'd hate to make rcu_read_*lock be a notrace. I've done some debugging 
with wanting to know where the rcu locks were taken.

I'm sure there's lots of functions that people will want to add notrace 
for. Really, the notrace on a function should only be there to prevent 
crashes (functions used by the tracer or early boot up code for some 
archs).

That said, there are times when you want to avoid tracing things on early 
boot up. Thus, if someone adds to the kernel command line 
"ftrace=function" you have no way to filter out these functions you don't 
care about.

What if I add a "ftrace_notrace=<function list>" kernel command line, that 
has <function list> be a comma separated list of functions you want to go 
into the "set_ftrace_notrace" on boot up? Would that satisfy you. Then you 
can keep adding to the list dynamically every boot. And keep it there in a 
grub file.

This will also keep people from constantly asking for notrace annotations 
just because they are annoyed by the functions that always fill up their 
logs.

-- Steve

Re: [PATCH] tracing: annotate emit_log_char() notrace

[Thomas Gleixner]

On Thu, 28 May 2009, Steven Rostedt wrote:
> > IIRC the same happens with a serial console, but that can be worse as
> > you busy wait during the character output.
> > 
> > It'd be nice if we could inherit the notrace from the caller :)
> > 
> 
> I'd hate to make rcu_read_*lock be a notrace. I've done some debugging 
> with wanting to know where the rcu locks were taken.

Sure.
 
> I'm sure there's lots of functions that people will want to add notrace 
> for. Really, the notrace on a function should only be there to prevent 
> crashes (functions used by the tracer or early boot up code for some 
> archs).

Well, lets look at the atomic notifier then. Why is it notrace ? And
if there is a reason why does it trace the calls which are done inside
of it. We should really think about inheriting the notrace down the
call chain at least for those calls which must be annotated to avoid
wreckage. That could then be made optional (via commandline) for all
notrace calls.

> That said, there are times when you want to avoid tracing things on early 
> boot up. Thus, if someone adds to the kernel command line 
> "ftrace=function" you have no way to filter out these functions you don't 
> care about.
> 
> What if I add a "ftrace_notrace=<function list>" kernel command line, that 
> has <function list> be a comma separated list of functions you want to go 
> into the "set_ftrace_notrace" on boot up? Would that satisfy you. Then you 
> can keep adding to the list dynamically every boot. And keep it there in a 
> grub file.

That list might grow fast beyond the command line lenght limit :)

But yeah, I can see your point. At least it would be better than
cursing and adding ad hoc notrace patches all over the place.

Thanks,

	tglx

Re: [PATCH] tracing: annotate emit_log_char() notrace

[Steven Rostedt]

On Thu, 28 May 2009, Thomas Gleixner wrote:

> On Thu, 28 May 2009, Steven Rostedt wrote:
> > > IIRC the same happens with a serial console, but that can be worse as
> > > you busy wait during the character output.
> > > 
> > > It'd be nice if we could inherit the notrace from the caller :)
> > > 
> > 
> > I'd hate to make rcu_read_*lock be a notrace. I've done some debugging 
> > with wanting to know where the rcu locks were taken.
> 
> Sure.
>  
> > I'm sure there's lots of functions that people will want to add notrace 
> > for. Really, the notrace on a function should only be there to prevent 
> > crashes (functions used by the tracer or early boot up code for some 
> > archs).
> 
> Well, lets look at the atomic notifier then. Why is it notrace ? And
> if there is a reason why does it trace the calls which are done inside
> of it. We should really think about inheriting the notrace down the
> call chain at least for those calls which must be annotated to avoid
> wreckage. That could then be made optional (via commandline) for all
> notrace calls.

Every function marked with __kprobes becomes notrace, which atomic 
notifier is.

We probably can even remove that now. Ingo added it when we had the issue 
with the NMI causing lockups. See 36dcd67ae994fece615b7c700958d215e884b9ae
But we have since fixed the NMI issues.

Also, there's no real way to inherit notrace automatically. Well we could 
write some really nasty scripts to try it at compile time. notrace is 
simply an attribute in gcc to prevent it from calling mcount.

> 
> > That said, there are times when you want to avoid tracing things on early 
> > boot up. Thus, if someone adds to the kernel command line 
> > "ftrace=function" you have no way to filter out these functions you don't 
> > care about.
> > 
> > What if I add a "ftrace_notrace=<function list>" kernel command line, that 
> > has <function list> be a comma separated list of functions you want to go 
> > into the "set_ftrace_notrace" on boot up? Would that satisfy you. Then you 
> > can keep adding to the list dynamically every boot. And keep it there in a 
> > grub file.
> 
> That list might grow fast beyond the command line lenght limit :)
> 
> But yeah, I can see your point. At least it would be better than
> cursing and adding ad hoc notrace patches all over the place.
> 

Well, the boot options still allow for simple wild cards. So hopefully the 
list will not grow too much. You can also just add a list of functions 
that you want to trace (filter as suppose to notrace).

If you are tracing after boot up, then you can add the list to a start up 
script and just echo into the set_ftrace_notrace file.

-- Steve