Re: perf trace report with time consumed

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

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

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 --]