Skip to contentSkip to conversation

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

DISCUSSION Sasha Levin 4 participants 13 messages May 12, 2015 – May 26, 2015

Subsystems (3)
x86 KVM KVM x86
lore
Share & tools
lore

Sasha Levin

author
#0 lore raw

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 <[email protected]>
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 <[email protected]>
    Signed-off-by: Luiz Capitulino <[email protected]>
    Signed-off-by: Paolo Bonzini <[email protected]>

Thanks,
Sasha

#1 lore raw
Quoted 10 lines · On Tue, 12 May 2015 19:17:24 -0400 Sasha Levin <[email protected]> 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.

Quoted 57 lines

commit ff7bbb9c6ab6e6620429daeff39424bbde1a94b4

Author: Luiz Capitulino <[email protected]>
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 <[email protected]>
    Signed-off-by: Luiz Capitulino <[email protected]>
    Signed-off-by: Paolo Bonzini <[email protected]>

Thanks,
Sasha

author
#2 lore raw
Quoted 12 lines · Luiz Capitulino
Quoted 9 lines · On Tue, 12 May 2015 19:17:24 -0400 Sasha Levin <[email protected]> wrote:
Quoted 9 lines

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

[...]

Quoted 6 lines
Quoted 1 line
Quoted 1 line

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

maintainer
#3 lore raw
In reply to Luiz Capitulino
Quoted 12 lines · Luiz Capitulino
Quoted 9 lines · On Tue, 12 May 2015 19:17:24 -0400 Sasha Levin <[email protected]> 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..

[...]

Quoted 6 lines
Quoted 1 line

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

#4 lore raw
In reply to Sasha Levin
Quoted 10 lines · 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:

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?

author
#5 lore raw
Quoted 17 lines · Marcelo Tosatti
Quoted 10 lines · 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:

Paolo, Sasha,

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

Quoted 8 lines

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

#6 lore raw
Quoted 27 lines · Sasha Levin
Quoted 17 lines · Marcelo Tosatti
Quoted 10 lines · 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:

Paolo, Sasha,

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

Quoted 8 lines

"
*
* 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?

Quoted 7 lines

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.

author
#7 lore raw
Quoted 28 lines · Marcelo Tosatti
Quoted 27 lines · Sasha Levin
Quoted 27 lines · Marcelo Tosatti
Quoted 25 lines
Quoted 25 lines · Sasha Levin
Quoted 10 lines
Quoted 10 lines

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?

Quoted 8 lines
Quoted 7 lines
Quoted 7 lines

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

author
#8 lore raw
Quoted 34 lines · Sasha Levin
Quoted 33 lines · Marcelo Tosatti
Quoted 32 lines · Sasha Levin
Quoted 32 lines · Marcelo Tosatti
Quoted 17 lines
Quoted 17 lines · Sasha Levin
Quoted 10 lines
Quoted 10 lines

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:

Quoted 8 lines
Quoted 8 lines

"
*
* 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).

Quoted 7 lines
Quoted 3 lines
Quoted 2 lines
Quoted 2 lines

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

#9 lore raw
Quoted 43 lines · Sasha Levin
Quoted 34 lines · Sasha Levin
Quoted 33 lines · Marcelo Tosatti
Quoted 32 lines · Sasha Levin
Quoted 32 lines · Marcelo Tosatti
Quoted 17 lines
Quoted 17 lines · Sasha Levin
Quoted 10 lines
Quoted 10 lines

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:

Quoted 8 lines
Quoted 8 lines

"
*
* 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).

Quoted 7 lines
Quoted 3 lines
Quoted 2 lines
Quoted 2 lines

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.

Quoted 8 lines

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

#10 lore raw
Quoted 53 lines · On Thu, 21 May 2015 21:41:23 -0300 Marcelo Tosatti <[email protected]> wrote:
Quoted 43 lines · Sasha Levin
Quoted 34 lines · Sasha Levin
Quoted 33 lines · Marcelo Tosatti
Quoted 32 lines · Sasha Levin
Quoted 32 lines · Marcelo Tosatti
Quoted 17 lines
Quoted 17 lines · Sasha Levin
Quoted 10 lines
Quoted 10 lines

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:

Quoted 8 lines
Quoted 8 lines

"
*
* 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).

Quoted 7 lines
Quoted 3 lines
Quoted 2 lines
Quoted 2 lines

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.

Quoted 8 lines

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

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.

author
#11 lore raw
Quoted 10 lines · Luiz Capitulino
Quoted 7 lines

Sasha,

Quoted 6 lines

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

#12 lore raw

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

In reply to Sasha Levin

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 <[email protected]>
arch/x86/kvm/x86.c +2 -0
index cc2c759..ea40d24 100644
@@ -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;