High vm-exit latencies during kvm boot-up/shutdown
Hi,
I'm seeing fairly high vm-exit latencies (300-400 us) during and only during qemu/kvm startup and shutdown on a Core2 T5500 in 32-bit mode. It's most probably while the VM runs inside bios code. During the rest of the time, while some Linux guest is running, the exit latencies are within microseconds, thus perfectly fine for the real-time scenarios I have in mind.
Has anyone some idea what goes on there? As those hundreds of micros precisely frame the assembly block in vmx_vcpu_run, I wonder what guest code could cause such long delays. A quick glance at the bochs bios code did not enlighten me yet.
Thanks,
Jan
-------------------------------------------------------------------------
This SF.net email is sponsored by: Splunk Inc.
Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
_______________________________________________
kvm-devel mailing list [email protected]
https://lists.sourceforge.net/lists/listinfo/kvm-devel
Quoted 8 lines · kvm-devel-bounces-5NWGOfrQmneRv+LV9MX5uipxlwaOVQ5f@public.gmane.org wrote:
Hi,
I'm seeing fairly high vm-exit latencies (300-400 us) during and only during qemu/kvm startup and shutdown on a Core2 T5500 in 32-bit mode. It's most probably while the VM runs inside bios code. During the rest of the time, while some Linux guest is running, the exit latencies are within microseconds, thus perfectly fine for the real-time scenarios I have in mind.
How is this time spent? All in Qemu?
Usually a kernel only VM Exit cost less than 1us.
Eddie
-------------------------------------------------------------------------
This SF.net email is sponsored by: Splunk Inc.
Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
Quoted 11 lines · Eddie
Quoted 8 lines · kvm-devel-bounces-5NWGOfrQmneRv+LV9MX5uipxlwaOVQ5f@public.gmane.org wrote:
Hi,
I'm seeing fairly high vm-exit latencies (300-400 us) during and only during qemu/kvm startup and shutdown on a Core2 T5500 in 32-bit mode. It's most probably while the VM runs inside bios code. During the rest of the time, while some Linux guest is running, the exit latencies are within microseconds, thus perfectly fine for the real-time scenarios I have in mind.
How is this time spent? All in Qemu?
Most probably. I have a function tracer installed, and it does not report any kernel function call between the begin of the asm block and its end.
Quoted 1 line
Usually a kernel only VM Exit cost less than 1us.
That's what I'm seeing for the rest as well.
I have read that certain guest states do not allow preemptions by external interrupts (here it is the timer IRQ), but both GUEST_INTERRUPTIBILITY_INFO and GUEST_ACTIVITY_STATE are 0 on entry, e.g. Is there a way for the guest to trigger a non-preemptible SMM entry, and that without the kernel noticing it?
Jan
-------------------------------------------------------------------------
This SF.net email is sponsored by: Splunk Inc.
Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
_______________________________________________
kvm-devel mailing list [email protected]
https://lists.sourceforge.net/lists/listinfo/kvm-devel
Quoted 22 lines
-----Original Message-----
From: jan.kiszka-S0/[email protected] [mailto:jan.kiszka-S0/[email protected]]
Sent: 2007年10月23日 14:38
To: Dong, Eddie
Cc: [email protected]
Subject: Re: [kvm-devel] High vm-exit latencies during kvm
boot-up/shutdownQuoted 4 lines · Eddie
Quoted 3 lines · kvm-devel-bounces-5NWGOfrQmneRv+LV9MX5uipxlwaOVQ5f@public.gmane.org wrote:
Hi,
I'm seeing fairly high vm-exit latencies (300-400 us)
during and only
Quoted 1 line
Quoted 1 line
during qemu/kvm startup and shutdown on a Core2 T5500 in
32-bit mode.
Quoted 1 line
Quoted 1 line
It's most probably while the VM runs inside bios code.
During the rest
Quoted 1 line
Quoted 1 line
of the time, while some Linux guest is running, the exit
latencies are
Quoted 8 lines
Quoted 4 lines
Quoted 2 lines
within microseconds, thus perfectly fine for the real-time scenarios I have in mind.
How is this time spent? All in Qemu?
Most probably. I have a function tracer installed, and it does not report any kernel function call between the begin of the asm block and its end.
If the time is spent in Qemu, then it is possible to be that long since Qemu may read/write disk for the VM virtual disk.
Quoted 11 lines
Quoted 2 lines
Usually a kernel only VM Exit cost less than 1us.
That's what I'm seeing for the rest as well.
I have read that certain guest states do not allow preemptions by external interrupts (here it is the timer IRQ), but both
GUEST_INTERRUPTIBILITY_INFOandGUEST_ACTIVITY_STATEare 0 on entry, e.g. Is there a way for the guest to trigger a non-preemptible SMM entry, and that without the kernel noticing it?
I am not aware of this possibility.
Eddie
-------------------------------------------------------------------------
This SF.net email is sponsored by: Splunk Inc.
Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
_______________________________________________
kvm-devel mailing list [email protected]
https://lists.sourceforge.net/lists/listinfo/kvm-devel
Quoted 13 lines · Jan Kiszka
Quoted 11 lines · Eddie
Quoted 9 lines · kvm-devel-bounces-5NWGOfrQmneRv+LV9MX5uipxlwaOVQ5f@public.gmane.org wrote:
Hi,
I'm seeing fairly high vm-exit latencies (300-400 us) during and only during qemu/kvm startup and shutdown on a Core2 T5500 in 32-bit mode. It's most probably while the VM runs inside bios code. During the rest of the time, while some Linux guest is running, the exit latencies are within microseconds, thus perfectly fine for the real-time scenarios I have in mind.
Quoted 8 lines
Quoted 2 lines
How is this time spent? All in Qemu?
Most probably. I have a function tracer installed, and it does not report any kernel function call between the begin of the asm block and its end.
Which asm block?
Quoted 12 lines
Quoted 2 lines
Usually a kernel only VM Exit cost less than 1us.
That's what I'm seeing for the rest as well.
I have read that certain guest states do not allow preemptions by external interrupts (here it is the timer IRQ), but both
GUEST_INTERRUPTIBILITY_INFOandGUEST_ACTIVITY_STATEare 0 on entry, e.g. Is there a way for the guest to trigger a non-preemptible SMM entry, and that without the kernel noticing it?
Which timer interrupt? The host timer interrupt or the guest timer interrupt?
Try to be much more specific in your descriptions, including what you mean by vm exit and exactly how you measured it.
Signature · 8 lines
Do not meddle in the internals of kernels, for they are subtle and quick to panic. ------------------------------------------------------------------------- This SF.net email is sponsored by: Splunk Inc. Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
Quoted 24 lines · Eddie
Quoted 24 lines
-----Original Message-----
From: jan.kiszka-S0/[email protected] [mailto:jan.kiszka-S0/[email protected]]
Sent: 2007年10月23日 14:38
To: Dong, Eddie
Cc: [email protected]
Subject: Re: [kvm-devel] High vm-exit latencies during kvm
boot-up/shutdownQuoted 4 lines · Eddie
Quoted 3 lines · kvm-devel-bounces-5NWGOfrQmneRv+LV9MX5uipxlwaOVQ5f@public.gmane.org wrote:
Hi,
I'm seeing fairly high vm-exit latencies (300-400 us)
during and only
Quoted 1 line
Quoted 1 line
during qemu/kvm startup and shutdown on a Core2 T5500 in
32-bit mode.
Quoted 1 line
Quoted 1 line
It's most probably while the VM runs inside bios code.
During the rest
Quoted 1 line
Quoted 1 line
of the time, while some Linux guest is running, the exit
latencies are
Quoted 2 lines
Quoted 2 lines
within microseconds, thus perfectly fine for the real-time scenarios I have in mind.
Quoted 7 lines
Quoted 4 lines
Quoted 1 line
How is this time spent? All in Qemu?
Most probably. I have a function tracer installed, and it does not report any kernel function call between the begin of the asm block and its end.
If the time is spent in Qemu, then it is possible to be that long since Qemu may read/write disk for the VM virtual disk.
Clarification: I can't precisely tell what code is executed in VM mode, as I don't have qemu or that guest instrumented. I just see the kernel entering VM mode and leaving it again more than 300 us later. So I wonder why this is allowed while some external IRQ is pending.
Quoted 4 lines
Quoted 4 lines
Quoted 2 lines
Usually a kernel only VM Exit cost less than 1us.
That's what I'm seeing for the rest as well.
Quoted 8 lines
Quoted 6 lines
I have read that certain guest states do not allow preemptions by external interrupts (here it is the timer IRQ), but both
GUEST_INTERRUPTIBILITY_INFOandGUEST_ACTIVITY_STATEare 0 on entry, e.g. Is there a way for the guest to trigger a non-preemptible SMM entry, and that without the kernel noticing it?I am not aware of this possibility.
Eddie
Jan
-------------------------------------------------------------------------
This SF.net email is sponsored by: Splunk Inc.
Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
_______________________________________________
kvm-devel mailing list [email protected]
https://lists.sourceforge.net/lists/listinfo/kvm-devel
Quoted 6 lines · Jan Kiszka
Clarification: I can't precisely tell what code is executed in VM mode, as I don't have qemu or that guest instrumented. I just see the kernel entering VM mode and leaving it again more than 300 us later. So I wonder why this is allowed while some external IRQ is pending.
How do you know an external interrupt is pending?
kvm programs the hardware to exit when an external interrupt arrives.
Signature · 1 line
Do not meddle in the internals of kernels, for they are subtle and quick to panic.
-------------------------------------------------------------------------
This SF.net email is sponsored by: Splunk Inc.
Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
_______________________________________________
kvm-devel mailing list [email protected]
https://lists.sourceforge.net/lists/listinfo/kvm-devel
Avi,
[somehow your mails do not get through to my private account, so I'm switching]
Quoted 9 lines · Avi Kivity
Quoted 6 lines · Jan Kiszka
Clarification: I can't precisely tell what code is executed in VM mode, as I don't have qemu or that guest instrumented. I just see the kernel entering VM mode and leaving it again more than 300 us later. So I wonder why this is allowed while some external IRQ is pending.
How do you know an external interrupt is pending?
It's the host timer IRQ, programmed to fire in certain intervals (100 us here). Test case is some latency measurement tool like tglx's cyclictest or similar programs we use in Xenomai.
Quoted 3 lines
kvm programs the hardware to exit when an external interrupt arrives.
Here is a latency trace I just managed to capture over 2.6.23.1-rt1 with latest kvm from git hacked into (kvm generally seems to work fine this way):
...
qemu-sys-7543 0...1 13897us : vmcs_write16+0xb/0x20 (vmx_save_host_state+0x1a7/0x1c0) qemu-sys-7543 0...1 13897us : vmcs_writel+0xb/0x30 (vmcs_write16+0x1e/0x20) qemu-sys-7543 0...1 13898us : segment_base+0xc/0x70 (vmx_save_host_state+0xa0/0x1c0) qemu-sys-7543 0...1 13898us : vmcs_writel+0xb/0x30 (vmx_save_host_state+0xb0/0x1c0) qemu-sys-7543 0...1 13898us : segment_base+0xc/0x70 (vmx_save_host_state+0xbf/0x1c0) qemu-sys-7543 0...1 13898us : vmcs_writel+0xb/0x30 (vmx_save_host_state+0xcf/0x1c0) qemu-sys-7543 0...1 13898us : load_msrs+0xb/0x40 (vmx_save_host_state+0xe7/0x1c0) qemu-sys-7543 0...1 13898us : kvm_load_guest_fpu+0x8/0x40 (kvm_vcpu_ioctl_run+0xbf/0x570) qemu-sys-7543 0D..1 13899us : vmx_vcpu_run+0xc/0x110 (kvm_vcpu_ioctl_run+0x120/0x570)
qemu-sys-7543 0D..1 13899us!: vmcs_writel+0xb/0x30 (vmx_vcpu_run+0x22/0x110) qemu-sys-7543 0D..1 14344us : vmcs_read32+0xb/0x20 (vmx_vcpu_run+0xc7/0x110) qemu-sys-7543 0D..1 14345us : vmcs_readl+0x8/0x10 (vmcs_read32+0x16/0x20) qemu-sys-7543 0D..1 14345us : vmcs_read32+0xb/0x20 (vmx_vcpu_run+0xf4/0x110) qemu-sys-7543 0D..1 14345us+: vmcs_readl+0x8/0x10 (vmcs_read32+0x16/0x20) qemu-sys-7543 0D..1 14349us : irq_enter+0xb/0x30 (do_IRQ+0x45/0xc0) qemu-sys-7543 0D.h1 14350us : do_IRQ+0x73/0xc0 (f8caae24 0 0) qemu-sys-7543 0D.h1 14351us : handle_level_irq+0xe/0x120 (do_IRQ+0x7d/0xc0) qemu-sys-7543 0D.h1 14351us : __spin_lock+0xc/0x30 (handle_level_irq+0x24/0x120) qemu-sys-7543 0D.h2 14352us : mask_and_ack_8259A+0x14/0x120 (handle_level_irq+0x37/0x120) qemu-sys-7543 0D.h2 14352us+: __spin_lock_irqsave+0x11/0x60 (mask_and_ack_8259A+0x2a/0x120) qemu-sys-7543 0D.h3 14357us : __spin_unlock_irqrestore+0xc/0x60 (mask_and_ack_8259A+0x7a/0x120) qemu-sys-7543 0D.h2 14358us : redirect_hardirq+0x8/0x70 (handle_level_irq+0x72/0x120) qemu-sys-7543 0D.h2 14358us : __spin_unlock+0xb/0x40 (handle_level_irq+0x8e/0x120) qemu-sys-7543 0D.h1 14358us : handle_IRQ_event+0xe/0x110 (handle_level_irq+0x9a/0x120) qemu-sys-7543 0D.h1 14359us : timer_interrupt+0xb/0x60 (handle_IRQ_event+0x67/0x110) qemu-sys-7543 0D.h1 14359us : hrtimer_interrupt+0xe/0x1f0 (timer_interrupt+0x20/0x60)
...
One can see 345 us latency between vm-enter and vm-exit in vmx_vcpu_run - and this while cyclictest runs at a period of 100 us!
I got the same results over Adeos/I-pipe & Xenomai with the function tracer there, also pointing to the period while the CPU is in VM mode.
Anyone any ideas? Greg, I put you on CC as you said you once saw "decent latencies" with your patches. Are there still magic bits missing in official kvm?
Jan
Signature · 8 lines
Siemens AG, Corporate Technology, CT SE 2 Corporate Competence Center Embedded Linux ------------------------------------------------------------------------- This SF.net email is sponsored by: Splunk Inc. Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
Quoted 63 lines · Jan Kiszka
Avi,
[somehow your mails do not get through to my private account, so I'm switching]
Quoted 11 lines · Avi Kivity
Quoted 7 lines · Jan Kiszka
Clarification: I can't precisely tell what code is executed in VM mode, as I don't have qemu or that guest instrumented. I just see the kernel entering VM mode and leaving it again more than 300 us later. So I wonder why this is allowed while some external IRQ is pending.
How do you know an external interrupt is pending?
It's the host timer IRQ, programmed to fire in certain intervals (100 us here). Test case is some latency measurement tool like tglx's cyclictest or similar programs we use in Xenomai.
Quoted 3 lines
kvm programs the hardware to exit when an external interrupt arrives.
Here is a latency trace I just managed to capture over 2.6.23.1-rt1 with latest kvm from git hacked into (kvm generally seems to work fine this way):
...
qemu-sys-7543 0...1 13897us :vmcs_write16+0xb/0x20(vmx_save_host_state+0x1a7/0x1c0) qemu-sys-7543 0...1 13897us :vmcs_writel+0xb/0x30(vmcs_write16+0x1e/0x20) qemu-sys-7543 0...1 13898us :segment_base+0xc/0x70(vmx_save_host_state+0xa0/0x1c0) qemu-sys-7543 0...1 13898us :vmcs_writel+0xb/0x30(vmx_save_host_state+0xb0/0x1c0) qemu-sys-7543 0...1 13898us :segment_base+0xc/0x70(vmx_save_host_state+0xbf/0x1c0) qemu-sys-7543 0...1 13898us :vmcs_writel+0xb/0x30(vmx_save_host_state+0xcf/0x1c0) qemu-sys-7543 0...1 13898us :load_msrs+0xb/0x40(vmx_save_host_state+0xe7/0x1c0) qemu-sys-7543 0...1 13898us :kvm_load_guest_fpu+0x8/0x40(kvm_vcpu_ioctl_run+0xbf/0x570) qemu-sys-7543 0D..1 13899us :vmx_vcpu_run+0xc/0x110(kvm_vcpu_ioctl_run+0x120/0x570)qemu-sys-7543 0D..1 13899us!: vmcs_writel+0xb/0x30 (vmx_vcpu_run+0x22/0x110) qemu-sys-7543 0D..1 14344us : vmcs_read32+0xb/0x20 (vmx_vcpu_run+0xc7/0x110) qemu-sys-7543 0D..1 14345us : vmcs_readl+0x8/0x10 (vmcs_read32+0x16/0x20) qemu-sys-7543 0D..1 14345us : vmcs_read32+0xb/0x20 (vmx_vcpu_run+0xf4/0x110) qemu-sys-7543 0D..1 14345us+: vmcs_readl+0x8/0x10 (vmcs_read32+0x16/0x20) qemu-sys-7543 0D..1 14349us : irq_enter+0xb/0x30 (do_IRQ+0x45/0xc0) qemu-sys-7543 0D.h1 14350us : do_IRQ+0x73/0xc0 (f8caae24 0 0) qemu-sys-7543 0D.h1 14351us : handle_level_irq+0xe/0x120 (do_IRQ+0x7d/0xc0) qemu-sys-7543 0D.h1 14351us : __spin_lock+0xc/0x30 (handle_level_irq+0x24/0x120) qemu-sys-7543 0D.h2 14352us : mask_and_ack_8259A+0x14/0x120 (handle_level_irq+0x37/0x120) qemu-sys-7543 0D.h2 14352us+: __spin_lock_irqsave+0x11/0x60 (mask_and_ack_8259A+0x2a/0x120) qemu-sys-7543 0D.h3 14357us : __spin_unlock_irqrestore+0xc/0x60 (mask_and_ack_8259A+0x7a/0x120) qemu-sys-7543 0D.h2 14358us : redirect_hardirq+0x8/0x70 (handle_level_irq+0x72/0x120) qemu-sys-7543 0D.h2 14358us : __spin_unlock+0xb/0x40 (handle_level_irq+0x8e/0x120) qemu-sys-7543 0D.h1 14358us : handle_IRQ_event+0xe/0x110 (handle_level_irq+0x9a/0x120) qemu-sys-7543 0D.h1 14359us : timer_interrupt+0xb/0x60 (handle_IRQ_event+0x67/0x110) qemu-sys-7543 0D.h1 14359us : hrtimer_interrupt+0xe/0x1f0 (timer_interrupt+0x20/0x60)...
One can see 345 us latency between vm-enter and vm-exit in
vmx_vcpu_run- and this while cyclictest runs at a period of 100 us!
Quoted 7 lines
I got the same results over Adeos/I-pipe & Xenomai with the function tracer there, also pointing to the period while the CPU is in VM mode.
Anyone any ideas? Greg, I put you on CC as you said you once saw "decent latencies" with your patches. Are there still magic bits missing in official kvm?
No bits missing as far as I know. It should just work.
Can you explain some more about the latenct tracer? How does it work? Seeing vmx_vcpu_run() in there confuses me, as it always runs with interrupts disabled (it does dispatch NMIs, so we could be seeing an NMI).
Please post a disassembly of your vmx_vcpu_run so we can interpret the offsets.
Signature · 8 lines
Do not meddle in the internals of kernels, for they are subtle and quick to panic. ------------------------------------------------------------------------- This SF.net email is sponsored by: Splunk Inc. Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
Quoted 65 lines · Avi Kivity
Quoted 64 lines · Jan Kiszka
Avi,
[somehow your mails do not get through to my private account, so I'm switching]
Quoted 11 lines · Avi Kivity
Quoted 7 lines · Jan Kiszka
Clarification: I can't precisely tell what code is executed in VM mode, as I don't have qemu or that guest instrumented. I just see the kernel entering VM mode and leaving it again more than 300 us later. So I wonder why this is allowed while some external IRQ is pending.
How do you know an external interrupt is pending?
It's the host timer IRQ, programmed to fire in certain intervals (100 us here). Test case is some latency measurement tool like tglx's cyclictest or similar programs we use in Xenomai.
Quoted 3 lines
kvm programs the hardware to exit when an external interrupt arrives.
Here is a latency trace I just managed to capture over 2.6.23.1-rt1 with latest kvm from git hacked into (kvm generally seems to work fine this way):
...
qemu-sys-7543 0...1 13897us :vmcs_write16+0xb/0x20(vmx_save_host_state+0x1a7/0x1c0) qemu-sys-7543 0...1 13897us :vmcs_writel+0xb/0x30(vmcs_write16+0x1e/0x20) qemu-sys-7543 0...1 13898us :segment_base+0xc/0x70(vmx_save_host_state+0xa0/0x1c0) qemu-sys-7543 0...1 13898us :vmcs_writel+0xb/0x30(vmx_save_host_state+0xb0/0x1c0) qemu-sys-7543 0...1 13898us :segment_base+0xc/0x70(vmx_save_host_state+0xbf/0x1c0) qemu-sys-7543 0...1 13898us :vmcs_writel+0xb/0x30(vmx_save_host_state+0xcf/0x1c0) qemu-sys-7543 0...1 13898us :load_msrs+0xb/0x40(vmx_save_host_state+0xe7/0x1c0) qemu-sys-7543 0...1 13898us :kvm_load_guest_fpu+0x8/0x40(kvm_vcpu_ioctl_run+0xbf/0x570) qemu-sys-7543 0D..1 13899us :vmx_vcpu_run+0xc/0x110(kvm_vcpu_ioctl_run+0x120/0x570)qemu-sys-7543 0D..1 13899us!: vmcs_writel+0xb/0x30 (vmx_vcpu_run+0x22/0x110) qemu-sys-7543 0D..1 14344us : vmcs_read32+0xb/0x20 (vmx_vcpu_run+0xc7/0x110) qemu-sys-7543 0D..1 14345us : vmcs_readl+0x8/0x10 (vmcs_read32+0x16/0x20) qemu-sys-7543 0D..1 14345us : vmcs_read32+0xb/0x20 (vmx_vcpu_run+0xf4/0x110) qemu-sys-7543 0D..1 14345us+: vmcs_readl+0x8/0x10 (vmcs_read32+0x16/0x20) qemu-sys-7543 0D..1 14349us : irq_enter+0xb/0x30 (do_IRQ+0x45/0xc0) qemu-sys-7543 0D.h1 14350us : do_IRQ+0x73/0xc0 (f8caae24 0 0) qemu-sys-7543 0D.h1 14351us : handle_level_irq+0xe/0x120 (do_IRQ+0x7d/0xc0) qemu-sys-7543 0D.h1 14351us : __spin_lock+0xc/0x30 (handle_level_irq+0x24/0x120) qemu-sys-7543 0D.h2 14352us : mask_and_ack_8259A+0x14/0x120 (handle_level_irq+0x37/0x120) qemu-sys-7543 0D.h2 14352us+: __spin_lock_irqsave+0x11/0x60 (mask_and_ack_8259A+0x2a/0x120) qemu-sys-7543 0D.h3 14357us : __spin_unlock_irqrestore+0xc/0x60 (mask_and_ack_8259A+0x7a/0x120) qemu-sys-7543 0D.h2 14358us : redirect_hardirq+0x8/0x70 (handle_level_irq+0x72/0x120) qemu-sys-7543 0D.h2 14358us : __spin_unlock+0xb/0x40 (handle_level_irq+0x8e/0x120) qemu-sys-7543 0D.h1 14358us : handle_IRQ_event+0xe/0x110 (handle_level_irq+0x9a/0x120) qemu-sys-7543 0D.h1 14359us : timer_interrupt+0xb/0x60 (handle_IRQ_event+0x67/0x110) qemu-sys-7543 0D.h1 14359us : hrtimer_interrupt+0xe/0x1f0 (timer_interrupt+0x20/0x60)...
One can see 345 us latency between vm-enter and vm-exit in
vmx_vcpu_run- and this while cyclictest runs at a period of 100 us!I got the same results over Adeos/I-pipe & Xenomai with the function tracer there, also pointing to the period while the CPU is in VM mode.
Quoted 8 lines
Quoted 4 lines
Anyone any ideas? Greg, I put you on CC as you said you once saw "decent latencies" with your patches. Are there still magic bits missing in official kvm?
No bits missing as far as I know. It should just work.
Can you explain some more about the latenct tracer? How does it work?
Ah, sorry: The latency tracers in both -rt and I-pipe use gcc's -pg to put a call to a function called mcount at the beginning of each compiled function. mcount is provided by the tracers and stores the caller address, its parent, the current time, and more in a log. An API is provided to start and stop the trace, e.g. after someone (kernel or user space) detected large wakeup latencies.
Quoted 2 lines
Seeing
vmx_vcpu_run()in there confuses me, as it always runs with interrupts disabled (it does dispatch NMIs, so we could be seeing an NMI).
The point is that the cyclictest does not find large latencies when kvm is not happening to start or stop right now. And if you are thinking about NMIs triggered by the kvm code on vm-exit: I also instrumented that code path, and it is not taken in case of the long delay.
Quoted 3 lines
Please post a disassembly of your
vmx_vcpu_runso we can interpret the offsets.
Here it comes:
00002df0 <vmx_vcpu_run>:
2df0: 55 push %ebp
2df1: 89 e5 mov %esp,%ebp
2df3: 53 push %ebx
2df4: 83 ec 08 sub $0x8,%esp
2df7: e8 fc ff ff ff call 2df8 <vmx_vcpu_run+0x8>
2dfc: 8b 5d 08 mov 0x8(%ebp),%ebx
2dff: 0f 20 c0 mov %cr0,%eax
2e02: 89 44 24 04 mov %eax,0x4(%esp)
2e06: c7 04 24 00 6c 00 00 movl $0x6c00,(%esp)
2e0d: e8 be d8 ff ff call 6d0 <vmcs_writel>
2e12: 8b 83 80 0d 00 00 mov 0xd80(%ebx),%eax
2e18: ba 14 6c 00 00 mov $0x6c14,%edx
2e1d: 89 d9 mov %ebx,%ecx
2e1f: 60 pusha
2e20: 51 push %ecx
2e21: 0f 79 d4 vmwrite %esp,%edx
2e24: 83 f8 00 cmp $0x0,%eax
2e27: 8b 81 78 01 00 00 mov 0x178(%ecx),%eax
2e2d: 0f 22 d0 mov %eax,%cr2
2e30: 8b 81 50 01 00 00 mov 0x150(%ecx),%eax
2e36: 8b 99 5c 01 00 00 mov 0x15c(%ecx),%ebx
2e3c: 8b 91 58 01 00 00 mov 0x158(%ecx),%edx
2e42: 8b b1 68 01 00 00 mov 0x168(%ecx),%esi
2e48: 8b b9 6c 01 00 00 mov 0x16c(%ecx),%edi
2e4e: 8b a9 64 01 00 00 mov 0x164(%ecx),%ebp
2e54: 8b 89 54 01 00 00 mov 0x154(%ecx),%ecx
2e5a: 75 05 jne 2e61 <vmx_vcpu_run+0x71>
2e5c: 0f 01 c2 vmlaunch
2e5f: eb 03 jmp 2e64 <vmx_vcpu_run+0x74>
2e61: 0f 01 c3 vmresume
2e64: 87 0c 24 xchg %ecx,(%esp)
2e67: 89 81 50 01 00 00 mov %eax,0x150(%ecx)
2e6d: 89 99 5c 01 00 00 mov %ebx,0x15c(%ecx)
2e73: ff 34 24 pushl (%esp)
2e76: 8f 81 54 01 00 00 popl 0x154(%ecx)
2e7c: 89 91 58 01 00 00 mov %edx,0x158(%ecx)
2e82: 89 b1 68 01 00 00 mov %esi,0x168(%ecx)
2e88: 89 b9 6c 01 00 00 mov %edi,0x16c(%ecx)
2e8e: 89 a9 64 01 00 00 mov %ebp,0x164(%ecx)
2e94: 0f 20 d0 mov %cr2,%eax
2e97: 89 81 78 01 00 00 mov %eax,0x178(%ecx)
2e9d: 8b 0c 24 mov (%esp),%ecx
2ea0: 59 pop %ecx
2ea1: 61 popa
2ea2: 0f 96 c0 setbe %al
2ea5: 88 83 84 0d 00 00 mov %al,0xd84(%ebx)
2eab: c7 04 24 24 48 00 00 movl $0x4824,(%esp)
2eb2: e8 49 d2 ff ff call 100 <vmcs_read32>
2eb7: a8 03 test $0x3,%al
2eb9: 0f 94 c0 sete %al
2ebc: 0f b6 c0 movzbl %al,%eax
2ebf: 89 83 28 01 00 00 mov %eax,0x128(%ebx)
2ec5: b8 7b 00 00 00 mov $0x7b,%eax
2eca: 8e d8 mov %eax,%ds
2ecc: 8e c0 mov %eax,%es
2ece: c7 83 80 0d 00 00 01 movl $0x1,0xd80(%ebx)
2ed5: 00 00 00
2ed8: c7 04 24 04 44 00 00 movl $0x4404,(%esp)
2edf: e8 1c d2 ff ff call 100 <vmcs_read32>
2ee4: 25 00 07 00 00 and $0x700,%eax
2ee9: 3d 00 02 00 00 cmp $0x200,%eax
2eee: 75 02 jne 2ef2 <vmx_vcpu_run+0x102>
2ef0: cd 02 int $0x2
2ef2: 83 c4 08 add $0x8,%esp
2ef5: 5b pop %ebx
2ef6: 5d pop %ebp
2ef7: c3 ret
2ef8: 90 nop
2ef9: 8d b4 26 00 00 00 00 lea 0x0(%esi),%esiNote that the first, unresolved call here goes to mcount().
Jan
Signature · 8 lines
Siemens AG, Corporate Technology, CT SE 2 Corporate Competence Center Embedded Linux ------------------------------------------------------------------------- This SF.net email is sponsored by: Splunk Inc. Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
Quoted 67 lines · Avi Kivity
Quoted 66 lines · Jan Kiszka
Avi,
[somehow your mails do not get through to my private account, so I'm switching]
Quoted 11 lines · Avi Kivity
Quoted 7 lines · Jan Kiszka
Clarification: I can't precisely tell what code is executed in VM mode, as I don't have qemu or that guest instrumented. I just see the kernel entering VM mode and leaving it again more than 300 us later. So I wonder why this is allowed while some external IRQ is pending.
How do you know an external interrupt is pending?
It's the host timer IRQ, programmed to fire in certain intervals (100 us here). Test case is some latency measurement tool like tglx's cyclictest or similar programs we use in Xenomai.
Quoted 3 lines
kvm programs the hardware to exit when an external interrupt arrives.
Here is a latency trace I just managed to capture over 2.6.23.1-rt1 with latest kvm from git hacked into (kvm generally seems to work fine this way):
...
qemu-sys-7543 0...1 13897us :vmcs_write16+0xb/0x20(vmx_save_host_state+0x1a7/0x1c0) qemu-sys-7543 0...1 13897us :vmcs_writel+0xb/0x30(vmcs_write16+0x1e/0x20) qemu-sys-7543 0...1 13898us :segment_base+0xc/0x70(vmx_save_host_state+0xa0/0x1c0) qemu-sys-7543 0...1 13898us :vmcs_writel+0xb/0x30(vmx_save_host_state+0xb0/0x1c0) qemu-sys-7543 0...1 13898us :segment_base+0xc/0x70(vmx_save_host_state+0xbf/0x1c0) qemu-sys-7543 0...1 13898us :vmcs_writel+0xb/0x30(vmx_save_host_state+0xcf/0x1c0) qemu-sys-7543 0...1 13898us :load_msrs+0xb/0x40(vmx_save_host_state+0xe7/0x1c0) qemu-sys-7543 0...1 13898us :kvm_load_guest_fpu+0x8/0x40(kvm_vcpu_ioctl_run+0xbf/0x570) qemu-sys-7543 0D..1 13899us :vmx_vcpu_run+0xc/0x110(kvm_vcpu_ioctl_run+0x120/0x570)qemu-sys-7543 0D..1 13899us!: vmcs_writel+0xb/0x30 (vmx_vcpu_run+0x22/0x110) qemu-sys-7543 0D..1 14344us : vmcs_read32+0xb/0x20 (vmx_vcpu_run+0xc7/0x110) qemu-sys-7543 0D..1 14345us : vmcs_readl+0x8/0x10 (vmcs_read32+0x16/0x20) qemu-sys-7543 0D..1 14345us : vmcs_read32+0xb/0x20 (vmx_vcpu_run+0xf4/0x110) qemu-sys-7543 0D..1 14345us+: vmcs_readl+0x8/0x10 (vmcs_read32+0x16/0x20) qemu-sys-7543 0D..1 14349us : irq_enter+0xb/0x30 (do_IRQ+0x45/0xc0) qemu-sys-7543 0D.h1 14350us : do_IRQ+0x73/0xc0 (f8caae24 0 0) qemu-sys-7543 0D.h1 14351us : handle_level_irq+0xe/0x120 (do_IRQ+0x7d/0xc0) qemu-sys-7543 0D.h1 14351us : __spin_lock+0xc/0x30 (handle_level_irq+0x24/0x120) qemu-sys-7543 0D.h2 14352us : mask_and_ack_8259A+0x14/0x120 (handle_level_irq+0x37/0x120) qemu-sys-7543 0D.h2 14352us+: __spin_lock_irqsave+0x11/0x60 (mask_and_ack_8259A+0x2a/0x120) qemu-sys-7543 0D.h3 14357us : __spin_unlock_irqrestore+0xc/0x60 (mask_and_ack_8259A+0x7a/0x120) qemu-sys-7543 0D.h2 14358us : redirect_hardirq+0x8/0x70 (handle_level_irq+0x72/0x120) qemu-sys-7543 0D.h2 14358us : __spin_unlock+0xb/0x40 (handle_level_irq+0x8e/0x120) qemu-sys-7543 0D.h1 14358us : handle_IRQ_event+0xe/0x110 (handle_level_irq+0x9a/0x120) qemu-sys-7543 0D.h1 14359us : timer_interrupt+0xb/0x60 (handle_IRQ_event+0x67/0x110) qemu-sys-7543 0D.h1 14359us : hrtimer_interrupt+0xe/0x1f0 (timer_interrupt+0x20/0x60)...
One can see 345 us latency between vm-enter and vm-exit in
vmx_vcpu_run- and this while cyclictest runs at a period of 100 us!I got the same results over Adeos/I-pipe & Xenomai with the function tracer there, also pointing to the period while the CPU is in VM mode.
Quoted 6 lines
Quoted 4 lines
Anyone any ideas? Greg, I put you on CC as you said you once saw "decent latencies" with your patches. Are there still magic bits missing in official kvm?
No bits missing as far as I know. It should just work.
That could very well be the case these days. I know back when I was looking at it, KVM would not run on VMX + -rt without modification or it would crash/hang (this was around the time I was working on that smp_function_call stuff). And without careful modification it would run very poorly (with high (300us+ latencies) revealed in cyclictest.
However, I was able to craft the vmx_vcpu_run path so that a VM could run side-by-side with cyclictest with sub 40us latencies. In fact, normally it was sub 30us, but on an occasional run I would get a spike to ~37us.
Unfortunately I am deep into other non-KVM related -rt issues at the moment, so I can't work on it any further for a bit.
Regards,
-Greg
-------------------------------------------------------------------------
This SF.net email is sponsored by: Splunk Inc.
Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
_______________________________________________
kvm-devel mailing list [email protected]
https://lists.sourceforge.net/lists/listinfo/kvm-devel
Quoted 8 lines · Jan Kiszka
Quoted 2 lines · Avi Kivity
Seeing
vmx_vcpu_run()in there confuses me, as it always runs with interrupts disabled (it does dispatch NMIs, so we could be seeing an NMI).The point is that the cyclictest does not find large latencies when kvm is not happening to start or stop right now. And if you are thinking about NMIs triggered by the kvm code on vm-exit: I also instrumented that code path, and it is not taken in case of the long delay.
Actually, that instrumentation was for an older version. In this one here, the vm-entry/exit block is clearly framed by traced vmcs_xxx calls.
Jan
Signature · 8 lines
Siemens AG, Corporate Technology, CT SE 2 Corporate Competence Center Embedded Linux ------------------------------------------------------------------------- This SF.net email is sponsored by: Splunk Inc. Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
Quoted 78 lines · Gregory Haskins
Quoted 62 lines · Avi Kivity
Quoted 61 lines · Jan Kiszka
Avi,
[somehow your mails do not get through to my private account, so I'm switching]
Quoted 11 lines · Avi Kivity
Quoted 7 lines · Jan Kiszka
Clarification: I can't precisely tell what code is executed in VM mode, as I don't have qemu or that guest instrumented. I just see the kernel entering VM mode and leaving it again more than 300 us later. So I wonder why this is allowed while some external IRQ is pending.
How do you know an external interrupt is pending?
It's the host timer IRQ, programmed to fire in certain intervals (100 us here). Test case is some latency measurement tool like tglx's cyclictest or similar programs we use in Xenomai.
Quoted 3 lines
kvm programs the hardware to exit when an external interrupt arrives.
Here is a latency trace I just managed to capture over 2.6.23.1-rt1 with latest kvm from git hacked into (kvm generally seems to work fine this way):
...
qemu-sys-7543 0...1 13897us :vmcs_write16+0xb/0x20(vmx_save_host_state+0x1a7/0x1c0) qemu-sys-7543 0...1 13897us :vmcs_writel+0xb/0x30(vmcs_write16+0x1e/0x20) qemu-sys-7543 0...1 13898us :segment_base+0xc/0x70(vmx_save_host_state+0xa0/0x1c0) qemu-sys-7543 0...1 13898us :vmcs_writel+0xb/0x30(vmx_save_host_state+0xb0/0x1c0) qemu-sys-7543 0...1 13898us :segment_base+0xc/0x70(vmx_save_host_state+0xbf/0x1c0) qemu-sys-7543 0...1 13898us :vmcs_writel+0xb/0x30(vmx_save_host_state+0xcf/0x1c0) qemu-sys-7543 0...1 13898us :load_msrs+0xb/0x40(vmx_save_host_state+0xe7/0x1c0) qemu-sys-7543 0...1 13898us :kvm_load_guest_fpu+0x8/0x40(kvm_vcpu_ioctl_run+0xbf/0x570) qemu-sys-7543 0D..1 13899us :vmx_vcpu_run+0xc/0x110(kvm_vcpu_ioctl_run+0x120/0x570)qemu-sys-7543 0D..1 13899us!: vmcs_writel+0xb/0x30 (vmx_vcpu_run+0x22/0x110) qemu-sys-7543 0D..1 14344us : vmcs_read32+0xb/0x20 (vmx_vcpu_run+0xc7/0x110) qemu-sys-7543 0D..1 14345us : vmcs_readl+0x8/0x10 (vmcs_read32+0x16/0x20) qemu-sys-7543 0D..1 14345us : vmcs_read32+0xb/0x20 (vmx_vcpu_run+0xf4/0x110) qemu-sys-7543 0D..1 14345us+: vmcs_readl+0x8/0x10 (vmcs_read32+0x16/0x20) qemu-sys-7543 0D..1 14349us : irq_enter+0xb/0x30 (do_IRQ+0x45/0xc0) qemu-sys-7543 0D.h1 14350us : do_IRQ+0x73/0xc0 (f8caae24 0 0) qemu-sys-7543 0D.h1 14351us : handle_level_irq+0xe/0x120 (do_IRQ+0x7d/0xc0) qemu-sys-7543 0D.h1 14351us : __spin_lock+0xc/0x30 (handle_level_irq+0x24/0x120) qemu-sys-7543 0D.h2 14352us : mask_and_ack_8259A+0x14/0x120 (handle_level_irq+0x37/0x120) qemu-sys-7543 0D.h2 14352us+: __spin_lock_irqsave+0x11/0x60 (mask_and_ack_8259A+0x2a/0x120) qemu-sys-7543 0D.h3 14357us : __spin_unlock_irqrestore+0xc/0x60 (mask_and_ack_8259A+0x7a/0x120) qemu-sys-7543 0D.h2 14358us : redirect_hardirq+0x8/0x70 (handle_level_irq+0x72/0x120) qemu-sys-7543 0D.h2 14358us : __spin_unlock+0xb/0x40 (handle_level_irq+0x8e/0x120) qemu-sys-7543 0D.h1 14358us : handle_IRQ_event+0xe/0x110 (handle_level_irq+0x9a/0x120) qemu-sys-7543 0D.h1 14359us : timer_interrupt+0xb/0x60 (handle_IRQ_event+0x67/0x110) qemu-sys-7543 0D.h1 14359us : hrtimer_interrupt+0xe/0x1f0 (timer_interrupt+0x20/0x60)...
One can see 345 us latency between vm-enter and vm-exit in
vmx_vcpu_run- and this while cyclictest runs at a period of 100 us!Quoted 8 lines
Quoted 7 lines
I got the same results over Adeos/I-pipe & Xenomai with the function tracer there, also pointing to the period while the CPU is in VM mode.
Anyone any ideas? Greg, I put you on CC as you said you once saw "decent latencies" with your patches. Are there still magic bits missing in official kvm?
No bits missing as far as I know. It should just work.
That could very well be the case these days. I know back when I was looking at it, KVM would not run on VMX + -rt without modification or it would crash/hang (this was around the time I was working on that
smp_function_callstuff). And without careful modification it would run very poorly (with high (300us+ latencies) revealed in cyclictest.
Quoted 7 lines
However, I was able to craft the
vmx_vcpu_runpath so that a VM could run side-by-side with cyclictest with sub 40us latencies. In fact, normally it was sub 30us, but on an occasional run I would get a spike to ~37us.Unfortunately I am deep into other non-KVM related -rt issues at the moment, so I can't work on it any further for a bit.
Do you have some patch fragments left over? At least /me would be interested to study and maybe forward port them. Or can you briefly explain the issue above and/or the general problem behind this delay?
Thanks,
Jan
Signature · 8 lines
Siemens AG, Corporate Technology, CT SE 2 Corporate Competence Center Embedded Linux ------------------------------------------------------------------------- This SF.net email is sponsored by: Splunk Inc. Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
Quoted 84 lines · Jan Kiszka
Quoted 72 lines · Avi Kivity
Quoted 70 lines · Jan Kiszka
Avi,
[somehow your mails do not get through to my private account, so I'm switching]
Quoted 11 lines · Avi Kivity
Quoted 8 lines · Jan Kiszka
Clarification: I can't precisely tell what code is executed in VM mode, as I don't have qemu or that guest instrumented. I just see the kernel entering VM mode and leaving it again more than 300 us later. So I wonder why this is allowed while some external IRQ is pending.
Quoted 3 lines
How do you know an external interrupt is pending?
It's the host timer IRQ, programmed to fire in certain intervals (100 us here). Test case is some latency measurement tool like tglx's cyclictest or similar programs we use in Xenomai.
Quoted 4 lines
kvm programs the hardware to exit when an external interrupt arrives.
Here is a latency trace I just managed to capture over 2.6.23.1-rt1 with latest kvm from git hacked into (kvm generally seems to work fine this way):
...
qemu-sys-7543 0...1 13897us :vmcs_write16+0xb/0x20(vmx_save_host_state+0x1a7/0x1c0) qemu-sys-7543 0...1 13897us :vmcs_writel+0xb/0x30(vmcs_write16+0x1e/0x20) qemu-sys-7543 0...1 13898us :segment_base+0xc/0x70(vmx_save_host_state+0xa0/0x1c0) qemu-sys-7543 0...1 13898us :vmcs_writel+0xb/0x30(vmx_save_host_state+0xb0/0x1c0) qemu-sys-7543 0...1 13898us :segment_base+0xc/0x70(vmx_save_host_state+0xbf/0x1c0) qemu-sys-7543 0...1 13898us :vmcs_writel+0xb/0x30(vmx_save_host_state+0xcf/0x1c0) qemu-sys-7543 0...1 13898us :load_msrs+0xb/0x40(vmx_save_host_state+0xe7/0x1c0) qemu-sys-7543 0...1 13898us :kvm_load_guest_fpu+0x8/0x40(kvm_vcpu_ioctl_run+0xbf/0x570) qemu-sys-7543 0D..1 13899us :vmx_vcpu_run+0xc/0x110(kvm_vcpu_ioctl_run+0x120/0x570)qemu-sys-7543 0D..1 13899us!: vmcs_writel+0xb/0x30 (vmx_vcpu_run+0x22/0x110) qemu-sys-7543 0D..1 14344us : vmcs_read32+0xb/0x20 (vmx_vcpu_run+0xc7/0x110) qemu-sys-7543 0D..1 14345us : vmcs_readl+0x8/0x10 (vmcs_read32+0x16/0x20) qemu-sys-7543 0D..1 14345us : vmcs_read32+0xb/0x20 (vmx_vcpu_run+0xf4/0x110) qemu-sys-7543 0D..1 14345us+: vmcs_readl+0x8/0x10 (vmcs_read32+0x16/0x20) qemu-sys-7543 0D..1 14349us : irq_enter+0xb/0x30 (do_IRQ+0x45/0xc0) qemu-sys-7543 0D.h1 14350us : do_IRQ+0x73/0xc0 (f8caae24 0 0) qemu-sys-7543 0D.h1 14351us : handle_level_irq+0xe/0x120 (do_IRQ+0x7d/0xc0) qemu-sys-7543 0D.h1 14351us : __spin_lock+0xc/0x30 (handle_level_irq+0x24/0x120) qemu-sys-7543 0D.h2 14352us : mask_and_ack_8259A+0x14/0x120 (handle_level_irq+0x37/0x120) qemu-sys-7543 0D.h2 14352us+: __spin_lock_irqsave+0x11/0x60 (mask_and_ack_8259A+0x2a/0x120) qemu-sys-7543 0D.h3 14357us : __spin_unlock_irqrestore+0xc/0x60 (mask_and_ack_8259A+0x7a/0x120) qemu-sys-7543 0D.h2 14358us : redirect_hardirq+0x8/0x70 (handle_level_irq+0x72/0x120) qemu-sys-7543 0D.h2 14358us : __spin_unlock+0xb/0x40 (handle_level_irq+0x8e/0x120) qemu-sys-7543 0D.h1 14358us : handle_IRQ_event+0xe/0x110 (handle_level_irq+0x9a/0x120) qemu-sys-7543 0D.h1 14359us : timer_interrupt+0xb/0x60 (handle_IRQ_event+0x67/0x110) qemu-sys-7543 0D.h1 14359us : hrtimer_interrupt+0xe/0x1f0 (timer_interrupt+0x20/0x60)...
One can see 345 us latency between vm-enter and vm-exit in
vmx_vcpu_run- and this while cyclictest runs at a period of 100 us!I got the same results over Adeos/I-pipe & Xenomai with the function tracer there, also pointing to the period while the CPU is in VM mode.
Quoted 9 lines
Quoted 5 lines
Anyone any ideas? Greg, I put you on CC as you said you once saw "decent latencies" with your patches. Are there still magic bits missing in official kvm?
No bits missing as far as I know. It should just work.
Can you explain some more about the latenct tracer? How does it work?
Quoted 8 lines
Ah, sorry: The latency tracers in both -rt and I-pipe use gcc's -pg to put a call to a function called mcount at the beginning of each compiled function. mcount is provided by the tracers and stores the caller address, its parent, the current time, and more in a log. An API is provided to start and stop the trace, e.g. after someone (kernel or user space) detected large wakeup latencies.
Ok. So it is not interrupt driven, and that's how you get traces in functions that run with interrupts disabled.
Quoted 10 lines
Quoted 3 lines
Seeing
vmx_vcpu_run()in there confuses me, as it always runs with interrupts disabled (it does dispatch NMIs, so we could be seeing an NMI).The point is that the cyclictest does not find large latencies when kvm is not happening to start or stop right now. And if you are thinking about NMIs triggered by the kvm code on vm-exit: I also instrumented that code path, and it is not taken in case of the long delay.
Right. With your explanation it all makes sense, and indeed it looks like the guest is not exiting.
Quoted 7 lines
Quoted 3 lines
Please post a disassembly of your
vmx_vcpu_runso we can interpret the offsets.Here it comes:
00002df0<vmx_vcpu_run>:
Quoted 11 lines
2df0: 55 push %ebp
2df1: 89 e5 mov %esp,%ebp
2df3: 53 push %ebx
2df4: 83 ec 08 sub $0x8,%esp
2df7: e8 fc ff ff ff call 2df8 <vmx_vcpu_run+0x8>
2dfc: 8b 5d 08 mov 0x8(%ebp),%ebx
2dff: 0f 20 c0 mov %cr0,%eax
2e02: 89 44 24 04 mov %eax,0x4(%esp)
2e06: c7 04 24 00 6c 00 00 movl $0x6c00,(%esp)
2e0d: e8 be d8 ff ff call 6d0 <vmcs_writel>first trace
Quoted 30 lines
2e12: 8b 83 80 0d 00 00 mov 0xd80(%ebx),%eax
2e18: ba 14 6c 00 00 mov $0x6c14,%edx
2e1d: 89 d9 mov %ebx,%ecx
2e1f: 60 pusha
2e20: 51 push %ecx
2e21: 0f 79 d4 vmwrite %esp,%edx
2e24: 83 f8 00 cmp $0x0,%eax
2e27: 8b 81 78 01 00 00 mov 0x178(%ecx),%eax
2e2d: 0f 22 d0 mov %eax,%cr2
2e30: 8b 81 50 01 00 00 mov 0x150(%ecx),%eax
2e36: 8b 99 5c 01 00 00 mov 0x15c(%ecx),%ebx
2e3c: 8b 91 58 01 00 00 mov 0x158(%ecx),%edx
2e42: 8b b1 68 01 00 00 mov 0x168(%ecx),%esi
2e48: 8b b9 6c 01 00 00 mov 0x16c(%ecx),%edi
2e4e: 8b a9 64 01 00 00 mov 0x164(%ecx),%ebp
2e54: 8b 89 54 01 00 00 mov 0x154(%ecx),%ecx
2e5a: 75 05 jne 2e61 <vmx_vcpu_run+0x71>
2e5c: 0f 01 c2 vmlaunch
2e5f: eb 03 jmp 2e64 <vmx_vcpu_run+0x74>
2e61: 0f 01 c3 vmresume
2e64: 87 0c 24 xchg %ecx,(%esp)
2e67: 89 81 50 01 00 00 mov %eax,0x150(%ecx)
2e6d: 89 99 5c 01 00 00 mov %ebx,0x15c(%ecx)
2e73: ff 34 24 pushl (%esp)
2e76: 8f 81 54 01 00 00 popl 0x154(%ecx)
2e7c: 89 91 58 01 00 00 mov %edx,0x158(%ecx)
2e82: 89 b1 68 01 00 00 mov %esi,0x168(%ecx)
2e88: 89 b9 6c 01 00 00 mov %edi,0x16c(%ecx)
2e8e: 89 a9 64 01 00 00 mov %ebp,0x164(%ecx)
2e94: 0f 20 d0 mov %cr2,%eaxQuoted 9 lines
2e97: 89 81 78 01 00 00 mov %eax,0x178(%ecx)
2e9d: 8b 0c 24 mov (%esp),%ecx
2ea0: 59 pop %ecx
2ea1: 61 popa
2ea2: 0f 96 c0 setbe %al
2ea5: 88 83 84 0d 00 00 mov %al,0xd84(%ebx)
2eab: c7 04 24 24 48 00 00 movl $0x4824,(%esp)
2eb2: e8 49 d2 ff ff call 100 <vmcs_read32>second trace
Quoted 22 lines
2eb7: a8 03 test $0x3,%al
2eb9: 0f 94 c0 sete %al
2ebc: 0f b6 c0 movzbl %al,%eax
2ebf: 89 83 28 01 00 00 mov %eax,0x128(%ebx)
2ec5: b8 7b 00 00 00 mov $0x7b,%eax
2eca: 8e d8 mov %eax,%ds
2ecc: 8e c0 mov %eax,%es
2ece: c7 83 80 0d 00 00 01 movl $0x1,0xd80(%ebx)
2ed5: 00 00 00
2ed8: c7 04 24 04 44 00 00 movl $0x4404,(%esp)
2edf: e8 1c d2 ff ff call 100 <vmcs_read32>
2ee4: 25 00 07 00 00 and $0x700,%eax
2ee9: 3d 00 02 00 00 cmp $0x200,%eax
2eee: 75 02 jne 2ef2 <vmx_vcpu_run+0x102>
2ef0: cd 02 int $0x2
2ef2: 83 c4 08 add $0x8,%esp
2ef5: 5b pop %ebx
2ef6: 5d pop %ebp
2ef7: c3 ret
2ef8: 90 nop
2ef9: 8d b4 26 00 00 00 00 lea 0x0(%esi),%esiQuoted 3 lines
Note that the first, unresolved call here goes to
mcount().
(the -r option to objdump is handy)
Exiting on a pending interrupt is controlled by the vmcs word PIN_BASED_EXEC_CONTROL, bit PIN_BASED_EXT_INTR_MASK. Can you check (via vmcs_read32()) that the bit is indeed set?
[if not, a guest can just enter a busy loop and kill a processor]
Signature · 8 lines
Do not meddle in the internals of kernels, for they are subtle and quick to panic. ------------------------------------------------------------------------- This SF.net email is sponsored by: Splunk Inc. Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
Quoted 87 lines · Avi Kivity
Quoted 7 lines · Jan Kiszka
Quoted 3 lines · Avi Kivity
Please post a disassembly of your
vmx_vcpu_runso we can interpret the offsets.Here it comes:
00002df0<vmx_vcpu_run>:Quoted 11 lines
2df0: 55 push %ebp 2df1: 89 e5 mov %esp,%ebp 2df3: 53 push %ebx 2df4: 83 ec 08 sub $0x8,%esp 2df7: e8 fc ff ff ff call 2df8 <vmx_vcpu_run+0x8> 2dfc: 8b 5d 08 mov 0x8(%ebp),%ebx 2dff: 0f 20 c0 mov %cr0,%eax 2e02: 89 44 24 04 mov %eax,0x4(%esp) 2e06: c7 04 24 00 6c 00 00 movl $0x6c00,(%esp) 2e0d: e8 be d8 ff ff call 6d0 <vmcs_writel>first trace
Quoted 30 lines
2e12: 8b 83 80 0d 00 00 mov 0xd80(%ebx),%eax 2e18: ba 14 6c 00 00 mov $0x6c14,%edx 2e1d: 89 d9 mov %ebx,%ecx 2e1f: 60 pusha 2e20: 51 push %ecx 2e21: 0f 79 d4 vmwrite %esp,%edx 2e24: 83 f8 00 cmp $0x0,%eax 2e27: 8b 81 78 01 00 00 mov 0x178(%ecx),%eax 2e2d: 0f 22 d0 mov %eax,%cr2 2e30: 8b 81 50 01 00 00 mov 0x150(%ecx),%eax 2e36: 8b 99 5c 01 00 00 mov 0x15c(%ecx),%ebx 2e3c: 8b 91 58 01 00 00 mov 0x158(%ecx),%edx 2e42: 8b b1 68 01 00 00 mov 0x168(%ecx),%esi 2e48: 8b b9 6c 01 00 00 mov 0x16c(%ecx),%edi 2e4e: 8b a9 64 01 00 00 mov 0x164(%ecx),%ebp 2e54: 8b 89 54 01 00 00 mov 0x154(%ecx),%ecx 2e5a: 75 05 jne 2e61 <vmx_vcpu_run+0x71> 2e5c: 0f 01 c2 vmlaunch 2e5f: eb 03 jmp 2e64 <vmx_vcpu_run+0x74> 2e61: 0f 01 c3 vmresume 2e64: 87 0c 24 xchg %ecx,(%esp) 2e67: 89 81 50 01 00 00 mov %eax,0x150(%ecx) 2e6d: 89 99 5c 01 00 00 mov %ebx,0x15c(%ecx) 2e73: ff 34 24 pushl (%esp) 2e76: 8f 81 54 01 00 00 popl 0x154(%ecx) 2e7c: 89 91 58 01 00 00 mov %edx,0x158(%ecx) 2e82: 89 b1 68 01 00 00 mov %esi,0x168(%ecx) 2e88: 89 b9 6c 01 00 00 mov %edi,0x16c(%ecx) 2e8e: 89 a9 64 01 00 00 mov %ebp,0x164(%ecx) 2e94: 0f 20 d0 mov %cr2,%eaxQuoted 9 lines
2e97: 89 81 78 01 00 00 mov %eax,0x178(%ecx) 2e9d: 8b 0c 24 mov (%esp),%ecx 2ea0: 59 pop %ecx 2ea1: 61 popa 2ea2: 0f 96 c0 setbe %al 2ea5: 88 83 84 0d 00 00 mov %al,0xd84(%ebx) 2eab: c7 04 24 24 48 00 00 movl $0x4824,(%esp) 2eb2: e8 49 d2 ff ff call 100 <vmcs_read32>second trace
Quoted 22 lines
2eb7: a8 03 test $0x3,%al 2eb9: 0f 94 c0 sete %al 2ebc: 0f b6 c0 movzbl %al,%eax 2ebf: 89 83 28 01 00 00 mov %eax,0x128(%ebx) 2ec5: b8 7b 00 00 00 mov $0x7b,%eax 2eca: 8e d8 mov %eax,%ds 2ecc: 8e c0 mov %eax,%es 2ece: c7 83 80 0d 00 00 01 movl $0x1,0xd80(%ebx) 2ed5: 00 00 00 2ed8: c7 04 24 04 44 00 00 movl $0x4404,(%esp) 2edf: e8 1c d2 ff ff call 100 <vmcs_read32> 2ee4: 25 00 07 00 00 and $0x700,%eax 2ee9: 3d 00 02 00 00 cmp $0x200,%eax 2eee: 75 02 jne 2ef2 <vmx_vcpu_run+0x102> 2ef0: cd 02 int $0x2 2ef2: 83 c4 08 add $0x8,%esp 2ef5: 5b pop %ebx 2ef6: 5d pop %ebp 2ef7: c3 ret 2ef8: 90 nop 2ef9: 8d b4 26 00 00 00 00 lea 0x0(%esi),%esi
Quoted 5 lines
Quoted 3 lines
Note that the first, unresolved call here goes to
mcount().(the -r option to objdump is handy)
Great, one never stops learning. :)
Quoted 7 lines
Exiting on a pending interrupt is controlled by the vmcs word
PIN_BASED_EXEC_CONTROL, bitPIN_BASED_EXT_INTR_MASK. Can you check (viavmcs_read32()) that the bit is indeed set?[if not, a guest can just enter a busy loop and kill a processor]
I traced it right before and after the asm block, and in all cases (including those with low latency exits) it's just 0x1f, which should be fine.
Earlier, I also checked GUEST_INTERRUPTIBILITY_INFO and GUEST_ACTIVITY_STATE, but found neither some suspicious state nor a difference compared to fast exits.
Jan
Signature · 8 lines
Siemens AG, Corporate Technology, CT SE 2 Corporate Competence Center Embedded Linux ------------------------------------------------------------------------- This SF.net email is sponsored by: Splunk Inc. Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
Quoted 5 lines · Jan Kiszka
Quoted 5 lines
Exiting on a pending interrupt is controlled by the vmcs word
PIN_BASED_EXEC_CONTROL, bitPIN_BASED_EXT_INTR_MASK. Can you check (viavmcs_read32()) that the bit is indeed set?
Quoted 9 lines
Quoted 3 lines
[if not, a guest can just enter a busy loop and kill a processor]
I traced it right before and after the asm block, and in all cases (including those with low latency exits) it's just
0x1f, which should be fine.
Yes.
Quoted 4 lines
Earlier, I also checked
GUEST_INTERRUPTIBILITY_INFOandGUEST_ACTIVITY_STATE, but found neither some suspicious state nor a difference compared to fast exits.
GUEST_* things are unrelated; these talk about whether the guest is ready to receive an interrupt, but we don't really care, do we?
I don't have any idea why this is happening. This is completely unrelated to -rt issues -- this is between kvm and the hardware.
Is this on a uniprocessor system? If not, can you try nosmp?
Signature · 8 lines
Do not meddle in the internals of kernels, for they are subtle and quick to panic. ------------------------------------------------------------------------- This SF.net email is sponsored by: Splunk Inc. Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
Quoted 16 lines · Avi Kivity
Quoted 4 lines · Jan Kiszka
Quoted 4 lines
Exiting on a pending interrupt is controlled by the vmcs word
PIN_BASED_EXEC_CONTROL, bitPIN_BASED_EXT_INTR_MASK. Can you check (viavmcs_read32()) that the bit is indeed set?Quoted 8 lines
Quoted 3 lines
[if not, a guest can just enter a busy loop and kill a processor]
I traced it right before and after the asm block, and in all cases (including those with low latency exits) it's just
0x1f, which should be fine.Yes.
Quoted 7 lines
Quoted 4 lines
Earlier, I also checked
GUEST_INTERRUPTIBILITY_INFOandGUEST_ACTIVITY_STATE, but found neither some suspicious state nor a difference compared to fast exits.GUEST_* things are unrelated; these talk about whether the guest is ready to receive an interrupt, but we don't really care, do we?
Nope, of course (looks like my VMX manual interpreter still needs improvements...).
Quoted 5 lines
I don't have any idea why this is happening. This is completely unrelated to -rt issues -- this is between kvm and the hardware.
Is this on a uniprocessor system? If not, can you try nosmp?
It's both: -rt tests were performed with nosmp (-rt locks up under SMP here), and the Xenomai tests, including the last instrumentation, ran in SMP mode. So I tend to exclude SMP effects.
Do you have some suggestion how to analyse what the guest is executing while those IRQs are delayed? As I said, I suspect some interaction of the Bochs BIOS is triggering the effect, because it only shows up (with a Linux guest) before the BIOS prints the first messages.
Jan
Signature · 8 lines
Siemens AG, Corporate Technology, CT SE 2 Corporate Competence Center Embedded Linux ------------------------------------------------------------------------- This SF.net email is sponsored by: Splunk Inc. Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
Quoted 9 lines · Jan Kiszka
It's both: -rt tests were performed with nosmp (-rt locks up under SMP here), and the Xenomai tests, including the last instrumentation, ran in SMP mode. So I tend to exclude SMP effects.
Do you have some suggestion how to analyse what the guest is executing while those IRQs are delayed? As I said, I suspect some interaction of the Bochs BIOS is triggering the effect, because it only shows up (with a Linux guest) before the BIOS prints the first messages.
The guest is probably spinning. Can you try modifying user/test/bootstrap.S, around the start label, to look like
start: jmp start
? This can then be executed with
user/kvmctl user/test/bootstrap user/test/access.flat
This will give us something consistent to test. The output of kvm_stat should also be interesting (should show exits and irq_exits advancing at 10K/sec).
(once Linux starts executing, it takes a lot of pagefault exits for the mmu, and then a lot of hlt exit once it idles).
Signature · 8 lines
Do not meddle in the internals of kernels, for they are subtle and quick to panic. ------------------------------------------------------------------------- This SF.net email is sponsored by: Splunk Inc. Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
Quoted 11 lines · Avi Kivity
Quoted 9 lines · Jan Kiszka
It's both: -rt tests were performed with nosmp (-rt locks up under SMP here), and the Xenomai tests, including the last instrumentation, ran in SMP mode. So I tend to exclude SMP effects.
Do you have some suggestion how to analyse what the guest is executing while those IRQs are delayed? As I said, I suspect some interaction of the Bochs BIOS is triggering the effect, because it only shows up (with a Linux guest) before the BIOS prints the first messages.
Quoted 8 lines
The guest is probably spinning. Can you try modifying
user/test/bootstrap.S, around the start label, to look likestart: jmp start
? This can then be executed with
user/kvmctl user/test/bootstrap user/test/access.flat
Access flat is not being built here (kvm-48), or I'm pressing the wrong button. Forcing it with "make test/access.flat" gives build errors. What's the trick?
Quoted 4 lines
This will give us something consistent to test. The output of
kvm_statshould also be interesting (should show exits andirq_exitsadvancing at 10K/sec).
You probably mean with the artificial test, not with qemu/kvm.
Quoted 6 lines
(once Linux starts executing, it takes a lot of pagefault exits for the mmu, and then a lot of hlt exit once it idles).
Jan
Signature · 8 lines
Siemens AG, Corporate Technology, CT SE 2 Corporate Competence Center Embedded Linux ------------------------------------------------------------------------- This SF.net email is sponsored by: Splunk Inc. Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
Quoted 19 lines · Jan Kiszka
Quoted 17 lines · Avi Kivity
Quoted 10 lines · Jan Kiszka
It's both: -rt tests were performed with nosmp (-rt locks up under SMP here), and the Xenomai tests, including the last instrumentation, ran in SMP mode. So I tend to exclude SMP effects.
Do you have some suggestion how to analyse what the guest is executing while those IRQs are delayed? As I said, I suspect some interaction of the Bochs BIOS is triggering the effect, because it only shows up (with a Linux guest) before the BIOS prints the first messages.
The guest is probably spinning. Can you try modifying
user/test/bootstrap.S, around the start label, to look likestart: jmp start
Quoted 10 lines
Quoted 4 lines
? This can then be executed with
user/kvmctl user/test/bootstrap user/test/access.flat
Access flat is not being built here (kvm-48), or I'm pressing the wrong button. Forcing it with "make test/access.flat" gives build errors. What's the trick?
Sorry, it's x86_64 specific. Just pick any other small file, since it won't be executed anyway, and there are no format requirements.
Quoted 8 lines
Quoted 4 lines
This will give us something consistent to test. The output of
kvm_statshould also be interesting (should show exits andirq_exitsadvancing at 10K/sec).You probably mean with the artificial test, not with qemu/kvm.
Yes.
Signature · 8 lines
Do not meddle in the internals of kernels, for they are subtle and quick to panic. ------------------------------------------------------------------------- This SF.net email is sponsored by: Splunk Inc. Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
Quoted 37 lines · Avi Kivity
Quoted 19 lines · Jan Kiszka
Quoted 17 lines · Avi Kivity
Quoted 10 lines · Jan Kiszka
It's both: -rt tests were performed with nosmp (-rt locks up under SMP here), and the Xenomai tests, including the last instrumentation, ran in SMP mode. So I tend to exclude SMP effects.
Do you have some suggestion how to analyse what the guest is executing while those IRQs are delayed? As I said, I suspect some interaction of the Bochs BIOS is triggering the effect, because it only shows up (with a Linux guest) before the BIOS prints the first messages.
The guest is probably spinning. Can you try modifying
user/test/bootstrap.S, around the start label, to look likestart: jmp start
Quoted 9 lines
Quoted 4 lines
? This can then be executed with
user/kvmctl user/test/bootstrap user/test/access.flat
Access flat is not being built here (kvm-48), or I'm pressing the wrong button. Forcing it with "make test/access.flat" gives build errors. What's the trick?
Sorry, it's
x86_64specific. Just pick any other small file, since it won't be executed anyway, and there are no format requirements.Quoted 4 lines
Quoted 4 lines
This will give us something consistent to test. The output of
kvm_statshould also be interesting (should show exits andirq_exitsadvancing at 10K/sec).
Quoted 6 lines
Quoted 3 lines
You probably mean with the artificial test, not with qemu/kvm.
Yes.
I ran
user/kvmctl user/test/bootstrap user/test/smp.flat
with the busy loop hacked into bootstrap, but I got no latency spots this time. And what should I look for in the output of kvm_stat?
Jan
Signature · 8 lines
Siemens AG, Corporate Technology, CT SE 2 Corporate Competence Center Embedded Linux ------------------------------------------------------------------------- This SF.net email is sponsored by: Splunk Inc. Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
Quoted 8 lines · Jan Kiszka
I ran
user/kvmctl user/test/bootstrap user/test/smp.flat
with the busy loop hacked into bootstrap, but I got no latency spots this time. And what should I look for in the output of
kvm_stat?
The first numeric column is the total number of exits; the second is the rate of change (per second). For a spinning workload, both irq_exits and exits rate should equal the timer frequency.
Signature · 8 lines
error compiling committee.c: too many arguments to function ------------------------------------------------------------------------- This SF.net email is sponsored by: Splunk Inc. Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
Quoted 5 lines · Avi Kivity
Quoted 4 lines · Jan Kiszka
I ran
user/kvmctl user/test/bootstrap user/test/smp.flat
Quoted 8 lines
Quoted 4 lines
with the busy loop hacked into bootstrap, but I got no latency spots this time. And what should I look for in the output of
kvm_stat?The first numeric column is the total number of exits; the second is the rate of change (per second). For a spinning workload, both
irq_exitsand exits rate should equal the timer frequency.
It matches roughly, but this isn't surprising given the lack of latency peaks in this scenario.
Jan
Signature · 8 lines
Siemens AG, Corporate Technology, CT SE 2 Corporate Competence Center Embedded Linux ------------------------------------------------------------------------- This SF.net email is sponsored by: Splunk Inc. Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
Quoted 13 lines · Jan Kiszka
Quoted 11 lines · Avi Kivity
Quoted 9 lines · Jan Kiszka
I ran
user/kvmctl user/test/bootstrap user/test/smp.flat
with the busy loop hacked into bootstrap, but I got no latency spots this time. And what should I look for in the output of
kvm_stat?
Quoted 9 lines
Quoted 4 lines
The first numeric column is the total number of exits; the second is the rate of change (per second). For a spinning workload, both
irq_exitsand exits rate should equal the timer frequency.It matches roughly, but this isn't surprising given the lack of latency peaks in this scenario.
Okay, that's expected. But I really can't think what causes the latency spike you see running the bios code. 300 microseconds is enough for 3000 cache misses. No instruction can cause so many except rep movs and friends, and these are supposed to be preemptible.
You might try isolating it by adding code to output markers to some I/O port and scattering it throughout the bios. A binary search should find the problem spot quickly.
Signature · 8 lines
error compiling committee.c: too many arguments to function ------------------------------------------------------------------------- This SF.net email is sponsored by: Splunk Inc. Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
Quoted 23 lines · Avi Kivity
Quoted 13 lines · Jan Kiszka
Quoted 11 lines · Avi Kivity
Quoted 9 lines · Jan Kiszka
I ran
user/kvmctl user/test/bootstrap user/test/smp.flat
with the busy loop hacked into bootstrap, but I got no latency spots this time. And what should I look for in the output of
kvm_stat?Quoted 8 lines
Quoted 4 lines
The first numeric column is the total number of exits; the second is the rate of change (per second). For a spinning workload, both
irq_exitsand exits rate should equal the timer frequency.It matches roughly, but this isn't surprising given the lack of latency peaks in this scenario.
Quoted 9 lines
Okay, that's expected. But I really can't think what causes the latency spike you see running the bios code. 300 microseconds is enough for 3000 cache misses. No instruction can cause so many except rep movs and friends, and these are supposed to be preemptible.
You might try isolating it by adding code to output markers to some I/O port and scattering it throughout the bios. A binary search should find the problem spot quickly.
Got it! It's wbinvd from smm_init in rombios32.c! Anyone any comments on this?
Jan (who's leaving now...)
Signature · 8 lines
Siemens AG, Corporate Technology, CT SE 2 Corporate Competence Center Embedded Linux ------------------------------------------------------------------------- This SF.net email is sponsored by: Splunk Inc. Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
Quoted 35 lines · Jan Kiszka
Quoted 33 lines · Avi Kivity
Quoted 16 lines · Jan Kiszka
Quoted 13 lines · Avi Kivity
Quoted 10 lines · Jan Kiszka
I ran
user/kvmctl user/test/bootstrap user/test/smp.flat
with the busy loop hacked into bootstrap, but I got no latency spots this time. And what should I look for in the output of
kvm_stat?Quoted 10 lines
Quoted 5 lines
The first numeric column is the total number of exits; the second is the rate of change (per second). For a spinning workload, both
irq_exitsand exits rate should equal the timer frequency.It matches roughly, but this isn't surprising given the lack of latency peaks in this scenario.
Okay, that's expected. But I really can't think what causes the latency spike you see running the bios code. 300 microseconds is enough for 3000 cache misses. No instruction can cause so many except rep movs and friends, and these are supposed to be preemptible.
Quoted 9 lines
Quoted 5 lines
You might try isolating it by adding code to output markers to some I/O port and scattering it throughout the bios. A binary search should find the problem spot quickly.
Got it! It's wbinvd from
smm_initinrombios32.c! Anyone any comments on this?
Ha! A real life 300usec instruction!
Unfortunately, it cannot be trapped on Intel (it can be trapped on AMD). Looks like a minor hole in VT, as a guest can generate very high latencies this way.
For our bios, we can remove it, but there's no way to ensure an untrusted guest doesn't use it.
Signature · 8 lines
error compiling committee.c: too many arguments to function ------------------------------------------------------------------------- This SF.net email is sponsored by: Splunk Inc. Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
Quoted 10 lines · Avi Kivity
Quoted 3 lines · Jan Kiszka
Got it! It's wbinvd from
smm_initinrombios32.c! Anyone any comments on this?Ha! A real life 300usec instruction!
Unfortunately, it cannot be trapped on Intel (it can be trapped on AMD). Looks like a minor hole in VT, as a guest can generate very high latencies this way.
I unfortunately do not have an AMD box at hand to test (I obviously order the wrong processor then...), but does this mean it is trapped by kvm-amd already? Or would there be more work required on that side?
Quoted 3 lines
For our bios, we can remove it, but there's no way to ensure an untrusted guest doesn't use it.
Yep. Any ideas if and at which stages (bootup, normal operation) Windows is issues wbinvd noise?
Jan
Signature · 8 lines
Siemens AG, Corporate Technology, CT SE 2 Corporate Competence Center Embedded Linux ------------------------------------------------------------------------- This SF.net email is sponsored by: Splunk Inc. Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
Quoted 10 lines · Jan Kiszka
Quoted 8 lines · Avi Kivity
Quoted 4 lines · Jan Kiszka
Got it! It's wbinvd from
smm_initinrombios32.c! Anyone any comments on this?Ha! A real life 300usec instruction!
Quoted 10 lines
Quoted 4 lines
Unfortunately, it cannot be trapped on Intel (it can be trapped on AMD). Looks like a minor hole in VT, as a guest can generate very high latencies this way.
I unfortunately do not have an AMD box at hand to test (I obviously order the wrong processor then...), but does this mean it is trapped by kvm-amd already? Or would there be more work required on that side?
There's a two-liner required to make it work. I'll add it soon.
Quoted 7 lines
Quoted 3 lines
For our bios, we can remove it, but there's no way to ensure an untrusted guest doesn't use it.
Yep. Any ideas if and at which stages (bootup, normal operation) Windows is issues wbinvd noise?
No idea. I'll check it with an AMD machine.
I'd be surprised it it did that during normal operation. It's also conceivable that it doesn't issue it at all.
Signature · 8 lines
error compiling committee.c: too many arguments to function ------------------------------------------------------------------------- This SF.net email is sponsored by: Splunk Inc. Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
Quoted 3 lines
There's a two-liner required to make it work. I'll add it soon.
But you still needs to issue WBINVD to all pCPUs which just move non-response time from one place to another, not? Eddie
-------------------------------------------------------------------------
This SF.net email is sponsored by: Splunk Inc.
Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
Quoted 6 lines · Eddie
Quoted 3 lines
There's a two-liner required to make it work. I'll add it soon.
But you still needs to issue WBINVD to all pCPUs which just move non-response time from one place to another, not?
You don't actually need to emulate wbinvd, you can just ignore it.
The only reason I can think of to use wbinvd is if you're taking a cpu down (for a deep sleep state, or if you're shutting it off). A guest need not do that.
Any other reason? dma? all dma today is cache-coherent, no?
Signature · 8 lines
error compiling committee.c: too many arguments to function ------------------------------------------------------------------------- This SF.net email is sponsored by: Splunk Inc. Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
Quoted 8 lines · Avi Kivity
Quoted 6 lines · Eddie
Quoted 3 lines
There's a two-liner required to make it work. I'll add it soon.
But you still needs to issue WBINVD to all pCPUs which just move non-response time from one place to another, not?
Quoted 8 lines
You don't actually need to emulate wbinvd, you can just ignore it.
The only reason I can think of to use wbinvd is if you're taking a cpu down (for a deep sleep state, or if you're shutting it off). A guest need not do that.
Any other reason? dma? all dma today is cache-coherent, no?
For legacy PCI device, yes it is cache-cohetent, but for PCIe devices, it is no longer a must. A PCIe device may not generate snoopy cycle and thus require OS to flush cache.
For example, a guest with direct device, say audio, can copy data to dma buffer and then wbinvd to flush cache out and ask HW DMA to output.
Thx,Eddie
-------------------------------------------------------------------------
This SF.net email is sponsored by: Splunk Inc.
Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
Quoted 16 lines · Eddie
Quoted 7 lines · Avi Kivity
Quoted 6 lines · Eddie
Quoted 3 lines
There's a two-liner required to make it work. I'll add it soon.
But you still needs to issue WBINVD to all pCPUs which just move non-response time from one place to another, not?
Quoted 8 lines
You don't actually need to emulate wbinvd, you can just ignore it.
The only reason I can think of to use wbinvd is if you're taking a cpu down (for a deep sleep state, or if you're shutting it off). A guest need not do that.
Any other reason? dma? all dma today is cache-coherent, no?
Quoted 7 lines
For legacy PCI device, yes it is cache-cohetent, but for PCIe devices, it is no longer a must. A PCIe device may not generate snoopy cycle and thus require OS to flush cache.
For example, a guest with direct device, say audio, can copy data to dma buffer and then wbinvd to flush cache out and ask HW DMA to output.
So if you want the higher performance of PCIe you need performance-killing wbindv (not to speak of latency)? That sounds a bit contradictory to me. So this is also true for native PCIe usage?
What really frightens me about wbinvd is that its latency "nicely" scales with the cache sizes. And I think my observed latency is far from being the worst case. In a different experiment, I once measured wbinvd latencies of a few milliseconds... :(
Jan
Signature · 8 lines
Siemens AG, Corporate Technology, CT SE 2 Corporate Competence Center Embedded Linux ------------------------------------------------------------------------- This SF.net email is sponsored by: Splunk Inc. Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
Quoted 5 lines · Jan Kiszka
So if you want the higher performance of PCIe you need performance-killing wbindv (not to speak of latency)? That sounds a bit contradictory to me. So this is also true for native PCIe usage?
Mmm, I won't say so. When you want to get RT performance, you won't use unknown OS such as Windows. If you use your RT linux, the OS (guest) itself should not use wbinvd.
For the Bochs BIOS case, like Avi mentioned, we can simply remove it.
Quoted 6 lines
What really frightens me about wbinvd is that its latency "nicely" scales with the cache sizes. And I think my observed latency is far from
being the worst case. In a different experiment, I once measured wbinvd latencies of a few milliseconds... :(
I don't know details, but it could be. While RT usage can easily remove this instruction.
thx,eddie
-------------------------------------------------------------------------
This SF.net email is sponsored by: Splunk Inc.
Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
Quoted 21 lines · Eddie
Quoted 10 lines · Avi Kivity
Quoted 8 lines · Eddie
Quoted 4 lines
There's a two-liner required to make it work. I'll add it soon.
But you still needs to issue WBINVD to all pCPUs which just move non-response time from one place to another, not?
Quoted 9 lines
You don't actually need to emulate wbinvd, you can just ignore it.
The only reason I can think of to use wbinvd is if you're taking a cpu down (for a deep sleep state, or if you're shutting it off). A guest need not do that.
Any other reason? dma? all dma today is cache-coherent, no?
Quoted 8 lines
For legacy PCI device, yes it is cache-cohetent, but for PCIe devices, it is no longer a must. A PCIe device may not generate snoopy cycle and thus require OS to flush cache.
For example, a guest with direct device, say audio, can copy data to dma buffer and then wbinvd to flush cache out and ask HW DMA to output.
Okay. In that case the host can emulate wbinvd by using the clflush instruction, which is much faster (although overall execution time may be higher), maintaining real-time response times.
Signature · 8 lines
error compiling committee.c: too many arguments to function ------------------------------------------------------------------------- This SF.net email is sponsored by: Splunk Inc. Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
Quoted 27 lines · Jan Kiszka
Quoted 25 lines · Eddie
Quoted 10 lines · Avi Kivity
Quoted 8 lines · Eddie
Quoted 4 lines
There's a two-liner required to make it work. I'll add it soon.
But you still needs to issue WBINVD to all pCPUs which just move non-response time from one place to another, not?
Quoted 9 lines
You don't actually need to emulate wbinvd, you can just ignore it.
The only reason I can think of to use wbinvd is if you're taking a cpu down (for a deep sleep state, or if you're shutting it off). A guest need not do that.
Any other reason? dma? all dma today is cache-coherent, no?
For legacy PCI device, yes it is cache-cohetent, but for PCIe devices, it is no longer a must. A PCIe device may not generate snoopy cycle and thus require OS to flush cache.
Quoted 10 lines
Quoted 4 lines
For example, a guest with direct device, say audio, can copy data to dma buffer and then wbinvd to flush cache out and ask HW DMA to output.
So if you want the higher performance of PCIe you need performance-killing wbindv (not to speak of latency)? That sounds a bit contradictory to me. So this is also true for native PCIe usage?
Yes, good point. wbinvd is not only expensive in that it takes a long time to execute, it blows your caches so that anything that executes afterwards takes a huge hit.
Signature · 8 lines
error compiling committee.c: too many arguments to function ------------------------------------------------------------------------- This SF.net email is sponsored by: Splunk Inc. Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
Quoted 26 lines · Avi Kivity
Quoted 25 lines · Eddie
Quoted 10 lines · Avi Kivity
Quoted 8 lines · Eddie
Quoted 4 lines
There's a two-liner required to make it work. I'll add it soon.
But you still needs to issue WBINVD to all pCPUs which just move non-response time from one place to another, not?
Quoted 9 lines
You don't actually need to emulate wbinvd, you can just ignore it.
The only reason I can think of to use wbinvd is if you're taking a cpu down (for a deep sleep state, or if you're shutting it off). A guest need not do that.
Any other reason? dma? all dma today is cache-coherent, no?
For legacy PCI device, yes it is cache-cohetent, but for PCIe devices, it is no longer a must. A PCIe device may not generate snoopy cycle and thus require OS to flush cache.
Quoted 8 lines
Quoted 4 lines
For example, a guest with direct device, say audio, can copy data to dma buffer and then wbinvd to flush cache out and ask HW DMA to output.
Okay. In that case the host can emulate wbinvd by using the clflush instruction, which is much faster (although overall execution time may be higher), maintaining real-time response times.
Faster? maybe.
The issue is clflush take va parameter. So KVM needs to map gpa first and
then do flush.
WIth this additional overhead. I am not sure which one is faster. But yes,
this is the trend we may walk toward to reduce Deny of Service. (flush host or other VM's cache will slowdown whole system).
Eddie
-------------------------------------------------------------------------
This SF.net email is sponsored by: Splunk Inc.
Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
Quoted 12 lines · Eddie
Quoted 5 lines · Jan Kiszka
So if you want the higher performance of PCIe you need performance-killing wbindv (not to speak of latency)? That sounds a bit contradictory to me. So this is also true for native PCIe usage?
Mmm, I won't say so. When you want to get RT performance, you won't use unknown OS such as Windows. If you use your RT linux, the OS (guest) itself should not use wbinvd.
The idea is to have a RT-Linux on the host that runs RT jobs but also use it to run mgmt/other code on windows guests.
This way you can better utilize an idle RT linux while keeping short latencies for the RT jobs.
Dor.
Quoted 15 lines
For the Bochs BIOS case, like Avi mentioned, we can simply remove it.
Quoted 6 lines
What really frightens me about wbinvd is that its latency "nicely" scales with the cache sizes. And I think my observed latency is far from
being the worst case. In a different experiment, I once measured wbinvd latencies of a few milliseconds... :(I don't know details, but it could be. While RT usage can easily remove this instruction.
thx,eddie
Quoted 10 lines
-------------------------------------------------------------------------
This SF.net email is sponsored by: Splunk Inc.
Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
_______________________________________________
kvm-devel mailing list [email protected]
https://lists.sourceforge.net/lists/listinfo/kvm-devel
-------------------------------------------------------------------------
This SF.net email is sponsored by: Splunk Inc.
Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
Quoted 11 lines · Eddie
Quoted 5 lines
Quoted 1 line
Okay. In that case the host can emulate wbinvd by using the clflush instruction, which is much faster (although overall execution time may be higher), maintaining real-time response times.
Faster? maybe.
The issue is clflush take va parameter. So KVM needs to map gpa first and
then do flush.
Quoted 5 lines
WIth this additional overhead. I am not sure which one is faster. But yes,
this is the trend we may walk toward to reduce Deny of Service. (flush host or other VM's cache will slowdown whole system).
The issue is not total time to execute (wbinvd is probably faster), but the time where interrupts are blocked. wbinvd can block interrupts for milliseconds, and if your industrial control machine needs service every 100 microsecond, something breaks.
[Background: this is for running Linux with realtime extensions as host, with realtime processes on the host doing the control tasks and a guest doing the GUI and perhaps communications.]
Signature · 8 lines
error compiling committee.c: too many arguments to function ------------------------------------------------------------------------- This SF.net email is sponsored by: Splunk Inc. Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
Quoted 8 lines · Eddie
Quoted 5 lines · Jan Kiszka
So if you want the higher performance of PCIe you need performance-killing wbindv (not to speak of latency)? That sounds a bit contradictory to me. So this is also true for native PCIe usage?
Quoted 5 lines
Mmm, I won't say so. When you want to get RT performance, you won't use unknown OS such as Windows. If you use your RT linux, the OS (guest) itself should not use wbinvd.
Well, virtualization lets you use an unknown OS without fear of compromising host security, so a real-time capable hypervisor (which kvm is, or very nearly) should be able to let you use an unknown OS without fear of compromising real-time response times. Right now the only unresolvable issue I see is wbinvd.
Signature · 8 lines
error compiling committee.c: too many arguments to function ------------------------------------------------------------------------- This SF.net email is sponsored by: Splunk Inc. Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/
Quoted 15 lines · Avi Kivity
Quoted 8 lines · Eddie
Quoted 5 lines · Jan Kiszka
So if you want the higher performance of PCIe you need performance-killing wbindv (not to speak of latency)? That sounds a bit contradictory to me. So this is also true for native PCIe usage?
Quoted 5 lines
Mmm, I won't say so. When you want to get RT performance, you won't use unknown OS such as Windows. If you use your RT linux, the OS (guest) itself should not use wbinvd.
Quoted 7 lines
Well, virtualization lets you use an unknown OS without fear of compromising host security, so a real-time capable hypervisor (which kvm is, or very nearly) should be able to let you use an unknown OS without
fear of compromising real-time response times. Right now the only unresolvable issue I see is wbinvd.
Got it, I was mis-understood the problem!
Eddie
-------------------------------------------------------------------------
This SF.net email is sponsored by: Splunk Inc.
Still grepping through log files to find problems? Stop. Now Search log events and configuration files using AJAX and a browser. Download your FREE copy of Splunk now >> http://get.splunk.com/