perf trace report with time consumed

perf trace report with time consumed

[Milian Wolff]

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

Hey all,

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.

Is this functionality there already? Or do I have to write another "perf 
inject" command, similar to "perf inject --sched-stat"?

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

Re: perf trace report with time consumed

[Arnaldo Carvalho de Melo]

Em Tue, Mar 29, 2016 at 10:39:36PM +0200, Milian Wolff escreveu:
> Hey all,
> 
> 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.

Humm, perhaps use 'perf trace', maybe this is the push to add support for callgraphs there:


[root@jouet ~]# trace record sleep 1
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.026 MB perf.data (68 samples) ]
[root@jouet ~]# ls -la perf.data
-rw-------. 1 root root 34446 Mar 30 11:49 perf.data
[root@jouet ~]# trace -s -i perf.data

 Summary of events:

 sleep (1139), 67 events, 98.5%, 0.000 msec

   syscall            calls    total       min       avg       max      stddev
                               (msec)    (msec)    (msec)    (msec)        (%)
   --------------- -------- --------- --------- --------- ---------     ------
   read                   1     0.002     0.002     0.002     0.002      0.00%
   open                   3     0.017     0.005     0.006     0.006      3.14%
   close                  5     0.004     0.001     0.001     0.002     30.49%
   fstat                  3     0.003     0.001     0.001     0.002     22.16%
   mmap                   9     0.028     0.001     0.003     0.005     14.67%
   mprotect               4     0.018     0.003     0.005     0.007     17.07%
   munmap                 1     0.008     0.008     0.008     0.008      0.00%
   brk                    4     0.005     0.000     0.001     0.003     43.48%
   access                 1     0.005     0.005     0.005     0.005      0.00%
   nanosleep              1  1000.056  1000.056  1000.056  1000.056      0.00%
   arch_prctl             1     0.001     0.001     0.001     0.001      0.00%


[root@jouet ~]# trace -i perf.data
     0.021 ( 0.001 ms): sleep/1139 brk(                                                                  ) = 0x5619db285000
     0.036 ( 0.003 ms): sleep/1139 mmap(len: 4096, prot: READ|WRITE, flags: PRIVATE|ANONYMOUS, fd: -1    ) = 0x7f3e5264b000
     0.046 ( 0.005 ms): sleep/1139 access(filename: 0x52449e10, mode: R                                  ) = -1 ENOENT No such file or directory
     0.055 ( 0.005 ms): sleep/1139 open(filename: 0x52448761, flags: CLOEXEC                             ) = 4
     0.058 ( 0.002 ms): sleep/1139 fstat(fd: 4, statbuf: 0x7ffebed25ef0                                  ) = 0
     0.062 ( 0.004 ms): sleep/1139 mmap(len: 106798, prot: READ, flags: PRIVATE, fd: 4                   ) = 0x7f3e52630000
     0.063 ( 0.001 ms): sleep/1139 close(fd: 4                                                           ) = 0
     0.078 ( 0.006 ms): sleep/1139 open(filename: 0x5264b640, flags: CLOEXEC                             ) = 4
     0.081 ( 0.002 ms): sleep/1139 read(fd: 4, buf: 0x7ffebed26080, count: 832                           ) = 832
     0.083 ( 0.001 ms): sleep/1139 fstat(fd: 4, statbuf: 0x7ffebed25f30                                  ) = 0
     0.089 ( 0.004 ms): sleep/1139 mmap(len: 3934784, prot: EXEC|READ, flags: PRIVATE|DENYWRITE, fd: 4   ) = 0x7f3e5206b000
     0.097 ( 0.007 ms): sleep/1139 mprotect(start: 0x7f3e52222000, len: 2097152                          ) = 0
     0.103 ( 0.005 ms): sleep/1139 mmap(addr: 0x7f3e52422000, len: 24576, prot: READ|WRITE, flags: PRIVATE|DENYWRITE|FIXED, fd: 4, off: 1798144) = 0x7f3e52422
     0.109 ( 0.003 ms): sleep/1139 mmap(addr: 0x7f3e52428000, len: 14912, prot: READ|WRITE, flags: PRIVATE|ANONYMOUS|FIXED, fd: -1) = 0x7f3e52428000
     0.114 ( 0.001 ms): sleep/1139 close(fd: 4                                                           ) = 0
     0.126 ( 0.002 ms): sleep/1139 mmap(len: 4096, prot: READ|WRITE, flags: PRIVATE|ANONYMOUS, fd: -1    ) = 0x7f3e5262f000
     0.131 ( 0.002 ms): sleep/1139 mmap(len: 4096, prot: READ|WRITE, flags: PRIVATE|ANONYMOUS, fd: -1    ) = 0x7f3e5262e000
     0.134 ( 0.001 ms): sleep/1139 mmap(len: 4096, prot: READ|WRITE, flags: PRIVATE|ANONYMOUS, fd: -1    ) = 0x7f3e5262d000
     0.136 ( 0.001 ms): sleep/1139 arch_prctl(option: 4098, arg2: 139905646913280, arg3: 3, arg4: 34, arg5: 4294967295) = 0
     0.201 ( 0.005 ms): sleep/1139 mprotect(start: 0x7f3e52422000, len: 16384, prot: READ                ) = 0
     0.224 ( 0.004 ms): sleep/1139 mprotect(start: 0x5619d955f000, len: 4096, prot: READ                 ) = 0
     0.229 ( 0.003 ms): sleep/1139 mprotect(start: 0x7f3e5264c000, len: 4096, prot: READ                 ) = 0
     0.239 ( 0.008 ms): sleep/1139 munmap(addr: 0x7f3e52630000, len: 106798                              ) = 0
     0.306 ( 0.001 ms): sleep/1139 brk(                                                                  ) = 0x5619db285000
     0.309 ( 0.003 ms): sleep/1139 brk(brk: 0x5619db2a6000                                               ) = 0x5619db2a6000
     0.310 ( 0.000 ms): sleep/1139 brk(                                                                  ) = 0x5619db2a6000
     0.320 ( 0.006 ms): sleep/1139 open(filename: 0x521f6e20, flags: CLOEXEC                             ) = 4
     0.325 ( 0.001 ms): sleep/1139 fstat(fd: 4, statbuf: 0x7f3e524279a0                                  ) = 0
     0.330 ( 0.004 ms): sleep/1139 mmap(len: 111950656, prot: READ, flags: PRIVATE, fd: 4                ) = 0x7f3e4b5a7000
     0.335 ( 0.001 ms): sleep/1139 close(fd: 4                                                           ) = 0
  1000.423 (1000.056 ms): sleep/1139 nanosleep(rqtp: 0x7ffebed266c0                                        ) = 0
  1000.440 ( 0.002 ms): sleep/1139 close(fd: 1                                                           ) = 0
  1000.443 ( 0.001 ms): sleep/1139 close(fd: 2                                                           ) = 0
  1000.447 ( 0.000 ms): sleep/1139 exit_group(                                                           
[root@jouet ~]# 

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'.

- Arnaldo
 
> Is this functionality there already? Or do I have to write another "perf 
> inject" command, similar to "perf inject --sched-stat"?
> 
> 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

Re: perf trace report with time consumed

[Milian Wolff]

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

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:
> > Hey all,
> > 
> > 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.
> 
> Humm, perhaps use 'perf trace', maybe this is the push to add support for
> callgraphs there:

Yes, there and/or to inject is what I think is missing. I'll hopefully find 
some time to hack on it over the weekend, I think it would be very useful to 
have. See also below for more.

> [root@jouet ~]# trace record sleep 1
> [ perf record: Woken up 1 times to write data ]
> [ perf record: Captured and wrote 0.026 MB perf.data (68 samples) ]
> [root@jouet ~]# ls -la perf.data
> -rw-------. 1 root root 34446 Mar 30 11:49 perf.data
> [root@jouet ~]# trace -s -i perf.data
> 
>  Summary of events:
> 
>  sleep (1139), 67 events, 98.5%, 0.000 msec
> 
>    syscall            calls    total       min       avg       max     
> stddev (msec)    (msec)    (msec)    (msec)        (%) ---------------
> -------- --------- --------- --------- ---------     ------ read           
>        1     0.002     0.002     0.002     0.002      0.00% open           
>        3     0.017     0.005     0.006     0.006      3.14% close          
>        5     0.004     0.001     0.001     0.002     30.49% fstat          
>        3     0.003     0.001     0.001     0.002     22.16% mmap           
>        9     0.028     0.001     0.003     0.005     14.67% mprotect       
>        4     0.018     0.003     0.005     0.007     17.07% munmap         
>        1     0.008     0.008     0.008     0.008      0.00% brk            
>        4     0.005     0.000     0.001     0.003     43.48% access         
>        1     0.005     0.005     0.005     0.005      0.00% nanosleep      
>        1  1000.056  1000.056  1000.056  1000.056      0.00% arch_prctl     
>        1     0.001     0.001     0.001     0.001      0.00%
> 
> 
> [root@jouet ~]# trace -i perf.data
>      0.021 ( 0.001 ms): sleep/1139 brk(                                     
>                             ) = 0x5619db285000 0.036 ( 0.003 ms):
> sleep/1139 mmap(len: 4096, prot: READ|WRITE, flags: PRIVATE|ANONYMOUS, fd:
> -1    ) = 0x7f3e5264b000 0.046 ( 0.005 ms): sleep/1139 access(filename:
> 0x52449e10, mode: R                                  ) = -1 ENOENT No such
> file or directory 0.055 ( 0.005 ms): sleep/1139 open(filename: 0x52448761,
> flags: CLOEXEC                             ) = 4 0.058 ( 0.002 ms):
> sleep/1139 fstat(fd: 4, statbuf: 0x7ffebed25ef0                            
>      ) = 0 0.062 ( 0.004 ms): sleep/1139 mmap(len: 106798, prot: READ,
> flags: PRIVATE, fd: 4                   ) = 0x7f3e52630000 0.063 ( 0.001
> ms): sleep/1139 close(fd: 4                                                
>           ) = 0 0.078 ( 0.006 ms): sleep/1139 open(filename: 0x5264b640,
> flags: CLOEXEC                             ) = 4 0.081 ( 0.002 ms):
> sleep/1139 read(fd: 4, buf: 0x7ffebed26080, count: 832                     
>      ) = 832 0.083 ( 0.001 ms): sleep/1139 fstat(fd: 4, statbuf:
> 0x7ffebed25f30                                  ) = 0 0.089 ( 0.004 ms):
> sleep/1139 mmap(len: 3934784, prot: EXEC|READ, flags: PRIVATE|DENYWRITE,
> fd: 4   ) = 0x7f3e5206b000 0.097 ( 0.007 ms): sleep/1139 mprotect(start:
> 0x7f3e52222000, len: 2097152                          ) = 0 0.103 ( 0.005
> ms): sleep/1139 mmap(addr: 0x7f3e52422000, len: 24576, prot: READ|WRITE,
> flags: PRIVATE|DENYWRITE|FIXED, fd: 4, off: 1798144) = 0x7f3e52422 0.109 (
> 0.003 ms): sleep/1139 mmap(addr: 0x7f3e52428000, len: 14912, prot:
> READ|WRITE, flags: PRIVATE|ANONYMOUS|FIXED, fd: -1) = 0x7f3e52428000 0.114
> ( 0.001 ms): sleep/1139 close(fd: 4                                        
>                   ) = 0 0.126 ( 0.002 ms): sleep/1139 mmap(len: 4096, prot:
> READ|WRITE, flags: PRIVATE|ANONYMOUS, fd: -1    ) = 0x7f3e5262f000 0.131 (
> 0.002 ms): sleep/1139 mmap(len: 4096, prot: READ|WRITE, flags:
> PRIVATE|ANONYMOUS, fd: -1    ) = 0x7f3e5262e000 0.134 ( 0.001 ms):
> sleep/1139 mmap(len: 4096, prot: READ|WRITE, flags: PRIVATE|ANONYMOUS, fd:
> -1    ) = 0x7f3e5262d000 0.136 ( 0.001 ms): sleep/1139 arch_prctl(option:
> 4098, arg2: 139905646913280, arg3: 3, arg4: 34, arg5: 4294967295) = 0 0.201
> ( 0.005 ms): sleep/1139 mprotect(start: 0x7f3e52422000, len: 16384, prot:
> READ                ) = 0 0.224 ( 0.004 ms): sleep/1139 mprotect(start:
> 0x5619d955f000, len: 4096, prot: READ                 ) = 0 0.229 ( 0.003
> ms): sleep/1139 mprotect(start: 0x7f3e5264c000, len: 4096, prot: READ      
>           ) = 0 0.239 ( 0.008 ms): sleep/1139 munmap(addr: 0x7f3e52630000,
> len: 106798                              ) = 0 0.306 ( 0.001 ms):
> sleep/1139 brk(                                                            
>      ) = 0x5619db285000 0.309 ( 0.003 ms): sleep/1139 brk(brk:
> 0x5619db2a6000                                               ) =
> 0x5619db2a6000 0.310 ( 0.000 ms): sleep/1139 brk(                          
>                                        ) = 0x5619db2a6000 0.320 ( 0.006
> ms): sleep/1139 open(filename: 0x521f6e20, flags: CLOEXEC                  
>           ) = 4 0.325 ( 0.001 ms): sleep/1139 fstat(fd: 4, statbuf:
> 0x7f3e524279a0                                  ) = 0 0.330 ( 0.004 ms):
> sleep/1139 mmap(len: 111950656, prot: READ, flags: PRIVATE, fd: 4          
>      ) = 0x7f3e4b5a7000 0.335 ( 0.001 ms): sleep/1139 close(fd: 4          
>                                                 ) = 0 1000.423 (1000.056
> ms): sleep/1139 nanosleep(rqtp: 0x7ffebed266c0                             
>           ) = 0 1000.440 ( 0.002 ms): sleep/1139 close(fd: 1               
>                                            ) = 0 1000.443 ( 0.001 ms):
> sleep/1139 close(fd: 2                                                     
>      ) = 0 1000.447 ( 0.000 ms): sleep/1139 exit_group(
> [root@jouet ~]#
> 
> 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.
 
But I still think that this would be useful to have as well:

> > Is this functionality there already? Or do I have to write another "perf
> > inject" command, similar to "perf inject --sched-stat"?

That would allow one to browse the aggregated call stacks in bottom-up/top-
down manner with `perf report`. `perf trace` allows the aggregation by syscall 
via `--summary`, but I don't see a good way to add a call stacks visualization 
there in any decent way. `perf inject` + `perf report` could solve that 
nicely, no?

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

Re: perf trace report with time consumed

[Arnaldo Carvalho de Melo]

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 :-\

> But I still think that this would be useful to have as well:
> 
> > > Is this functionality there already? Or do I have to write another "perf
> > > inject" command, similar to "perf inject --sched-stat"?
> 
> That would allow one to browse the aggregated call stacks in bottom-up/top-
> down manner with `perf report`. `perf trace` allows the aggregation by syscall 
> via `--summary`, but I don't see a good way to add a call stacks visualization 
> there in any decent way. `perf inject` + `perf report` could solve that 
> nicely, no?

Probably, try it :-)

- Arnaldo

Re: perf trace report with time consumed

[Milian Wolff]

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

Re: perf trace report with time consumed

[Arnaldo Carvalho de Melo]

Em Fri, Apr 01, 2016 at 12:34:44AM +0200, Milian Wolff escreveu:
> 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`.

Jiri?

I have to investigate this, I cooked up a patch almost the same as
yours, only using the top callchain OPT_ stuff because it also sets
those symbol_conf globals, but ended up having trouble with libunwind
:-\

BTW: Those callchain related globals have to go, finally, because I want
to be able to enable callchain collection/reporting per event, i.e.
output that shows callchains for some 'perf probe' events while not for
all syscalls except for futex(), etc.

- Arnaldo

Re: perf trace report with time consumed

[Jiri Olsa]

On Fri, Apr 01, 2016 at 10:01:40AM -0300, Arnaldo Carvalho de Melo wrote:
> Em Fri, Apr 01, 2016 at 12:34:44AM +0200, Milian Wolff escreveu:
> > 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

hum, I need some special change to run this?

is there command related to latest Arnaldo's perf/core
that reproduces the issue?

thanks,
jirka

> > 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`.
> 
> Jiri?
> 
> I have to investigate this, I cooked up a patch almost the same as
> yours, only using the top callchain OPT_ stuff because it also sets
> those symbol_conf globals, but ended up having trouble with libunwind
> :-\
> 
> BTW: Those callchain related globals have to go, finally, because I want
> to be able to enable callchain collection/reporting per event, i.e.
> output that shows callchains for some 'perf probe' events while not for
> all syscalls except for futex(), etc.
> 
> - Arnaldo

Re: perf trace report with time consumed

[Milian Wolff]

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

Re: perf trace report with time consumed

[Jiri Olsa]

On Sun, Apr 03, 2016 at 08:46:19PM +0200, Milian Wolff wrote:
> 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.

would you please resend, I can't apply the one you posted

[jolsa@krava linux-perf]$ patch -p1 < /tmp/w
patching file tools/perf/builtin-trace.c
Hunk #1 FAILED at 34.
patch: **** malformed patch at line 126: PRINT_IP_OPT_DSO | PRINT_IP_OPT_SYM /* TODO print_opts*/,

thanks,
jirka

Re: perf trace report with time consumed

[Milian Wolff]

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

On Montag, 4. April 2016 08:14:08 CEST Jiri Olsa wrote:
> On Sun, Apr 03, 2016 at 08:46:19PM +0200, Milian Wolff wrote:
> > 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.
> 
> would you please resend, I can't apply the one you posted
> 
> [jolsa@krava linux-perf]$ patch -p1 < /tmp/w
> patching file tools/perf/builtin-trace.c
> Hunk #1 FAILED at 34.
> patch: **** malformed patch at line 126: PRINT_IP_OPT_DSO | PRINT_IP_OPT_SYM
> /* TODO print_opts*/,

I send Jiri the patch off-list to which he replied:

> > so by enabling call graph you enabled code in unwind__prepare_access
> > which will set thread->priv which perf trace is already using for
> > some other stuff..
> > 
> > the thread__trace will think the thread->priv is already allocated
> > and rest of the code will access thread->priv as struct thread_trace
> > while it's allocated as unw_addr_space_t
> > 
> > I guess either perf trace or the unwind code need to change
> > another location for its private data in the thread..
> > we could move that dwarf private stuff to separate location
> > 
> > I'll prepare patch this week if I dont see anyone else doing that ;-)

This is indeed the reason, my naive approach of adding a `priv2` to `thread` 
and adding a "2" suffix to all uses of `thread__{set,}priv` in `builtin-
trace.c` makes it work:

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
     0.174 ( 0.002 ms): ex_sleep/4390 close(fd: 3                                                           
) = 0
                  20379e syscall_slow_exit_work ([kernel.kallsyms])
                  203bc4 syscall_return_slowpath ([kernel.kallsyms])
                  797248 int_ret_from_sys_call ([kernel.kallsyms])
            7f688a8c7e07 close (/usr/lib/ld-2.23.so)
            7f688a8bf20b _dl_sysdep_read_whole_file (/usr/lib/ld-2.23.so)
            7f688a8c5446 _dl_load_cache_lookup (/usr/lib/ld-2.23.so)
            7f688a8b79ba _dl_map_object (/usr/lib/ld-2.23.so)
            7f688a8bbcb2 openaux (/usr/lib/ld-2.23.so)
            7f688a8be264 _dl_catch_error (/usr/lib/ld-2.23.so)
            7f688a8bbf23 _dl_map_object_deps (/usr/lib/ld-2.23.so)
            7f688a8b2033 dl_main (/usr/lib/ld-2.23.so)
            7f688a8c629c _dl_sysdep_start (/usr/lib/ld-2.23.so)
            7f688a8b3d4a _dl_start (/usr/lib/ld-2.23.so)
            7f688a8afd98 _dl_start_user (/usr/lib/ld-2.23.so)
     0.200 ( 0.004 ms): ex_sleep/4390 open(filename: 0x8aad10b0, flags: 
CLOEXEC                             ) = 3
                  20379e syscall_slow_exit_work ([kernel.kallsyms])
                  203bc4 syscall_return_slowpath ([kernel.kallsyms])
                  797248 int_ret_from_sys_call ([kernel.kallsyms])
            7f688a8c7d07 open64 (/usr/lib/ld-2.23.so)
            7f688a8b58d8 open_verify.constprop.7 (/usr/lib/ld-2.23.so)
     0.204 ( 0.003 ms): ex_sleep/4390 read(fd: 3, buf: 0x7ffe4d16e7a8, count: 
832                           ) = 832
                  20379e syscall_slow_exit_work ([kernel.kallsyms])
                  203bc4 syscall_return_slowpath ([kernel.kallsyms])
                  797248 int_ret_from_sys_call ([kernel.kallsyms])
            7f688a8c7d27 read (/usr/lib/ld-2.23.so)
            7f688a8b591c open_verify.constprop.7 (/usr/lib/ld-2.23.so)
     0.210 ( 0.002 ms): ex_sleep/4390 fstat(fd: 3, statbuf: 0x7ffe4d16e640                                  
) = 0
                  20379e syscall_slow_exit_work ([kernel.kallsyms])
                  203bc4 syscall_return_slowpath ([kernel.kallsyms])
                  797248 int_ret_from_sys_call ([kernel.kallsyms])
            7f688a8c7c94 _fxstat (/usr/lib/ld-2.23.so)
            7f688a8b44f2 _dl_map_object_from_fd (/usr/lib/ld-2.23.so)
LOST 1 events!
LOST 2 events!
LOST 2 events!
LOST 2 events!
LOST 4 events!
LOST 2 events!
LOST 4 events!
LOST 2 events!
LOST 2 events!
LOST 4 events!
  1000.525 (1000.317 ms): ex_sleep/4390  ... [continued]: nanosleep()) = 0
                  20379e syscall_slow_exit_work ([kernel.kallsyms])
                  203bc4 syscall_return_slowpath ([kernel.kallsyms])
                  797248 int_ret_from_sys_call ([kernel.kallsyms])
  1001.637 ( 1.091 ms): ex_sleep/4390 nanosleep(rqtp: 0x7ffe4d16eec0                                        
) = 0
                  20379e syscall_slow_exit_work ([kernel.kallsyms])
                  203bc4 syscall_return_slowpath ([kernel.kallsyms])
                  797248 int_ret_from_sys_call ([kernel.kallsyms])
            7f688a5c5600 __nanosleep (/usr/lib/libc-2.23.so)
            7f688a5ef0c4 usleep (/usr/lib/libc-2.23.so)
            5582244227cd main (/tmp/ex_sleep)
  1001.702 ( 0.059 ms): ex_sleep/4390 nanosleep(rqtp: 0x7ffe4d16eec0                                        
) = 0
                  20379e syscall_slow_exit_work ([kernel.kallsyms])
                  203bc4 syscall_return_slowpath ([kernel.kallsyms])
                  797248 int_ret_from_sys_call ([kernel.kallsyms])
            7f688a5c5600 __nanosleep (/usr/lib/libc-2.23.so)
            7f688a5ef0c4 usleep (/usr/lib/libc-2.23.so)
            5582244227d7 main (/tmp/ex_sleep)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

