kvm: odd time values since "kvmclock: set scheduler clock stable"

kvm: odd time values since "kvmclock: set scheduler clock stable"

[Sasha Levin]

Hi all,

I'm seeing odd jump in time values during boot of a KVM guest:

[...]
[    0.000000] tsc: Detected 2260.998 MHz processor
[3376355.247558] Calibrating delay loop (skipped) preset value..
[...]

I've bisected it to:


commit ff7bbb9c6ab6e6620429daeff39424bbde1a94b4
Author: Luiz Capitulino <lcapitulino@redhat.com>
Date:   Thu Apr 23 17:12:42 2015 -0400

    kvmclock: set scheduler clock stable

    If you try to enable NOHZ_FULL on a guest today, you'll get
    the following error when the guest tries to deactivate the
    scheduler tick:

     WARNING: CPU: 3 PID: 2182 at kernel/time/tick-sched.c:192 can_stop_full_tick+0xb9/0x290()
     NO_HZ FULL will not work with unstable sched clock
     CPU: 3 PID: 2182 Comm: kworker/3:1 Not tainted 4.0.0-10545-gb9bb6fb #204
     Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
     Workqueue: events flush_to_ldisc
      ffffffff8162a0c7 ffff88011f583e88 ffffffff814e6ba0 0000000000000002
      ffff88011f583ed8 ffff88011f583ec8 ffffffff8104d095 ffff88011f583eb8
      0000000000000000 0000000000000003 0000000000000001 0000000000000001
     Call Trace:
      <IRQ>  [<ffffffff814e6ba0>] dump_stack+0x4f/0x7b
      [<ffffffff8104d095>] warn_slowpath_common+0x85/0xc0
      [<ffffffff8104d146>] warn_slowpath_fmt+0x46/0x50
      [<ffffffff810bd2a9>] can_stop_full_tick+0xb9/0x290
      [<ffffffff810bd9ed>] tick_nohz_irq_exit+0x8d/0xb0
      [<ffffffff810511c5>] irq_exit+0xc5/0x130
      [<ffffffff814f180a>] smp_apic_timer_interrupt+0x4a/0x60
      [<ffffffff814eff5e>] apic_timer_interrupt+0x6e/0x80
      <EOI>  [<ffffffff814ee5d1>] ? _raw_spin_unlock_irqrestore+0x31/0x60
      [<ffffffff8108bbc8>] __wake_up+0x48/0x60
      [<ffffffff8134836c>] n_tty_receive_buf_common+0x49c/0xba0
      [<ffffffff8134a6bf>] ? tty_ldisc_ref+0x1f/0x70
      [<ffffffff81348a84>] n_tty_receive_buf2+0x14/0x20
      [<ffffffff8134b390>] flush_to_ldisc+0xe0/0x120
      [<ffffffff81064d05>] process_one_work+0x1d5/0x540
      [<ffffffff81064c81>] ? process_one_work+0x151/0x540
      [<ffffffff81065191>] worker_thread+0x121/0x470
      [<ffffffff81065070>] ? process_one_work+0x540/0x540
      [<ffffffff8106b4df>] kthread+0xef/0x110
      [<ffffffff8106b3f0>] ? __kthread_parkme+0xa0/0xa0
      [<ffffffff814ef4f2>] ret_from_fork+0x42/0x70
      [<ffffffff8106b3f0>] ? __kthread_parkme+0xa0/0xa0
     ---[ end trace 06e3507544a38866 ]---

    However, it turns out that kvmclock does provide a stable
    sched_clock callback. So, let the scheduler know this which
    in turn makes NOHZ_FULL work in the guest.

    Signed-off-by: Marcelo Tosatti <mtosatti@redhat.com>
    Signed-off-by: Luiz Capitulino <lcapitulino@redhat.com>
    Signed-off-by: Paolo Bonzini <pbonzini@redhat.com>


Thanks,
Sasha

Re: kvm: odd time values since "kvmclock: set scheduler clock stable"

[Luiz Capitulino]

On Tue, 12 May 2015 19:17:24 -0400
Sasha Levin <sasha.levin@oracle.com> wrote:

