trace-cmd errors on kvm events

trace-cmd errors on kvm events

[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

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

Re: trace-cmd errors on kvm events

[Stefan Hajnoczi]

On Fri, Apr 8, 2011 at 7:53 PM, David Ahern <dsahern@gmail.com> wrote:
> 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?

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

Re: trace-cmd errors on kvm events

[David Ahern]

On 04/08/11 14:50, Stefan Hajnoczi wrote:
> On Fri, Apr 8, 2011 at 7:53 PM, David Ahern <dsahern@gmail.com> wrote:
>> 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?
> 
> 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.

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


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

Re: trace-cmd errors on kvm events

[Jan Kiszka]

[-- Attachment #1: Type: text/plain, Size: 324 bytes --]

On 2011-04-08 20:53, David Ahern wrote:
> 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


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 259 bytes --]

Re: trace-cmd errors on kvm events

[David Ahern]

On 04/08/11 15:07, Jan Kiszka wrote:
> On 2011-04-08 20:53, David Ahern wrote:
>> 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
> 

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
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

David

Re: trace-cmd errors on kvm events

[Jan Kiszka]

[-- Attachment #1: Type: text/plain, Size: 1553 bytes --]

On 2011-04-08 23:12, David Ahern wrote:
> 
> 
> On 04/08/11 15:07, Jan Kiszka wrote:
>> On 2011-04-08 20:53, David Ahern wrote:
>>> 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
>>
> 
> 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
> 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


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 259 bytes --]

Re: trace-cmd errors on kvm events

[David Ahern]

On 04/08/11 15:18, Jan Kiszka wrote:
> 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

Re: trace-cmd errors on kvm events

[Jan Kiszka]

[-- Attachment #1: Type: text/plain, Size: 1082 bytes --]

On 2011-04-09 01:26, David Ahern wrote:
> On 04/08/11 15:18, Jan Kiszka wrote:
>> 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.

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


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 259 bytes --]

Re: trace-cmd errors on kvm events

[David Ahern]

On 04/08/11 17:42, Jan Kiszka wrote:
> 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.

Re: trace-cmd errors on kvm events

[Steven Rostedt]

On Fri, Apr 08, 2011 at 11:07:23PM +0200, Jan Kiszka wrote:
> On 2011-04-08 20:53, David Ahern wrote:
> > 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