trace-cmd errors on kvm events

DISCUSSION David Ahern 4 participants 10 messages Apr 8, 2011 – Apr 21, 2011 KVM

lore

Share & tools

lore

David Ahern

author

2011-04-08 18:53 UTC #0 lore raw

2.6.38.2 kernel with trace-cmd git pulled this morning:

trace-cmd record -e kvm

trace-cmd report 2>&1 | less

trace-cmd: No such file or directory
function ftrace_print_symbols_seq not defined failed to read event print fmt for kvm_nested_vmexit_inject 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_exit
bad op token {
failed to read event print fmt for kvm_emulate_insn

        qemu-kvm-1864  [002]  2253.714134: kvm_entry:            vcpu 1
        qemu-kvm-1863  [008]  2253.714136: kvm_exit:             [FAILED
TO PARSE] exit_reason=44 guest_rip=0xc01185ed isa=1 info1=4272 info2=0
        qemu-kvm-1864  [002]  2253.714138: kvm_exit:             [FAILED
TO PARSE] exit_reason=44 guest_rip=0xc01185ed isa=1 info1=4272 info2=0
        qemu-kvm-1863  [008]  2253.714145: kvm_emulate_insn:     [FAILED

TO PARSE] rip=3222373869 csbase=0 len=2 insn=<89>^H]<C3><8B>^U<EC><95>K<C0>U <89><E5>]<8D>^E flags=5 failed=0

I have not used trace-cmd much, so I am not familiar with the code. Is this a known issue? Suggestions on how to debug?

Thanks,
David

Stefan Hajnoczi

2011-04-08 20:50 UTC #1 lore raw

Quoted 25 lines · David Ahern

2.6.38.2 kernel with trace-cmd git pulled this morning:
trace-cmd record -e kvm
trace-cmd report 2>&1 | less
trace-cmd: No such file or directory
function ftrace_print_symbols_seq not defined failed to read event print fmt for kvm_nested_vmexit_inject 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_exit
bad op token {
failed to read event print fmt for kvm_emulate_insn
qemu-kvm-1864 [002] 2253.714134: kvm_entry: vcpu 1 qemu-kvm-1863 [008] 2253.714136: kvm_exit: [FAILED TO PARSE] exit_reason=44 guest_rip=0xc01185ed isa=1 info1=4272 info2=0 qemu-kvm-1864 [002] 2253.714138: kvm_exit: [FAILED TO PARSE] exit_reason=44 guest_rip=0xc01185ed isa=1 info1=4272 info2=0 qemu-kvm-1863 [008] 2253.714145: kvm_emulate_insn: [FAILED TO PARSE] rip=3222373869 csbase=0 len=2 insn=<89>^H]<C3><8B>^U<EC><95>K<C0>U <89><E5>]<8D>^E flags=5 failed=0

Quoted 2 lines

I have not used trace-cmd much, so I am not familiar with the code. Is this a known issue? Suggestions on how to debug?

I think there have been issues for a long time. I've never gotten perf or trace-cmd to be happy with kvm:* events. Here is a related thread from a while back:

https://lkml.org/lkml/2010/5/26/194

When I looked a while back the problem was due to how there is some preprocessor magic in Linux that ends up exporting C expressions as strings to userspace and neither perf nor trace-cmd have the parsing smarts to evaluate the C expressions at runtime.

I ended up using ftrace instead which handles everything inside the kernel and compiles in those C expressions.

Stefan

David Ahern

author

2011-04-08 20:59 UTC #2 lore raw

Quoted 33 lines · Stefan Hajnoczi

Quoted 22 lines · David Ahern
2.6.38.2 kernel with trace-cmd git pulled this morning:
trace-cmd record -e kvm
trace-cmd report 2>&1 | less
trace-cmd: No such file or directory
function ftrace_print_symbols_seq not defined failed to read event print fmt for kvm_nested_vmexit_inject 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_exit
bad op token {
failed to read event print fmt for kvm_emulate_insn
       qemu-kvm-1864  [002]  2253.714134: kvm_entry:            vcpu 1
       qemu-kvm-1863  [008]  2253.714136: kvm_exit:             [FAILED
TO PARSE] exit_reason=44 guest_rip=0xc01185ed isa=1 info1=4272 info2=0
       qemu-kvm-1864  [002]  2253.714138: kvm_exit:             [FAILED
TO PARSE] exit_reason=44 guest_rip=0xc01185ed isa=1 info1=4272 info2=0
       qemu-kvm-1863  [008]  2253.714145: kvm_emulate_insn:     [FAILED
Quoted 5 lines
TO PARSE] rip=3222373869 csbase=0 len=2 insn=<89>^H]<C3><8B>^U<EC><95>K<C0>U <89><E5>]<8D>^E flags=5 failed=0
I have not used trace-cmd much, so I am not familiar with the code. Is this a known issue? Suggestions on how to debug?
I think there have been issues for a long time. I've never gotten perf or trace-cmd to be happy with kvm:* events. Here is a related thread from a while back:

Quoted 6 lines

https://lkml.org/lkml/2010/5/26/194
When I looked a while back the problem was due to how there is some preprocessor magic in Linux that ends up exporting C expressions as strings to userspace and neither perf nor trace-cmd have the parsing smarts to evaluate the C expressions at runtime.

Hmm.. ok. I thought it had been added - to trace-cmd at least. And I recall Avi recently sending a patch to trace-cmd folks - I took that to mean it works. Evidently, not.

David

Quoted 5 lines

I ended up using ftrace instead which handles everything inside the kernel and compiles in those C expressions.
Stefan

Jan Kiszka

2011-04-08 21:07 UTC #3 lore raw

In reply to David Ahern

Quoted 7 lines · David Ahern