> Hi all,
> 
> I'm seeing odd jump in time values during boot of a KVM guest:
> 
> [...]
> [    0.000000] tsc: Detected 2260.998 MHz processor
> [3376355.247558] Calibrating delay loop (skipped) preset value..
> [...]
> 
> I've bisected it to:

Thanks for bisecting. You just boot a guest to reproduce this? How
many vCPUs does the guest have?

Paolo, I think it's better to drop this patch for now.

> 
> 
> commit ff7bbb9c6ab6e6620429daeff39424bbde1a94b4
> Author: Luiz Capitulino <lcapitulino@redhat.com>
> Date:   Thu Apr 23 17:12:42 2015 -0400
> 
>     kvmclock: set scheduler clock stable
> 
>     If you try to enable NOHZ_FULL on a guest today, you'll get
>     the following error when the guest tries to deactivate the
>     scheduler tick:
> 
>      WARNING: CPU: 3 PID: 2182 at kernel/time/tick-sched.c:192 can_stop_full_tick+0xb9/0x290()
>      NO_HZ FULL will not work with unstable sched clock
>      CPU: 3 PID: 2182 Comm: kworker/3:1 Not tainted 4.0.0-10545-gb9bb6fb #204
>      Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
>      Workqueue: events flush_to_ldisc
>       ffffffff8162a0c7 ffff88011f583e88 ffffffff814e6ba0 0000000000000002
>       ffff88011f583ed8 ffff88011f583ec8 ffffffff8104d095 ffff88011f583eb8
>       0000000000000000 0000000000000003 0000000000000001 0000000000000001
>      Call Trace:
>       <IRQ>  [<ffffffff814e6ba0>] dump_stack+0x4f/0x7b
>       [<ffffffff8104d095>] warn_slowpath_common+0x85/0xc0
>       [<ffffffff8104d146>] warn_slowpath_fmt+0x46/0x50
>       [<ffffffff810bd2a9>] can_stop_full_tick+0xb9/0x290
>       [<ffffffff810bd9ed>] tick_nohz_irq_exit+0x8d/0xb0
>       [<ffffffff810511c5>] irq_exit+0xc5/0x130
>       [<ffffffff814f180a>] smp_apic_timer_interrupt+0x4a/0x60
>       [<ffffffff814eff5e>] apic_timer_interrupt+0x6e/0x80
>       <EOI>  [<ffffffff814ee5d1>] ? _raw_spin_unlock_irqrestore+0x31/0x60
>       [<ffffffff8108bbc8>] __wake_up+0x48/0x60
>       [<ffffffff8134836c>] n_tty_receive_buf_common+0x49c/0xba0
>       [<ffffffff8134a6bf>] ? tty_ldisc_ref+0x1f/0x70
>       [<ffffffff81348a84>] n_tty_receive_buf2+0x14/0x20
>       [<ffffffff8134b390>] flush_to_ldisc+0xe0/0x120
>       [<ffffffff81064d05>] process_one_work+0x1d5/0x540
>       [<ffffffff81064c81>] ? process_one_work+0x151/0x540
>       [<ffffffff81065191>] worker_thread+0x121/0x470
>       [<ffffffff81065070>] ? process_one_work+0x540/0x540
>       [<ffffffff8106b4df>] kthread+0xef/0x110
>       [<ffffffff8106b3f0>] ? __kthread_parkme+0xa0/0xa0
>       [<ffffffff814ef4f2>] ret_from_fork+0x42/0x70
>       [<ffffffff8106b3f0>] ? __kthread_parkme+0xa0/0xa0
>      ---[ end trace 06e3507544a38866 ]---
> 
>     However, it turns out that kvmclock does provide a stable
>     sched_clock callback. So, let the scheduler know this which
>     in turn makes NOHZ_FULL work in the guest.
> 
>     Signed-off-by: Marcelo Tosatti <mtosatti@redhat.com>
>     Signed-off-by: Luiz Capitulino <lcapitulino@redhat.com>
>     Signed-off-by: Paolo Bonzini <pbonzini@redhat.com>
> 
> 
> Thanks,
> Sasha
> 

Re: kvm: odd time values since "kvmclock: set scheduler clock stable"

[Sasha Levin]

