[RFC PATCH 0/2] libtraceevent/perf: Add support for trace-cmd plugins

[RFC PATCH 0/2] libtraceevent/perf: Add support for trace-cmd plugins

[David Ahern]

Now that perf is using libtraceevent and libtraceevent is based
on trace-cmd both can be extended to leverage the plugins written
for trace-cmd to improve pretty printing of the events.

Given that it is based on code from trace-cmd I am not sure what the
right approach is, so wanted to throw this out for comments/suggestions.

David Ahern (2):
  libtraceevent: Add support for tracecmd plugins
  perf: add support for trace-cmd plugins

 tools/lib/traceevent/Makefile           |    2 +-
 tools/lib/traceevent/tracecmd-plugins.c |  280 +++++++++++++++++++++++++++++++
 tools/lib/traceevent/tracecmd-plugins.h |   34 ++++
 tools/perf/util/trace-event-parse.c     |    4 +
 4 files changed, 319 insertions(+), 1 deletion(-)
 create mode 100644 tools/lib/traceevent/tracecmd-plugins.c
 create mode 100644 tools/lib/traceevent/tracecmd-plugins.h

-- 
1.7.10.1

[RFC PATCH 1/2] libtraceevent: Add support for tracecmd plugins

[David Ahern]

Plugin code pulled from trace-cmd repository as of 9a5cd1c1,
cherry-picked the plugin loading functions from trace-util.c
and declarations in trace-cmd.h

Signed-off-by: David Ahern <dsahern@gmail.com>
---
 tools/lib/traceevent/Makefile           |    2 +-
 tools/lib/traceevent/tracecmd-plugins.c |  280 +++++++++++++++++++++++++++++++
 tools/lib/traceevent/tracecmd-plugins.h |   34 ++++
 3 files changed, 315 insertions(+), 1 deletion(-)
 create mode 100644 tools/lib/traceevent/tracecmd-plugins.c
 create mode 100644 tools/lib/traceevent/tracecmd-plugins.h

diff --git a/tools/lib/traceevent/Makefile b/tools/lib/traceevent/Makefile
index 3d69aa9..b1833ff 100644
--- a/tools/lib/traceevent/Makefile
+++ b/tools/lib/traceevent/Makefile
@@ -188,7 +188,7 @@ $(obj)/%.o: $(src)/%.c
 %.o: $(src)/%.c
 	$(Q)$(call do_compile)
 
-PEVENT_LIB_OBJS = event-parse.o trace-seq.o parse-filter.o parse-utils.o
+PEVENT_LIB_OBJS = event-parse.o trace-seq.o parse-filter.o parse-utils.o tracecmd-plugins.o
 
 ALL_OBJS = $(PEVENT_LIB_OBJS)
 
