Skip to contentSkip to conversation

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

PATCH Applied Frederic Weisbecker 2 participants 6 messages Dec 22, 2008 – Dec 23, 2008 Tracing

v1 of 2 Applied Latest is v2 →

lore
Share & tools
lore

Frederic Weisbecker

author
#0 lore raw

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

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 <[email protected]>

---

kernel/trace/trace_functions_graph.c +6 -0
index 4bf39fc..20c0b0d 100644
@@ -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)
Signature · 1 line
1.6.0.4
Applied
#1 lore raw
Quoted 7 lines · 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 <[email protected]>

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

kernel/trace/trace_functions_graph.c print_graph_comment(struct print_entry *trace, struct trace_seq *s, · line 592

Quoted 9 lines
kernel/trace/trace_functions_graph.c +5 -0
@@ -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

#2 lore raw

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

author
#3 lore raw

2008/12/23 Ingo Molnar <[email protected]>:

Quoted 46 lines

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:

Quoted 9 lines
       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.

author
#4 lore raw
In reply to Ingo Molnar

2008/12/23 Ingo Molnar <[email protected]>:

Quoted 26 lines · Frederic Weisbecker
Quoted 8 lines

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 <[email protected]>

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

kernel/trace/trace_functions_graph.c print_graph_comment(struct print_entry *trace, struct trace_seq *s, · line 592

Quoted 9 lines
kernel/trace/trace_functions_graph.c +5 -0
@@ -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?

Quoted 2 lines

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.

#5 lore raw
Quoted 30 lines · Frédéric Weisbecker

2008/12/23 Ingo Molnar <[email protected]>:

Quoted 26 lines · Frederic Weisbecker
Quoted 8 lines

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 <[email protected]>

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

kernel/trace/trace_functions_graph.c print_graph_comment(struct print_entry *trace, struct trace_seq *s, · line 592

Quoted 9 lines
kernel/trace/trace_functions_graph.c +5 -0
@@ -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?

Quoted 2 lines

Ingo

Quoted 8 lines

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