On 05/13/2015 08:58 AM, Luiz Capitulino wrote:
> On Tue, 12 May 2015 19:17:24 -0400
> Sasha Levin <sasha.levin@oracle.com> wrote:
> 
>> > Hi all,
>> > 
>> > I'm seeing odd jump in time values during boot of a KVM guest:
>> > 
>> > [...]
>> > [    0.000000] tsc: Detected 2260.998 MHz processor
>> > [3376355.247558] Calibrating delay loop (skipped) preset value..
>> > [...]
>> > 
>> > I've bisected it to:
> Thanks for bisecting. You just boot a guest to reproduce this? How
> many vCPUs does the guest have?
> 
> Paolo, I think it's better to drop this patch for now.
> 

Yup, just booting a 32 VCPU guest - it happens very early during boot.


Thanks,
Sasha

Re: kvm: odd time values since "kvmclock: set scheduler clock stable"

[Paolo Bonzini]

On 13/05/2015 14:58, Luiz Capitulino wrote:
> On Tue, 12 May 2015 19:17:24 -0400
> Sasha Levin <sasha.levin@oracle.com> wrote:
> 
>> Hi all,
>>
>> I'm seeing odd jump in time values during boot of a KVM guest:
>>
>> [...]
>> [    0.000000] tsc: Detected 2260.998 MHz processor
>> [3376355.247558] Calibrating delay loop (skipped) preset value..
>> [...]
>>
>> I've bisected it to:
> 
> Thanks for bisecting. You just boot a guest to reproduce this? How
> many vCPUs does the guest have?
> 
> Paolo, I think it's better to drop this patch for now.

Ok, reverted.

Paolo

Re: kvm: odd time values since "kvmclock: set scheduler clock stable"

[Marcelo Tosatti]

On Tue, May 12, 2015 at 07:17:24PM -0400, Sasha Levin wrote:
> Hi all,
> 
> I'm seeing odd jump in time values during boot of a KVM guest:
> 
> [...]
> [    0.000000] tsc: Detected 2260.998 MHz processor
> [3376355.247558] Calibrating delay loop (skipped) preset value..
> [...]
> 
> I've bisected it to:

Paolo, Sasha,

Although this might seem undesirable, there is no requirement 
for sched_clock to initialize at 0:

"
 *
 * There is no strict promise about the base, although it tends to start
 * at 0 on boot (but people really shouldn't rely on that).
 *
"

Sasha, are you seeing any problem other than the apparent time jump?

Re: kvm: odd time values since "kvmclock: set scheduler clock stable"

[Sasha Levin]

On 05/18/2015 06:39 PM, Marcelo Tosatti wrote:
> On Tue, May 12, 2015 at 07:17:24PM -0400, Sasha Levin wrote:
>> Hi all,
>>
>> I'm seeing odd jump in time values during boot of a KVM guest:
>>
>> [...]
>> [    0.000000] tsc: Detected 2260.998 MHz processor
>> [3376355.247558] Calibrating delay loop (skipped) preset value..
>> [...]
>>
>> I've bisected it to:
> 
> Paolo, Sasha,
> 
> Although this might seem undesirable, there is no requirement 
> for sched_clock to initialize at 0:
> 
> "
>  *
>  * There is no strict promise about the base, although it tends to start
>  * at 0 on boot (but people really shouldn't rely on that).
>  *
> "
> 
> Sasha, are you seeing any problem other than the apparent time jump?

Nope, but I've looked at it again and it seems that it jumps to the host's
clock (that is, in the example above the 3376355 value was the host's clock
value).


Thanks,
Sasha

Re: kvm: odd time values since "kvmclock: set scheduler clock stable"

[Marcelo Tosatti]

GOn Mon, May 18, 2015 at 07:45:41PM -0400, Sasha Levin wrote:
> On 05/18/2015 06:39 PM, Marcelo Tosatti wrote:
> > On Tue, May 12, 2015 at 07:17:24PM -0400, Sasha Levin wrote:
> >> Hi all,
> >>
> >> I'm seeing odd jump in time values during boot of a KVM guest:
> >>
> >> [...]
> >> [    0.000000] tsc: Detected 2260.998 MHz processor
> >> [3376355.247558] Calibrating delay loop (skipped) preset value..
> >> [...]
> >>
> >> I've bisected it to:
> > 
> > Paolo, Sasha,
> > 
> > Although this might seem undesirable, there is no requirement 
> > for sched_clock to initialize at 0:
> > 
> > "
> >  *
> >  * There is no strict promise about the base, although it tends to start
> >  * at 0 on boot (but people really shouldn't rely on that).
> >  *
> > "
> > 
> > Sasha, are you seeing any problem other than the apparent time jump?
> 
> Nope, but I've looked at it again and it seems that it jumps to the host's
> clock (that is, in the example above the 3376355 value was the host's clock
> value).
> 
> 
> Thanks,
> Sasha

Sasha, thats right. Its the host monotonic clock.

Re: kvm: odd time values since "kvmclock: set scheduler clock stable"

[Sasha Levin]

On 05/18/2015 08:13 PM, Marcelo Tosatti wrote:
> GOn Mon, May 18, 2015 at 07:45:41PM -0400, Sasha Levin wrote:
>> > On 05/18/2015 06:39 PM, Marcelo Tosatti wrote:
>>> > > On Tue, May 12, 2015 at 07:17:24PM -0400, Sasha Levin wrote:
>>>> > >> Hi all,
>>>> > >>
>>>> > >> I'm seeing odd jump in time values during boot of a KVM guest:
>>>> > >>
>>>> > >> [...]
>>>> > >> [    0.000000] tsc: Detected 2260.998 MHz processor
>>>> > >> [3376355.247558] Calibrating delay loop (skipped) preset value..
>>>> > >> [...]
>>>> > >>
>>>> > >> I've bisected it to:
>>> > > 
>>> > > Paolo, Sasha,
>>> > > 
>>> > > Although this might seem undesirable, there is no requirement 
>>> > > for sched_clock to initialize at 0:
>>> > > 
>>> > > "
>>> > >  *
>>> > >  * There is no strict promise about the base, although it tends to start
>>> > >  * at 0 on boot (but people really shouldn't rely on that).
>>> > >  *
>>> > > "
>>> > > 
>>> > > Sasha, are you seeing any problem other than the apparent time jump?
>> > 
>> > Nope, but I've looked at it again and it seems that it jumps to the host's
>> > clock (that is, in the example above the 3376355 value was the host's clock
>> > value).
>> > 
>> > 
>> > Thanks,
>> > Sasha
> Sasha, thats right. Its the host monotonic clock.

It's worth figuring out if (what) userspace breaks on that. I know it says that
you shouldn't rely on that, but I'd happily place a bet on at least one userspace
treating it as "seconds since boot" or something similar.


Thanks,
Sasha

Re: kvm: odd time values since "kvmclock: set scheduler clock stable"

[Sasha Levin]

On 05/18/2015 10:02 PM, Sasha Levin wrote:
> On 05/18/2015 08:13 PM, Marcelo Tosatti wrote:
>> GOn Mon, May 18, 2015 at 07:45:41PM -0400, Sasha Levin wrote:
>>>> On 05/18/2015 06:39 PM, Marcelo Tosatti wrote:
>>>>>> On Tue, May 12, 2015 at 07:17:24PM -0400, Sasha Levin wrote:
>>>>>>>> Hi all,
>>>>>>>>
>>>>>>>> I'm seeing odd jump in time values during boot of a KVM guest:
>>>>>>>>
>>>>>>>> [...]
>>>>>>>> [    0.000000] tsc: Detected 2260.998 MHz processor
>>>>>>>> [3376355.247558] Calibrating delay loop (skipped) preset value..
>>>>>>>> [...]
>>>>>>>>
>>>>>>>> I've bisected it to:
>>>>>>
>>>>>> Paolo, Sasha,
>>>>>>
>>>>>> Although this might seem undesirable, there is no requirement 
>>>>>> for sched_clock to initialize at 0:
>>>>>>
>>>>>> "
>>>>>>  *
>>>>>>  * There is no strict promise about the base, although it tends to start
>>>>>>  * at 0 on boot (but people really shouldn't rely on that).
>>>>>>  *
>>>>>> "
>>>>>>
>>>>>> Sasha, are you seeing any problem other than the apparent time jump?
>>>>
>>>> Nope, but I've looked at it again and it seems that it jumps to the host's
>>>> clock (that is, in the example above the 3376355 value was the host's clock
>>>> value).
>>>>
>>>>
>>>> Thanks,
>>>> Sasha
>> Sasha, thats right. Its the host monotonic clock.
> 
> It's worth figuring out if (what) userspace breaks on that. I know it says that
> you shouldn't rely on that, but I'd happily place a bet on at least one userspace
> treating it as "seconds since boot" or something similar.

Didn't need to go far... In the guest:

# date
Tue May 19 02:11:46 UTC 2015
# echo hi > /dev/kmsg
[3907533.080112] hi
# dmesg -T
[Fri Jul  3 07:33:41 2015] hi



Thanks,
Sasha

KVM: x86: zero kvmclock_offset when vcpu0 initializes kvmclock system MSR

[Marcelo Tosatti]

Initialize kvmclock base, on kvmclock system MSR write time, 
so that the guest sees kvmclock counting from zero.

This matches baremetal behaviour when kvmclock in guest
sets sched clock stable.

Signed-off-by: Marcelo Tosatti <mtosatti@redhat.com>

diff --git a/arch/x86/kvm/x86.c b/arch/x86/kvm/x86.c
index cc2c759..ea40d24 100644
--- a/arch/x86/kvm/x86.c
+++ b/arch/x86/kvm/x86.c
@@ -2188,6 +2188,8 @@ int kvm_set_msr_common(struct kvm_vcpu *vcpu, struct msr_data *msr_info)
 					&vcpu->requests);
 
 			ka->boot_vcpu_runs_old_kvmclock = tmp;
+
+			ka->kvmclock_offset = get_kernel_ns();
 		}
 
 		vcpu->arch.time = data;

Re: kvm: odd time values since "kvmclock: set scheduler clock stable"

[Marcelo Tosatti]

On Mon, May 18, 2015 at 10:13:03PM -0400, Sasha Levin wrote:
> On 05/18/2015 10:02 PM, Sasha Levin wrote:
> > On 05/18/2015 08:13 PM, Marcelo Tosatti wrote:
> >> GOn Mon, May 18, 2015 at 07:45:41PM -0400, Sasha Levin wrote:
> >>>> On 05/18/2015 06:39 PM, Marcelo Tosatti wrote:
> >>>>>> On Tue, May 12, 2015 at 07:17:24PM -0400, Sasha Levin wrote:
> >>>>>>>> Hi all,
> >>>>>>>>
> >>>>>>>> I'm seeing odd jump in time values during boot of a KVM guest:
> >>>>>>>>
> >>>>>>>> [...]
> >>>>>>>> [    0.000000] tsc: Detected 2260.998 MHz processor
> >>>>>>>> [3376355.247558] Calibrating delay loop (skipped) preset value..
> >>>>>>>> [...]
> >>>>>>>>
> >>>>>>>> I've bisected it to:
> >>>>>>
> >>>>>> Paolo, Sasha,
> >>>>>>
> >>>>>> Although this might seem undesirable, there is no requirement 
> >>>>>> for sched_clock to initialize at 0:
> >>>>>>
> >>>>>> "
> >>>>>>  *
> >>>>>>  * There is no strict promise about the base, although it tends to start
> >>>>>>  * at 0 on boot (but people really shouldn't rely on that).
> >>>>>>  *
> >>>>>> "
> >>>>>>
> >>>>>> Sasha, are you seeing any problem other than the apparent time jump?
> >>>>
> >>>> Nope, but I've looked at it again and it seems that it jumps to the host's
> >>>> clock (that is, in the example above the 3376355 value was the host's clock
> >>>> value).
> >>>>
> >>>>
> >>>> Thanks,
> >>>> Sasha
> >> Sasha, thats right. Its the host monotonic clock.
> > 
> > It's worth figuring out if (what) userspace breaks on that. I know it says that
> > you shouldn't rely on that, but I'd happily place a bet on at least one userspace
> > treating it as "seconds since boot" or something similar.
> 
> Didn't need to go far... In the guest:
> 
> # date
> Tue May 19 02:11:46 UTC 2015
> # echo hi > /dev/kmsg
> [3907533.080112] hi
> # dmesg -T
> [Fri Jul  3 07:33:41 2015] hi

Sasha,

Can you give the suggested patch (hypervisor patch...) a try please?
(with a patched guest, obviously).

KVM: x86: zero kvmclock_offset when vcpu0 initializes kvmclock system
MSR

Re: kvm: odd time values since "kvmclock: set scheduler clock stable"

[Luiz Capitulino]

On Thu, 21 May 2015 21:41:23 -0300
Marcelo Tosatti <mtosatti@redhat.com> wrote:

> On Mon, May 18, 2015 at 10:13:03PM -0400, Sasha Levin wrote:
> > On 05/18/2015 10:02 PM, Sasha Levin wrote:
> > > On 05/18/2015 08:13 PM, Marcelo Tosatti wrote:
> > >> GOn Mon, May 18, 2015 at 07:45:41PM -0400, Sasha Levin wrote:
> > >>>> On 05/18/2015 06:39 PM, Marcelo Tosatti wrote:
> > >>>>>> On Tue, May 12, 2015 at 07:17:24PM -0400, Sasha Levin wrote:
> > >>>>>>>> Hi all,
> > >>>>>>>>
> > >>>>>>>> I'm seeing odd jump in time values during boot of a KVM guest:
> > >>>>>>>>
> > >>>>>>>> [...]
> > >>>>>>>> [    0.000000] tsc: Detected 2260.998 MHz processor
> > >>>>>>>> [3376355.247558] Calibrating delay loop (skipped) preset value..
> > >>>>>>>> [...]
> > >>>>>>>>
> > >>>>>>>> I've bisected it to:
> > >>>>>>
> > >>>>>> Paolo, Sasha,
> > >>>>>>
> > >>>>>> Although this might seem undesirable, there is no requirement 
> > >>>>>> for sched_clock to initialize at 0:
> > >>>>>>
> > >>>>>> "
> > >>>>>>  *
> > >>>>>>  * There is no strict promise about the base, although it tends to start
> > >>>>>>  * at 0 on boot (but people really shouldn't rely on that).
> > >>>>>>  *
> > >>>>>> "
> > >>>>>>
> > >>>>>> Sasha, are you seeing any problem other than the apparent time jump?
> > >>>>
> > >>>> Nope, but I've looked at it again and it seems that it jumps to the host's
> > >>>> clock (that is, in the example above the 3376355 value was the host's clock
> > >>>> value).
> > >>>>
> > >>>>
> > >>>> Thanks,
> > >>>> Sasha
> > >> Sasha, thats right. Its the host monotonic clock.
> > > 
> > > It's worth figuring out if (what) userspace breaks on that. I know it says that
> > > you shouldn't rely on that, but I'd happily place a bet on at least one userspace
> > > treating it as "seconds since boot" or something similar.
> > 
> > Didn't need to go far... In the guest:
> > 
> > # date
> > Tue May 19 02:11:46 UTC 2015
> > # echo hi > /dev/kmsg
> > [3907533.080112] hi
> > # dmesg -T
> > [Fri Jul  3 07:33:41 2015] hi
> 
> Sasha,
> 
> Can you give the suggested patch (hypervisor patch...) a try please?
> (with a patched guest, obviously).
> 
> KVM: x86: zero kvmclock_offset when vcpu0 initializes kvmclock system
> MSR

I've tried your v2, it works for me. My test-case is very simple though:
I just boot a VM, log in and reboot. This reproduces the issue Sasha
reported 100% of the times for me (don't need multi-vcpu guest either).

Would be nice to hear from Sasha too.

Re: kvm: odd time values since "kvmclock: set scheduler clock stable"

[Sasha Levin]

On 05/26/2015 09:21 AM, Luiz Capitulino wrote:
>> Sasha,
>> > 
>> > Can you give the suggested patch (hypervisor patch...) a try please?
>> > (with a patched guest, obviously).
>> > 
>> > KVM: x86: zero kvmclock_offset when vcpu0 initializes kvmclock system
>> > MSR
> I've tried your v2, it works for me. My test-case is very simple though:
> I just boot a VM, log in and reboot. This reproduces the issue Sasha
> reported 100% of the times for me (don't need multi-vcpu guest either).

Sorry for the delay, we had a long weekend here.

It seems to work fine here, no more jumps when booting.


Thanks,
Sasha