Is there a way to increase the event buffer or something like that to not lose 
events when the costly dwarf unwinding happens for the first time? Consecutive 
unwinding is cached by libunwind and much faster.

Alternatively, I could try to unwind in the `sys_enter`, but then I'd need to 
buffer the output to print the trace after the duration line...

How would you guys handle this situation?

Also, Jiri, Arnaldo - what would be your suggestion on how to handle the 
`thread::priv` situation - I doubt my naive `priv2` approach is acceptable.

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

Re: perf trace report with time consumed

[Jiri Olsa]

On Mon, Apr 04, 2016 at 11:17:11PM +0200, Milian Wolff wrote:

SNIP

>             7f688a5ef0c4 usleep (/usr/lib/libc-2.23.so)
>             5582244227cd main (/tmp/ex_sleep)
>   1001.702 ( 0.059 ms): ex_sleep/4390 nanosleep(rqtp: 0x7ffe4d16eec0                                        
> ) = 0
>                   20379e syscall_slow_exit_work ([kernel.kallsyms])
>                   203bc4 syscall_return_slowpath ([kernel.kallsyms])
>                   797248 int_ret_from_sys_call ([kernel.kallsyms])
>             7f688a5c5600 __nanosleep (/usr/lib/libc-2.23.so)
>             7f688a5ef0c4 usleep (/usr/lib/libc-2.23.so)
>             5582244227d7 main (/tmp/ex_sleep)
> ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
> 
> Is there a way to increase the event buffer or something like that to not lose 
> events when the costly dwarf unwinding happens for the first time? Consecutive 
> unwinding is cached by libunwind and much faster.