diff --git a/tools/lib/traceevent/tracecmd-plugins.c b/tools/lib/traceevent/tracecmd-plugins.c
new file mode 100644
index 0000000..24b004a
--- /dev/null
+++ b/tools/lib/traceevent/tracecmd-plugins.c
@@ -0,0 +1,280 @@
+/*
+ * Copyright (C) 2009, 2010 Red Hat Inc, Steven Rostedt <srostedt@redhat.com>
+ *
+ * ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
+ * This program is free software; you can redistribute it and/or
+ * modify it under the terms of the GNU Lesser General Public
+ * License as published by the Free Software Foundation;
+ * version 2.1 of the License (not later!)
+ *
+ * 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 Lesser General Public License for more details.
+ *
+ * You should have received a copy of the GNU Lesser General Public
+ * License along with this program; if not, write to the Free Software
+ * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
+ *
+ * ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
+ */
+#define _GNU_SOURCE
+#include <stdio.h>
+#include <stdlib.h>
+#include <string.h>
+#include <dirent.h>
+#include <ctype.h>
+#include <errno.h>
+#include <dlfcn.h>
+#include <fcntl.h>
+#include <unistd.h>
+#include <sys/mount.h>
+#include <sys/types.h>
+#include <sys/stat.h>
+
+#include "tracecmd-plugins.h"
+
+#define LOCAL_PLUGIN_DIR ".trace-cmd/plugins"
+
+int tracecmd_disable_sys_plugins;
+int tracecmd_disable_plugins;
+
+
+static struct trace_plugin_options {
+	struct trace_plugin_options	*next;
+	char				*plugin;
+	char				*option;
+	char				*value;
+} *trace_plugin_options;
+
+#define _STR(x) #x
+#define STR(x) _STR(x)
+
+#ifndef MAX_PATH
+# define MAX_PATH 1024
+#endif
+
+static struct plugin_list {
+	struct plugin_list	*next;
+	char			*name;
+	void			*handle;
+};
+
+static void update_option(const char *file, struct plugin_option *option)
+{
+	struct trace_plugin_options *op;
+	char *plugin;
+
+	if (option->plugin_alias) {
+		plugin = strdup(option->plugin_alias);
+		if (!plugin)
+			die("malloc");
+	} else {
+		char *p;
+		plugin = strdup(file);
+		if (!plugin)
+			die("malloc");
+		p = strstr(plugin, ".");
+		if (p)
+			*p = '\0';
+	}
+
+	/* first look for named options */
+	for (op = trace_plugin_options; op; op = op->next) {
+		if (!op->plugin)
+			continue;
+		if (strcmp(op->plugin, plugin) != 0)
+			continue;
+		if (strcmp(op->option, option->name) != 0)
+			continue;
+
+		option->value = op->value;
+		option->set = 1;
+		goto out;
+	}
+
+	/* first look for unnamed options */
+	for (op = trace_plugin_options; op; op = op->next) {
+		if (op->plugin)
+			continue;
+		if (strcmp(op->option, option->name) != 0)
+			continue;
+
+		option->value = op->value;
+		option->set = 1;
+		break;
+	}
+
+ out:
+	free(plugin);
+}
+
+static void load_plugin(struct pevent *pevent, const char *path,
+			const char *file, void *data)
+{
+	struct plugin_list **plugin_list = data;
+	pevent_plugin_load_func func;
+	struct plugin_list *list;
+	struct plugin_option *options;
+	const char *alias;
+	char *plugin;
+	void *handle;
+
+	plugin = malloc_or_die(strlen(path) + strlen(file) + 2);
+
+	strcpy(plugin, path);
+	strcat(plugin, "/");
+	strcat(plugin, file);
+
+	handle = dlopen(plugin, RTLD_NOW | RTLD_GLOBAL);
+	if (!handle) {
+		warning("cound not load plugin '%s'\n%s\n",
+			plugin, dlerror());
+		goto out_free;
+	}
+
+	alias = dlsym(handle, PEVENT_PLUGIN_ALIAS_NAME);
+	if (!alias)
+		alias = file;
+
+	options = dlsym(handle, PEVENT_PLUGIN_OPTIONS_NAME);
+	if (options) {
+		while (options->name) {
+			update_option(alias, options);
+			options++;
+		}
+	}
+
+	func = dlsym(handle, PEVENT_PLUGIN_LOADER_NAME);
+	if (!func) {
+		warning("cound not find func '%s' in plugin '%s'\n%s\n",
+			PEVENT_PLUGIN_LOADER_NAME, plugin, dlerror());
+		goto out_free;
+	}
+
+	list = malloc_or_die(sizeof(*list));
+	list->next = *plugin_list;
+	list->handle = handle;
+	list->name = plugin;
+	*plugin_list = list;
+
+	pr_stat("registering plugin: %s", plugin);
+	func(pevent);
+	return;
+
+ out_free:
+	free(plugin);
+}
+
+static void
+trace_util_load_plugins_dir(struct pevent *pevent, const char *suffix,
+			    const char *path,
+			    void (*load_plugin)(struct pevent *pevent,
+						const char *path,
+						const char *name,
+						void *data),
+			    void *data)
+{
+	struct dirent *dent;
+	struct stat st;
+	DIR *dir;
+	int ret;
+
+	ret = stat(path, &st);
+	if (ret < 0)
+		return;
+
+	if (!S_ISDIR(st.st_mode))
+		return;
+
+	dir = opendir(path);
+	if (!dir)
+		return;
+
+	while ((dent = readdir(dir))) {
+		const char *name = dent->d_name;
+
+		if (strcmp(name, ".") == 0 ||
+		    strcmp(name, "..") == 0)
+			continue;
+
+		/* Only load plugins that end in suffix */
+		if (strcmp(name + (strlen(name) - strlen(suffix)), suffix) != 0)
+			continue;
+
+		load_plugin(pevent, path, name, data);
+	}
+
+	closedir(dir);
+
+	return;
+}
+
+void trace_util_load_plugins(struct pevent *pevent, const char *suffix,
+			     void (*load_plugin)(struct pevent *pevent,
+						 const char *path,
+						 const char *name,
+						 void *data),
+			     void *data)
+{
+	char *home;
+	char *path;
+        char *envdir;
+
+	if (tracecmd_disable_plugins)
+		return;
+
+/* If a system plugin directory was defined, check that first */
+#ifdef PLUGIN_DIR
+	if (!tracecmd_disable_sys_plugins)
+		trace_util_load_plugins_dir(pevent, suffix, PLUGIN_DIR,
+					    load_plugin, data);
+#endif
+
+	/* Next let the environment-set plugin directory override the system defaults */
+	envdir = getenv("TRACE_CMD_PLUGIN_DIR");
+	if (envdir)
+		trace_util_load_plugins_dir(pevent, suffix, envdir, load_plugin, data);
+
+	/* Now let the home directory override the environment or system defaults */
+	home = getenv("HOME");
+
+	if (!home)
+		return;
+
+	path = malloc_or_die(strlen(home) + strlen(LOCAL_PLUGIN_DIR) + 2);
+
+	strcpy(path, home);
+	strcat(path, "/");
+	strcat(path, LOCAL_PLUGIN_DIR);
+
+	trace_util_load_plugins_dir(pevent, suffix, path, load_plugin, data);
+
+	free(path);
+}
+
+struct plugin_list *tracecmd_load_plugins(struct pevent *pevent)
+{
+	struct plugin_list *list = NULL;
+
+	trace_util_load_plugins(pevent, ".so", load_plugin, &list);
+
+	return list;
+}
+
+void tracecmd_unload_plugins(struct plugin_list *plugin_list)
+{
+	pevent_plugin_unload_func func;
+	struct plugin_list *list;
+
+	while (plugin_list) {
+		list = plugin_list;
+		plugin_list = list->next;
+		func = dlsym(list->handle, PEVENT_PLUGIN_UNLOADER_NAME);
+		if (func)
+			func();
+		dlclose(list->handle);
+		free(list->name);
+		free(list);
+	}
+}
diff --git a/tools/lib/traceevent/tracecmd-plugins.h b/tools/lib/traceevent/tracecmd-plugins.h
new file mode 100644
index 0000000..1a65d50
--- /dev/null
+++ b/tools/lib/traceevent/tracecmd-plugins.h
@@ -0,0 +1,34 @@
+/*
+ * Copyright (C) 2008, 2009, 2010 Red Hat Inc, Steven Rostedt <srostedt@redhat.com>
+ *
+ * ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
+ * This program is free software; you can redistribute it and/or
+ * modify it under the terms of the GNU Lesser General Public
+ * License as published by the Free Software Foundation;
+ * version 2.1 of the License (not later!)
+ *
+ * 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 Lesser General Public License for more details.
+ *
+ * You should have received a copy of the GNU Lesser General Public
+ * License along with this program; if not, write to the Free Software
+ * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
+ *
+ * ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
+ */
+#ifndef _TRACECMD__PLUGINS_H
+#define _TRACECMD__PLUGINS_H
+
+#include <stdlib.h>
+#include "event-parse.h"
+
+extern int tracecmd_disable_sys_plugins;
+extern int tracecmd_disable_plugins;
+
+struct plugin_list;
+struct plugin_list *tracecmd_load_plugins(struct pevent *pevent);
+void tracecmd_unload_plugins(struct plugin_list *list);
+
+#endif /* _TRACECMD__PLUGINS_H */
-- 
1.7.10.1

