Re: perf trace report with time consumed

[Milian Wolff <milian.wolff@kdab.com>]

[-- Attachment #1: Type: text/plain, Size: 7136 bytes --]

Jiri, see my mail below for the WIP patch below that triggers the crash when 
DWARF callchains are enabled for `perf trace`.

Would be great if you could tell me what I'm missing.

Thanks!

On Freitag, 1. April 2016 00:34:44 CEST Milian Wolff wrote:
> On Mittwoch, 30. März 2016 18:58:33 CEST Arnaldo Carvalho de Melo wrote:
> > Em Wed, Mar 30, 2016 at 11:24:17PM +0200, Milian Wolff escreveu:
> > > On Mittwoch, 30. März 2016 11:53:14 CEST Arnaldo Carvalho de Melo wrote:
> > > > Em Tue, Mar 29, 2016 at 10:39:36PM +0200, Milian Wolff escreveu:
> > > > > with "perf trace record --call-graph dwarf" I get a nice data file
> > > > > with
> > > > > potentially everything required to find slow syscalls in user space
> > > > > applications. But I'm missing a way to rewrite the data file to let
> > > > > "perf
> > > > > report" attribute samples with the time spent as cost, instead of
> > > > > the
> > > > > raw
> > > > > number of syscalls, i.e. samples.
> > 
> > <SNIP>
> > 
> > > > There is even:
> > > > 
> > > > [root@jouet ~]# trace --duration 1000 -i perf.data
> > > > 
> > > >   1000.423 (1000.056 ms): sleep/1139 nanosleep(rqtp: 0x7ffebed266c0) =
> > > >   0
> > > > 
> > > > [root@jouet ~]#
> > > > 
> > > > Having that with callgraph from userspace is what you're asking for,
> > > > no?
> > > > 
> > > > 'trace' here is just an alias for 'perf trace'.
> > > 
> > > Yep, I think having the individual trace entries annotated with their
> > > backtrace would be a useful addition and also brings perf trace closer
> > > to
> > > strace, cf. it's -k option.
> > 
> > Humm, I was unaware of that:
> >        -k          Print the execution stack trace of the traced
> > 		   
> > 		   processes after each system call (experimental).
> > 		   This option is available only if strace is built with
> > 		   libunwind.
> > 
> > Which is not the case in fedora23 :-\
> 
> I tried playing around with the source code to add that feature and have hit
> some issues and need some guidance.
> 
> My WIP patch currently is:
> 
> ~~~~~~~~~~~~~~~~~
> diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c
> index 69960c3..cc3df97 100644
> --- a/tools/perf/builtin-trace.c
> +++ b/tools/perf/builtin-trace.c
> @@ -34,6 +34,7 @@
>  #include "trace-event.h"
>  #include "util/parse-events.h"
>  #include "util/bpf-loader.h"
> +#include "util/callchain.h"
> 
>  #include <libaudit.h>
>  #include <stdlib.h>
> @@ -2161,6 +2162,18 @@ signed_print:
>  		goto signed_print;
> 
>  	fputc('\n', trace->output);
> +
> +	if (sample->callchain) {
> +		struct addr_location al;
> +		if (machine__resolve(trace->host, &al, sample) < 0) {
> +			pr_err("problem processing %d event, skipping it.\n",
> +			    event->header.type);
> +			return -1;
> +		}
> +
> +		perf_evsel__print_ip(evsel, sample, &al, PRINT_IP_OPT_IP |
> PRINT_IP_OPT_DSO | PRINT_IP_OPT_SYM /* TODO print_opts*/,
> +				     scripting_max_stack);
> +	}
>  out:
>  	ttrace->entry_pending = false;
>  	err = 0;
> @@ -3221,6 +3234,9 @@ int cmd_trace(int argc, const char **argv, const char
> *prefix __maybe_unused)
>  		     "Trace pagefaults", parse_pagefaults, "maj"),
>  	OPT_BOOLEAN(0, "syscalls", &trace.trace_syscalls, "Trace syscalls"),
>  	OPT_BOOLEAN('f', "force", &trace.force, "don't complain, do it"),
> +	OPT_CALLBACK(0, "call-graph", &trace.opts,
> +		     "record_mode[,record_size]", record_callchain_help,
> +		     &record_parse_callchain_opt),
>  	OPT_UINTEGER(0, "proc-map-timeout", &trace.opts.proc_map_timeout,
>  			"per thread proc mmap processing timeout in ms"),
>  	OPT_END()
> @@ -3248,6 +3264,11 @@ int cmd_trace(int argc, const char **argv, const char
> *prefix __maybe_unused)
>  		trace.opts.sample_time = true;
>  	}
> 
> +	if (trace.opts.callgraph_set) {
> +		symbol_conf.use_callchain = true;
> +		callchain_param.enabled = true;
> +	}
> +
>  	if (trace.evlist->nr_entries > 0)
>  		evlist__set_evsel_handler(trace.evlist, trace__event_handler);
> ~~~~~~~~~~~~~~~~~
> 
> Which gives me something when doing
> 
> ~~~~~~~~~~~~~~~~~
> perf trace -e nanosleep --call-graph fp path/to/ex_sleep
>   1000.177 (1000.177 ms): ex_sleep/7965 nanosleep(rqtp: 0x7ffd123d3470,
> rmtp: 0x7ffd123d3470                  ) = 0
>                   20379e syscall_slow_exit_work ([kernel.kallsyms])
>                   203bc4 syscall_return_slowpath ([kernel.kallsyms])
>                   797248 int_ret_from_sys_call ([kernel.kallsyms])
>                    b7600 __nanosleep (/usr/lib/libc-2.23.so)
>          1fe258d4c544155 [unknown] ([unknown])
> ~~~~~~~~~~~~~~~~~
> 
> Nice, so the frame point unwinding seems to work already. But I'm a
> user-space person and none of my tools have that. So let's try dwarf:
> 
> ~~~~~~~~~~~~~~~~~
> perf trace -e nanosleep --call-graph dwarf path/to/ex_sleep
> perf: Segmentation fault
> Obtained 10 stack frames.
> perf(sighandler_dump_stack+0x4f) [0x5637fdcfc85f]
> /usr/lib/libc.so.6(+0x3332f) [0x7fe888b2132f]
> /usr/lib/libc.so.6(__vsnprintf_chk+0x6b) [0x7fe888be38db]
> perf(+0xb3f93) [0x5637fdc56f93]
> perf(+0xb8fec) [0x5637fdc5bfec]
> perf(cmd_trace+0x1c14) [0x5637fdc5e5c4]
> perf(+0xe6bae) [0x5637fdc89bae]
> perf(main+0x6e3) [0x5637fdc23a83]
> /usr/lib/libc.so.6(__libc_start_main+0xef) [0x7fe888b0e70f]
> perf(_start+0x28) [0x5637fdc23bc8]
> Segmentation fault (core dumped)
> ~~~~~~~~~~~~~~~~~
> 
> Ouch :( Valgrind gives me:
> 
> ~~~~~~~~~~~~~~~~~
> ==8053== Syscall param msync(start) points to uninitialised byte(s)
> ==8053==    at 0x528A700: __msync_nocancel (in /usr/lib/libpthread-2.23.so)
> ==8053==    by 0x4E396D6: validate_mem (Ginit.c:137)
> ==8053==    by 0x4E396D6: access_mem (Ginit.c:171)
> ==8053==    by 0x4E3F79D: dwarf_get (libunwind_i.h:168)
> ==8053==    by 0x4E3F79D: apply_reg_state (Gparser.c:819)
> ==8053==    by 0x4E3EE72: _ULx86_64_dwarf_find_save_locs (Gparser.c:907)
> ==8053==    by 0x4E4126A: _ULx86_64_dwarf_step (Gstep.c:34)
> ==8053==    by 0x4E3A873: _ULx86_64_step (Gstep.c:71)
> ==8053==    by 0x4E3B9CF: trace_init_addr (Gtrace.c:248)
> ==8053==    by 0x4E3B9CF: trace_lookup (Gtrace.c:330)
> ==8053==    by 0x4E3B9CF: _ULx86_64_tdep_trace (Gtrace.c:447)
> ==8053==    by 0x4E38C8F: backtrace (backtrace.c:69)
> ==8053==    by 0x26185F: dump_stack (util.c:338)
> ==8053==    by 0x26185F: sighandler_dump_stack (util.c:356)
> ==8053==    by 0x69B232F: ??? (in /usr/lib/libc-2.23.so)
> ==8053==    by 0x6A748DA: __vsnprintf_chk (in /usr/lib/libc-2.23.so)
> ==8053==    by 0x1BBF93: vsnprintf (stdio2.h:77)
> ==8053==    by 0x1BBF93: scnprintf (kernel.h:91)
> ==8053==  Address 0xffeffa000 is on thread 1's stack
> ==8053==  in frame #7, created by backtrace (backtrace.c:59)
> ~~~~~~~~~~~~~~~~
> 
> Any idea what I'm missing in the setup routine? It works fine for `perf
> trace record --call-graph dwarf`.
> 
> Thanks


-- 
Milian Wolff | milian.wolff@kdab.com | Software Engineer
KDAB (Deutschland) GmbH&Co KG, a KDAB Group company
Tel: +49-30-521325470
KDAB - The Qt Experts

[-- Attachment #2: smime.p7s --]
[-- Type: application/pkcs7-signature, Size: 5903 bytes --]