not sure about perf trace, but there's -m option available for perf record
that allows you to increase the buffer size

> 
> Alternatively, I could try to unwind in the `sys_enter`, but then I'd need to 
> buffer the output to print the trace after the duration line...
> 
> How would you guys handle this situation?
> 
> Also, Jiri, Arnaldo - what would be your suggestion on how to handle the 
> `thread::priv` situation - I doubt my naive `priv2` approach is acceptable.

yea, I think one priv is more than enough ;-)

I think we want to move the the unwinder usage of this field into separate field

thanks,
jirka

[PATCH] perf tools: Add dedicated unwind addr_space member into thread struct

[Jiri Olsa]

On Tue, Apr 05, 2016 at 10:35:24AM +0200, Jiri Olsa wrote:
> On Mon, Apr 04, 2016 at 11:17:11PM +0200, Milian Wolff wrote:
> 
> SNIP
> 
> >             7f688a5ef0c4 usleep (/usr/lib/libc-2.23.so)
> >             5582244227cd main (/tmp/ex_sleep)
> >   1001.702 ( 0.059 ms): ex_sleep/4390 nanosleep(rqtp: 0x7ffe4d16eec0                                        
> > ) = 0
> >                   20379e syscall_slow_exit_work ([kernel.kallsyms])
> >                   203bc4 syscall_return_slowpath ([kernel.kallsyms])
> >                   797248 int_ret_from_sys_call ([kernel.kallsyms])
> >             7f688a5c5600 __nanosleep (/usr/lib/libc-2.23.so)
> >             7f688a5ef0c4 usleep (/usr/lib/libc-2.23.so)
> >             5582244227d7 main (/tmp/ex_sleep)
> > ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
> > 
> > Is there a way to increase the event buffer or something like that to not lose 
> > events when the costly dwarf unwinding happens for the first time? Consecutive 
> > unwinding is cached by libunwind and much faster.
> 
> not sure about perf trace, but there's -m option available for perf record
> that allows you to increase the buffer size
> 
> > 
> > Alternatively, I could try to unwind in the `sys_enter`, but then I'd need to 
> > buffer the output to print the trace after the duration line...
> > 
> > How would you guys handle this situation?
> > 
> > Also, Jiri, Arnaldo - what would be your suggestion on how to handle the 
> > `thread::priv` situation - I doubt my naive `priv2` approach is acceptable.
> 
> yea, I think one priv is more than enough ;-)
> 
> I think we want to move the the unwinder usage of this field into separate field