[RFC PATCH 2/2] perf: add support for trace-cmd plugins

[David Ahern]

Improves pretty printing of events when using perf-script. e.g.,
perf record -p 8731 -e kvm:* -fo /tmp/perf.data -- sleep 1

Currently when dumping kvm events you ugliness like this:
$ perf script -i /tmp/perf.data
Warning: bad op token {
Warning: failed to read event print fmt for kvm_emulate_insn
...
        qemu-kvm  8734 [006] 826443.468554: kvm_emulate_insn:
<...>-8734  [006]     0.000000000: kvm_emulate_insn:
[FAILED TO PARSE] rip=18446744071579001937 csbase=0 len=6
insn=<89><B7> flags=9 failed=0

Ignoring the duplication of data the event is not readable.
With this patch and using the kvm plugin for trace-cmd you get:

        qemu-kvm  8734 [006] 826443.468554: kvm_emulate_insn:
0:ffffffff81026451: mov %esi, 0xff5fb000(%rdi)

which is a bit more readable.

Signed-off-by: David Ahern <dsahern@gmail.com>
---
 tools/perf/util/trace-event-parse.c |    4 ++++
 1 file changed, 4 insertions(+)

diff --git a/tools/perf/util/trace-event-parse.c b/tools/perf/util/trace-event-parse.c
index df2fddb..7b149c5 100644
--- a/tools/perf/util/trace-event-parse.c
+++ b/tools/perf/util/trace-event-parse.c
@@ -27,6 +27,7 @@
 #include "../perf.h"
 #include "util.h"
 #include "trace-event.h"
+#include "tracecmd-plugins.h"
 
 int header_page_size_size;
 int header_page_ts_size;
@@ -36,6 +37,7 @@ struct pevent *perf_pevent;
 static struct pevent *pevent;
 
 bool latency_format;
+struct plugin_list *list;
 
 int read_trace_init(int file_bigendian, int host_bigendian)
 {
@@ -45,6 +47,8 @@ int read_trace_init(int file_bigendian, int host_bigendian)
 	perf_pevent = pevent_alloc();
 	pevent = perf_pevent;
 
+	list = tracecmd_load_plugins(pevent);
+
 	pevent_set_flag(pevent, PEVENT_NSEC_OUTPUT);
 	pevent_set_file_bigendian(pevent, file_bigendian);
 	pevent_set_host_bigendian(pevent, host_bigendian);
-- 
1.7.10.1

Re: [RFC PATCH 0/2] libtraceevent/perf: Add support for trace-cmd plugins

[Namhyung Kim]

Hi, David

On Thu, 14 Jun 2012 11:35:31 -0600, David Ahern wrote:
> Now that perf is using libtraceevent and libtraceevent is based
> on trace-cmd both can be extended to leverage the plugins written
> for trace-cmd to improve pretty printing of the events.
>
> Given that it is based on code from trace-cmd I am not sure what the
> right approach is, so wanted to throw this out for comments/suggestions.
>

Yeah, it can be useful to reuse existing code for extending the
functionality. But I'm not so sure including the plugin APIs into
libtraceevent is the right thing (at least in its current form).

And for this particular case in patch 2/2, it seems that format of the
kvm_emulate_insn event is broken already and should be fixed anyway.
Further improvement in this area can be addressed in perf kvm or other
users if needed.

So I'd like to hear from others.
Arnaldo and Steven, what do you think?

Thanks,
Namhyung

Re: [RFC PATCH 0/2] libtraceevent/perf: Add support for trace-cmd plugins

[Steven Rostedt]

On Mon, 2012-06-18 at 17:35 +0900, Namhyung Kim wrote:
> Hi, David
> 
> On Thu, 14 Jun 2012 11:35:31 -0600, David Ahern wrote:
> > Now that perf is using libtraceevent and libtraceevent is based
> > on trace-cmd both can be extended to leverage the plugins written
> > for trace-cmd to improve pretty printing of the events.
> >
> > Given that it is based on code from trace-cmd I am not sure what the
> > right approach is, so wanted to throw this out for comments/suggestions.
> >
> 
> Yeah, it can be useful to reuse existing code for extending the
> functionality. But I'm not so sure including the plugin APIs into
> libtraceevent is the right thing (at least in its current form).
> 
> And for this particular case in patch 2/2, it seems that format of the
> kvm_emulate_insn event is broken already and should be fixed anyway.
> Further improvement in this area can be addressed in perf kvm or other
> users if needed.
> 
> So I'd like to hear from others.
> Arnaldo and Steven, what do you think?

It's been crazy lately, so sorry for the late reply David.

Anyway, I think it is important to get this into either libtraceevent or
another library, but I agree with Namhyung that it should not go in, in
its current form.

Either we add the 'pevent_' names to it, and we need to change things a
bit.

I want to redesign the plugin interface. Well, I do not need to be the
one to redesign it, but it needs to be updated by someone.

Plugins need an interface that they can take parameters, or be modified
at run time. An option passed to perf or trace-cmd could modify how the
plugin works. Or during viewing of the output, parameters can be passed
to tell plugins to do things differently.

Basically, we need to discuss the interface between plugins and the
libtraceevent library. Once we get a good idea of what is needed, then
we can start reusing the code from trace-cmd to make a much better
interface for users.

Thanks!

-- Steve

Re: [RFC PATCH 0/2] libtraceevent/perf: Add support for trace-cmd plugins

[David Ahern]

On 6/18/12 8:21 AM, Steven Rostedt wrote:
>
> Anyway, I think it is important to get this into either libtraceevent or
> another library, but I agree with Namhyung that it should not go in, in
> its current form.

Great. No resistance to bringing this in.

> Either we add the 'pevent_' names to it, and we need to change things a
> bit.

Sure, namespace cleanup is trivial.

> I want to redesign the plugin interface. Well, I do not need to be the
> one to redesign it, but it needs to be updated by someone.
>
> Plugins need an interface that they can take parameters, or be modified
> at run time. An option passed to perf or trace-cmd could modify how the
> plugin works. Or during viewing of the output, parameters can be passed
> to tell plugins to do things differently.
>
> Basically, we need to discuss the interface between plugins and the
> libtraceevent library. Once we get a good idea of what is needed, then
> we can start reusing the code from trace-cmd to make a much better
> interface for users.

Ok. I'll poke around with this over the summer as I get spare time.

David

Re: [RFC PATCH 0/2] libtraceevent/perf: Add support for trace-cmd plugins

[David Ahern]

Hi Namhyung:

On 6/18/12 2:35 AM, Namhyung Kim wrote:
> And for this particular case in patch 2/2, it seems that format of the
> kvm_emulate_insn event is broken already and should be fixed anyway.
> Further improvement in this area can be addressed in perf kvm or other
> users if needed.

kvm tracepoints are fine; perf just doesn't handle their (advanced) 
formatting.

Note that I am referring to kvm:* tracepoints, not perf-kvm which has 
its own issues that need to be fixed.

David

Re: [RFC PATCH 0/2] libtraceevent/perf: Add support for trace-cmd plugins

[Namhyung Kim]

On Mon, 18 Jun 2012 08:38:20 -0600, David Ahern wrote:
> Hi Namhyung:
>

Hi David,


> On 6/18/12 2:35 AM, Namhyung Kim wrote:
>> And for this particular case in patch 2/2, it seems that format of the
>> kvm_emulate_insn event is broken already and should be fixed anyway.
>> Further improvement in this area can be addressed in perf kvm or other
>> users if needed.
>
> kvm tracepoints are fine; perf just doesn't handle their (advanced)
> formatting.
>

Yeah, I think it's a libtraceevent's issue, not perf's. Please see
below:

TRACE_EVENT(kvm_emulate_insn,
        ...
	TP_printk("%x:%llx:%s (%s)%s",
		  __entry->csbase, __entry->rip,
		  __print_insn(__entry->insn, __entry->len),
		  __print_symbolic(__entry->flags,
				   kvm_trace_symbol_emul_flags),
		  __entry->failed ? " failed" : ""
		)
	);

And __print_insn is defined as:

#define __print_insn(insn, ilen) ({		                 \
	int i;							 \
	const char *ret = p->buffer + p->len;			 \
								 \
	for (i = 0; i < ilen; ++i)				 \
		trace_seq_printf(p, " %02x", insn[i]);		 \
	trace_seq_printf(p, "%c", 0);				 \
	ret;							 \
	})

