Re: High vm-exit latencies during kvm boot-up/shutdown

Avi Kivity
2007-10-23T15:26:08Z

Jan Kiszka wrote:
> Avi Kivity wrote:
>
>> Jan Kiszka wrote:
>>
>>> Avi,
>>>
>>> [somehow your mails do not get through to my private account, so I'm
>>> switching]
>>>
>>> Avi Kivity wrote:
>>>
>>>
>>>> Jan Kiszka wrote:
>>>>
>>>>
>>>>> 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.
>>>
>>>
>>>
>>>> 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?
>>>
>>>
>> 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.
>
>

Ok. So it is not interrupt driven, and that's how you get traces in
functions that run with interrupts disabled.

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

>> Please post a disassembly of your vmx_vcpu_run so 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>
>

first trace

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

second trace

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

--
Do not meddle in the internals of kernels, for they are subtle and quick to panic.