need to run test over this, but will try to post it this week
let me know if this solution would work for you

thanks,
jirka

---
Adding dedicated unwind addr_space member into thread struct.

Link: http://lkml.kernel.org/n/tip-pwiici9lf2l0iuji1jv1f5kx@git.kernel.org
Signed-off-by: Jiri Olsa <jolsa@kernel.org>
---
 tools/perf/util/thread.h           |  6 ++++++
 tools/perf/util/unwind-libunwind.c | 25 +++++++++----------------
 2 files changed, 15 insertions(+), 16 deletions(-)

diff --git a/tools/perf/util/thread.h b/tools/perf/util/thread.h
index a0ac0317affb..e214207bb13a 100644
--- a/tools/perf/util/thread.h
+++ b/tools/perf/util/thread.h
@@ -9,6 +9,9 @@
 #include "symbol.h"
 #include <strlist.h>
 #include <intlist.h>
+#ifdef HAVE_LIBUNWIND_SUPPORT
+#include <libunwind.h>
+#endif
 
 struct thread_stack;
 
@@ -32,6 +35,9 @@ struct thread {
 
 	void			*priv;
 	struct thread_stack	*ts;
+#ifdef HAVE_LIBUNWIND_SUPPORT
+	unw_addr_space_t	addr_space;
+#endif
 };
 
 struct machine;