2.6.38.2 kernel with trace-cmd git pulled this morning:
trace-cmd record -e kvm
trace-cmd report 2>&1 | less
trace-cmd: No such file or directory

Does this error come from trace-cmd failing to find its kvm plugin? Check what strace -e open says.

Jan

David Ahern

author

2011-04-08 21:12 UTC #4 lore raw

Quoted 5 lines · Jan Kiszka

Quoted 4 lines · David Ahern
2.6.38.2 kernel with trace-cmd git pulled this morning:
trace-cmd record -e kvm

Quoted 9 lines

Quoted 3 lines
trace-cmd report 2>&1 | less
trace-cmd: No such file or directory
Does this error come from trace-cmd failing to find its kvm plugin? Check what strace -e open says.
Jan

Tried that before - it was not enlightening.
strace -e trace=open trace-cmd report 2>&1 | less

open("/etc/ld.so.cache", O_RDONLY)      = 3
open("/lib64/libdl.so.2", O_RDONLY)     = 3
open("/lib64/libc.so.6", O_RDONLY)      = 3
open("/root/trace.dat", O_RDONLY)       = 3

David

Jan Kiszka

2011-04-08 21:18 UTC #5 lore raw

Quoted 25 lines · David Ahern

Quoted 5 lines · Jan Kiszka
Quoted 4 lines · David Ahern
2.6.38.2 kernel with trace-cmd git pulled this morning:
trace-cmd record -e kvm
Quoted 9 lines
Quoted 3 lines
trace-cmd report 2>&1 | less
trace-cmd: No such file or directory
Does this error come from trace-cmd failing to find its kvm plugin? Check what strace -e open says.
Jan
Tried that before - it was not enlightening.
strace -e trace=open trace-cmd report 2>&1 | less
open("/etc/ld.so.cache", O_RDONLY)      = 3
open("/lib64/libdl.so.2", O_RDONLY)     = 3
open("/lib64/libc.so.6", O_RDONLY)      = 3
open("/root/trace.dat", O_RDONLY)       = 3

Quoted 10 lines

trace-cmd: No such file or directory
function ftrace_print_symbols_seq not defined failed to read event print fmt for kvm_nested_vmexit_inject 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_exit
bad op token {
failed to read event print fmt for kvm_emulate_insn
open("/proc/meminfo", O_RDONLY) = 4

Let me check... indeed, I'm getting the same file-not-found here with trace-cmd.git 9cce1c9b5b when starting it directly from its build directory.

But maybe your trace-cmd or kernel versions are too old / incompatible. I'm not getting complaints about unparseable events with the above snapshot and 2.6.38.

Jan

David Ahern

author

2011-04-08 23:26 UTC #6 lore raw

Quoted 6 lines · Jan Kiszka

Let me check... indeed, I'm getting the same file-not-found here with trace-cmd.git 9cce1c9b5b when starting it directly from its build directory.
But maybe your trace-cmd or kernel versions are too old / incompatible. I'm not getting complaints about unparseable events with the above snapshot and 2.6.38.

2.6.38.2 kernel, trace-cmd 3e8b5b8 which is March 18 (though git pull done this morning).

For grins I checked-out 9cce1c9b5b and same error:
trace-cmd record -e kvm -- sleep 1 trace-cmd report 2>&1 | less

You do have to put stderr onto stdout to see the messages I reported earlier. Or look for [FAILED TO PARSE] on the kvm_exit and kvm_emulate_insn lines.

David

Jan Kiszka

2011-04-08 23:42 UTC #7 lore raw

Quoted 11 lines · David Ahern

Quoted 6 lines · Jan Kiszka
Let me check... indeed, I'm getting the same file-not-found here with trace-cmd.git 9cce1c9b5b when starting it directly from its build directory.
But maybe your trace-cmd or kernel versions are too old / incompatible. I'm not getting complaints about unparseable events with the above snapshot and 2.6.38.
2.6.38.2 kernel, trace-cmd 3e8b5b8 which is March 18 (though git pull done this morning).

Quoted 7 lines

For grins I checked-out 9cce1c9b5b and same error:
trace-cmd record -e kvm -- sleep 1 trace-cmd report 2>&1 | less
You do have to put stderr onto stdout to see the messages I reported earlier. Or look for [FAILED TO PARSE] on the kvm_exit and kvm_emulate_insn lines.

I did that.

What I also did is updating trace-cmd git and then reinstalling the latest plugins: make install_plugins prefix=$HOME. They then end up in $HOME/.trace-cmd/plugins. Now I do not have a single error message anymore, including that file not found.

Jan

David Ahern

author

2011-04-08 23:58 UTC #8 lore raw

Quoted 4 lines · Jan Kiszka

What I also did is updating trace-cmd git and then reinstalling the latest plugins: make install_plugins prefix=$HOME. They then end up in $HOME/.trace-cmd/plugins. Now I do not have a single error message anymore, including that file not found.

Indeed. That did the trick. I was just running out of the build directory -- without doing an install of any kind.

Steven Rostedt

2011-04-21 21:37 UTC #9 lore raw

In reply to Jan Kiszka

Quoted 12 lines · Jan Kiszka

Quoted 7 lines · David Ahern
2.6.38.2 kernel with trace-cmd git pulled this morning:
trace-cmd record -e kvm
trace-cmd report 2>&1 | less
trace-cmd: No such file or directory
Does this error come from trace-cmd failing to find its kvm plugin? Check what strace -e open says.

I need to spend some time and fix it. That "No such file or directory" is from the way trace-cmd does error handling. It checks if errno is set and if so, it prints out perror(). What usually happens is I do a stat() on a file which sets errno, and forget about it. Then if trace-cmd finds some internal error, it calls the warning() message, which then prints out the stale errno.

-- Steve