[Qemu-devel] errno 13, fopen qemu trace file.

[Qemu-devel] errno 13, fopen qemu trace file.

[Nir Levy]

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

Hello everybody,

I have a progress in tracing qemu,
I add the thread and tag done for each kvm_ioctl, kvm_vm_ioctl, kvm_vcpu_ioctl
in purpose of investigating pure hypervisor activity and delays on host.
the kvm type print only for convenience.

for example:
kvm_ioctl 3106435.230545 pid=11347 thread=11347 type=0xae03 arg=0x25
kvm_ioctl_done 3106435.230546 pid=11347 thread=11347 type=0xae03 arg=0x25 diff=1 (KVM_CHECK_EXTENSION)
kvm_vcpu_ioctl 3106435.253930 pid=11347 thread=11354 cpu_index=0x2 type=0x4008ae9c arg=0x56417e6cb4f0
kvm_vcpu_ioctl_done 3106435.253931 pid=11347 thread=11354 cpu_index=0x2 type=0x4008ae9c arg=0x56417e6cb4f0 diff=1 (KVM_X86_SETUP_MCE)

kvm_vm_ioctl 3106435.268896 pid=11347 thread=11347 type=0x4020ae46 arg=0x7ffed97cf9d0
kvm_vm_ioctl_done 3106435.269082 pid=11347 thread=11347 type=0x4020ae46 arg=0x7ffed97cf9d0 diff=186 (KVM_SET_USER_MEMORY_REGION)

I have notice KVM_RUN can take even seconds but that is probably low priority tasks,(io workers probably)
but this 186micro second on the main qemu thread is suspicious and might cause application running over vm delays.

however when I have switch back to installed libvirtd 1.2.13.2
( my version has extended timeout for qemu debugging - ver 1.2.21)


