libtraceevent/perf: Add support for trace-cmd plugins

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.

Hi, David

Quoted 7 lines · 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.

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?

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.

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.

Hi Namhyung:

Quoted 4 lines

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

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.

Quoted 28 lines · Namhyung Kim

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

Quoted 3 lines

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

Quoted 9 lines

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.

Quoted 10 lines · Namhyung Kim

Quoted 9 lines

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

Quoted 4 lines

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.

Quoted 12 lines · Steven Rostedt

Quoted 10 lines · Namhyung Kim

Quoted 9 lines

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.

Quoted 10 lines · Steven Rostedt

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;

Quoted 6 lines

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.

Quoted 5 lines · Steven Rostedt

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?

Quoted 3 lines

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: