From f7380c12ec6cfd69f274ba6181cd01c764f877bb Mon Sep 17 00:00:00 2001 From: Dima Kogan Date: Tue, 29 Mar 2016 12:47:53 -0300 Subject: perf script perl: Perl scripts now get a backtrace, like the python ones We have some infrastructure to use perl or python to analyze logs generated by perf. Prior to this patch, only the python tools had access to backtrace information. This patch makes this information available to perl scripts as well. Example: Let's look at malloc() calls made by the seq utility. First we create a probe point: $ perf probe -x /lib/x86_64-linux-gnu/libc.so.6 malloc Added new events: ... Now we run seq, while monitoring malloc() calls with perf $ perf record --call-graph=dwarf -e probe_libc:malloc seq 5 1 2 3 4 5 [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 0.064 MB perf.data (6 samples) ] We can use perf to look at its log to see the malloc calls and the backtrace $ perf script seq 14195 [000] 1927993.748254: probe_libc:malloc: (7f9ff8edd320) bytes=0x22 7f9ff8edd320 malloc (/lib/x86_64-linux-gnu/libc-2.22.so) 7f9ff8e8eab0 set_binding_values.part.0 (/lib/x86_64-linux-gnu/libc-2.22.so) 7f9ff8e8eda1 __bindtextdomain (/lib/x86_64-linux-gnu/libc-2.22.so) 401b22 main (/usr/bin/seq) 7f9ff8e82610 __libc_start_main (/lib/x86_64-linux-gnu/libc-2.22.so) 402799 _start (/usr/bin/seq) ... We can also use the scripting facilities. We create a skeleton perl script that simply prints out the events $ perf script -g perl generated Perl script: perf-script.pl We can then use this script to see the malloc() calls with a backtrace. Prior to this patch, the backtrace was not available to the perl scripts. $ perf script -s perf-script.pl probe_libc::malloc 0 1927993.748254260 14195 seq __probe_ip=140325052863264, bytes=34 [7f9ff8edd320] malloc [7f9ff8e8eab0] set_binding_values.part.0 [7f9ff8e8eda1] __bindtextdomain [401b22] main [7f9ff8e82610] __libc_start_main [402799] _start ... Tested-by: Arnaldo Carvalho de Melo Link: http://lkml.kernel.org/r/87mvphzld0.fsf@secretsauce.net Signed-off-by: Dima Kogan --- .../perf/util/scripting-engines/trace-event-perl.c | 114 +++++++++++++++++++-- 1 file changed, 106 insertions(+), 8 deletions(-) (limited to 'tools/perf/util/scripting-engines/trace-event-perl.c') diff --git a/tools/perf/util/scripting-engines/trace-event-perl.c b/tools/perf/util/scripting-engines/trace-event-perl.c index b3aabc0d4eb0..1d160855cda9 100644 --- a/tools/perf/util/scripting-engines/trace-event-perl.c +++ b/tools/perf/util/scripting-engines/trace-event-perl.c @@ -31,6 +31,8 @@ #include #include "../../perf.h" +#include "../callchain.h" +#include "../machine.h" #include "../thread.h" #include "../event.h" #include "../trace-event.h" @@ -248,10 +250,78 @@ static void define_event_symbols(struct event_format *event, define_event_symbols(event, ev_name, args->next); } +static SV *perl_process_callchain(struct perf_sample *sample, + struct perf_evsel *evsel, + struct addr_location *al) +{ + AV *list; + + list = newAV(); + if (!list) + goto exit; + + if (!symbol_conf.use_callchain || !sample->callchain) + goto exit; + + if (thread__resolve_callchain(al->thread, evsel, + sample, NULL, NULL, + PERF_MAX_STACK_DEPTH) != 0) { + pr_err("Failed to resolve callchain. Skipping\n"); + goto exit; + } + callchain_cursor_commit(&callchain_cursor); + + + while (1) { + HV *elem; + struct callchain_cursor_node *node; + node = callchain_cursor_current(&callchain_cursor); + if (!node) + break; + + elem = newHV(); + if (!elem) + goto exit; + + hv_stores(elem, "ip", newSVuv(node->ip)); + + if (node->sym) { + HV *sym = newHV(); + if (!sym) + goto exit; + hv_stores(sym, "start", newSVuv(node->sym->start)); + hv_stores(sym, "end", newSVuv(node->sym->end)); + hv_stores(sym, "binding", newSVuv(node->sym->binding)); + hv_stores(sym, "name", newSVpvn(node->sym->name, + node->sym->namelen)); + hv_stores(elem, "sym", newRV_noinc((SV*)sym)); + } + + if (node->map) { + struct map *map = node->map; + const char *dsoname = "[unknown]"; + if (map && map->dso && (map->dso->name || map->dso->long_name)) { + if (symbol_conf.show_kernel_path && map->dso->long_name) + dsoname = map->dso->long_name; + else if (map->dso->name) + dsoname = map->dso->name; + } + hv_stores(elem, "dso", newSVpv(dsoname,0)); + } + + callchain_cursor_advance(&callchain_cursor); + av_push(list, newRV_noinc((SV*)elem)); + } + +exit: + return newRV_noinc((SV*)list); +} + static void perl_process_tracepoint(struct perf_sample *sample, struct perf_evsel *evsel, - struct thread *thread) + struct addr_location *al) { + struct thread *thread = al->thread; struct event_format *event = evsel->tp_format; struct format_field *field; static char handler[256]; @@ -295,6 +365,7 @@ static void perl_process_tracepoint(struct perf_sample *sample, XPUSHs(sv_2mortal(newSVuv(ns))); XPUSHs(sv_2mortal(newSViv(pid))); XPUSHs(sv_2mortal(newSVpv(comm, 0))); + XPUSHs(sv_2mortal(perl_process_callchain(sample, evsel, al))); /* common fields other than pid can be accessed via xsub fns */ @@ -329,6 +400,7 @@ static void perl_process_tracepoint(struct perf_sample *sample, XPUSHs(sv_2mortal(newSVuv(nsecs))); XPUSHs(sv_2mortal(newSViv(pid))); XPUSHs(sv_2mortal(newSVpv(comm, 0))); + XPUSHs(sv_2mortal(perl_process_callchain(sample, evsel, al))); call_pv("main::trace_unhandled", G_SCALAR); } SPAGAIN; @@ -366,7 +438,7 @@ static void perl_process_event(union perf_event *event, struct perf_evsel *evsel, struct addr_location *al) { - perl_process_tracepoint(sample, evsel, al->thread); + perl_process_tracepoint(sample, evsel, al); perl_process_event_generic(event, sample, evsel); } @@ -490,7 +562,27 @@ static int perl_generate_script(struct pevent *pevent, const char *outfile) fprintf(ofp, "use Perf::Trace::Util;\n\n"); fprintf(ofp, "sub trace_begin\n{\n\t# optional\n}\n\n"); - fprintf(ofp, "sub trace_end\n{\n\t# optional\n}\n\n"); + fprintf(ofp, "sub trace_end\n{\n\t# optional\n}\n"); + + + fprintf(ofp, "\n\ +sub print_backtrace\n\ +{\n\ + my $callchain = shift;\n\ + for my $node (@$callchain)\n\ + {\n\ + if(exists $node->{sym})\n\ + {\n\ + printf( \"\\t[\\%%x] \\%%s\\n\", $node->{ip}, $node->{sym}{name});\n\ + }\n\ + else\n\ + {\n\ + printf( \"\\t[\\%%x]\\n\", $node{ip});\n\ + }\n\ + }\n\ +}\n\n\ +"); + while ((event = trace_find_next_event(pevent, event))) { fprintf(ofp, "sub %s::%s\n{\n", event->system, event->name); @@ -502,7 +594,8 @@ static int perl_generate_script(struct pevent *pevent, const char *outfile) fprintf(ofp, "$common_secs, "); fprintf(ofp, "$common_nsecs,\n"); fprintf(ofp, "\t $common_pid, "); - fprintf(ofp, "$common_comm,\n\t "); + fprintf(ofp, "$common_comm, "); + fprintf(ofp, "$common_callchain,\n\t "); not_first = 0; count = 0; @@ -519,7 +612,7 @@ static int perl_generate_script(struct pevent *pevent, const char *outfile) fprintf(ofp, "\tprint_header($event_name, $common_cpu, " "$common_secs, $common_nsecs,\n\t " - "$common_pid, $common_comm);\n\n"); + "$common_pid, $common_comm, $common_callchain);\n\n"); fprintf(ofp, "\tprintf(\""); @@ -581,17 +674,22 @@ static int perl_generate_script(struct pevent *pevent, const char *outfile) fprintf(ofp, "$%s", f->name); } - fprintf(ofp, ");\n"); + fprintf(ofp, ");\n\n"); + + fprintf(ofp, "\tprint_backtrace($common_callchain);\n"); + fprintf(ofp, "}\n\n"); } fprintf(ofp, "sub trace_unhandled\n{\n\tmy ($event_name, $context, " "$common_cpu, $common_secs, $common_nsecs,\n\t " - "$common_pid, $common_comm) = @_;\n\n"); + "$common_pid, $common_comm, $common_callchain) = @_;\n\n"); fprintf(ofp, "\tprint_header($event_name, $common_cpu, " "$common_secs, $common_nsecs,\n\t $common_pid, " - "$common_comm);\n}\n\n"); + "$common_comm, $common_callchain);\n"); + fprintf(ofp, "\tprint_backtrace($common_callchain);\n"); + fprintf(ofp, "}\n\n"); fprintf(ofp, "sub print_header\n{\n" "\tmy ($event_name, $cpu, $secs, $nsecs, $pid, $comm) = @_;\n\n" -- cgit v1.2.3 From 76e20522b709f3772e415d70b108028454a86ad5 Mon Sep 17 00:00:00 2001 From: Arnaldo Carvalho de Melo Date: Tue, 5 Apr 2016 12:21:44 -0300 Subject: perf script perl: Do error checking on new backtrace routine This ended up triggering these warnings when building on Ubuntu 12.04.5: util/scripting-engines/trace-event-perl.c: In function 'perl_process_callchain': util/scripting-engines/trace-event-perl.c:293:4: error: value computed is not used [-Werror=unused-value] util/scripting-engines/trace-event-perl.c:294:4: error: value computed is not used [-Werror=unused-value] util/scripting-engines/trace-event-perl.c:295:4: error: value computed is not used [-Werror=unused-value] util/scripting-engines/trace-event-perl.c:297:4: error: value computed is not used [-Werror=unused-value] util/scripting-engines/trace-event-perl.c:309:4: error: value computed is not used [-Werror=unused-value] cc1: all warnings being treated as errors mv: cannot stat `/tmp/build/perf/util/scripting-engines/.trace-event-perl.o.tmp': No such file or directory make[4]: *** [/tmp/build/perf/util/scripting-engines/trace-event-perl.o] Error 1 Fix it by doing error checking when building the perl data structures related to callchains. Cc: Adrian Hunter Cc: David Ahern Cc: Dima Kogan Cc: Frederic Weisbecker Cc: Jiri Olsa Cc: Namhyung Kim Fixes: f7380c12ec6c ("perf script perl: Perl scripts now get a backtrace, like the python ones") Signed-off-by: Arnaldo Carvalho de Melo --- .../perf/util/scripting-engines/trace-event-perl.c | 30 +++++++++++++++------- 1 file changed, 21 insertions(+), 9 deletions(-) (limited to 'tools/perf/util/scripting-engines/trace-event-perl.c') diff --git a/tools/perf/util/scripting-engines/trace-event-perl.c b/tools/perf/util/scripting-engines/trace-event-perl.c index 1d160855cda9..35ed00a600fb 100644 --- a/tools/perf/util/scripting-engines/trace-event-perl.c +++ b/tools/perf/util/scripting-engines/trace-event-perl.c @@ -283,18 +283,27 @@ static SV *perl_process_callchain(struct perf_sample *sample, if (!elem) goto exit; - hv_stores(elem, "ip", newSVuv(node->ip)); + if (!hv_stores(elem, "ip", newSVuv(node->ip))) { + hv_undef(elem); + goto exit; + } if (node->sym) { HV *sym = newHV(); - if (!sym) + if (!sym) { + hv_undef(elem); + goto exit; + } + if (!hv_stores(sym, "start", newSVuv(node->sym->start)) || + !hv_stores(sym, "end", newSVuv(node->sym->end)) || + !hv_stores(sym, "binding", newSVuv(node->sym->binding)) || + !hv_stores(sym, "name", newSVpvn(node->sym->name, + node->sym->namelen)) || + !hv_stores(elem, "sym", newRV_noinc((SV*)sym))) { + hv_undef(sym); + hv_undef(elem); goto exit; - hv_stores(sym, "start", newSVuv(node->sym->start)); - hv_stores(sym, "end", newSVuv(node->sym->end)); - hv_stores(sym, "binding", newSVuv(node->sym->binding)); - hv_stores(sym, "name", newSVpvn(node->sym->name, - node->sym->namelen)); - hv_stores(elem, "sym", newRV_noinc((SV*)sym)); + } } if (node->map) { @@ -306,7 +315,10 @@ static SV *perl_process_callchain(struct perf_sample *sample, else if (map->dso->name) dsoname = map->dso->name; } - hv_stores(elem, "dso", newSVpv(dsoname,0)); + if (!hv_stores(elem, "dso", newSVpv(dsoname,0))) { + hv_undef(elem); + goto exit; + } } callchain_cursor_advance(&callchain_cursor); -- cgit v1.2.3 From 91d7b2de318ff701451dfc7ede1c029b150ef0e9 Mon Sep 17 00:00:00 2001 From: Arnaldo Carvalho de Melo Date: Thu, 14 Apr 2016 14:48:07 -0300 Subject: perf callchain: Start moving away from global per thread cursors The recent perf_evsel__fprintf_callchain() move to evsel.c added several new symbol requirements to the python binding, for instance: # perf test -v python 16: Try 'import perf' in python, checking link problems : --- start --- test child forked, pid 18030 Traceback (most recent call last): File "", line 1, in ImportError: /tmp/build/perf/python/perf.so: undefined symbol: callchain_cursor test child finished with -1 ---- end ---- Try 'import perf' in python, checking link problems: FAILED! # This would require linking against callchain.c to access to the global callchain_cursor variables. Since lots of functions already receive as a parameter a callchain_cursor struct pointer, make that be the case for some more function so that we can start phasing out usage of yet another global variable. Cc: Adrian Hunter Cc: David Ahern Cc: Frederic Weisbecker Cc: Jiri Olsa Cc: Namhyung Kim Cc: Wang Nan Link: http://lkml.kernel.org/n/tip-djko3097eyg2rn66v2qcqfvn@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/util/scripting-engines/trace-event-perl.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) (limited to 'tools/perf/util/scripting-engines/trace-event-perl.c') diff --git a/tools/perf/util/scripting-engines/trace-event-perl.c b/tools/perf/util/scripting-engines/trace-event-perl.c index 35ed00a600fb..ae1cebc307c5 100644 --- a/tools/perf/util/scripting-engines/trace-event-perl.c +++ b/tools/perf/util/scripting-engines/trace-event-perl.c @@ -263,7 +263,7 @@ static SV *perl_process_callchain(struct perf_sample *sample, if (!symbol_conf.use_callchain || !sample->callchain) goto exit; - if (thread__resolve_callchain(al->thread, evsel, + if (thread__resolve_callchain(al->thread, &callchain_cursor, evsel, sample, NULL, NULL, PERF_MAX_STACK_DEPTH) != 0) { pr_err("Failed to resolve callchain. Skipping\n"); -- cgit v1.2.3 From 4cb93446c587d56e2a54f4f83113daba2c0b6dee Mon Sep 17 00:00:00 2001 From: Arnaldo Carvalho de Melo Date: Wed, 27 Apr 2016 10:16:24 -0300 Subject: perf tools: Set the maximum allowed stack from /proc/sys/kernel/perf_event_max_stack There is an upper limit to what tooling considers a valid callchain, and it was tied to the hardcoded value in the kernel, PERF_MAX_STACK_DEPTH (127), now that this can be tuned via a sysctl, make it read it and use that as the upper limit, falling back to PERF_MAX_STACK_DEPTH for kernels where this sysctl isn't present. Cc: Adrian Hunter Cc: Brendan Gregg Cc: David Ahern Cc: Frederic Weisbecker Cc: Jiri Olsa Cc: Milian Wolff Cc: Namhyung Kim Cc: Wang Nan Link: http://lkml.kernel.org/n/tip-yjqsd30nnkogvj5oyx9ghir9@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/util/scripting-engines/trace-event-perl.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) (limited to 'tools/perf/util/scripting-engines/trace-event-perl.c') diff --git a/tools/perf/util/scripting-engines/trace-event-perl.c b/tools/perf/util/scripting-engines/trace-event-perl.c index ae1cebc307c5..62c7f6988e0e 100644 --- a/tools/perf/util/scripting-engines/trace-event-perl.c +++ b/tools/perf/util/scripting-engines/trace-event-perl.c @@ -265,7 +265,7 @@ static SV *perl_process_callchain(struct perf_sample *sample, if (thread__resolve_callchain(al->thread, &callchain_cursor, evsel, sample, NULL, NULL, - PERF_MAX_STACK_DEPTH) != 0) { + sysctl_perf_event_max_stack) != 0) { pr_err("Failed to resolve callchain. Skipping\n"); goto exit; } -- cgit v1.2.3