The parse error is occurred at the beginning of the compound statment:

  Warning: bad op token {
  Warning: failed to read event print fmt for kvm_emulate_insn

I don't think we can handle this kind of compound statments easily. So I
just said it *seems* broken. :) Btw, calling trace_seq_printf() here also
looks like a problem and I have no idea where the 'p' came from.

Thanks,
Namhyung


> Note that I am referring to kvm:* tracepoints, not perf-kvm which has
> its own issues that need to be fixed.
>
> David

Re: [RFC PATCH 0/2] libtraceevent/perf: Add support for trace-cmd plugins

[Steven Rostedt]

On Tue, 2012-06-19 at 09:45 +0900, Namhyung Kim wrote:

> TRACE_EVENT(kvm_emulate_insn,
>         ...
> 	TP_printk("%x:%llx:%s (%s)%s",
> 		  __entry->csbase, __entry->rip,
> 		  __print_insn(__entry->insn, __entry->len),
> 		  __print_symbolic(__entry->flags,
> 				   kvm_trace_symbol_emul_flags),
> 		  __entry->failed ? " failed" : ""
> 		)
> 	);
> 
> And __print_insn is defined as:
> 
> #define __print_insn(insn, ilen) ({		                 \
> 	int i;							 \
> 	const char *ret = p->buffer + p->len;			 \
> 								 \
> 	for (i = 0; i < ilen; ++i)				 \
> 		trace_seq_printf(p, " %02x", insn[i]);		 \
> 	trace_seq_printf(p, "%c", 0);				 \
> 	ret;							 \
> 	})
> 
> The parse error is occurred at the beginning of the compound statment:
> 
>   Warning: bad op token {
>   Warning: failed to read event print fmt for kvm_emulate_insn
> 
> I don't think we can handle this kind of compound statments easily. So I
> just said it *seems* broken. :) Btw, calling trace_seq_printf() here also
> looks like a problem and I have no idea where the 'p' came from.

This is why we want the plugin. What the plugins do is registers how to
parse the data of the event. The event format file is still parsed to
find where the data is located, but the printf fmt: field (TP_printk) is
ignored. The plugin provides the format to print the data with.

Lets look at the kvm plugin for kvm_emulate_insn:

static int kvm_emulate_insn_handler(struct trace_seq *s, struct record *record,
                                    struct event_format *event, void *context)
{
        unsigned long long rip, csbase, len, flags, failed;
        int llen;
        uint8_t *insn;
        const char *disasm;