void st_set_trace_file_enabled(bool enable)
{
        ...
        trace_fp = fopen(trace_file_name, "wb");

trace_fp returns null and errno is 13 access denied.
In my installation I did not create cgroup,

If you have some hint for this issue it will be great.
regards.
Nir Levy
SW Engineer


Nir Levy
SW Engineer

Web: www.asocstech.com<http://www.asocstech.com/> |
[cid:image001.jpg@01D1B599.5A2C9530]


[-- Attachment #2: image001.jpg --]
[-- Type: image/jpeg, Size: 2704 bytes --]

Re: [Qemu-devel] errno 13, fopen qemu trace file.

[Daniel P. Berrange]

On Thu, Aug 18, 2016 at 12:58:29PM +0000, Nir Levy wrote:
> Hello everybody,
> 
> I have a progress in tracing qemu,
> I add the thread and tag done for each kvm_ioctl, kvm_vm_ioctl, kvm_vcpu_ioctl
> in purpose of investigating pure hypervisor activity and delays on host.
> the kvm type print only for convenience.
> 
> for example:
> kvm_ioctl 3106435.230545 pid=11347 thread=11347 type=0xae03 arg=0x25
> kvm_ioctl_done 3106435.230546 pid=11347 thread=11347 type=0xae03 arg=0x25 diff=1 (KVM_CHECK_EXTENSION)
> kvm_vcpu_ioctl 3106435.253930 pid=11347 thread=11354 cpu_index=0x2 type=0x4008ae9c arg=0x56417e6cb4f0
> kvm_vcpu_ioctl_done 3106435.253931 pid=11347 thread=11354 cpu_index=0x2 type=0x4008ae9c arg=0x56417e6cb4f0 diff=1 (KVM_X86_SETUP_MCE)
> 
> kvm_vm_ioctl 3106435.268896 pid=11347 thread=11347 type=0x4020ae46 arg=0x7ffed97cf9d0
> kvm_vm_ioctl_done 3106435.269082 pid=11347 thread=11347 type=0x4020ae46 arg=0x7ffed97cf9d0 diff=186 (KVM_SET_USER_MEMORY_REGION)
> 
> I have notice KVM_RUN can take even seconds but that is probably low priority tasks,(io workers probably)
> but this 186micro second on the main qemu thread is suspicious and might cause application running over vm delays.
> 
> however when I have switch back to installed libvirtd 1.2.13.2
> ( my version has extended timeout for qemu debugging - ver 1.2.21)
> 
> 
> void st_set_trace_file_enabled(bool enable)
> {
>         ...
>         trace_fp = fopen(trace_file_name, "wb");
> 
> trace_fp returns null and errno is 13 access denied.
> In my installation I did not create cgroup,
> 
> If you have some hint for this issue it will be great.

Libvirt doesn't support use of the simpletrace backend. The security
policy will prevent simpletrace from even creating its output file.

It is recommended to use a dynamic trace backend like dtrace/systemtap/
ltt-ust so that QEMU does not need to directly create trace output
files itself.

Regards,
Daniel
-- 
|: http://berrange.com      -o-    http://www.flickr.com/photos/dberrange/ :|
|: http://libvirt.org              -o-             http://virt-manager.org :|
|: http://autobuild.org       -o-         http://search.cpan.org/~danberr/ :|
|: http://entangle-photo.org       -o-       http://live.gnome.org/gtk-vnc :|

Re: [Qemu-devel] errno 13, fopen qemu trace file.

[Stefan Hajnoczi]

On Thu, Aug 18, 2016 at 1:58 PM, Nir Levy <nirl@asocsnetworks.com> wrote:
> I have a progress in tracing qemu,
> I add the thread and tag done for each kvm_ioctl, kvm_vm_ioctl, kvm_vcpu_ioctl
> in purpose of investigating pure hypervisor activity and delays on host.
> the kvm type print only for convenience.
>
> for example:
>
> kvm_ioctl 3106435.230545 pid=11347 thread=11347 type=0xae03 arg=0x25
>
> kvm_ioctl_done 3106435.230546 pid=11347 thread=11347 type=0xae03 arg=0x25 diff=1 (KVM_CHECK_EXTENSION)
>
> kvm_vcpu_ioctl 3106435.253930 pid=11347 thread=11354 cpu_index=0x2 type=0x4008ae9c arg=0x56417e6cb4f0
>
> kvm_vcpu_ioctl_done 3106435.253931 pid=11347 thread=11354 cpu_index=0x2 type=0x4008ae9c arg=0x56417e6cb4f0 diff=1 (KVM_X86_SETUP_MCE)
>
> kvm_vm_ioctl 3106435.268896 pid=11347 thread=11347 type=0x4020ae46 arg=0x7ffed97cf9d0
>
> kvm_vm_ioctl_done 3106435.269082 pid=11347 thread=11347 type=0x4020ae46 arg=0x7ffed97cf9d0 diff=186 (KVM_SET_USER_MEMORY_REGION)
>
>
> I have notice KVM_RUN can take even seconds but that is probably low priority tasks,(io workers probably)

Please read Linux Documentation/virtual/kvm/api.txt to learn about the
ioctl calls.

KVM_RUN is *the* ioctl that executes guest code.  Unless a vcpu is
halted we should be inside KVM_RUN, so spending time inside this ioctl
is normal.

> but this 186micro second on the main qemu thread is suspicious and might cause application running over vm delays.

By "186micro second" you are referring to KVM_SET_USER_MEMORY_REGION
in the trace above.

Is this ioctl called in the critical path?  I doubt it since the
KVM_X86_SETUP_MCE ioctl in your trace happens during initialization
time from kvm_arch_init_vcpu() and is not in the critical path when
the guest is running.

Why worry about latencies that do not affect running guests?

Stefan

Re: [Qemu-devel] errno 13, fopen qemu trace file.

[Nir Levy]

Daniel, Thanks for your response.

But I have succeeded using simpletrace when building libvirt from source file into some/other/dir/install 

I am using Fedora22 which does not support lttng.
at the mather of fact I have installed lttng before and build the kernel modules (2.6.0) still no trace generated.
Michael Jeanson is working for supplying modules (2.8.0) for the next fedora (25)
fedora 23 and 24 do support systemtap but not over 22 on my kernel 4.2.8 (which we stick to in Asocs due to known performance degradation in later releases)

Regards.
Nir.


-----Original Message-----
From: Daniel P. Berrange [mailto:berrange@redhat.com] 
Sent: Thursday, August 18, 2016 4:11 PM
To: Nir Levy <nirl@asocsnetworks.com>
Cc: qemu-devel@nongnu.org; Stefan Hajnoczi <stefanha@gmail.com>
Subject: Re: [Qemu-devel] errno 13, fopen qemu trace file.

On Thu, Aug 18, 2016 at 12:58:29PM +0000, Nir Levy wrote:
> Hello everybody,
> 
> I have a progress in tracing qemu,
> I add the thread and tag done for each kvm_ioctl, kvm_vm_ioctl, 
> kvm_vcpu_ioctl in purpose of investigating pure hypervisor activity and delays on host.
> the kvm type print only for convenience.
> 
> for example:
> kvm_ioctl 3106435.230545 pid=11347 thread=11347 type=0xae03 arg=0x25 
> kvm_ioctl_done 3106435.230546 pid=11347 thread=11347 type=0xae03 
> arg=0x25 diff=1 (KVM_CHECK_EXTENSION) kvm_vcpu_ioctl 3106435.253930 
> pid=11347 thread=11354 cpu_index=0x2 type=0x4008ae9c 
> arg=0x56417e6cb4f0 kvm_vcpu_ioctl_done 3106435.253931 pid=11347 
> thread=11354 cpu_index=0x2 type=0x4008ae9c arg=0x56417e6cb4f0 diff=1 
> (KVM_X86_SETUP_MCE)
> 
> kvm_vm_ioctl 3106435.268896 pid=11347 thread=11347 type=0x4020ae46 
> arg=0x7ffed97cf9d0 kvm_vm_ioctl_done 3106435.269082 pid=11347 
> thread=11347 type=0x4020ae46 arg=0x7ffed97cf9d0 diff=186 
> (KVM_SET_USER_MEMORY_REGION)
> 
> I have notice KVM_RUN can take even seconds but that is probably low 
> priority tasks,(io workers probably) but this 186micro second on the main qemu thread is suspicious and might cause application running over vm delays.
> 
> however when I have switch back to installed libvirtd 1.2.13.2 ( my 
> version has extended timeout for qemu debugging - ver 1.2.21)
> 
> 
> void st_set_trace_file_enabled(bool enable) {
>         ...
>         trace_fp = fopen(trace_file_name, "wb");
> 
> trace_fp returns null and errno is 13 access denied.
> In my installation I did not create cgroup,
> 
> If you have some hint for this issue it will be great.

Libvirt doesn't support use of the simpletrace backend. The security policy will prevent simpletrace from even creating its output file.

It is recommended to use a dynamic trace backend like dtrace/systemtap/ ltt-ust so that QEMU does not need to directly create trace output files itself.

Regards,
Daniel
-- 
|: http://berrange.com      -o-    http://www.flickr.com/photos/dberrange/ :|
|: http://libvirt.org              -o-             http://virt-manager.org :|
|: http://autobuild.org       -o-         http://search.cpan.org/~danberr/ :|
|: http://entangle-photo.org       -o-       http://live.gnome.org/gtk-vnc :|

Re: [Qemu-devel] errno 13, fopen qemu trace file.

[Daniel P. Berrange]

On Thu, Aug 18, 2016 at 01:31:19PM +0000, Nir Levy wrote:
> Daniel, Thanks for your response.
> 
> But I have succeeded using simpletrace when building libvirt from source file into some/other/dir/install

I can only assume you built libvirt so that qemu runs as root,
instead of an unprivileged user account, and/or have not enabled
selinux for libvirt.

> 
> I am using Fedora22 which does not support lttng.
> at the mather of fact I have installed lttng before and build the kernel modules (2.6.0) still no trace generated.
> Michael Jeanson is working for supplying modules (2.8.0) for the next fedora (25)
> fedora 23 and 24 do support systemtap but not over 22 on my kernel 4.2.8 (which we stick to in Asocs due to known performance degradation in later releases)

systemtap is supported in all Fedora releases - if there's any
problems do file bugs against it, as its expected to work as
it is the supported tracing mechanism for Fedora with qemu and
libvirt.


Regards,
Daniel
-- 
|: http://berrange.com      -o-    http://www.flickr.com/photos/dberrange/ :|
|: http://libvirt.org              -o-             http://virt-manager.org :|
|: http://autobuild.org       -o-         http://search.cpan.org/~danberr/ :|
|: http://entangle-photo.org       -o-       http://live.gnome.org/gtk-vnc :|

Re: [Qemu-devel] errno 13, fopen qemu trace file.

[Nir Levy]

Hello Stefan,

you are right that those are initial latencies,
I just gave those example for highlighting my goals.
I have started reading the ../Virtual/kvm/api. Documentation this is from where I intent to learn the operation I have printed.
still I am stuck with Asocs' testing libvirtd not allowing me to open the trace file 
Regards,
Nir,

-----Original Message-----
From: Stefan Hajnoczi [mailto:stefanha@gmail.com] 
Sent: Thursday, August 18, 2016 4:22 PM
To: Nir Levy <nirl@asocsnetworks.com>
Cc: qemu-devel@nongnu.org
Subject: Re: errno 13, fopen qemu trace file.

On Thu, Aug 18, 2016 at 1:58 PM, Nir Levy <nirl@asocsnetworks.com> wrote:
> I have a progress in tracing qemu,
> I add the thread and tag done for each kvm_ioctl, kvm_vm_ioctl, 
> kvm_vcpu_ioctl in purpose of investigating pure hypervisor activity and delays on host.
> the kvm type print only for convenience.
>
> for example:
>
> kvm_ioctl 3106435.230545 pid=11347 thread=11347 type=0xae03 arg=0x25
>
> kvm_ioctl_done 3106435.230546 pid=11347 thread=11347 type=0xae03 
> arg=0x25 diff=1 (KVM_CHECK_EXTENSION)
>
> kvm_vcpu_ioctl 3106435.253930 pid=11347 thread=11354 cpu_index=0x2 
> type=0x4008ae9c arg=0x56417e6cb4f0
>
> kvm_vcpu_ioctl_done 3106435.253931 pid=11347 thread=11354 
> cpu_index=0x2 type=0x4008ae9c arg=0x56417e6cb4f0 diff=1 
> (KVM_X86_SETUP_MCE)
>
> kvm_vm_ioctl 3106435.268896 pid=11347 thread=11347 type=0x4020ae46 
> arg=0x7ffed97cf9d0
>
> kvm_vm_ioctl_done 3106435.269082 pid=11347 thread=11347 
> type=0x4020ae46 arg=0x7ffed97cf9d0 diff=186 
> (KVM_SET_USER_MEMORY_REGION)
>
>
> I have notice KVM_RUN can take even seconds but that is probably low 
> priority tasks,(io workers probably)

Please read Linux Documentation/virtual/kvm/api.txt to learn about the ioctl calls.

KVM_RUN is *the* ioctl that executes guest code.  Unless a vcpu is halted we should be inside KVM_RUN, so spending time inside this ioctl is normal.

> but this 186micro second on the main qemu thread is suspicious and might cause application running over vm delays.

By "186micro second" you are referring to KVM_SET_USER_MEMORY_REGION in the trace above.

Is this ioctl called in the critical path?  I doubt it since the KVM_X86_SETUP_MCE ioctl in your trace happens during initialization time from kvm_arch_init_vcpu() and is not in the critical path when the guest is running.

Why worry about latencies that do not affect running guests?

Stefan