Perf trace event parse errors for KVM events
in [Kernel]
|
Prev: [PATCH] dynamic_debug: allow to set dynamic debug flags right at module load time
Next: [PATCH] writeback: fix non-integrity write-back
From: Stefan Hajnoczi on 26 May 2010 08:40 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} -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo(a)vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
From: Stefan Hajnoczi on 28 May 2010 12:50 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 -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo(a)vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
From: Marcelo Tosatti on 28 May 2010 17:40 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? -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo(a)vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
From: Steven Rostedt on 28 May 2010 17:50 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 -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo(a)vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
From: Stefan Hajnoczi on 29 May 2010 04:30
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 -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo(a)vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/ |