[PATCH] tracing/function-graph-tracer: strip ending newlines on comments

[PATCH] tracing/function-graph-tracer: strip ending newlines on comments

[Frederic Weisbecker]

Impact: trivial output improvement

Ending newlines are appended automatically on comments by the function graph tracer
because the newlines needs to be placed after the "*/" characters.
So if the user puts an ending whitespace, we want to strip it.

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
---
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 4bf39fc..20c0b0d 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -540,6 +540,7 @@ print_graph_comment(struct print_entry *trace, struct trace_seq *s,
 		   struct trace_entry *ent, struct trace_iterator *iter)
 {
 	int i;
+	int len;
 	int ret;
 
 	/* Pid */
@@ -584,6 +585,11 @@ print_graph_comment(struct print_entry *trace, struct trace_seq *s,
 				return TRACE_TYPE_PARTIAL_LINE;
 		}
 
+	/* Strip ending newline on the comment */
+	len = strlen(trace->buf);
+	if (trace->buf[len - 1] == '\n')
+		trace->buf[len - 1] = '\0';
+
 	/* The comment */
 	ret = trace_seq_printf(s, "/* %s", trace->buf);
 	if (!ret)
-- 
1.6.0.4

Re: [PATCH] tracing/function-graph-tracer: strip ending newlines on comments

[Ingo Molnar]

* Frederic Weisbecker <fweisbec@gmail.com> wrote:

> Impact: trivial output improvement
> 
> Ending newlines are appended automatically on comments by the function graph tracer
> because the newlines needs to be placed after the "*/" characters.
> So if the user puts an ending whitespace, we want to strip it.
> 
> Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>

applied to tip/tracing/function-graph-tracer, thanks Frederic!

> @@ -584,6 +585,11 @@ print_graph_comment(struct print_entry *trace, struct trace_seq *s,
>  				return TRACE_TYPE_PARTIAL_LINE;
>  		}
>  
> +	/* Strip ending newline on the comment */
> +	len = strlen(trace->buf);
> +	if (trace->buf[len - 1] == '\n')
> +		trace->buf[len - 1] = '\0';
> +

Hm, dont we know the length of the buffer already, so that we could avoid 
the strlen() overhead?

	Ingo

Re: [PATCH] tracing/function-graph-tracer: strip ending newlines on comments

[Ingo Molnar]

btw., ftrace_printk() is not NMI safe:
x
BUG: spinlock recursion on CPU#1, loop_yield/3360
 lock: ffffffff807a0c60, .magic: dead4ead, .owner: loop_yield/3360, .owner_cpu: 1
Pid: 3360, comm: loop_yield Not tainted 2.6.28-rc9-tip #48
Call Trace:
 <NMI>  [<ffffffff8038ba23>] spin_bug+0xa2/0xaa
 [<ffffffff8038baf8>] _raw_spin_lock+0x42/0x134
 [<ffffffff8059f0fc>] _spin_lock_irqsave+0x44/0x50
 [<ffffffff802890c4>] ? trace_vprintk+0x8e/0x164
 [<ffffffff8059eeea>] ? _spin_unlock_irqrestore+0x3d/0x4c
 [<ffffffff802890c4>] trace_vprintk+0x8e/0x164
 [<ffffffff802182a6>] ? __hw_perf_counter_set_period+0x1ed/0x280
 [<ffffffff802892ef>] __ftrace_printk+0x55/0x57
 [<ffffffff802182cc>] __hw_perf_counter_set_period+0x213/0x280
 [<ffffffff80218d8c>] __smp_perf_counter_interrupt+0x21c/0x3c2
 [<ffffffff805a043a>] perf_counter_nmi_handler+0x35/0x3f
 [<ffffffff805a1cc9>] notifier_call_chain+0x5e/0x92
 [<ffffffff805a1d5b>] __atomic_notifier_call_chain+0x5e/0x87
 [<ffffffff805a1cfd>] ? __atomic_notifier_call_chain+0x0/0x87
 [<ffffffff805a1d93>] atomic_notifier_call_chain+0xf/0x11
 [<ffffffff80258e9d>] notify_die+0x2e/0x30
 [<ffffffff8059fdd2>] do_nmi+0x9f/0x25f
 [<ffffffff8059f7fa>] nmi+0x1a/0x2c
 [<ffffffff80287104>] ? __rb_reserve_next+0x4b/0x3c8
 [<ffffffff802871dd>] ? __rb_reserve_next+0x124/0x3c8
 <<EOE>>  <IRQ>  [<ffffffff80287628>] rb_reserve_next_event+0x1a7/0x307
 [<ffffffff8028796c>] ring_buffer_lock_reserve+0x8b/0xd3
 [<ffffffff8028910b>] trace_vprintk+0xd5/0x164
 [<ffffffff80260fb3>] ? trace_hardirqs_on_caller+0xfd/0x138
 [<ffffffff8028dd2b>] ? __perf_counter_remove_from_context+0x60/0x179
 [<ffffffff802892ef>] __ftrace_printk+0x55/0x57
 [<ffffffff802180a6>] ? pmc_generic_disable+0x266/0x279
 [<ffffffff8028dd59>] __perf_counter_remove_from_context+0x8e/0x179
 [<ffffffff8026835d>] generic_smp_call_function_single_interrupt+0x87/0xc0
 [<ffffffff8021fd8d>] smp_call_function_single_interrupt+0x24/0x34
 [<ffffffff8020d053>] call_function_single_interrupt+0x13/0x20
 <EOI> 

caused by:

        spin_lock_irqsave(&trace_buf_lock, irq_flags);

which locking is necessiated by:

        static DEFINE_SPINLOCK(trace_buf_lock);
        static char trace_buf[TRACE_BUF_SIZE];

i think this should be changed to a PER_CPU data structure - and if an NMI 
context mixes up the buffer, that's not a big issue. (i'd not complicate 
it by using a NMI specific buffer)

	Ingo

Re: [PATCH] tracing/function-graph-tracer: strip ending newlines on comments

[Frédéric Weisbecker]

2008/12/23 Ingo Molnar <mingo@elte.hu>:
>
> * Frederic Weisbecker <fweisbec@gmail.com> wrote:
>
>> Impact: trivial output improvement
>>
>> Ending newlines are appended automatically on comments by the function graph tracer
>> because the newlines needs to be placed after the "*/" characters.
>> So if the user puts an ending whitespace, we want to strip it.
>>
>> Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
>
> applied to tip/tracing/function-graph-tracer, thanks Frederic!
>
>> @@ -584,6 +585,11 @@ print_graph_comment(struct print_entry *trace, struct trace_seq *s,
>>                               return TRACE_TYPE_PARTIAL_LINE;
>>               }
>>
>> +     /* Strip ending newline on the comment */
>> +     len = strlen(trace->buf);
>> +     if (trace->buf[len - 1] == '\n')
>> +             trace->buf[len - 1] = '\0';
>> +
>
> Hm, dont we know the length of the buffer already, so that we could avoid
> the strlen() overhead?
>
>        Ingo
>

We know it during the insertion. But we need a new field struct print_entry.
That makes me remind that I didn't considered the TRACE_CONT rest of
the buffer in this patch.
Actually, the most easy solution would be to print entirely the buffer
to the seq, and then delete
the newline directly to the seq. That would be a bit crappy but
actually the only solution.

So my patch is wrong in cases of long messages.

Re: [PATCH] tracing/function-graph-tracer: strip ending newlines on comments

[Ingo Molnar]

* Frédéric Weisbecker <fweisbec@gmail.com> wrote:

> 2008/12/23 Ingo Molnar <mingo@elte.hu>:
> >
> > * Frederic Weisbecker <fweisbec@gmail.com> wrote:
> >
> >> Impact: trivial output improvement
> >>
> >> Ending newlines are appended automatically on comments by the function graph tracer
> >> because the newlines needs to be placed after the "*/" characters.
> >> So if the user puts an ending whitespace, we want to strip it.
> >>
> >> Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
> >
> > applied to tip/tracing/function-graph-tracer, thanks Frederic!
> >
> >> @@ -584,6 +585,11 @@ print_graph_comment(struct print_entry *trace, struct trace_seq *s,
> >>                               return TRACE_TYPE_PARTIAL_LINE;
> >>               }
> >>
> >> +     /* Strip ending newline on the comment */
> >> +     len = strlen(trace->buf);
> >> +     if (trace->buf[len - 1] == '\n')
> >> +             trace->buf[len - 1] = '\0';
> >> +
> >
> > Hm, dont we know the length of the buffer already, so that we could avoid
> > the strlen() overhead?
> >
> >        Ingo
> >
> 
> We know it during the insertion. But we need a new field struct 
> print_entry. That makes me remind that I didn't considered the 
> TRACE_CONT rest of the buffer in this patch. Actually, the most easy 
> solution would be to print entirely the buffer to the seq, and then 
> delete the newline directly to the seq. That would be a bit crappy but 
> actually the only solution.
> 
> So my patch is wrong in cases of long messages.

ok, i zapped it for now and will wait for v2.

	Ingo

Re: [PATCH] tracing/function-graph-tracer: strip ending newlines on comments

[Frédéric Weisbecker]

2008/12/23 Ingo Molnar <mingo@elte.hu>:
>
> btw., ftrace_printk() is not NMI safe:
> x
> BUG: spinlock recursion on CPU#1, loop_yield/3360
>  lock: ffffffff807a0c60, .magic: dead4ead, .owner: loop_yield/3360, .owner_cpu: 1
> Pid: 3360, comm: loop_yield Not tainted 2.6.28-rc9-tip #48
> Call Trace:
>  <NMI>  [<ffffffff8038ba23>] spin_bug+0xa2/0xaa
>  [<ffffffff8038baf8>] _raw_spin_lock+0x42/0x134
>  [<ffffffff8059f0fc>] _spin_lock_irqsave+0x44/0x50
>  [<ffffffff802890c4>] ? trace_vprintk+0x8e/0x164
>  [<ffffffff8059eeea>] ? _spin_unlock_irqrestore+0x3d/0x4c
>  [<ffffffff802890c4>] trace_vprintk+0x8e/0x164
>  [<ffffffff802182a6>] ? __hw_perf_counter_set_period+0x1ed/0x280
>  [<ffffffff802892ef>] __ftrace_printk+0x55/0x57
>  [<ffffffff802182cc>] __hw_perf_counter_set_period+0x213/0x280
>  [<ffffffff80218d8c>] __smp_perf_counter_interrupt+0x21c/0x3c2
>  [<ffffffff805a043a>] perf_counter_nmi_handler+0x35/0x3f
>  [<ffffffff805a1cc9>] notifier_call_chain+0x5e/0x92
>  [<ffffffff805a1d5b>] __atomic_notifier_call_chain+0x5e/0x87
>  [<ffffffff805a1cfd>] ? __atomic_notifier_call_chain+0x0/0x87
>  [<ffffffff805a1d93>] atomic_notifier_call_chain+0xf/0x11
>  [<ffffffff80258e9d>] notify_die+0x2e/0x30
>  [<ffffffff8059fdd2>] do_nmi+0x9f/0x25f
>  [<ffffffff8059f7fa>] nmi+0x1a/0x2c
>  [<ffffffff80287104>] ? __rb_reserve_next+0x4b/0x3c8
>  [<ffffffff802871dd>] ? __rb_reserve_next+0x124/0x3c8
>  <<EOE>>  <IRQ>  [<ffffffff80287628>] rb_reserve_next_event+0x1a7/0x307
>  [<ffffffff8028796c>] ring_buffer_lock_reserve+0x8b/0xd3
>  [<ffffffff8028910b>] trace_vprintk+0xd5/0x164
>  [<ffffffff80260fb3>] ? trace_hardirqs_on_caller+0xfd/0x138
>  [<ffffffff8028dd2b>] ? __perf_counter_remove_from_context+0x60/0x179
>  [<ffffffff802892ef>] __ftrace_printk+0x55/0x57
>  [<ffffffff802180a6>] ? pmc_generic_disable+0x266/0x279
>  [<ffffffff8028dd59>] __perf_counter_remove_from_context+0x8e/0x179
>  [<ffffffff8026835d>] generic_smp_call_function_single_interrupt+0x87/0xc0
>  [<ffffffff8021fd8d>] smp_call_function_single_interrupt+0x24/0x34
>  [<ffffffff8020d053>] call_function_single_interrupt+0x13/0x20
>  <EOI>
>
> caused by:
>
>        spin_lock_irqsave(&trace_buf_lock, irq_flags);
>
> which locking is necessiated by:
>
>        static DEFINE_SPINLOCK(trace_buf_lock);
>        static char trace_buf[TRACE_BUF_SIZE];
>
> i think this should be changed to a PER_CPU data structure - and if an NMI
> context mixes up the buffer, that's not a big issue. (i'd not complicate
> it by using a NMI specific buffer)
>
>        Ingo
>

Ok. That would be great if the nmi context detection implemented
inside arch/x86/kernel/ftrace.c could be standardized,
we could also make easy the handling of such situations.

For now I will fix it with a per_cpu buffer.

Thanks.