diff --git a/tools/perf/util/unwind-libunwind.c b/tools/perf/util/unwind-libunwind.c
index ee7e372297e5..63687d3a344e 100644
--- a/tools/perf/util/unwind-libunwind.c
+++ b/tools/perf/util/unwind-libunwind.c
@@ -32,6 +32,7 @@
 #include "symbol.h"
 #include "util.h"
 #include "debug.h"
+#include "asm/bug.h"
 
 extern int
 UNW_OBJ(dwarf_search_unwind_table) (unw_addr_space_t as,
@@ -580,43 +581,33 @@ static unw_accessors_t accessors = {
 
 int unwind__prepare_access(struct thread *thread)
 {
-	unw_addr_space_t addr_space;
-
 	if (callchain_param.record_mode != CALLCHAIN_DWARF)
 		return 0;
 
-	addr_space = unw_create_addr_space(&accessors, 0);
-	if (!addr_space) {
+	thread->addr_space = unw_create_addr_space(&accessors, 0);
+	if (!thread->addr_space) {
 		pr_err("unwind: Can't create unwind address space.\n");
 		return -ENOMEM;
 	}
 
-	unw_set_caching_policy(addr_space, UNW_CACHE_GLOBAL);
-	thread__set_priv(thread, addr_space);
-
+	unw_set_caching_policy(thread->addr_space, UNW_CACHE_GLOBAL);
 	return 0;
 }
 
 void unwind__flush_access(struct thread *thread)
 {
-	unw_addr_space_t addr_space;
-
 	if (callchain_param.record_mode != CALLCHAIN_DWARF)
 		return;
 
-	addr_space = thread__priv(thread);
-	unw_flush_cache(addr_space, 0, 0);
+	unw_flush_cache(thread->addr_space, 0, 0);
 }
 
 void unwind__finish_access(struct thread *thread)
 {
-	unw_addr_space_t addr_space;
-
 	if (callchain_param.record_mode != CALLCHAIN_DWARF)
 		return;
 
-	addr_space = thread__priv(thread);
-	unw_destroy_addr_space(addr_space);
+	unw_destroy_addr_space(thread->addr_space);
 }
 
 static int get_entries(struct unwind_info *ui, unwind_entry_cb_t cb,
@@ -639,7 +630,9 @@ static int get_entries(struct unwind_info *ui, unwind_entry_cb_t cb,
 	 * unwind itself.
 	 */
 	if (max_stack - 1 > 0) {
-		addr_space = thread__priv(ui->thread);
+		WARN_ONCE(!ui->thread, "WARNING: ui->thread is NULL");
+		addr_space = ui->thread->addr_space;
+
 		if (addr_space == NULL)
 			return -1;
 
-- 
2.4.11

Re: [PATCH] perf tools: Add dedicated unwind addr_space member into thread struct

[Milian Wolff]

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

On Mittwoch, 6. April 2016 17:46:57 CEST Jiri Olsa wrote:
> On Tue, Apr 05, 2016 at 10:35:24AM +0200, Jiri Olsa wrote:
> > On Mon, Apr 04, 2016 at 11:17:11PM +0200, Milian Wolff wrote:
> > 
> > SNIP
> > 
> > >             7f688a5ef0c4 usleep (/usr/lib/libc-2.23.so)
> > >             5582244227cd main (/tmp/ex_sleep)
> > >   
> > >   1001.702 ( 0.059 ms): ex_sleep/4390 nanosleep(rqtp: 0x7ffe4d16eec0
> > > 
> > > ) = 0
> > > 
> > >                   20379e syscall_slow_exit_work ([kernel.kallsyms])
> > >                   203bc4 syscall_return_slowpath ([kernel.kallsyms])
> > >                   797248 int_ret_from_sys_call ([kernel.kallsyms])
> > >             
> > >             7f688a5c5600 __nanosleep (/usr/lib/libc-2.23.so)
> > >             7f688a5ef0c4 usleep (/usr/lib/libc-2.23.so)
> > >             5582244227d7 main (/tmp/ex_sleep)
> > > 
> > > ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
> > > 
> > > Is there a way to increase the event buffer or something like that to
> > > not lose events when the costly dwarf unwinding happens for the first
> > > time? Consecutive unwinding is cached by libunwind and much faster.
> > 
> > not sure about perf trace, but there's -m option available for perf record
> > that allows you to increase the buffer size
> > 
> > > Alternatively, I could try to unwind in the `sys_enter`, but then I'd
> > > need to buffer the output to print the trace after the duration line...
> > > 
> > > How would you guys handle this situation?
> > > 
> > > Also, Jiri, Arnaldo - what would be your suggestion on how to handle the
> > > `thread::priv` situation - I doubt my naive `priv2` approach is
> > > acceptable.
> > 
> > yea, I think one priv is more than enough ;-)
> > 
> > I think we want to move the the unwinder usage of this field into separate
> > field
> need to run test over this, but will try to post it this week
> let me know if this solution would work for you

Yes, works for me, thanks a lot!

Feel free to add

    Tested-by: Milian Wolff <milian.wolff@kdab.com>

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

Re: perf trace report with time consumed

[Milian Wolff]

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

On Dienstag, 5. April 2016 10:35:24 CEST Jiri Olsa wrote:
> On Mon, Apr 04, 2016 at 11:17:11PM +0200, Milian Wolff wrote:
> 
> SNIP
> 
> >             7f688a5ef0c4 usleep (/usr/lib/libc-2.23.so)
> >             5582244227cd main (/tmp/ex_sleep)
> >   
> >   1001.702 ( 0.059 ms): ex_sleep/4390 nanosleep(rqtp: 0x7ffe4d16eec0
> > 
> > ) = 0
> > 
> >                   20379e syscall_slow_exit_work ([kernel.kallsyms])
> >                   203bc4 syscall_return_slowpath ([kernel.kallsyms])
> >                   797248 int_ret_from_sys_call ([kernel.kallsyms])
> >             
> >             7f688a5c5600 __nanosleep (/usr/lib/libc-2.23.so)
> >             7f688a5ef0c4 usleep (/usr/lib/libc-2.23.so)
> >             5582244227d7 main (/tmp/ex_sleep)
> > 
> > ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
> > 
> > Is there a way to increase the event buffer or something like that to not
> > lose events when the costly dwarf unwinding happens for the first time?
> > Consecutive unwinding is cached by libunwind and much faster.
> 
> not sure about perf trace, but there's -m option available for perf record
> that allows you to increase the buffer size

<snip>

Yes, trace also knows the -m and even passing "-m 1M" already makes it the 
above use-case work. What is the default value? Could/Should it maybe be 
increased? 1M is not a lot of memory, sounds like a good trade-off to me?

Bye

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

Re: [PATCH] perf tools: Add dedicated unwind addr_space member into thread struct

[Arnaldo Carvalho de Melo]

Em Wed, Apr 06, 2016 at 11:15:27PM +0200, Milian Wolff escreveu:
> On Mittwoch, 6. April 2016 17:46:57 CEST Jiri Olsa wrote:
> > On Tue, Apr 05, 2016 at 10:35:24AM +0200, Jiri Olsa wrote:
> > > On Mon, Apr 04, 2016 at 11:17:11PM +0200, Milian Wolff wrote:
> > > 
> > > SNIP
> > > 
> > > >             7f688a5ef0c4 usleep (/usr/lib/libc-2.23.so)
> > > >             5582244227cd main (/tmp/ex_sleep)
> > > >   
> > > >   1001.702 ( 0.059 ms): ex_sleep/4390 nanosleep(rqtp: 0x7ffe4d16eec0
> > > > 
> > > > ) = 0
> > > > 
> > > >                   20379e syscall_slow_exit_work ([kernel.kallsyms])
> > > >                   203bc4 syscall_return_slowpath ([kernel.kallsyms])
> > > >                   797248 int_ret_from_sys_call ([kernel.kallsyms])
> > > >             
> > > >             7f688a5c5600 __nanosleep (/usr/lib/libc-2.23.so)
> > > >             7f688a5ef0c4 usleep (/usr/lib/libc-2.23.so)
> > > >             5582244227d7 main (/tmp/ex_sleep)
> > > > 
> > > > ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
> > > > 
> > > > Is there a way to increase the event buffer or something like that to
> > > > not lose events when the costly dwarf unwinding happens for the first
> > > > time? Consecutive unwinding is cached by libunwind and much faster.
> > > 
> > > not sure about perf trace, but there's -m option available for perf record
> > > that allows you to increase the buffer size
> > > 
> > > > Alternatively, I could try to unwind in the `sys_enter`, but then I'd
> > > > need to buffer the output to print the trace after the duration line...
> > > > 
> > > > How would you guys handle this situation?
> > > > 
> > > > Also, Jiri, Arnaldo - what would be your suggestion on how to handle the
> > > > `thread::priv` situation - I doubt my naive `priv2` approach is
> > > > acceptable.
> > > 
> > > yea, I think one priv is more than enough ;-)
> > > 
> > > I think we want to move the the unwinder usage of this field into separate
> > > field
> > need to run test over this, but will try to post it this week
> > let me know if this solution would work for you
> 
> Yes, works for me, thanks a lot!
> 
> Feel free to add
> 
>     Tested-by: Milian Wolff <milian.wolff@kdab.com>

Added, thanks,

- Arnaldo

Re: perf trace report with time consumed

[Arnaldo Carvalho de Melo]

Em Wed, Apr 06, 2016 at 11:16:27PM +0200, Milian Wolff escreveu:
> On Dienstag, 5. April 2016 10:35:24 CEST Jiri Olsa wrote:
> > On Mon, Apr 04, 2016 at 11:17:11PM +0200, Milian Wolff wrote:
> > > Is there a way to increase the event buffer or something like that to not
> > > lose events when the costly dwarf unwinding happens for the first time?
> > > Consecutive unwinding is cached by libunwind and much faster.

> > not sure about perf trace, but there's -m option available for perf record
> > that allows you to increase the buffer size
 
> <snip>
 
> Yes, trace also knows the -m and even passing "-m 1M" already makes it the 
> above use-case work. What is the default value? Could/Should it maybe be 
> increased? 1M is not a lot of memory, sounds like a good trade-off to me?

I think we should do that and also use some heuristic based on the
target to bump the number of mmap data pages, i.e. is it system wide?
Does it contains callchains? What is the record_size for --call-graph
dwarf?

- Arnaldo