linux/tools/perf/util/scripting-engines/trace-event-perl.c
Dima Kogan f7380c12ec 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 <acme@redhat.com>
Link: http://lkml.kernel.org/r/87mvphzld0.fsf@secretsauce.net
Signed-off-by: Dima Kogan <dima@secretsauce.net>
2016-03-30 11:14:09 -03:00

735 lines
18 KiB
C

/*
* trace-event-perl. Feed perf script events to an embedded Perl interpreter.
*
* Copyright (C) 2009 Tom Zanussi <tzanussi@gmail.com>
*
* This program is free software; you can redistribute it and/or modify
* it under the terms of the GNU General Public License as published by
* the Free Software Foundation; either version 2 of the License, or
* (at your option) any later version.
*
* This program is distributed in the hope that it will be useful,
* but WITHOUT ANY WARRANTY; without even the implied warranty of
* MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
* GNU General Public License for more details.
*
* You should have received a copy of the GNU General Public License
* along with this program; if not, write to the Free Software
* Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307 USA
*
*/
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <ctype.h>
#include <errno.h>
#include <linux/bitmap.h>
#include "../util.h"
#include <EXTERN.h>
#include <perl.h>
#include "../../perf.h"
#include "../callchain.h"
#include "../machine.h"
#include "../thread.h"
#include "../event.h"
#include "../trace-event.h"
#include "../evsel.h"
#include "../debug.h"
void boot_Perf__Trace__Context(pTHX_ CV *cv);
void boot_DynaLoader(pTHX_ CV *cv);
typedef PerlInterpreter * INTERP;
void xs_init(pTHX);
void xs_init(pTHX)
{
const char *file = __FILE__;
dXSUB_SYS;
newXS("Perf::Trace::Context::bootstrap", boot_Perf__Trace__Context,
file);
newXS("DynaLoader::boot_DynaLoader", boot_DynaLoader, file);
}
INTERP my_perl;
#define TRACE_EVENT_TYPE_MAX \
((1 << (sizeof(unsigned short) * 8)) - 1)
static DECLARE_BITMAP(events_defined, TRACE_EVENT_TYPE_MAX);
extern struct scripting_context *scripting_context;
static char *cur_field_name;
static int zero_flag_atom;
static void define_symbolic_value(const char *ev_name,
const char *field_name,
const char *field_value,
const char *field_str)
{
unsigned long long value;
dSP;
value = eval_flag(field_value);
ENTER;
SAVETMPS;
PUSHMARK(SP);
XPUSHs(sv_2mortal(newSVpv(ev_name, 0)));
XPUSHs(sv_2mortal(newSVpv(field_name, 0)));
XPUSHs(sv_2mortal(newSVuv(value)));
XPUSHs(sv_2mortal(newSVpv(field_str, 0)));
PUTBACK;
if (get_cv("main::define_symbolic_value", 0))
call_pv("main::define_symbolic_value", G_SCALAR);
SPAGAIN;
PUTBACK;
FREETMPS;
LEAVE;
}
static void define_symbolic_values(struct print_flag_sym *field,
const char *ev_name,
const char *field_name)
{
define_symbolic_value(ev_name, field_name, field->value, field->str);
if (field->next)
define_symbolic_values(field->next, ev_name, field_name);
}
static void define_symbolic_field(const char *ev_name,
const char *field_name)
{
dSP;
ENTER;
SAVETMPS;
PUSHMARK(SP);
XPUSHs(sv_2mortal(newSVpv(ev_name, 0)));
XPUSHs(sv_2mortal(newSVpv(field_name, 0)));
PUTBACK;
if (get_cv("main::define_symbolic_field", 0))
call_pv("main::define_symbolic_field", G_SCALAR);
SPAGAIN;
PUTBACK;
FREETMPS;
LEAVE;
}
static void define_flag_value(const char *ev_name,
const char *field_name,
const char *field_value,
const char *field_str)
{
unsigned long long value;
dSP;
value = eval_flag(field_value);
ENTER;
SAVETMPS;
PUSHMARK(SP);
XPUSHs(sv_2mortal(newSVpv(ev_name, 0)));
XPUSHs(sv_2mortal(newSVpv(field_name, 0)));
XPUSHs(sv_2mortal(newSVuv(value)));
XPUSHs(sv_2mortal(newSVpv(field_str, 0)));
PUTBACK;
if (get_cv("main::define_flag_value", 0))
call_pv("main::define_flag_value", G_SCALAR);
SPAGAIN;
PUTBACK;
FREETMPS;
LEAVE;
}
static void define_flag_values(struct print_flag_sym *field,
const char *ev_name,
const char *field_name)
{
define_flag_value(ev_name, field_name, field->value, field->str);
if (field->next)
define_flag_values(field->next, ev_name, field_name);
}
static void define_flag_field(const char *ev_name,
const char *field_name,
const char *delim)
{
dSP;
ENTER;
SAVETMPS;
PUSHMARK(SP);
XPUSHs(sv_2mortal(newSVpv(ev_name, 0)));
XPUSHs(sv_2mortal(newSVpv(field_name, 0)));
XPUSHs(sv_2mortal(newSVpv(delim, 0)));
PUTBACK;
if (get_cv("main::define_flag_field", 0))
call_pv("main::define_flag_field", G_SCALAR);
SPAGAIN;
PUTBACK;
FREETMPS;
LEAVE;
}
static void define_event_symbols(struct event_format *event,
const char *ev_name,
struct print_arg *args)
{
if (args == NULL)
return;
switch (args->type) {
case PRINT_NULL:
break;
case PRINT_ATOM:
define_flag_value(ev_name, cur_field_name, "0",
args->atom.atom);
zero_flag_atom = 0;
break;
case PRINT_FIELD:
free(cur_field_name);
cur_field_name = strdup(args->field.name);
break;
case PRINT_FLAGS:
define_event_symbols(event, ev_name, args->flags.field);
define_flag_field(ev_name, cur_field_name, args->flags.delim);
define_flag_values(args->flags.flags, ev_name, cur_field_name);
break;
case PRINT_SYMBOL:
define_event_symbols(event, ev_name, args->symbol.field);
define_symbolic_field(ev_name, cur_field_name);
define_symbolic_values(args->symbol.symbols, ev_name,
cur_field_name);
break;
case PRINT_HEX:
define_event_symbols(event, ev_name, args->hex.field);
define_event_symbols(event, ev_name, args->hex.size);
break;
case PRINT_INT_ARRAY:
define_event_symbols(event, ev_name, args->int_array.field);
define_event_symbols(event, ev_name, args->int_array.count);
define_event_symbols(event, ev_name, args->int_array.el_size);
break;
case PRINT_BSTRING:
case PRINT_DYNAMIC_ARRAY:
case PRINT_DYNAMIC_ARRAY_LEN:
case PRINT_STRING:
case PRINT_BITMASK:
break;
case PRINT_TYPE:
define_event_symbols(event, ev_name, args->typecast.item);
break;
case PRINT_OP:
if (strcmp(args->op.op, ":") == 0)
zero_flag_atom = 1;
define_event_symbols(event, ev_name, args->op.left);
define_event_symbols(event, ev_name, args->op.right);
break;
case PRINT_FUNC:
default:
pr_err("Unsupported print arg type\n");
/* we should warn... */
return;
}
if (args->next)
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 addr_location *al)
{
struct thread *thread = al->thread;
struct event_format *event = evsel->tp_format;
struct format_field *field;
static char handler[256];
unsigned long long val;
unsigned long s, ns;
int pid;
int cpu = sample->cpu;
void *data = sample->raw_data;
unsigned long long nsecs = sample->time;
const char *comm = thread__comm_str(thread);
dSP;
if (evsel->attr.type != PERF_TYPE_TRACEPOINT)
return;
if (!event)
die("ug! no event found for type %" PRIu64, (u64)evsel->attr.config);
pid = raw_field_value(event, "common_pid", data);
sprintf(handler, "%s::%s", event->system, event->name);
if (!test_and_set_bit(event->id, events_defined))
define_event_symbols(event, handler, event->print_fmt.args);
s = nsecs / NSECS_PER_SEC;
ns = nsecs - s * NSECS_PER_SEC;
scripting_context->event_data = data;
scripting_context->pevent = evsel->tp_format->pevent;
ENTER;
SAVETMPS;
PUSHMARK(SP);
XPUSHs(sv_2mortal(newSVpv(handler, 0)));
XPUSHs(sv_2mortal(newSViv(PTR2IV(scripting_context))));
XPUSHs(sv_2mortal(newSVuv(cpu)));
XPUSHs(sv_2mortal(newSVuv(s)));
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 */
for (field = event->format.fields; field; field = field->next) {
if (field->flags & FIELD_IS_STRING) {
int offset;
if (field->flags & FIELD_IS_DYNAMIC) {
offset = *(int *)(data + field->offset);
offset &= 0xffff;
} else
offset = field->offset;
XPUSHs(sv_2mortal(newSVpv((char *)data + offset, 0)));
} else { /* FIELD_IS_NUMERIC */
val = read_size(event, data + field->offset,
field->size);
if (field->flags & FIELD_IS_SIGNED) {
XPUSHs(sv_2mortal(newSViv(val)));
} else {
XPUSHs(sv_2mortal(newSVuv(val)));
}
}
}
PUTBACK;
if (get_cv(handler, 0))
call_pv(handler, G_SCALAR);
else if (get_cv("main::trace_unhandled", 0)) {
XPUSHs(sv_2mortal(newSVpv(handler, 0)));
XPUSHs(sv_2mortal(newSViv(PTR2IV(scripting_context))));
XPUSHs(sv_2mortal(newSVuv(cpu)));
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;
PUTBACK;
FREETMPS;
LEAVE;
}
static void perl_process_event_generic(union perf_event *event,
struct perf_sample *sample,
struct perf_evsel *evsel)
{
dSP;
if (!get_cv("process_event", 0))
return;
ENTER;
SAVETMPS;
PUSHMARK(SP);
XPUSHs(sv_2mortal(newSVpvn((const char *)event, event->header.size)));
XPUSHs(sv_2mortal(newSVpvn((const char *)&evsel->attr, sizeof(evsel->attr))));
XPUSHs(sv_2mortal(newSVpvn((const char *)sample, sizeof(*sample))));
XPUSHs(sv_2mortal(newSVpvn((const char *)sample->raw_data, sample->raw_size)));
PUTBACK;
call_pv("process_event", G_SCALAR);
SPAGAIN;
PUTBACK;
FREETMPS;
LEAVE;
}
static void perl_process_event(union perf_event *event,
struct perf_sample *sample,
struct perf_evsel *evsel,
struct addr_location *al)
{
perl_process_tracepoint(sample, evsel, al);
perl_process_event_generic(event, sample, evsel);
}
static void run_start_sub(void)
{
dSP; /* access to Perl stack */
PUSHMARK(SP);
if (get_cv("main::trace_begin", 0))
call_pv("main::trace_begin", G_DISCARD | G_NOARGS);
}
/*
* Start trace script
*/
static int perl_start_script(const char *script, int argc, const char **argv)
{
const char **command_line;
int i, err = 0;
command_line = malloc((argc + 2) * sizeof(const char *));
command_line[0] = "";
command_line[1] = script;
for (i = 2; i < argc + 2; i++)
command_line[i] = argv[i - 2];
my_perl = perl_alloc();
perl_construct(my_perl);
if (perl_parse(my_perl, xs_init, argc + 2, (char **)command_line,
(char **)NULL)) {
err = -1;
goto error;
}
if (perl_run(my_perl)) {
err = -1;
goto error;
}
if (SvTRUE(ERRSV)) {
err = -1;
goto error;
}
run_start_sub();
free(command_line);
return 0;
error:
perl_free(my_perl);
free(command_line);
return err;
}
static int perl_flush_script(void)
{
return 0;
}
/*
* Stop trace script
*/
static int perl_stop_script(void)
{
dSP; /* access to Perl stack */
PUSHMARK(SP);
if (get_cv("main::trace_end", 0))
call_pv("main::trace_end", G_DISCARD | G_NOARGS);
perl_destruct(my_perl);
perl_free(my_perl);
return 0;
}
static int perl_generate_script(struct pevent *pevent, const char *outfile)
{
struct event_format *event = NULL;
struct format_field *f;
char fname[PATH_MAX];
int not_first, count;
FILE *ofp;
sprintf(fname, "%s.pl", outfile);
ofp = fopen(fname, "w");
if (ofp == NULL) {
fprintf(stderr, "couldn't open %s\n", fname);
return -1;
}
fprintf(ofp, "# perf script event handlers, "
"generated by perf script -g perl\n");
fprintf(ofp, "# Licensed under the terms of the GNU GPL"
" License version 2\n\n");
fprintf(ofp, "# The common_* event handler fields are the most useful "
"fields common to\n");
fprintf(ofp, "# all events. They don't necessarily correspond to "
"the 'common_*' fields\n");
fprintf(ofp, "# in the format files. Those fields not available as "
"handler params can\n");
fprintf(ofp, "# be retrieved using Perl functions of the form "
"common_*($context).\n");
fprintf(ofp, "# See Context.pm for the list of available "
"functions.\n\n");
fprintf(ofp, "use lib \"$ENV{'PERF_EXEC_PATH'}/scripts/perl/"
"Perf-Trace-Util/lib\";\n");
fprintf(ofp, "use lib \"./Perf-Trace-Util/lib\";\n");
fprintf(ofp, "use Perf::Trace::Core;\n");
fprintf(ofp, "use Perf::Trace::Context;\n");
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");
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);
fprintf(ofp, "\tmy (");
fprintf(ofp, "$event_name, ");
fprintf(ofp, "$context, ");
fprintf(ofp, "$common_cpu, ");
fprintf(ofp, "$common_secs, ");
fprintf(ofp, "$common_nsecs,\n");
fprintf(ofp, "\t $common_pid, ");
fprintf(ofp, "$common_comm, ");
fprintf(ofp, "$common_callchain,\n\t ");
not_first = 0;
count = 0;
for (f = event->format.fields; f; f = f->next) {
if (not_first++)
fprintf(ofp, ", ");
if (++count % 5 == 0)
fprintf(ofp, "\n\t ");
fprintf(ofp, "$%s", f->name);
}
fprintf(ofp, ") = @_;\n\n");
fprintf(ofp, "\tprint_header($event_name, $common_cpu, "
"$common_secs, $common_nsecs,\n\t "
"$common_pid, $common_comm, $common_callchain);\n\n");
fprintf(ofp, "\tprintf(\"");
not_first = 0;
count = 0;
for (f = event->format.fields; f; f = f->next) {
if (not_first++)
fprintf(ofp, ", ");
if (count && count % 4 == 0) {
fprintf(ofp, "\".\n\t \"");
}
count++;
fprintf(ofp, "%s=", f->name);
if (f->flags & FIELD_IS_STRING ||
f->flags & FIELD_IS_FLAG ||
f->flags & FIELD_IS_SYMBOLIC)
fprintf(ofp, "%%s");
else if (f->flags & FIELD_IS_SIGNED)
fprintf(ofp, "%%d");
else
fprintf(ofp, "%%u");
}
fprintf(ofp, "\\n\",\n\t ");
not_first = 0;
count = 0;
for (f = event->format.fields; f; f = f->next) {
if (not_first++)
fprintf(ofp, ", ");
if (++count % 5 == 0)
fprintf(ofp, "\n\t ");
if (f->flags & FIELD_IS_FLAG) {
if ((count - 1) % 5 != 0) {
fprintf(ofp, "\n\t ");
count = 4;
}
fprintf(ofp, "flag_str(\"");
fprintf(ofp, "%s::%s\", ", event->system,
event->name);
fprintf(ofp, "\"%s\", $%s)", f->name,
f->name);
} else if (f->flags & FIELD_IS_SYMBOLIC) {
if ((count - 1) % 5 != 0) {
fprintf(ofp, "\n\t ");
count = 4;
}
fprintf(ofp, "symbol_str(\"");
fprintf(ofp, "%s::%s\", ", event->system,
event->name);
fprintf(ofp, "\"%s\", $%s)", f->name,
f->name);
} else
fprintf(ofp, "$%s", f->name);
}
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, $common_callchain) = @_;\n\n");
fprintf(ofp, "\tprint_header($event_name, $common_cpu, "
"$common_secs, $common_nsecs,\n\t $common_pid, "
"$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"
"\tprintf(\"%%-20s %%5u %%05u.%%09u %%8u %%-20s \",\n\t "
"$event_name, $cpu, $secs, $nsecs, $pid, $comm);\n}\n");
fprintf(ofp,
"\n# Packed byte string args of process_event():\n"
"#\n"
"# $event:\tunion perf_event\tutil/event.h\n"
"# $attr:\tstruct perf_event_attr\tlinux/perf_event.h\n"
"# $sample:\tstruct perf_sample\tutil/event.h\n"
"# $raw_data:\tperf_sample->raw_data\tutil/event.h\n"
"\n"
"sub process_event\n"
"{\n"
"\tmy ($event, $attr, $sample, $raw_data) = @_;\n"
"\n"
"\tmy @event\t= unpack(\"LSS\", $event);\n"
"\tmy @attr\t= unpack(\"LLQQQQQLLQQ\", $attr);\n"
"\tmy @sample\t= unpack(\"QLLQQQQQLL\", $sample);\n"
"\tmy @raw_data\t= unpack(\"C*\", $raw_data);\n"
"\n"
"\tuse Data::Dumper;\n"
"\tprint Dumper \\@event, \\@attr, \\@sample, \\@raw_data;\n"
"}\n");
fclose(ofp);
fprintf(stderr, "generated Perl script: %s\n", fname);
return 0;
}
struct scripting_ops perl_scripting_ops = {
.name = "Perl",
.start_script = perl_start_script,
.flush_script = perl_flush_script,
.stop_script = perl_stop_script,
.process_event = perl_process_event,
.generate_script = perl_generate_script,
};