* perf trace report with time consumed @ 2016-03-29 20:39 Milian Wolff 2016-03-30 14:53 ` Arnaldo Carvalho de Melo 0 siblings, 1 reply; 16+ messages in thread From: Milian Wolff @ 2016-03-29 20:39 UTC (permalink / raw) To: perf group [-- 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 --] ^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: perf trace report with time consumed 2016-03-29 20:39 perf trace report with time consumed Milian Wolff @ 2016-03-30 14:53 ` Arnaldo Carvalho de Melo 2016-03-30 21:24 ` Milian Wolff 0 siblings, 1 reply; 16+ messages in thread From: Arnaldo Carvalho de Melo @ 2016-03-30 14:53 UTC (permalink / raw) To: Milian Wolff; +Cc: perf group 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 ^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: perf trace report with time consumed 2016-03-30 14:53 ` Arnaldo Carvalho de Melo @ 2016-03-30 21:24 ` Milian Wolff 2016-03-30 21:58 ` Arnaldo Carvalho de Melo 0 siblings, 1 reply; 16+ messages in thread From: Milian Wolff @ 2016-03-30 21:24 UTC (permalink / raw) To: Arnaldo Carvalho de Melo; +Cc: perf group [-- 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 --] ^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: perf trace report with time consumed 2016-03-30 21:24 ` Milian Wolff @ 2016-03-30 21:58 ` Arnaldo Carvalho de Melo 2016-03-31 22:34 ` Milian Wolff 0 siblings, 1 reply; 16+ messages in thread From: Arnaldo Carvalho de Melo @ 2016-03-30 21:58 UTC (permalink / raw) To: Milian Wolff; +Cc: perf group 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 ^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: perf trace report with time consumed 2016-03-30 21:58 ` Arnaldo Carvalho de Melo @ 2016-03-31 22:34 ` Milian Wolff 2016-04-01 13:01 ` Arnaldo Carvalho de Melo 2016-04-03 18:46 ` Milian Wolff 0 siblings, 2 replies; 16+ messages in thread From: Milian Wolff @ 2016-03-31 22:34 UTC (permalink / raw) To: Arnaldo Carvalho de Melo; +Cc: perf group [-- 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 --] ^ permalink raw reply related [flat|nested] 16+ messages in thread
* Re: perf trace report with time consumed 2016-03-31 22:34 ` Milian Wolff @ 2016-04-01 13:01 ` Arnaldo Carvalho de Melo 2016-04-03 16:30 ` Jiri Olsa 2016-04-03 18:46 ` Milian Wolff 1 sibling, 1 reply; 16+ messages in thread From: Arnaldo Carvalho de Melo @ 2016-04-01 13:01 UTC (permalink / raw) To: Milian Wolff; +Cc: Jiri Olsa, perf group 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 ^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: perf trace report with time consumed 2016-04-01 13:01 ` Arnaldo Carvalho de Melo @ 2016-04-03 16:30 ` Jiri Olsa 0 siblings, 0 replies; 16+ messages in thread From: Jiri Olsa @ 2016-04-03 16:30 UTC (permalink / raw) To: Arnaldo Carvalho de Melo; +Cc: Milian Wolff, Jiri Olsa, perf group 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 ^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: perf trace report with time consumed 2016-03-31 22:34 ` Milian Wolff 2016-04-01 13:01 ` Arnaldo Carvalho de Melo @ 2016-04-03 18:46 ` Milian Wolff 2016-04-04 6:14 ` Jiri Olsa 1 sibling, 1 reply; 16+ messages in thread From: Milian Wolff @ 2016-04-03 18:46 UTC (permalink / raw) To: Arnaldo Carvalho de Melo; +Cc: perf group, Jiri Olsa [-- 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 --] ^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: perf trace report with time consumed 2016-04-03 18:46 ` Milian Wolff @ 2016-04-04 6:14 ` Jiri Olsa 2016-04-04 21:17 ` Milian Wolff 0 siblings, 1 reply; 16+ messages in thread From: Jiri Olsa @ 2016-04-04 6:14 UTC (permalink / raw) To: Milian Wolff; +Cc: Arnaldo Carvalho de Melo, perf group 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 ^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: perf trace report with time consumed 2016-04-04 6:14 ` Jiri Olsa @ 2016-04-04 21:17 ` Milian Wolff 2016-04-05 8:35 ` Jiri Olsa 0 siblings, 1 reply; 16+ messages in thread From: Milian Wolff @ 2016-04-04 21:17 UTC (permalink / raw) To: Jiri Olsa; +Cc: Arnaldo Carvalho de Melo, perf group [-- 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 --] ^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: perf trace report with time consumed 2016-04-04 21:17 ` Milian Wolff @ 2016-04-05 8:35 ` Jiri Olsa 2016-04-06 15:46 ` [PATCH] perf tools: Add dedicated unwind addr_space member into thread struct Jiri Olsa 2016-04-06 21:16 ` perf trace report with time consumed Milian Wolff 0 siblings, 2 replies; 16+ messages in thread From: Jiri Olsa @ 2016-04-05 8:35 UTC (permalink / raw) To: Milian Wolff; +Cc: Arnaldo Carvalho de Melo, perf group 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 ^ permalink raw reply [flat|nested] 16+ messages in thread
* [PATCH] perf tools: Add dedicated unwind addr_space member into thread struct 2016-04-05 8:35 ` Jiri Olsa @ 2016-04-06 15:46 ` Jiri Olsa 2016-04-06 21:15 ` Milian Wolff 2016-04-06 21:16 ` perf trace report with time consumed Milian Wolff 1 sibling, 1 reply; 16+ messages in thread From: Jiri Olsa @ 2016-04-06 15:46 UTC (permalink / raw) To: Milian Wolff; +Cc: Arnaldo Carvalho de Melo, perf group 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 ^ permalink raw reply related [flat|nested] 16+ messages in thread
* Re: [PATCH] perf tools: Add dedicated unwind addr_space member into thread struct 2016-04-06 15:46 ` [PATCH] perf tools: Add dedicated unwind addr_space member into thread struct Jiri Olsa @ 2016-04-06 21:15 ` Milian Wolff 2016-04-08 12:58 ` Arnaldo Carvalho de Melo 0 siblings, 1 reply; 16+ messages in thread From: Milian Wolff @ 2016-04-06 21:15 UTC (permalink / raw) To: Jiri Olsa; +Cc: Arnaldo Carvalho de Melo, perf group [-- 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 --] ^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: [PATCH] perf tools: Add dedicated unwind addr_space member into thread struct 2016-04-06 21:15 ` Milian Wolff @ 2016-04-08 12:58 ` Arnaldo Carvalho de Melo 0 siblings, 0 replies; 16+ messages in thread From: Arnaldo Carvalho de Melo @ 2016-04-08 12:58 UTC (permalink / raw) To: Milian Wolff; +Cc: Jiri Olsa, perf group 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 ^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: perf trace report with time consumed 2016-04-05 8:35 ` Jiri Olsa 2016-04-06 15:46 ` [PATCH] perf tools: Add dedicated unwind addr_space member into thread struct Jiri Olsa @ 2016-04-06 21:16 ` Milian Wolff 2016-04-08 13:01 ` Arnaldo Carvalho de Melo 1 sibling, 1 reply; 16+ messages in thread From: Milian Wolff @ 2016-04-06 21:16 UTC (permalink / raw) To: Jiri Olsa; +Cc: Arnaldo Carvalho de Melo, perf group [-- 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 --] ^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: perf trace report with time consumed 2016-04-06 21:16 ` perf trace report with time consumed Milian Wolff @ 2016-04-08 13:01 ` Arnaldo Carvalho de Melo 0 siblings, 0 replies; 16+ messages in thread From: Arnaldo Carvalho de Melo @ 2016-04-08 13:01 UTC (permalink / raw) To: Milian Wolff; +Cc: Jiri Olsa, perf group 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 ^ permalink raw reply [flat|nested] 16+ messages in thread
end of thread, other threads:[~2016-04-08 13:01 UTC | newest] Thread overview: 16+ messages (download: mbox.gz follow: Atom feed -- links below jump to the message on this page -- 2016-03-29 20:39 perf trace report with time consumed Milian Wolff 2016-03-30 14:53 ` Arnaldo Carvalho de Melo 2016-03-30 21:24 ` Milian Wolff 2016-03-30 21:58 ` Arnaldo Carvalho de Melo 2016-03-31 22:34 ` Milian Wolff 2016-04-01 13:01 ` Arnaldo Carvalho de Melo 2016-04-03 16:30 ` Jiri Olsa 2016-04-03 18:46 ` Milian Wolff 2016-04-04 6:14 ` Jiri Olsa 2016-04-04 21:17 ` Milian Wolff 2016-04-05 8:35 ` Jiri Olsa 2016-04-06 15:46 ` [PATCH] perf tools: Add dedicated unwind addr_space member into thread struct Jiri Olsa 2016-04-06 21:15 ` Milian Wolff 2016-04-08 12:58 ` Arnaldo Carvalho de Melo 2016-04-06 21:16 ` perf trace report with time consumed Milian Wolff 2016-04-08 13:01 ` Arnaldo Carvalho de Melo
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).