Perf trace event parse errors for KVM events

Perf trace event parse errors for KVM events

[Stefan Hajnoczi]

The "perf trace" command produces the following messages:

For kvm:kvm_apic:
$ perf trace
  Warning: Error: expected type 4 but read 7
  Warning: Error: expected type 5 but read 0
  Warning: failed to read event print fmt for kvm_apic

For kvm:kvm_inj_exception:
$ perf trace
  Warning: Error: expected type 4 but read 7
  Warning: Error: expected type 5 but read 0
  Warning: failed to read event print fmt for kvm_inj_exception

For kvm:kvm_emulate_insn:
$ perf trace
  Fatal: bad op token {

The other KVM trace events work fine.

To reproduce this issue (you don't need any actual KVM activity while running):
$ perf record -a -f -e 'kvm:kvm_apic' sleep 1
$ perf trace

Both linux-2.6.git 7e125f7b9cbfce4101191b8076d606c517a73066 and Avi's kvm.git
show this problem.

It appears that the perf.data written by "perf record" cannot be parsed by
"perf trace" run using the same perf binary.  The perf binary was built from
the same kernel tree that I am running (there should be no mismatch between the
kernel and the perf binary).

At the end of this email is a gdb session that shows where the
kvm:kvm_apic "expected type 4 but read 7" error occurs.

Any ideas?

Thanks,
Stefan

$ sudo gdb --args ./perf trace
[...]
(gdb) b warning
Breakpoint 1 at 0x42d000: file util/usage.c, line 74.
(gdb) r
Starting program: /home/stefanha/linux-2.6/tools/perf/perf trace
[Thread debugging using libthread_db enabled]

Breakpoint 1, warning (warn=0x463390 "Error: expected type %d but read %d") at util/usage.c:74
74      {
(gdb) bt
#0  warning (warn=0x463390 "Error: expected type %d but read %d") at util/usage.c:74
#1  0x0000000000443123 in __test_type_token (event=0x9d0d40, list=<value optimized out>, tok=<value optimized out>) at util/trace-event-parse.c:639
#2  test_type_token (event=0x9d0d40, list=<value optimized out>, tok=<value optimized out>) at util/trace-event-parse.c:656
#3  process_fields (event=0x9d0d40, list=<value optimized out>, tok=<value optimized out>) at util/trace-event-parse.c:1499
#4  0x0000000000442598 in process_symbols (event=0x9d0d40, arg=0x9d2110, tok=0x7fffffff9fa8, type=<value optimized out>) at util/trace-event-parse.c:1588
#5  process_arg_token (event=0x9d0d40, arg=0x9d2110, tok=0x7fffffff9fa8, type=<value optimized out>) at util/trace-event-parse.c:1703
#6  0x0000000000443cee in process_arg (event=0x9d0d40) at util/trace-event-parse.c:1034
#7  event_read_print_args (event=0x9d0d40) at util/trace-event-parse.c:1774
#8  event_read_print (event=0x9d0d40) at util/trace-event-parse.c:1853
#9  0x0000000000444c0e in parse_event_file (buf=<value optimized out>, size=<value optimized out>, sys=0x9ccf90 "kvm") at util/trace-event-parse.c:3192
#10 0x0000000000445e3d in read_event_file (fd=<value optimized out>, __repipe=<value optimized out>) at util/trace-event-read.c:236
#11 read_event_files (fd=<value optimized out>, __repipe=<value optimized out>) at util/trace-event-read.c:270
#12 trace_report (fd=<value optimized out>, __repipe=<value optimized out>) at util/trace-event-read.c:514
#13 0x0000000000434c52 in perf_file_section__process (self=0x9cc540, ph=0x9cc9a0, feat=1, fd=5) at util/header.c:777
#14 0x0000000000435ad9 in perf_header__process_sections (self=0x9cc9a0, fd=5, process=0x434b80 <perf_file_section__process>) at util/header.c:618
#15 0x0000000000436c31 in perf_header__read (session=0x9cc9a0, fd=5) at util/header.c:893
#16 0x000000000043d566 in perf_session__open (filename=<value optimized out>, mode=0, force=<value optimized out>, repipe=false) at util/session.c:51
#17 perf_session__new (filename=<value optimized out>, mode=0, force=<value optimized out>, repipe=false) at util/session.c:103
#18 0x00000000004169b7 in cmd_trace (argc=0, argv=0x7fffffffe6e0, prefix=<value optimized out>) at builtin-trace.c:666
#19 0x0000000000404dd7 in run_builtin (p=0x66ee58, argc=1, argv=0x7fffffffe6e0) at perf.c:265
#20 0x0000000000405876 in handle_internal_command (argc=1, argv=0x7fffffffe6e0) at perf.c:336
#21 run_argv (argc=1, argv=0x7fffffffe6e0) at perf.c:380
#22 main (argc=1, argv=0x7fffffffe6e0) at perf.c:464
(gdb) p *(struct event*)0x9d0d40
$1 = {next = 0x0, name = 0x9d0d90 "kvm_apic", id = 762, flags = 0, format = {nr_common = 5, nr_fields = 3, common_fields = 0x9d0df0, fields = 0x9d1d20},
  print_fmt = {format = 0x9d1ef0 "apic_%s %s = 0x%x", args = 0x9d1f30}, system = 0x0}

Re: Perf trace event parse errors for KVM events

[Stefan Hajnoczi]

I get parse errors when using Steven Rostedt's trace-cmd tool, too.

Any ideas what is going on here?  I can provide more info (e.g. trace
files) if necessary.

Stefan

Re: Perf trace event parse errors for KVM events

[Marcelo Tosatti]

On Fri, May 28, 2010 at 05:42:51PM +0100, Stefan Hajnoczi wrote:
> I get parse errors when using Steven Rostedt's trace-cmd tool, too.
> 
> Any ideas what is going on here?  I can provide more info (e.g. trace
> files) if necessary.

Non standard print_format for the problematic entries?

Re: Perf trace event parse errors for KVM events

[Steven Rostedt]

On Fri, 2010-05-28 at 17:42 +0100, Stefan Hajnoczi wrote:
> I get parse errors when using Steven Rostedt's trace-cmd tool, too.
> 
> Any ideas what is going on here?  I can provide more info (e.g. trace
> files) if necessary.

Does trace-cmd fail on the same tracepoints? Have you checkout the
latest code?.

I do know it fails on some of the KVM tracerpoints since the formatting
they use is obnoxious.

Could you show the "print-fmt" of the failing events?

Thanks,

-- Steve

Re: Perf trace event parse errors for KVM events

[Stefan Hajnoczi]

On Fri, May 28, 2010 at 05:45:57PM -0400, Steven Rostedt wrote:
> On Fri, 2010-05-28 at 17:42 +0100, Stefan Hajnoczi wrote:
> > I get parse errors when using Steven Rostedt's trace-cmd tool, too.
> > 
> > Any ideas what is going on here?  I can provide more info (e.g. trace
> > files) if necessary.
> 
> Does trace-cmd fail on the same tracepoints? Have you checkout the
> latest code?.

$ sudo trace-cmd record -e kvm:kvm_pio
$ trace-cmd report
version = 6
  bad op token {
  failed to read event print fmt for kvm_mmu_get_page
  bad op token {
  failed to read event print fmt for kvm_mmu_sync_page
  bad op token {
  failed to read event print fmt for kvm_mmu_unsync_page
  bad op token {
  failed to read event print fmt for kvm_mmu_zap_page
  Error: expected type 4 but read 7
  Error: expected type 5 but read 0
  failed to read event print fmt for kvm_apic
  function ftrace_print_symbols_seq not defined
  failed to read event print fmt for kvm_exit
  Error: expected type 4 but read 7
  Error: expected type 5 but read 0
  failed to read event print fmt for kvm_inj_exception
  function ftrace_print_symbols_seq not defined
  failed to read event print fmt for kvm_nested_vmexit
  function ftrace_print_symbols_seq not defined
  failed to read event print fmt for kvm_nested_vmexit_inject
  bad op token {
  failed to read event print fmt for kvm_emulate_insn

These are different from those reported by perf.

Yes, I use trace-cmd.git master branch (currently built from
b530a23f0442be322b1717e6dbce2bd502634cb4).

My kernel is 2.6.34 based.

> I do know it fails on some of the KVM tracerpoints since the formatting
> they use is obnoxious.
> 
> Could you show the "print-fmt" of the failing events?

Here are the details along with my amateur comments on what might have gone wrong:

$ for event in kvmmmu/kvm_mmu_get_page kvmmmu/kvm_mmu_sync_page kvmmmu/kvm_mmu_unsync_page kvmmmu/kvm_mmu_zap_page kvm/kvm_apic kvm/kvm_exit kvm/kvm_inj_exception kvm/kvm_nested_vmexit kvm/kvm_nested_vmexit_inject kvm/kvm_emulate_insn; do echo -n "$event: "; grep 'print fmt:' /sys/kernel/debug/tracing/events/$event/format; done

kvmmmu/kvm_mmu_get_page: print fmt: "%s %s", ({ const char *ret = p->buffer + p->len; static const char *access_str[] = { "---", "--x", "w--", "w-x", "-u-", "-ux", "wu-", "wux" }; union kvm_mmu_page_role role; role.word = REC->role; trace_seq_printf(p, "sp gfn %llx %u%s q%u%s %s%s" " %snxe root %u %s%c", REC->gfn, role.level, role.cr4_pae ? " pae" : "", role.quadrant, role.direct ? " direct" : "", access_str[role.access], role.invalid ? " invalid" : "", role.nxe ? "" : "!", REC->root_count, REC->unsync ? "unsync" : "sync", 0); ret; }), REC->created ? "new" : "existing"
kvmmmu/kvm_mmu_sync_page: print fmt: "%s", ({ const char *ret = p->buffer + p->len; static const char *access_str[] = { "---", "--x", "w--", "w-x", "-u-", "-ux", "wu-", "wux" }; union kvm_mmu_page_role role; role.word = REC->role; trace_seq_printf(p, "sp gfn %llx %u%s q%u%s %s%s" " %snxe root %u %s%c", REC->gfn, role.level, role.cr4_pae ? " pae" : "", role.quadrant, role.direct ? " direct" : "", access_str[role.access], role.invalid ? " invalid" : "", role.nxe ? "" : "!", REC->root_count, REC->unsync ? "unsync" : "sync", 0); ret; })
kvmmmu/kvm_mmu_unsync_page: print fmt: "%s", ({ const char *ret = p->buffer + p->len; static const char *access_str[] = { "---", "--x", "w--", "w-x", "-u-", "-ux", "wu-", "wux" }; union kvm_mmu_page_role role; role.word = REC->role; trace_seq_printf(p, "sp gfn %llx %u%s q%u%s %s%s" " %snxe root %u %s%c", REC->gfn, role.level, role.cr4_pae ? " pae" : "", role.quadrant, role.direct ? " direct" : "", access_str[role.access], role.invalid ? " invalid" : "", role.nxe ? "" : "!", REC->root_count, REC->unsync ? "unsync" : "sync", 0); ret; })
kvmmmu/kvm_mmu_zap_page: print fmt: "%s", ({ const char *ret = p->buffer + p->len; static const char *access_str[] = { "---", "--x", "w--", "w-x", "-u-", "-ux", "wu-", "wux" }; union kvm_mmu_page_role role; role.word = REC->role; trace_seq_printf(p, "sp gfn %llx %u%s q%u%s %s%s" " %snxe root %u %s%c", REC->gfn, role.level, role.cr4_pae ? " pae" : "", role.quadrant, role.direct ? " direct" : "", access_str[role.access], role.invalid ? " invalid" : "", role.nxe ? "" : "!", REC->root_count, REC->unsync ? "unsync" : "sync", 0); ret; })
kvm/kvm_emulate_insn: print fmt: "%x:%llx:%s (%s)%s", REC->csbase, REC->rip, ({ int i; const char *ret = p->buffer + p->len; for (i = 0; i < REC->len; ++i) trace_seq_printf(p, " %02x", REC->insn[i]); trace_seq_printf(p, "%c", 0); ret; }), __print_symbolic(REC->flags, { 0, "real" }, { (1 << 0) | (1 << 1), "vm16" }, { (1 << 0), "prot16" }, { (1 << 0) | (1 << 2), "prot32" }, { (1 << 0) | (1 << 3), "prot64" }), REC->failed ? " failed" : ""

Macro expanded into C code that shouldn't have?

kvm/kvm_apic: print fmt: "apic_%s %s = 0x%x", REC->rw ? "write" : "read", __print_symbolic(REC->reg, { 0x20, "APIC_" "ID" }, { 0x30, "APIC_" "LVR" }, { 0x80, "APIC_" "TASKPRI" }, { 0x90, "APIC_" "ARBPRI" }, { 0xA0, "APIC_" "PROCPRI" }, { 0xB0, "APIC_" "EOI" }, { 0xC0, "APIC_" "RRR" }, { 0xD0, "APIC_" "LDR" }, { 0xE0, "APIC_" "DFR" }, { 0xF0, "APIC_" "SPIV" }, { 0x100, "APIC_" "ISR" }, { 0x180, "APIC_" "TMR" }, { 0x200, "APIC_" "IRR" }, { 0x280, "APIC_" "ESR" }, { 0x300, "APIC_" "ICR" }, { 0x310, "APIC_" "ICR2" }, { 0x320, "APIC_" "LVTT" }, { 0x330, "APIC_" "LVTTHMR" }, { 0x340, "APIC_" "LVTPC" }, { 0x350, "APIC_" "LVT0" }, { 0x360, "APIC_" "LVT1" }, { 0x370, "APIC_" "LVTERR" }, { 0x380, "APIC_" "TMICT" }, { 0x390, "APIC_" "TMCCT" }, { 0x3E0, "APIC_" "TDCR" }, { 0x3F0, "APIC_" "SELF_IPI" }, { 0x400, "APIC_" "EFEAT" }, { 0x410, "APIC_" "ECTRL" }), REC->val
kvm/kvm_inj_exception: print fmt: "%s (0x%x)", __print_symbolic(REC->exception, { 0, "#" "DE" }, { 1, "#" "DB" }, { 3, "#" "BP" }, { 4, "#" "OF" }, { 5, "#" "BR" }, { 6, "#" "UD" }, { 7, "#" "NM" }, { 8, "#" "DF" }, { 10, "#" "TS" }, { 11, "#" "NP" }, { 12, "#" "SS" }, { 13, "#" "GP" }, { 14, "#" "PF" }, { 16, "#" "MF" }, { 18, "#" "MC" }), REC->has_error ? REC->error_code : 0

String literal concatenation not handled by parser?

kvm/kvm_exit: print fmt: "reason %s rip 0x%lx", ftrace_print_symbols_seq(p, REC->exit_reason, kvm_x86_ops->exit_reasons_str), REC->guest_rip
kvm/kvm_nested_vmexit: print fmt: "rip: 0x%016llx reason: %s ext_inf1: 0x%016llx ext_inf2: 0x%016llx ext_int: 0x%08x ext_int_err: 0x%08x", REC->rip, ftrace_print_symbols_seq(p, REC->exit_code, kvm_x86_ops->exit_reasons_str), REC->exit_info1, REC->exit_info2, REC->exit_int_info, REC->exit_int_info_err
kvm/kvm_nested_vmexit_inject: print fmt: "reason: %s ext_inf1: 0x%016llx ext_inf2: 0x%016llx ext_int: 0x%08x ext_int_err: 0x%08x", ftrace_print_symbols_seq(p, REC->exit_code, kvm_x86_ops->exit_reasons_str), REC->exit_info1, REC->exit_info2, REC->exit_int_info, REC->exit_int_info_err

ftrace_print_symbols_seq() not implemented in trace-cmd?

There are four problem cases in scsi too:

  function scsi_trace_parse_cdb not defined
  failed to read event print fmt for scsi_dispatch_cmd_start
  function scsi_trace_parse_cdb not defined
  failed to read event print fmt for scsi_dispatch_cmd_error

/sys/kernel/debug/tracing/events/scsi/scsi_dispatch_cmd_done/format:FORMAT TOO BIG
/sys/kernel/debug/tracing/events/scsi/scsi_dispatch_cmd_timeout/format:FORMAT TOO BIG

Stefan

Re: Perf trace event parse errors for KVM events

[Stefan Hajnoczi]

On Fri, May 28, 2010 at 05:45:57PM -0400, Steven Rostedt wrote:
> On Fri, 2010-05-28 at 17:42 +0100, Stefan Hajnoczi wrote:
> > I get parse errors when using Steven Rostedt's trace-cmd tool, too.
> > 
> > Any ideas what is going on here?  I can provide more info (e.g. trace
> > files) if necessary.
> 
> Does trace-cmd fail on the same tracepoints? Have you checkout the
> latest code?.

$ sudo trace-cmd record -e kvm:kvm_pio
$ trace-cmd report
version = 6
  bad op token {
  failed to read event print fmt for kvm_mmu_get_page
  bad op token {
  failed to read event print fmt for kvm_mmu_sync_page
  bad op token {
  failed to read event print fmt for kvm_mmu_unsync_page
  bad op token {
  failed to read event print fmt for kvm_mmu_zap_page
  Error: expected type 4 but read 7
  Error: expected type 5 but read 0
  failed to read event print fmt for kvm_apic
  function ftrace_print_symbols_seq not defined
  failed to read event print fmt for kvm_exit
  Error: expected type 4 but read 7
  Error: expected type 5 but read 0
  failed to read event print fmt for kvm_inj_exception
  function ftrace_print_symbols_seq not defined
  failed to read event print fmt for kvm_nested_vmexit
  function ftrace_print_symbols_seq not defined
  failed to read event print fmt for kvm_nested_vmexit_inject
  bad op token {
  failed to read event print fmt for kvm_emulate_insn

These are different from those reported by perf.

Yes, I use trace-cmd.git master branch (currently built from
b530a23f0442be322b1717e6dbce2bd502634cb4).

My kernel is 2.6.34 based.

> I do know it fails on some of the KVM tracerpoints since the formatting
> they use is obnoxious.
> 
> Could you show the "print-fmt" of the failing events?

Here are the details along with my amateur comments on what might have gone wrong:

$ for event in kvmmmu/kvm_mmu_get_page kvmmmu/kvm_mmu_sync_page kvmmmu/kvm_mmu_unsync_page kvmmmu/kvm_mmu_zap_page kvm/kvm_apic kvm/kvm_exit kvm/kvm_inj_exception kvm/kvm_nested_vmexit kvm/kvm_nested_vmexit_inject kvm/kvm_emulate_insn; do echo -n "$event: "; grep 'print fmt:' /sys/kernel/debug/tracing/events/$event/format; done

kvmmmu/kvm_mmu_get_page: print fmt: "%s %s", ({ const char *ret = p->buffer + p->len; static const char *access_str[] = { "---", "--x", "w--", "w-x", "-u-", "-ux", "wu-", "wux" }; union kvm_mmu_page_role role; role.word = REC->role; trace_seq_printf(p, "sp gfn %llx %u%s q%u%s %s%s" " %snxe root %u %s%c", REC->gfn, role.level, role.cr4_pae ? " pae" : "", role.quadrant, role.direct ? " direct" : "", access_str[role.access], role.invalid ? " invalid" : "", role.nxe ? "" : "!", REC->root_count, REC->unsync ? "unsync" : "sync", 0); ret; }), REC->created ? "new" : "existing"
kvmmmu/kvm_mmu_sync_page: print fmt: "%s", ({ const char *ret = p->buffer + p->len; static const char *access_str[] = { "---", "--x", "w--", "w-x", "-u-", "-ux", "wu-", "wux" }; union kvm_mmu_page_role role; role.word = REC->role; trace_seq_printf(p, "sp gfn %llx %u%s q%u%s %s%s" " %snxe root %u %s%c", REC->gfn, role.level, role.cr4_pae ? " pae" : "", role.quadrant, role.direct ? " direct" : "", access_str[role.access], role.invalid ? " invalid" : "", role.nxe ? "" : "!", REC->root_count, REC->unsync ? "unsync" : "sync", 0); ret; })
kvmmmu/kvm_mmu_unsync_page: print fmt: "%s", ({ const char *ret = p->buffer + p->len; static const char *access_str[] = { "---", "--x", "w--", "w-x", "-u-", "-ux", "wu-", "wux" }; union kvm_mmu_page_role role; role.word = REC->role; trace_seq_printf(p, "sp gfn %llx %u%s q%u%s %s%s" " %snxe root %u %s%c", REC->gfn, role.level, role.cr4_pae ? " pae" : "", role.quadrant, role.direct ? " direct" : "", access_str[role.access], role.invalid ? " invalid" : "", role.nxe ? "" : "!", REC->root_count, REC->unsync ? "unsync" : "sync", 0); ret; })
kvmmmu/kvm_mmu_zap_page: print fmt: "%s", ({ const char *ret = p->buffer + p->len; static const char *access_str[] = { "---", "--x", "w--", "w-x", "-u-", "-ux", "wu-", "wux" }; union kvm_mmu_page_role role; role.word = REC->role; trace_seq_printf(p, "sp gfn %llx %u%s q%u%s %s%s" " %snxe root %u %s%c", REC->gfn, role.level, role.cr4_pae ? " pae" : "", role.quadrant, role.direct ? " direct" : "", access_str[role.access], role.invalid ? " invalid" : "", role.nxe ? "" : "!", REC->root_count, REC->unsync ? "unsync" : "sync", 0); ret; })
kvm/kvm_emulate_insn: print fmt: "%x:%llx:%s (%s)%s", REC->csbase, REC->rip, ({ int i; const char *ret = p->buffer + p->len; for (i = 0; i < REC->len; ++i) trace_seq_printf(p, " %02x", REC->insn[i]); trace_seq_printf(p, "%c", 0); ret; }), __print_symbolic(REC->flags, { 0, "real" }, { (1 << 0) | (1 << 1), "vm16" }, { (1 << 0), "prot16" }, { (1 << 0) | (1 << 2), "prot32" }, { (1 << 0) | (1 << 3), "prot64" }), REC->failed ? " failed" : ""

Macro expanded into C code that shouldn't have?

kvm/kvm_apic: print fmt: "apic_%s %s = 0x%x", REC->rw ? "write" : "read", __print_symbolic(REC->reg, { 0x20, "APIC_" "ID" }, { 0x30, "APIC_" "LVR" }, { 0x80, "APIC_" "TASKPRI" }, { 0x90, "APIC_" "ARBPRI" }, { 0xA0, "APIC_" "PROCPRI" }, { 0xB0, "APIC_" "EOI" }, { 0xC0, "APIC_" "RRR" }, { 0xD0, "APIC_" "LDR" }, { 0xE0, "APIC_" "DFR" }, { 0xF0, "APIC_" "SPIV" }, { 0x100, "APIC_" "ISR" }, { 0x180, "APIC_" "TMR" }, { 0x200, "APIC_" "IRR" }, { 0x280, "APIC_" "ESR" }, { 0x300, "APIC_" "ICR" }, { 0x310, "APIC_" "ICR2" }, { 0x320, "APIC_" "LVTT" }, { 0x330, "APIC_" "LVTTHMR" }, { 0x340, "APIC_" "LVTPC" }, { 0x350, "APIC_" "LVT0" }, { 0x360, "APIC_" "LVT1" }, { 0x370, "APIC_" "LVTERR" }, { 0x380, "APIC_" "TMICT" }, { 0x390, "APIC_" "TMCCT" }, { 0x3E0, "APIC_" "TDCR" }, { 0x3F0, "APIC_" "SELF_IPI" },
  { 0x400, "APIC_" "EFEAT" }, { 0x410, "APIC_" "ECTRL" }), REC->val
kvm/kvm_inj_exception: print fmt: "%s (0x%x)", __print_symbolic(REC->exception, { 0, "#" "DE" }, { 1, "#" "DB" }, { 3, "#" "BP" }, { 4, "#" "OF" }, { 5, "#" "BR" }, { 6, "#" "UD" }, { 7, "#" "NM" }, { 8, "#" "DF" }, { 10, "#" "TS" }, { 11, "#" "NP" }, { 12, "#" "SS" }, { 13, "#" "GP" }, { 14, "#" "PF" }, { 16, "#" "MF" }, { 18, "#" "MC" }), REC->has_error ? REC->error_code : 0

String literal concatenation not handled by parser?

kvm/kvm_exit: print fmt: "reason %s rip 0x%lx", ftrace_print_symbols_seq(p, REC->exit_reason, kvm_x86_ops->exit_reasons_str), REC->guest_rip
kvm/kvm_nested_vmexit: print fmt: "rip: 0x%016llx reason: %s ext_inf1: 0x%016llx ext_inf2: 0x%016llx ext_int: 0x%08x ext_int_err: 0x%08x", REC->rip, ftrace_print_symbols_seq(p, REC->exit_code, kvm_x86_ops->exit_reasons_str), REC->exit_info1, REC->exit_info2, REC->exit_int_info, REC->exit_int_info_err
kvm/kvm_nested_vmexit_inject: print fmt: "reason: %s ext_inf1: 0x%016llx ext_inf2: 0x%016llx ext_int: 0x%08x ext_int_err: 0x%08x", ftrace_print_symbols_seq(p, REC->exit_code, kvm_x86_ops->exit_reasons_str), REC->exit_info1, REC->exit_info2, REC->exit_int_info, REC->exit_int_info_err

ftrace_print_symbols_seq() not implemented in trace-cmd?

There are four problem cases in scsi too:

  function scsi_trace_parse_cdb not defined
  failed to read event print fmt for scsi_dispatch_cmd_start
  function scsi_trace_parse_cdb not defined
  failed to read event print fmt for scsi_dispatch_cmd_error

/sys/kernel/debug/tracing/events/scsi/scsi_dispatch_cmd_done/format:FORMAT TOO BIG
/sys/kernel/debug/tracing/events/scsi/scsi_dispatch_cmd_timeout/format:FORMAT TOO BIG

Stefan

Re: Perf trace event parse errors for KVM events

[Avi Kivity]

On 05/29/2010 12:45 AM, Steven Rostedt wrote:
> On Fri, 2010-05-28 at 17:42 +0100, Stefan Hajnoczi wrote:
>    
>> I get parse errors when using Steven Rostedt's trace-cmd tool, too.
>>
>> Any ideas what is going on here?  I can provide more info (e.g. trace
>> files) if necessary.
>>      
> Does trace-cmd fail on the same tracepoints? Have you checkout the
> latest code?.
>
> I do know it fails on some of the KVM tracerpoints since the formatting
> they use is obnoxious.
>
>    

Isn't there a binary trace for this?

-- 
I have a truly marvellous patch that fixes the bug which this
signature is too narrow to contain.

Re: Perf trace event parse errors for KVM events

[Steven Rostedt]

On Sat, 2010-05-29 at 14:50 +0300, Avi Kivity wrote:
> On 05/29/2010 12:45 AM, Steven Rostedt wrote:
> > On Fri, 2010-05-28 at 17:42 +0100, Stefan Hajnoczi wrote:
> >    
> >> I get parse errors when using Steven Rostedt's trace-cmd tool, too.
> >>
> >> Any ideas what is going on here?  I can provide more info (e.g. trace
> >> files) if necessary.
> >>      
> > Does trace-cmd fail on the same tracepoints? Have you checkout the
> > latest code?.
> >
> > I do know it fails on some of the KVM tracerpoints since the formatting
> > they use is obnoxious.
> >
> >    
> 
> Isn't there a binary trace for this?
> 

The pretty printing from the kernel handles this fine. But there's
pressure to pass the format to userspace in binary and have the tool
parse it. Currently it uses the print fmt to figure out how to parse.

Using one of the examples that Stefan showed:

kvmmmu/kvm_mmu_get_page: print fmt: "%s %s", ({ const char *ret =
p->buffer + p->len; static const char *access_str[] = { "---", "--x",
"w--", "w-x", "-u-", "-ux", "wu-", "wux" }; union kvm_mmu_page_role
role; role.word = REC->role; trace_seq_printf(p, "sp gfn %llx %u%s q%u%s
%s%s" " %snxe root %u %s%c", REC->gfn, role.level, role.cr4_pae ? "
pae" : "", role.quadrant, role.direct ? " direct" : "",
access_str[role.access], role.invalid ? " invalid" : "", role.nxe ? "" :
"!", REC->root_count, REC->unsync ? "unsync" : "sync", 0); ret; }),
REC->created ? "new" : "existing"


You need a full C parser/interpreter to understand the above.

-- Steve

Re: Perf trace event parse errors for KVM events

[Avi Kivity]

On 05/29/2010 04:19 PM, Steven Rostedt wrote:
> On Sat, 2010-05-29 at 14:50 +0300, Avi Kivity wrote:
>    
>> On 05/29/2010 12:45 AM, Steven Rostedt wrote:
>>      
>>> On Fri, 2010-05-28 at 17:42 +0100, Stefan Hajnoczi wrote:
>>>
>>>        
>>>> I get parse errors when using Steven Rostedt's trace-cmd tool, too.
>>>>
>>>> Any ideas what is going on here?  I can provide more info (e.g. trace
>>>> files) if necessary.
>>>>
>>>>          
>>> Does trace-cmd fail on the same tracepoints? Have you checkout the
>>> latest code?.
>>>
>>> I do know it fails on some of the KVM tracerpoints since the formatting
>>> they use is obnoxious.
>>>
>>>
>>>        
>> Isn't there a binary trace for this?
>>
>>      
> The pretty printing from the kernel handles this fine. But there's
> pressure to pass the format to userspace in binary and have the tool
> parse it. Currently it uses the print fmt to figure out how to parse.
>
> Using one of the examples that Stefan showed:
>
> kvmmmu/kvm_mmu_get_page: print fmt: "%s %s", ({ const char *ret =
> p->buffer + p->len; static const char *access_str[] = { "---", "--x",
> "w--", "w-x", "-u-", "-ux", "wu-", "wux" }; union kvm_mmu_page_role
> role; role.word = REC->role; trace_seq_printf(p, "sp gfn %llx %u%s q%u%s
> %s%s" " %snxe root %u %s%c", REC->gfn, role.level, role.cr4_pae ? "
> pae" : "", role.quadrant, role.direct ? " direct" : "",
> access_str[role.access], role.invalid ? " invalid" : "", role.nxe ? "" :
> "!", REC->root_count, REC->unsync ? "unsync" : "sync", 0); ret; }),
> REC->created ? "new" : "existing"
>
>
> You need a full C parser/interpreter to understand the above.
>    

Right.  The tools can fall back to %x/%s based on the structure 
descriptor if they can't parse the format string.

-- 
error compiling committee.c: too many arguments to function

Re: Perf trace event parse errors for KVM events

[Steven Rostedt]

On Sun, 2010-05-30 at 11:10 +0300, Avi Kivity wrote:
> On 05/29/2010 04:19 PM, Steven Rostedt wrote:
>     
> > The pretty printing from the kernel handles this fine. But there's
> > pressure to pass the format to userspace in binary and have the tool
> > parse it. Currently it uses the print fmt to figure out how to parse.
> >
> > Using one of the examples that Stefan showed:
> >
> > kvmmmu/kvm_mmu_get_page: print fmt: "%s %s", ({ const char *ret =
> > p->buffer + p->len; static const char *access_str[] = { "---", "--x",
> > "w--", "w-x", "-u-", "-ux", "wu-", "wux" }; union kvm_mmu_page_role
> > role; role.word = REC->role; trace_seq_printf(p, "sp gfn %llx %u%s q%u%s
> > %s%s" " %snxe root %u %s%c", REC->gfn, role.level, role.cr4_pae ? "
> > pae" : "", role.quadrant, role.direct ? " direct" : "",
> > access_str[role.access], role.invalid ? " invalid" : "", role.nxe ? "" :
> > "!", REC->root_count, REC->unsync ? "unsync" : "sync", 0); ret; }),
> > REC->created ? "new" : "existing"
> >
> >
> > You need a full C parser/interpreter to understand the above.
> >    
> 
> Right.  The tools can fall back to %x/%s based on the structure 
> descriptor if they can't parse the format string.
> 

trace-cmd has plugin support to override how to read the format and
print it out. It now has the ability to write those plugins in python.

-- Steve

Re: Perf trace event parse errors for KVM events

[Avi Kivity]

On 05/30/2010 05:03 PM, Steven Rostedt wrote:
>
>> Right.  The tools can fall back to %x/%s based on the structure
>> descriptor if they can't parse the format string.
>>
>>      
> trace-cmd has plugin support to override how to read the format and
> print it out. It now has the ability to write those plugins in python.
>    

Cool.  May make sense to use simpler formatting in the kernel, and use 
trace-cmd plugins for the complicated cases.

It does raise issues with ABIs.  Can trace-cmd read plugins from 
/lib/modules/*?  We can then distribute the plugins with the kernel.

-- 
error compiling committee.c: too many arguments to function

Re: Perf trace event parse errors for KVM events

[Steven Rostedt]

On Sun, 2010-05-30 at 17:07 +0300, Avi Kivity wrote:
> On 05/30/2010 05:03 PM, Steven Rostedt wrote:
> >
> >> Right.  The tools can fall back to %x/%s based on the structure
> >> descriptor if they can't parse the format string.
> >>
> >>      
> > trace-cmd has plugin support to override how to read the format and
> > print it out. It now has the ability to write those plugins in python.
> >    
> 
> Cool.  May make sense to use simpler formatting in the kernel, and use 
> trace-cmd plugins for the complicated cases.
> 
> It does raise issues with ABIs.  Can trace-cmd read plugins from 
> /lib/modules/*?  We can then distribute the plugins with the kernel.
> 

We probably could do that. Perhaps if we can port the python code to
perf, then it would work for both. Then the plugins could be just python
scripts, (or binary .so modules) and have a tools/plugins dir?

The python part probably would be easier to port, since the .so modules
are a bit more specific to trace-cmd.

-- Steve

Re: Perf trace event parse errors for KVM events

[Avi Kivity]

On 05/30/2010 06:34 PM, Steven Rostedt wrote:
>
>> Cool.  May make sense to use simpler formatting in the kernel, and use
>> trace-cmd plugins for the complicated cases.
>>
>> It does raise issues with ABIs.  Can trace-cmd read plugins from
>> /lib/modules/*?  We can then distribute the plugins with the kernel.
>>
>>      
> We probably could do that. Perhaps if we can port the python code to
> perf, then it would work for both. Then the plugins could be just python
> scripts, (or binary .so modules) and have a tools/plugins dir?
>
> The python part probably would be easier to port, since the .so modules
> are a bit more specific to trace-cmd.
>    

One concern is performance.  Traces tend to be long, and running python 
code on each line will be slow.

If trace-cmd integrates a pager and a search mechanism that looks at the 
binary data instead of the text, we could format only the lines that are 
displayed.  But that is going to be a lot of work and I don't think it's 
worth the effort.

-- 
error compiling committee.c: too many arguments to function

Re: Perf trace event parse errors for KVM events

[Steven Rostedt]

On Tue, 2010-06-01 at 11:39 +0300, Avi Kivity wrote:
> On 05/30/2010 06:34 PM, Steven Rostedt wrote:
> >
> >> Cool.  May make sense to use simpler formatting in the kernel, and use
> >> trace-cmd plugins for the complicated cases.
> >>
> >> It does raise issues with ABIs.  Can trace-cmd read plugins from
> >> /lib/modules/*?  We can then distribute the plugins with the kernel.
> >>
> >>      
> > We probably could do that. Perhaps if we can port the python code to
> > perf, then it would work for both. Then the plugins could be just python
> > scripts, (or binary .so modules) and have a tools/plugins dir?
> >
> > The python part probably would be easier to port, since the .so modules
> > are a bit more specific to trace-cmd.
> >    
> 
> One concern is performance.  Traces tend to be long, and running python 
> code on each line will be slow.
> 
> If trace-cmd integrates a pager and a search mechanism that looks at the 
> binary data instead of the text, we could format only the lines that are 
> displayed.  But that is going to be a lot of work and I don't think it's 
> worth the effort.
> 

Every event gets its own ID. The plugin registers a callback to that ID.
When the ID is hit, the plugin is executed on that event to display its
binary format.

This is done after the data has been saved in binary format to a file.
It may slow down the executing of reading a data file, but it does not
affect the running of the trace one bit.

-- Steve

Re: Perf trace event parse errors for KVM events

[Avi Kivity]

On 06/01/2010 02:59 PM, Steven Rostedt wrote:
>
>> One concern is performance.  Traces tend to be long, and running python
>> code on each line will be slow.
>>
>> If trace-cmd integrates a pager and a search mechanism that looks at the
>> binary data instead of the text, we could format only the lines that are
>> displayed.  But that is going to be a lot of work and I don't think it's
>> worth the effort.
>>
>>      
> Every event gets its own ID. The plugin registers a callback to that ID.
> When the ID is hit, the plugin is executed on that event to display its
> binary format.
>
> This is done after the data has been saved in binary format to a file.
> It may slow down the executing of reading a data file, but it does not
> affect the running of the trace one bit.
>    

I meant that viewing would be slowed down.  It's an important part of 
using ftrace!

How long does the Python formatter take to process 100k or 1M events?

-- 
error compiling committee.c: too many arguments to function

Re: Perf trace event parse errors for KVM events

[Steven Rostedt]

On Tue, 2010-06-01 at 15:39 +0300, Avi Kivity wrote:
> On 06/01/2010 02:59 PM, Steven Rostedt wrote:

> I meant that viewing would be slowed down.  It's an important part of 
> using ftrace!
> 
> How long does the Python formatter take to process 100k or 1M events?
> 

I finally got around to testing this.

I ran a trace on lock_acquire, and traced 1,253,296 events.

I then created a python plugin to analyze the trace:

----
def lock_acquire(trace_seq, event):
    t = ''
    r = ''
    if int(event['flags']) & 1:
        t = 'try'
    if int(event['flags']) & 2:
        r = 'read'
    trace_seq.puts('t %x %s%s%s' % (
            event['lockdep_addr'], t, r,
            event['name']))

def register(pevent):
    pevent.register_event_handler("lock", "lock_acquire", lock_acquire)
----

Disclaimer, I'm not a python expert, and I'm sure the above python code
sucks.


[root@ixf9 trace-cmd.git]# time ./trace-cmd report -N >/dev/null 2>&1

real	0m4.653s
user	0m4.234s
sys	0m0.419s

* -N keeps trace-cmd from loading any plugins.


[root@ixf9 trace-cmd.git]# time PYTHONPATH=`pwd` ./trace-cmd report >/dev/null 2>&1

real	0m53.916s
user	0m53.047s
sys	0m0.859s


Yes, running a python interpreter is a bit more expensive. It took 4
seconds to read the million events with plain C, but 53 seconds to read
it in python.

That said...  This would only affect you if you were writing this to a
file. I doubt that you would notice this if you were scanning the trace
with less.

Also, I kicked this off in kernelshark, and it made no difference that I
can see. This is because kernelshark only evaluates the viewable area of
the screen.

-- Steve

Re: Perf trace event parse errors for KVM events

[Avi Kivity]

On 06/04/2010 12:57 AM, Steven Rostedt wrote:
> On Tue, 2010-06-01 at 15:39 +0300, Avi Kivity wrote:
>    
>> On 06/01/2010 02:59 PM, Steven Rostedt wrote:
>>      
>    
>> I meant that viewing would be slowed down.  It's an important part of
>> using ftrace!
>>
>> How long does the Python formatter take to process 100k or 1M events?
>>
>>      
> I finally got around to testing this.
>
> I ran a trace on lock_acquire, and traced 1,253,296 events.
>
> I then created a python plugin to analyze the trace:
>
> ----
> def lock_acquire(trace_seq, event):
>      t = ''
>      r = ''
>      if int(event['flags'])&  1:
>          t = 'try'
>      if int(event['flags'])&  2:
>          r = 'read'
>      trace_seq.puts('t %x %s%s%s' % (
>              event['lockdep_addr'], t, r,
>              event['name']))
>
> def register(pevent):
>      pevent.register_event_handler("lock", "lock_acquire", lock_acquire)
> ----
>
> Disclaimer, I'm not a python expert, and I'm sure the above python code
> sucks.
>    

I think Python more or less guarantees your code will suck no matter 
what you do.

> [root@ixf9 trace-cmd.git]# time ./trace-cmd report -N>/dev/null 2>&1
>
> real	0m4.653s
> user	0m4.234s
> sys	0m0.419s
>
> * -N keeps trace-cmd from loading any plugins.
>
>
> [root@ixf9 trace-cmd.git]# time PYTHONPATH=`pwd` ./trace-cmd report>/dev/null 2>&1
>
> real	0m53.916s
> user	0m53.047s
> sys	0m0.859s
>
>
> Yes, running a python interpreter is a bit more expensive. It took 4
> seconds to read the million events with plain C, but 53 seconds to read
> it in python.
>
> That said...  This would only affect you if you were writing this to a
> file. I doubt that you would notice this if you were scanning the trace
> with less.
>    

I'm more worried about searching with less.  But a minute for a million 
events isn't that bad.

> Also, I kicked this off in kernelshark, and it made no difference that I
> can see. This is because kernelshark only evaluates the viewable area of
> the screen.
>    

Neat.  Can it also search?  Where can I find it? <googles, finds, gawks>

-- 
error compiling committee.c: too many arguments to function

Re: Perf trace event parse errors for KVM events

[Steven Rostedt]

On Sun, 2010-06-06 at 11:08 +0300, Avi Kivity wrote:

> > Also, I kicked this off in kernelshark, and it made no difference that I
> > can see. This is because kernelshark only evaluates the viewable area of
> > the screen.
> >    
> 
> Neat.  Can it also search?  Where can I find it? <googles, finds, gawks>
> 

It's in the same repo as trace-cmd:

git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/trace-cmd.git

I'm still working on it. The latest is in the branch kernelshark-devel.

And yes, it does searches.

-- Steve

Re: Perf trace event parse errors for KVM events

[Avi Kivity]

On 06/06/2010 06:02 PM, Steven Rostedt wrote:
> On Sun, 2010-06-06 at 11:08 +0300, Avi Kivity wrote:
>
>    
>>> Also, I kicked this off in kernelshark, and it made no difference that I
>>> can see. This is because kernelshark only evaluates the viewable area of
>>> the screen.
>>>
>>>        
>> Neat.  Can it also search?  Where can I find it?<googles, finds, gawks>
>>
>>      
> It's in the same repo as trace-cmd:
>
> git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/trace-cmd.git
>
> I'm still working on it. The latest is in the branch kernelshark-devel.
>
> And yes, it does searches.
>    

I'll be tracking it.

In case you're interested in wishlists, my #1 would be to be able to 
initiate traces from the GUI (so it's easy to explore the available 
trace events and enable them interactively).

-- 
error compiling committee.c: too many arguments to function