        if (pevent_get_field_val(s, event, "rip", record, &rip, 1) < 0)
                return -1;

        if (pevent_get_field_val(s, event, "csbase", record, &csbase, 1) < 0)
                return -1;

        if (pevent_get_field_val(s, event, "len", record, &len, 1) < 0)
                return -1;

        if (pevent_get_field_val(s, event, "flags", record, &flags, 1) < 0)
                return -1;

        if (pevent_get_field_val(s, event, "failed", record, &failed, 1) < 0)
                return -1;

        insn = pevent_get_field_raw(s, event, "insn", record, &llen, 1);
        if (!insn)
                return -1;

        disasm = disassemble(insn, len, rip,
                             flags & KVM_EMUL_INSN_F_CR0_PE,
                             flags & KVM_EMUL_INSN_F_EFL_VM,
                             flags & KVM_EMUL_INSN_F_CS_D,
                             flags & KVM_EMUL_INSN_F_CS_L);

        trace_seq_printf(s, "%llx:%llx: %s%s", csbase, rip, disasm,
                         failed ? " FAIL" : "");

        return 0;
}


You see, this uses the information from libtraceevent to get the
required fields. Then it prints it out nicely for users. Here's the
output of trace-cmd report after a trace-cmd record -e kvm and starting
a guest:

             kvm-6172  [000] 14669573.114126: kvm_entry:            vcpu 0
             kvm-6172  [000] 14669573.114127: kvm_exit:             reason IO_INSTRUCTION rip 0xffff357a info cfc0008 0
             kvm-6172  [000] 14669573.114130: kvm_emulate_insn:     0:ffff357a: ec
             kvm-6172  [000] 14669573.114130: kvm_pio:              pio_read at 0xcfc size 1 count 1
             kvm-6172  [000] 14669573.114131: kvm_userspace_exit:   reason KVM_EXIT_IO (2)
             kvm-6172  [000] 14669573.114134: kvm_entry:            vcpu 0
             kvm-6172  [000] 14669573.114135: kvm_exit:             reason IO_INSTRUCTION rip 0xffff34f9 info cf80003 0
             kvm-6172  [000] 14669573.114136: kvm_pio:              pio_write at 0xcf8 size 4 count 1
             kvm-6172  [000] 14669573.114136: kvm_userspace_exit:   reason KVM_EXIT_IO (2)

I can disable plugins to show you the result of what happens without
them:

trace-cmd report -N
[...]
             kvm-6172  [000] 14669573.114126: kvm_entry:            vcpu 0
             kvm-6172  [000] 14669573.114127: kvm_exit:             [FAILED TO PARSE] exit_reason=30 guest_rip=0xffff357a isa=1 info1=217841672 info2=0
             kvm-6172  [000] 14669573.114130: kvm_emulate_insn:     [FAILED TO PARSE] rip=4294915450 csbase=0 len=1 insn=ì[ÃWVS<89>Ã<89>Öš^Gu^Q^O^E flags=5 failed=0
             kvm-6172  [000] 14669573.114130: kvm_pio:              pio_read at 0xcfc size 1 count 1
             kvm-6172  [000] 14669573.114131: kvm_userspace_exit:   reason KVM_EXIT_IO (2)
             kvm-6172  [000] 14669573.114134: kvm_entry:            vcpu 0

This is the power of plugins. I would expect to add something like:

tools/events/plugins/

where these can be added for everyone.

-- Steve

Re: [RFC PATCH 0/2] libtraceevent/perf: Add support for trace-cmd plugins

[Namhyung Kim]

On Mon, 18 Jun 2012 21:03:13 -0400, Steven Rostedt wrote:
> On Tue, 2012-06-19 at 09:45 +0900, Namhyung Kim wrote:
>
>> TRACE_EVENT(kvm_emulate_insn,
>>         ...
>> 	TP_printk("%x:%llx:%s (%s)%s",
>> 		  __entry->csbase, __entry->rip,
>> 		  __print_insn(__entry->insn, __entry->len),
>> 		  __print_symbolic(__entry->flags,
>> 				   kvm_trace_symbol_emul_flags),
>> 		  __entry->failed ? " failed" : ""
>> 		)
>> 	);
>> 
>> And __print_insn is defined as:
>> 
>> #define __print_insn(insn, ilen) ({		                 \
>> 	int i;							 \
>> 	const char *ret = p->buffer + p->len;			 \
>> 								 \
>> 	for (i = 0; i < ilen; ++i)				 \
>> 		trace_seq_printf(p, " %02x", insn[i]);		 \
>> 	trace_seq_printf(p, "%c", 0);				 \
>> 	ret;							 \
>> 	})
>> 
>> The parse error is occurred at the beginning of the compound statment:
>> 
>>   Warning: bad op token {
>>   Warning: failed to read event print fmt for kvm_emulate_insn
>> 
>> I don't think we can handle this kind of compound statments easily. So I
>> just said it *seems* broken. :) Btw, calling trace_seq_printf() here also
>> looks like a problem and I have no idea where the 'p' came from.
>
> This is why we want the plugin. What the plugins do is registers how to
> parse the data of the event. The event format file is still parsed to
> find where the data is located, but the printf fmt: field (TP_printk) is
> ignored. The plugin provides the format to print the data with.
>

Yeah, I know. It's great. :)


