[PATCH] ftrace: Handle TRACE_BPUTS in print_graph_comment

[PATCH] ftrace: Handle TRACE_BPUTS in print_graph_comment

[Namhyung Kim]

It missed to handle TRACE_BPUTS so messages recorded by trace_bputs()
will be shown with symbol info unnecessarily.

You can see it with the trace_printk sample code:

  # cd /sys/kernel/tracing/
  # echo sys_sync > set_graph_function
  # echo 1 > options/sym-offset
  # echo function_graph > current_tracer

Note that the sys_sync filter was there to prevent recording other
functions and the sym-offset option was needed since the first message
was called from a module init function so kallsyms doesn't have the
symbol and omitted in the output.

  # cd ~/build/kernel
  # insmod samples/trace_printk/trace-printk.ko

  # cd -
  # head trace

Before:

  # tracer: function_graph
  #
  # CPU  DURATION                  FUNCTION CALLS
  # |     |   |                     |   |   |   |
   1)               |  /* 0xffffffffa0002000: This is a static string that will use trace_bputs */
   1)               |  /* This is a dynamic string that will use trace_puts */
   1)               |  /* trace_printk_irq_work+0x5/0x7b [trace_printk]: (irq) This is a static string that will use trace_bputs */
   1)               |  /* (irq) This is a dynamic string that will use trace_puts */
   1)               |  /* (irq) This is a static string that will use trace_bprintk() */
   1)               |  /* (irq) This is a dynamic string that will use trace_printk */

After:

  # tracer: function_graph
  #
  # CPU  DURATION                  FUNCTION CALLS
  # |     |   |                     |   |   |   |
   1)               |  /* This is a static string that will use trace_bputs */
   1)               |  /* This is a dynamic string that will use trace_puts */
   1)               |  /* (irq) This is a static string that will use trace_bputs */
   1)               |  /* (irq) This is a dynamic string that will use trace_puts */
   1)               |  /* (irq) This is a static string that will use trace_bprintk() */
   1)               |  /* (irq) This is a dynamic string that will use trace_printk */

Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
 kernel/trace/trace_functions_graph.c | 5 +++++
 1 file changed, 5 insertions(+)

diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 9c7ffa4df5a8..4e480e870474 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -1182,6 +1182,11 @@ print_graph_comment(struct trace_seq *s, struct trace_entry *ent,
 	trace_seq_puts(s, "/* ");
 
 	switch (iter->ent->type) {
+	case TRACE_BPUTS:
+		ret = trace_print_bputs_msg_only(iter);
+		if (ret != TRACE_TYPE_HANDLED)
+			return ret;
+		break;
 	case TRACE_BPRINT:
 		ret = trace_print_bprintk_msg_only(iter);
 		if (ret != TRACE_TYPE_HANDLED)
-- 
2.9.3

Re: [PATCH] ftrace: Handle TRACE_BPUTS in print_graph_comment

[Steven Rostedt]

On Thu,  1 Sep 2016 11:43:54 +0900
Namhyung Kim <namhyung@kernel.org> wrote:

> It missed to handle TRACE_BPUTS so messages recorded by trace_bputs()
> will be shown with symbol info unnecessarily.
> 
> You can see it with the trace_printk sample code:
> 
>   # cd /sys/kernel/tracing/
>   # echo sys_sync > set_graph_function
>   # echo 1 > options/sym-offset
>   # echo function_graph > current_tracer
> 
> Note that the sys_sync filter was there to prevent recording other
> functions and the sym-offset option was needed since the first message
> was called from a module init function so kallsyms doesn't have the
> symbol and omitted in the output.
> 
>   # cd ~/build/kernel
>   # insmod samples/trace_printk/trace-printk.ko
> 
>   # cd -
>   # head trace
> 
> Before:
> 
>   # tracer: function_graph
>   #
>   # CPU  DURATION                  FUNCTION CALLS
>   # |     |   |                     |   |   |   |
>    1)               |  /* 0xffffffffa0002000: This is a static string that will use trace_bputs */
>    1)               |  /* This is a dynamic string that will use trace_puts */
>    1)               |  /* trace_printk_irq_work+0x5/0x7b [trace_printk]: (irq) This is a static string that will use trace_bputs */
>    1)               |  /* (irq) This is a dynamic string that will use trace_puts */
>    1)               |  /* (irq) This is a static string that will use trace_bprintk() */
>    1)               |  /* (irq) This is a dynamic string that will use trace_printk */
> 
> After:
> 
>   # tracer: function_graph
>   #
>   # CPU  DURATION                  FUNCTION CALLS
>   # |     |   |                     |   |   |   |
>    1)               |  /* This is a static string that will use trace_bputs */
>    1)               |  /* This is a dynamic string that will use trace_puts */
>    1)               |  /* (irq) This is a static string that will use trace_bputs */
>    1)               |  /* (irq) This is a dynamic string that will use trace_puts */
>    1)               |  /* (irq) This is a static string that will use trace_bprintk() */
>    1)               |  /* (irq) This is a dynamic string that will use trace_printk */
> 
> Signed-off-by: Namhyung Kim <namhyung@kernel.org>
> ---

Applied, thanks Namhyung!

-- Steve