Re: pvclock time drifting backward

[Sean Christopherson <seanjc@google.com>]

+David

On Wed, Mar 19, 2025, Ming Lin wrote:
> Hi,
> 
> After performing a live migration on a QEMU guest OS that had been running for over 30 days,
> we noticed that the guest OS time was more than 2 seconds behind the actual time.
> 
> After extensive debugging, we found that this issue is related to master_kernel_ns and master_cycle_now.
> 
> When the guest OS starts, the host initializes a pair of master_kernel_ns and master_cycle_now values.
> After live migration, the host updates these values.
> 
> Our debugging showed that if the host does not update master_kernel_ns/master_cycle_now,
> the guest OS time remains correct.
> 
> To illustrate how updating master_kernel_ns/master_cycle_now leads to the guest OS time drifting backward,
> we applied the following debug patch:
> 
> The patch adds a KVM debugfs entry to trigger time calculations and print the results.
> The patch runs on the host side, but we use __pvclock_read_cycles() to simulate the guest OS updating its time.
> 
> Example Output:
> 
> # cat /sys/kernel/debug/kvm/946-13/pvclock
> old: master_kernel_ns: 15119778316
> old: master_cycle_now: 37225912658
> old: ns: 1893199569691
> new: master_kernel_ns: 1908210098649
> new: master_cycle_now: 4391329912268
> new: ns: 1893199548401
> 
> tsc 4391329912368
> kvmclock_offset -15010550291
> diff: ns: 21290
> 
> Explanation of Parameters:
> 
> Input:
> "old: master_kernel_ns:" The master_kernel_ns value recorded when the guest OS started (remains unchanged during testing).
> "old: master_cycle_now:" The master_cycle_now value recorded when the guest OS started (remains unchanged during testing).
> "new: master_kernel_ns:" The latest master_kernel_ns value at the time of reading.
> "new: master_cycle_now:" The latest master_cycle_now value at the time of reading.
> tsc: The rdtsc() value at the time of reading.
> kvmclock_offset: The offset recorded by KVM_SET_CLOCK when the guest OS started (remains unchanged during testing).
> 
> Output:
> "old: ns:" Time in nanoseconds calculated using the old master_kernel_ns/master_cycle_now.
> "new: ns:" Time in nanoseconds calculated using the new master_kernel_ns/master_cycle_now.
> "diff: ns:" (old ns - new ns), representing the time drift relative to the guest OS start time.
> 
> Test Script:
> #!/bin/bash
> 
> qemu_pid=$(pidof qemu-system-x86_64)
> 
> while [ 1 ] ; do
>     echo "====================================="
>     echo "Guest OS running time: $(ps -p $qemu_pid -o etime= | awk '{print $1}')"
>     cat /sys/kernel/debug/kvm/*/pvclock
>     echo
>     sleep 10
> done
> 
> Test Results:
> Below are the first and last parts of a >2-hour test run.
> As time progresses, the time drift calculated using the latest master_kernel_ns/master_cycle_now increases monotonically.
> 
> After 2 hours and 18 minutes, the guest OS time drifted by approximately 93 milliseconds.
> 
> I have uploaded an image for a more intuitive visualization of the time drift:
> https://postimg.cc/crCDWtD7
> 
> Is this a real problem?

David can confirm, but I'm pretty sure the drift you are observing is addressed
by David's series to fix a plethora of kvmclock warts.

https://lore.kernel.org/all/20240522001817.619072-1-dwmw2@infradead.org

> If there is any fix patch, I’d be happy to test it. Thanks!
> 
> 
>     1 =====================================
>     2 guest os running time: 00:50
>     3 old: master_kernel_ns: 15119778316
>     4 old: master_cycle_now: 37225912658
>     5 old: ns: 48092694964
>     6 new: master_kernel_ns: 63103244699
>     7 new: master_cycle_now: 147587790614
>     8 new: ns: 48092694425
>     9
>    10 tsc 147587790654
>    11 kvmclock_offset -15010550291
>    12 diff: ns: 539
>    13
>    14 =====================================
>    15 guest os running time: 01:00
>    16 old: master_kernel_ns: 15119778316
>    17 old: master_cycle_now: 37225912658
>    18 old: ns: 58139026532
>    19 new: master_kernel_ns: 73149576143
>    20 new: master_cycle_now: 170694333104
>    21 new: ns: 58139025879
>    22
>    23 tsc 170694333168
>    24 kvmclock_offset -15010550291
>    25 diff: ns: 653
>    26
>    27 =====================================
>    28 guest os running time: 01:10
>    29 old: master_kernel_ns: 15119778316
>    30 old: master_cycle_now: 37225912658
>    31 old: ns: 68183772122
>    32 new: master_kernel_ns: 83194321616
>    33 new: master_cycle_now: 193797227862
>    34 new: ns: 68183771357
>    35
>    36 tsc 193797227936
>    37 kvmclock_offset -15010550291
>    38 diff: ns: 765
>    39
>    40 =====================================
>    41 guest os running time: 01:20
>    42 old: master_kernel_ns: 15119778316
>    43 old: master_cycle_now: 37225912658
>    44 old: ns: 78225289157
>    45 new: master_kernel_ns: 93235838545
>    46 new: master_cycle_now: 216892696976
>    47 new: ns: 78225288279
>    48
>    49 tsc 216892697034
>    50 kvmclock_offset -15010550291
>    51 diff: ns: 878
>    52
>    53 =====================================
>    54 guest os running time: 01:30
>    55 old: master_kernel_ns: 15119778316
>    56 old: master_cycle_now: 37225912658
>    57 old: ns: 88268955340
>    58 new: master_kernel_ns: 103279504612
>    59 new: master_cycle_now: 239993109102
>    60 new: ns: 88268954349
>    61
>    62 tsc 239993109168
>    63 kvmclock_offset -15010550291
>    64 diff: ns: 991
>    65
>    66 =====================================
>    67 guest os running time: 01:40
>    68 old: master_kernel_ns: 15119778316
>    69 old: master_cycle_now: 37225912658
>    70 old: ns: 98313212581
>    71 new: master_kernel_ns: 113323761740
>    72 new: master_cycle_now: 263094880668
>    73 new: ns: 98313211476
>    74
>    75 tsc 263094880732
>    76 kvmclock_offset -15010550291
>    77 diff: ns: 1105
> .....
> .....
> 10160 =====================================
> 10161 guest os running time: 02:17:11
> 10162 old: master_kernel_ns: 15119778316
> 10163 old: master_cycle_now: 37225912658
> 10164 old: ns: 8229817213297
> 10165 new: master_kernel_ns: 8244827670997
> 10166 new: master_cycle_now: 18965537819524
> 10167 new: ns: 8229817120748
> 10168
> 10169 tsc 18965537819622
> 10170 kvmclock_offset -15010550291
> 10171 diff: ns: 92549
> 10172 =====================================
> 10173 guest os running time: 02:17:21
> 10174 old: master_kernel_ns: 15119778316
> 10175 old: master_cycle_now: 37225912658
> 10176 old: ns: 8239861074959
> 10177 new: master_kernel_ns: 8254871532564
> 10178 new: master_cycle_now: 18988638681302
> 10179 new: ns: 8239860982297
> 10180
> 10181 tsc 18988638681358
> 10182 kvmclock_offset -15010550291
> 10183 diff: ns: 92662
> 10184 =====================================
> 10185 guest os running time: 02:17:31
> 10186 old: master_kernel_ns: 15119778316
> 10187 old: master_cycle_now: 37225912658
> 10188 old: ns: 8249904622988
> 10189 new: master_kernel_ns: 8264915080459
> 10190 new: master_cycle_now: 19011738821632
> 10191 new: ns: 8249904530213
> 10192
> 10193 tsc 19011738821736
> 10194 kvmclock_offset -15010550291
> 10195 diff: ns: 92775^@
> 10196 =====================================
> 10197 guest os running time: 02:17:41
> 10198 old: master_kernel_ns: 15119778316
> 10199 old: master_cycle_now: 37225912658
> 10200 old: ns: 8259949369203
> 10201 new: master_kernel_ns: 8274959826576
> 10202 new: master_cycle_now: 19034841717872
> 10203 new: ns: 8259949276315
> 10204
> 10205 tsc 19034841717942
> 10206 kvmclock_offset -15010550291
> 10207 diff: ns: 92888
> 10208 =====================================
> 10209 guest os running time: 02:17:51
> 10210 old: master_kernel_ns: 15119778316
> 10211 old: master_cycle_now: 37225912658
> 10212 old: ns: 8269996849598
> 10213 new: master_kernel_ns: 8285007306846
> 10214 new: master_cycle_now: 19057950902658
> 10215 new: ns: 8269996756597
> 10216
> 10217 tsc 19057950902756
> 10218 kvmclock_offset -15010550291
> 10219 diff: ns: 93001^@
> 10220 =====================================
> 10221 guest os running time: 02:18:02
> 10222 old: master_kernel_ns: 15119778316
> 10223 old: master_cycle_now: 37225912658
> 10224 old: ns: 8280039094317
> 10225 new: master_kernel_ns: 8295049551453
> 10226 new: master_cycle_now: 19081048045430
> 10227 new: ns: 8280039001203
> 10228
> 10229 tsc 19081048045526
> 10230 kvmclock_offset -15010550291
> 10231 diff: ns: 93114^@
> 
> 
> 
>     pvclock debugfs patch
> ---
>  arch/x86/include/asm/kvm_host.h |  4 +++
>  arch/x86/kvm/x86.c              | 29 +++++++++++++++-
>  b.sh                            |  1 +
>  virt/kvm/kvm_main.c             | 75 +++++++++++++++++++++++++++++++++++++++++
>  4 files changed, 108 insertions(+), 1 deletion(-)
> 
> diff --git a/arch/x86/include/asm/kvm_host.h b/arch/x86/include/asm/kvm_host.h
> index 32ae3aa50c7e..5a82a69bfe7a 100644
> --- a/arch/x86/include/asm/kvm_host.h
> +++ b/arch/x86/include/asm/kvm_host.h
> @@ -1411,6 +1411,10 @@ struct kvm_arch {
>      struct delayed_work kvmclock_update_work;
>      struct delayed_work kvmclock_sync_work;
> +    u64 old_master_kernel_ns;
> +    u64 old_master_cycle_now;
> +    s64 old_kvmclock_offset;
> +
>      struct kvm_xen_hvm_config xen_hvm_config;
>      /* reads protected by irq_srcu, writes by irq_lock */
> diff --git a/arch/x86/kvm/x86.c b/arch/x86/kvm/x86.c
> index 4b64ab350bcd..a56511ed8c5b 100644
> --- a/arch/x86/kvm/x86.c
> +++ b/arch/x86/kvm/x86.c
> @@ -2819,7 +2819,7 @@ static inline u64 vgettsc(struct pvclock_clock *clock, u64 *tsc_timestamp,
>   * As with get_kvmclock_base_ns(), this counts from boot time, at the
>   * frequency of CLOCK_MONOTONIC_RAW (hence adding gtos->offs_boot).
>   */
> -static int do_kvmclock_base(s64 *t, u64 *tsc_timestamp)
> +int do_kvmclock_base(s64 *t, u64 *tsc_timestamp)
>  {
>      struct pvclock_gtod_data *gtod = &pvclock_gtod_data;
>      unsigned long seq;
> @@ -2861,6 +2861,27 @@ static int do_monotonic(s64 *t, u64 *tsc_timestamp)
>      return mode;
>  }
> +u64 mydebug_get_kvmclock_ns(u64 master_kernel_ns, u64 master_cycle_now, s64 kvmclock_offset, u64 tsc)
> +{
> +        struct pvclock_vcpu_time_info hv_clock;
> +        u64 ret;
> +
> +        hv_clock.tsc_timestamp = master_cycle_now;
> +        hv_clock.system_time = master_kernel_ns + kvmclock_offset;
> +
> +        /* both __this_cpu_read() and rdtsc() should be on the same cpu */
> +        get_cpu();
> +
> +        kvm_get_time_scale(NSEC_PER_SEC, __this_cpu_read(cpu_tsc_khz) * 1000LL,
> +                                   &hv_clock.tsc_shift,
> +                                   &hv_clock.tsc_to_system_mul);
> +        ret = __pvclock_read_cycles(&hv_clock, tsc);
> +
> +        put_cpu();
> +
> +        return ret;
> +}
> +
>  static int do_realtime(struct timespec64 *ts, u64 *tsc_timestamp)
>  {
>      struct pvclock_gtod_data *gtod = &pvclock_gtod_data;
> @@ -2988,6 +3009,10 @@ static void pvclock_update_vm_gtod_copy(struct kvm *kvm)
>      host_tsc_clocksource = kvm_get_time_and_clockread(
>                      &ka->master_kernel_ns,
>                      &ka->master_cycle_now);
> +    ka->old_master_kernel_ns = ka->master_kernel_ns;
> +    ka->old_master_cycle_now = ka->master_cycle_now;
> +    printk("MYDEBUG: old_master_kernel_ns = %llu, old_master_cycle_now = %llu\n",
> +            ka->old_master_kernel_ns, ka->old_master_cycle_now);
>      ka->use_master_clock = host_tsc_clocksource && vcpus_matched
>                  && !ka->backwards_tsc_observed
> @@ -6989,6 +7014,8 @@ static int kvm_vm_ioctl_set_clock(struct kvm *kvm, void __user *argp)
>      else
>          now_raw_ns = get_kvmclock_base_ns();
>      ka->kvmclock_offset = data.clock - now_raw_ns;
> +    ka->old_kvmclock_offset = ka->kvmclock_offset;
> +    printk("MYDEBUG: old_kvmclock_offset = %lld\n", ka->old_kvmclock_offset);
>      kvm_end_pvclock_update(kvm);
>      return 0;
>  }
> diff --git a/b.sh b/b.sh
> new file mode 120000
> index 000000000000..0ff9a93fd53f
> --- /dev/null
> +++ b/b.sh
> @@ -0,0 +1 @@
> +/home/mlin/build.upstream/b.sh
> \ No newline at end of file
> diff --git a/virt/kvm/kvm_main.c b/virt/kvm/kvm_main.c
> index ba0327e2d0d3..d6b9a6e7275e 100644
> --- a/virt/kvm/kvm_main.c
> +++ b/virt/kvm/kvm_main.c
> @@ -399,6 +399,7 @@ int __kvm_mmu_topup_memory_cache(struct kvm_mmu_memory_cache *mc, int capacity,
>              return mc->nobjs >= min ? 0 : -ENOMEM;
>          mc->objects[mc->nobjs++] = obj;
>      }
> +
>      return 0;
>  }
> @@ -998,6 +999,78 @@ static void kvm_destroy_vm_debugfs(struct kvm *kvm)
>      }
>  }
> +extern int do_kvmclock_base(s64 *t, u64 *tsc_timestamp);
> +extern u64 mydebug_get_kvmclock_ns(u64 master_kernel_ns, u64 master_cycle_now, s64 kvmclock_offset, u64 tsc);
> +
> +static ssize_t kvm_mydebug_pvclock_read(struct file *file, char __user *buf,
> +                                size_t len, loff_t *ppos)
> +{
> +    struct kvm *kvm = file->private_data;
> +    struct kvm_arch *ka;
> +    char buffer[256];
> +    ssize_t ret, copied;
> +    u64 new_master_kernel_ns;
> +    u64 new_master_cycle_now;
> +    u64 old_ns, new_ns;
> +    u64 tsc;
> +
> +    if (!kvm) {
> +        pr_err("file->private_data is NULL\n");
> +        return -EINVAL;
> +    }
> +
> +    ka = &kvm->arch;
> +
> +    do_kvmclock_base(&new_master_kernel_ns, &new_master_cycle_now);
> +
> +    tsc = rdtsc();
> +
> +    old_ns = mydebug_get_kvmclock_ns(ka->old_master_kernel_ns, ka->old_master_cycle_now, ka->old_kvmclock_offset, tsc);
> +    new_ns = mydebug_get_kvmclock_ns(new_master_kernel_ns, new_master_cycle_now, ka->old_kvmclock_offset, tsc);
> +
> +    ret = snprintf(buffer, sizeof(buffer),
> +                   "old: master_kernel_ns: %llu\n"
> +                   "old: master_cycle_now: %llu\n"
> +                   "old: ns: %llu\n"
> +                   "new: master_kernel_ns: %llu\n"
> +                   "new: master_cycle_now: %llu\n"
> +                   "new: ns: %llu\n\n"
> +                   "tsc %llu\n"
> +                   "kvmclock_offset %lld\n"
> +                   "diff: ns: %lld\n",
> +                   ka->old_master_kernel_ns, ka->old_master_cycle_now, old_ns,
> +                   new_master_kernel_ns, new_master_cycle_now, new_ns,
> +                   tsc, ka->old_kvmclock_offset,
> +                  old_ns - new_ns
> +                  );
> +
> +    if (ret < 0)
> +        return ret;
> +
> +    if ((size_t)ret > sizeof(buffer))
> +        ret = sizeof(buffer);
> +
> +    if (*ppos >= ret)
> +        return 0; /* EOF */
> +
> +    copied = min(len, (size_t)(ret - *ppos));
> +
> +    if (copy_to_user(buf, buffer + *ppos, copied)) {
> +        pr_err("copy_to_user failed\n");
> +        return -EFAULT;
> +    }
> +
> +    *ppos += copied;
> +
> +    return copied;
> +}
> +
> +static const struct file_operations kvm_pvclock_fops = {
> +    .owner = THIS_MODULE,
> +    .read = kvm_mydebug_pvclock_read,
> +    .open = simple_open,
> +};
> +
>  static int kvm_create_vm_debugfs(struct kvm *kvm, const char *fdname)
>  {
>      static DEFINE_MUTEX(kvm_debugfs_lock);
> @@ -1063,6 +1136,8 @@ static int kvm_create_vm_debugfs(struct kvm *kvm, const char *fdname)
>                      &stat_fops_per_vm);
>      }
> +    debugfs_create_file("pvclock", 0444, kvm->debugfs_dentry, kvm, &kvm_pvclock_fops);
> +
>      kvm_arch_create_vm_debugfs(kvm);
>      return 0;
>  out_err:
>