> Lets look at the kvm plugin for kvm_emulate_insn:
>
> static int kvm_emulate_insn_handler(struct trace_seq *s, struct record *record,
>                                     struct event_format *event, void *context)
> {
>         unsigned long long rip, csbase, len, flags, failed;
>         int llen;
>         uint8_t *insn;
>         const char *disasm;
>
>         if (pevent_get_field_val(s, event, "rip", record, &rip, 1) < 0)
>                 return -1;
>
>         if (pevent_get_field_val(s, event, "csbase", record, &csbase, 1) < 0)
>                 return -1;
>
>         if (pevent_get_field_val(s, event, "len", record, &len, 1) < 0)
>                 return -1;
>
>         if (pevent_get_field_val(s, event, "flags", record, &flags, 1) < 0)
>                 return -1;
>
>         if (pevent_get_field_val(s, event, "failed", record, &failed, 1) < 0)
>                 return -1;
>
>         insn = pevent_get_field_raw(s, event, "insn", record, &llen, 1);
>         if (!insn)
>                 return -1;
>
>         disasm = disassemble(insn, len, rip,
>                              flags & KVM_EMUL_INSN_F_CR0_PE,
>                              flags & KVM_EMUL_INSN_F_EFL_VM,
>                              flags & KVM_EMUL_INSN_F_CS_D,
>                              flags & KVM_EMUL_INSN_F_CS_L);
>
>         trace_seq_printf(s, "%llx:%llx: %s%s", csbase, rip, disasm,
>                          failed ? " FAIL" : "");
>
>         return 0;
> }
>
>
> You see, this uses the information from libtraceevent to get the
> required fields. Then it prints it out nicely for users. Here's the
> output of trace-cmd report after a trace-cmd record -e kvm and starting
> a guest:
>
>              kvm-6172  [000] 14669573.114126: kvm_entry:            vcpu 0
>              kvm-6172  [000] 14669573.114127: kvm_exit:             reason IO_INSTRUCTION rip 0xffff357a info cfc0008 0
>              kvm-6172  [000] 14669573.114130: kvm_emulate_insn:     0:ffff357a: ec
>              kvm-6172  [000] 14669573.114130: kvm_pio:              pio_read at 0xcfc size 1 count 1
>              kvm-6172  [000] 14669573.114131: kvm_userspace_exit:   reason KVM_EXIT_IO (2)
>              kvm-6172  [000] 14669573.114134: kvm_entry:            vcpu 0
>              kvm-6172  [000] 14669573.114135: kvm_exit:             reason IO_INSTRUCTION rip 0xffff34f9 info cf80003 0
>              kvm-6172  [000] 14669573.114136: kvm_pio:              pio_write at 0xcf8 size 4 count 1
>              kvm-6172  [000] 14669573.114136: kvm_userspace_exit:   reason KVM_EXIT_IO (2)
>
> I can disable plugins to show you the result of what happens without
> them:
>
> trace-cmd report -N
> [...]
>              kvm-6172  [000] 14669573.114126: kvm_entry:            vcpu 0
>              kvm-6172  [000] 14669573.114127: kvm_exit:             [FAILED TO PARSE] exit_reason=30 guest_rip=0xffff357a isa=1 info1=217841672 info2=0
>              kvm-6172  [000] 14669573.114130: kvm_emulate_insn:     [FAILED TO PARSE] rip=4294915450 csbase=0 len=1 insn=ì[ÃWVS<89>Ã<89>Öš^Gu^Q^O^E flags=5 failed=0
>              kvm-6172  [000] 14669573.114130: kvm_pio:              pio_read at 0xcfc size 1 count 1
>              kvm-6172  [000] 14669573.114131: kvm_userspace_exit:   reason KVM_EXIT_IO (2)
>              kvm-6172  [000] 14669573.114134: kvm_entry:            vcpu 0
>

What I want to do is make it not to fail with default print_fmt (ie. w/o
plugin support). IOW using a plugin to improve things like above is
good, but not using it shouldn't break/fail anything. So I think fixing
the TP_printk is needed.

Thanks,
Namhyung


> This is the power of plugins. I would expect to add something like:
>
> tools/events/plugins/
>
> where these can be added for everyone.
>
> -- Steve

Re: [RFC PATCH 0/2] libtraceevent/perf: Add support for trace-cmd plugins

[David Ahern]

On 6/18/12 6:45 PM, Namhyung Kim wrote:
>> kvm tracepoints are fine; perf just doesn't handle their (advanced)
>> formatting.
>>
>
> Yeah, I think it's a libtraceevent's issue, not perf's. Please see
> below:

Well documented problem (search perf kvm bad op token.

In April 2011 (pre first libparseevent patch) I mentioned a 
desire/wish/dream for perf to be able to use trace-cmd's plugins to fix 
this:

http://lkml.indiana.edu/hypermail/linux/kernel/1104.1/00411.html

Maybe this dream can come true... ;-)

David

Re: [RFC PATCH 0/2] libtraceevent/perf: Add support for trace-cmd plugins

[Steven Rostedt]

On Tue, 2012-06-19 at 10:11 +0900, Namhyung Kim wrote:

> > trace-cmd report -N
> > [...]
> >              kvm-6172  [000] 14669573.114126: kvm_entry:            vcpu 0
> >              kvm-6172  [000] 14669573.114127: kvm_exit:             [FAILED TO PARSE] exit_reason=30 guest_rip=0xffff357a isa=1 info1=217841672 info2=0
> >              kvm-6172  [000] 14669573.114130: kvm_emulate_insn:     [FAILED TO PARSE] rip=4294915450 csbase=0 len=1 insn=ì[ÃWVS<89>Ã<89>Öš^Gu^Q^O^E flags=5 failed=0
> >              kvm-6172  [000] 14669573.114130: kvm_pio:              pio_read at 0xcfc size 1 count 1
> >              kvm-6172  [000] 14669573.114131: kvm_userspace_exit:   reason KVM_EXIT_IO (2)
> >              kvm-6172  [000] 14669573.114134: kvm_entry:            vcpu 0
> >
> 
> What I want to do is make it not to fail with default print_fmt (ie. w/o
> plugin support). IOW using a plugin to improve things like above is
> good, but not using it shouldn't break/fail anything. So I think fixing
> the TP_printk is needed.

I'm not sure its broken anymore per-say. As I just ran this without
plugins (with the -N switch) and it doesn't break. It sends out some
nasty warnings, but continues on its happy way with a warning that it
'[FAILED TO PARSE]'. And some warnings in the beginning.

But it doesn't totally fail. We could probably clean it up a bit too.
What it does above is simply print out the raw data and lists the
fields.

The problem with modifying the TP_printk() is that this is also used by
raw tracing (the /debug/tracing/trace file). Without using tools. The
TP_printk() is really for that. The plugins is the way for tools to
handle it.

-- Steve


 

Re: [RFC PATCH 0/2] libtraceevent/perf: Add support for trace-cmd plugins

[Namhyung Kim]

On Mon, 18 Jun 2012 21:26:02 -0400, Steven Rostedt wrote:
> On Tue, 2012-06-19 at 10:11 +0900, Namhyung Kim wrote:
>
>> > trace-cmd report -N
>> > [...]
>> >              kvm-6172  [000] 14669573.114126: kvm_entry:            vcpu 0
>> >              kvm-6172  [000] 14669573.114127: kvm_exit:             [FAILED TO PARSE] exit_reason=30 guest_rip=0xffff357a isa=1 info1=217841672 info2=0
>> >              kvm-6172  [000] 14669573.114130: kvm_emulate_insn:     [FAILED TO PARSE] rip=4294915450 csbase=0 len=1 insn=ì[ÃWVS<89>Ã<89>Öš^Gu^Q^O^E flags=5 failed=0
>> >              kvm-6172  [000] 14669573.114130: kvm_pio:              pio_read at 0xcfc size 1 count 1
>> >              kvm-6172  [000] 14669573.114131: kvm_userspace_exit:   reason KVM_EXIT_IO (2)
>> >              kvm-6172  [000] 14669573.114134: kvm_entry:            vcpu 0
>> >
>> 
>> What I want to do is make it not to fail with default print_fmt (ie. w/o
>> plugin support). IOW using a plugin to improve things like above is
>> good, but not using it shouldn't break/fail anything. So I think fixing
>> the TP_printk is needed.
>
> I'm not sure its broken anymore per-say. As I just ran this without
> plugins (with the -N switch) and it doesn't break. It sends out some
> nasty warnings, but continues on its happy way with a warning that it
> '[FAILED TO PARSE]'. And some warnings in the beginning.
>
> But it doesn't totally fail. We could probably clean it up a bit too.
> What it does above is simply print out the raw data and lists the
> fields.
>
> The problem with modifying the TP_printk() is that this is also used by
> raw tracing (the /debug/tracing/trace file). Without using tools. The
> TP_printk() is really for that. The plugins is the way for tools to
> handle it.
>

Ok. Then how about using __print_hex() for __print_insn? AFAICS
ftrace_print_hex_seq() looks almost same as __print_insn() and as it's a
generic function we can add its handler in libtraceevnt.

Thanks,
Namhyung

Re: [RFC PATCH 0/2] libtraceevent/perf: Add support for trace-cmd plugins

[Steven Rostedt]

[ I'm tired of getting error messages from sending to some stranger at
weisbec@gmail.com, I might as well send it to someone I know. Someone
with an 'f' ]


On Tue, 2012-06-19 at 10:40 +0900, Namhyung Kim wrote:
> On Mon, 18 Jun 2012 21:26:02 -0400, Steven Rostedt wrote:
> > On Tue, 2012-06-19 at 10:11 +0900, Namhyung Kim wrote:
> >
> >> > trace-cmd report -N
> >> > [...]
> >> >              kvm-6172  [000] 14669573.114126: kvm_entry:            vcpu 0
> >> >              kvm-6172  [000] 14669573.114127: kvm_exit:             [FAILED TO PARSE] exit_reason=30 guest_rip=0xffff357a isa=1 info1=217841672 info2=0
> >> >              kvm-6172  [000] 14669573.114130: kvm_emulate_insn:     [FAILED TO PARSE] rip=4294915450 csbase=0 len=1 insn=ì[ÃWVS<89>Ã<89>Öš^Gu^Q^O^E flags=5 failed=0
> >> >              kvm-6172  [000] 14669573.114130: kvm_pio:              pio_read at 0xcfc size 1 count 1
> >> >              kvm-6172  [000] 14669573.114131: kvm_userspace_exit:   reason KVM_EXIT_IO (2)
> >> >              kvm-6172  [000] 14669573.114134: kvm_entry:            vcpu 0
> >> >
> >> 

> Ok. Then how about using __print_hex() for __print_insn? AFAICS
> ftrace_print_hex_seq() looks almost same as __print_insn() and as it's a
> generic function we can add its handler in libtraceevnt.

We can be a bit better at the raw print, sure. Here's the format that's
there:

	field:__u64 rip;	offset:16;	size:8;	signed:0;
	field:__u32 csbase;	offset:24;	size:4;	signed:0;
	field:__u8 len;	offset:28;	size:1;	signed:0;
	field:__u8 insn[15];	offset:29;	size:15;	signed:0;
	field:__u8 flags;	offset:44;	size:1;	signed:0;
	field:__u8 failed;	offset:45;	size:1;	signed:0;

It treated __u* as decimal numbers, but it also saw that insn[15] was an
array, and with single bytes at that. So it thought it was a string, and
tried to print it out as such.

We can change the heuristics of this to make it more readable.

-- Steve
 

Re: [RFC PATCH 0/2] libtraceevent/perf: Add support for trace-cmd plugins

[Namhyung Kim]

On Mon, 18 Jun 2012 22:16:11 -0400, Steven Rostedt wrote:
> We can be a bit better at the raw print, sure. Here's the format that's
> there:
>
> 	field:__u64 rip;	offset:16;	size:8;	signed:0;
> 	field:__u32 csbase;	offset:24;	size:4;	signed:0;
> 	field:__u8 len;	offset:28;	size:1;	signed:0;
> 	field:__u8 insn[15];	offset:29;	size:15;	signed:0;
> 	field:__u8 flags;	offset:44;	size:1;	signed:0;
> 	field:__u8 failed;	offset:45;	size:1;	signed:0;
>
> It treated __u* as decimal numbers, but it also saw that insn[15] was an
> array, and with single bytes at that. So it thought it was a string, and
> tried to print it out as such.
>
> We can change the heuristics of this to make it more readable.
>

Right. The current heuristic treats an u8 array as a string:

static int field_is_string(struct format_field *field)
{
	if ((field->flags & FIELD_IS_ARRAY) &&
	    (strstr(field->type, "char") || strstr(field->type, "u8") ||
	     strstr(field->type, "s8")))
		return 1;

	return 0;
}

Do you want to get rid of u8 from the function? Or is there a
better way?

Thanks,
Namhyung

Re: [RFC PATCH 0/2] libtraceevent/perf: Add support for trace-cmd plugins

[Steven Rostedt]

On Tue, 2012-06-19 at 14:41 +0900, Namhyung Kim wrote:
> On Mon, 18 Jun 2012 22:16:11 -0400, Steven Rostedt wrote:
> > We can be a bit better at the raw print, sure. Here's the format that's
> > there:
> >
> > 	field:__u64 rip;	offset:16;	size:8;	signed:0;
> > 	field:__u32 csbase;	offset:24;	size:4;	signed:0;
> > 	field:__u8 len;	offset:28;	size:1;	signed:0;
> > 	field:__u8 insn[15];	offset:29;	size:15;	signed:0;
> > 	field:__u8 flags;	offset:44;	size:1;	signed:0;
> > 	field:__u8 failed;	offset:45;	size:1;	signed:0;
> >
> > It treated __u* as decimal numbers, but it also saw that insn[15] was an
> > array, and with single bytes at that. So it thought it was a string, and
> > tried to print it out as such.
> >
> > We can change the heuristics of this to make it more readable.
> >
> 
> Right. The current heuristic treats an u8 array as a string:
> 
> static int field_is_string(struct format_field *field)
> {
> 	if ((field->flags & FIELD_IS_ARRAY) &&
> 	    (strstr(field->type, "char") || strstr(field->type, "u8") ||
> 	     strstr(field->type, "s8")))
> 		return 1;
> 
> 	return 0;
> }
> 
> Do you want to get rid of u8 from the function? Or is there a
> better way?
> 

We could simply check if all the characters in the array passes
'isprint()' and if it does then print the string, otherwise print the
hex. Do this for all events, and if it one fails, then mark it always to
print hex.

-- Steve

Re: [RFC PATCH 0/2] libtraceevent/perf: Add support for trace-cmd plugins

[Namhyung Kim]

On Tue, 19 Jun 2012 07:54:42 -0400, Steven Rostedt wrote:
> We could simply check if all the characters in the array passes
> 'isprint()' and if it does then print the string, otherwise print the
> hex. Do this for all events, and if it one fails, then mark it always to
> print hex.
>

Ok, checking it at parse time is not possible because we cannot access
to its data. You meant something like this?


diff --git a/tools/lib/traceevent/event-parse.c b/tools/lib/traceevent/event-parse.c
index 853b604b6240..7dae44b74e0b 100644
--- a/tools/lib/traceevent/event-parse.c
+++ b/tools/lib/traceevent/event-parse.c
@@ -3655,6 +3655,16 @@ static void print_mac_arg(struct trace_seq *s, int mac, void *data, int size,
        trace_seq_printf(s, fmt, buf[0], buf[1], buf[2], buf[3], buf[4], buf[5]);
 }
 
+static int is_printable_array(char *p, unsigned int len)
+{
+       unsigned int i;
+
+       for (i = 0; i < len && p[i]; i++)
+               if (!isprint(p[i]))
+                       return 0;
+       return 1;
+}
+
 static void print_event_fields(struct trace_seq *s, void *data, int size,
                               struct event_format *event)
 {
@@ -3674,7 +3684,8 @@ static void print_event_fields(struct trace_seq *s, void *data, int size,
                                len = offset >> 16;
                                offset &= 0xffff;
                        }
-                       if (field->flags & FIELD_IS_STRING) {
+                       if ((field->flags & FIELD_IS_STRING) &&
+                           is_printable_array(data + offset, len)) {
                                trace_seq_printf(s, "%s", (char *)data + offset);
                        } else {
                                trace_seq_puts(s, "ARRAY[");
@@ -3685,6 +3696,7 @@ static void print_event_fields(struct trace_seq *s, void *data, int size,
                                                         *((unsigned char *)data + offset + i));
                                }
                                trace_seq_putc(s, ']');
+                               field->flags &= ~FIELD_IS_STRING;
                        }
                } else {
                        val = pevent_read_number(event->pevent, data + field->offset,

Re: [RFC PATCH 0/2] libtraceevent/perf: Add support for trace-cmd plugins

[Steven Rostedt]

On Tue, 2012-06-19 at 23:39 +0900, Namhyung Kim wrote:
> On Tue, 19 Jun 2012 07:54:42 -0400, Steven Rostedt wrote:
> > We could simply check if all the characters in the array passes
> > 'isprint()' and if it does then print the string, otherwise print the
> > hex. Do this for all events, and if it one fails, then mark it always to
> > print hex.
> >
> 
> Ok, checking it at parse time is not possible because we cannot access
> to its data. You meant something like this?
> 

Exactly!

-- Steve