[PATCH] tracing: use %pF in trace_dump_stack()

[PATCH] tracing: use %pF in trace_dump_stack()

[Vegard Nossum]

When using trace_dump_stack() you currently just get a list of function
names.

It can be very useful to know exactly where a call came from, especially
if there are multiple calls from one function to another.

By switching trace_dump_stack() to use %pF we get the function name and
the offset, which can also be further processed to give exact line number
information, like this:

    <...>-1087    3.... 3270529us : <stack trace>
     => pty_write+0x45/0x50
     => n_tty_write+0x358/0x470
     => tty_write+0x189/0x2f0
     => __vfs_write+0x23/0x120
     => vfs_write+0xb3/0x1b0
     => SyS_write+0x44/0xa0
     => entry_SYSCALL_64_fastpath+0x18/0xad

    $ scripts/faddr2line vmlinux tty_write+0x189/0x2f0
    tty_write+0x189/0x2f0:
    do_tty_write at drivers/tty/tty_io.c:1174
     (inlined by) tty_write at drivers/tty/tty_io.c:1257

Signed-off-by: Vegard Nossum <vegard.nossum@oracle.com>
---
 kernel/trace/trace_output.c | 4 +---
 1 file changed, 1 insertion(+), 3 deletions(-)

diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
index 02a4aeb22c47..879909efed33 100644
--- a/kernel/trace/trace_output.c
+++ b/kernel/trace/trace_output.c
@@ -1073,9 +1073,7 @@ static enum print_line_t trace_stack_print(struct trace_iterator *iter,
 		if (trace_seq_has_overflowed(s))
 			break;
 
-		trace_seq_puts(s, " => ");
-		seq_print_ip_sym(s, *p, flags);
-		trace_seq_putc(s, '\n');
+		trace_seq_printf(s, " => %pF\n", (void *) *p);
 	}
 
 	return trace_handle_return(s);
-- 
2.12.0.rc0

Re: [PATCH] tracing: use %pF in trace_dump_stack()

[Steven Rostedt]

On Tue,  9 May 2017 10:50:04 +0200
Vegard Nossum <vegard.nossum@oracle.com> wrote:

> When using trace_dump_stack() you currently just get a list of function
> names.
> 
> It can be very useful to know exactly where a call came from, especially
> if there are multiple calls from one function to another.
> 
> By switching trace_dump_stack() to use %pF we get the function name and
> the offset, which can also be further processed to give exact line number
> information, like this:
> 
>     <...>-1087    3.... 3270529us : <stack trace>
>      => pty_write+0x45/0x50
>      => n_tty_write+0x358/0x470
>      => tty_write+0x189/0x2f0
>      => __vfs_write+0x23/0x120
>      => vfs_write+0xb3/0x1b0
>      => SyS_write+0x44/0xa0
>      => entry_SYSCALL_64_fastpath+0x18/0xad  
> 
>     $ scripts/faddr2line vmlinux tty_write+0x189/0x2f0
>     tty_write+0x189/0x2f0:
>     do_tty_write at drivers/tty/tty_io.c:1174
>      (inlined by) tty_write at drivers/tty/tty_io.c:1257

I prefer not to see it by default. If you want to see it:

 echo 1 > /sys/kernel/debug/tracing/options/sym-offset

NACK.

-- Steve

> 
> Signed-off-by: Vegard Nossum <vegard.nossum@oracle.com>
> ---
>  kernel/trace/trace_output.c | 4 +---
>  1 file changed, 1 insertion(+), 3 deletions(-)
> 
> diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
> index 02a4aeb22c47..879909efed33 100644
> --- a/kernel/trace/trace_output.c
> +++ b/kernel/trace/trace_output.c
> @@ -1073,9 +1073,7 @@ static enum print_line_t trace_stack_print(struct trace_iterator *iter,
>  		if (trace_seq_has_overflowed(s))
>  			break;
>  
> -		trace_seq_puts(s, " => ");
> -		seq_print_ip_sym(s, *p, flags);
> -		trace_seq_putc(s, '\n');
> +		trace_seq_printf(s, " => %pF\n", (void *) *p);
>  	}
>  
>  	return trace_handle_return(s);