Skip to content

Commit a0868e7

Browse files
vittyvksean-jc
authored andcommitted
KVM: selftests: Compare wall time from xen shinfo against KVM_GET_CLOCK
xen_shinfo_test is observed to be flaky failing sporadically with "VM time too old". With min_ts/max_ts debug print added: Wall clock (v 3269818) 1704906491.986255664 Time info 1: v 1282712 tsc 33530585736 time 14014430025 mul 3587552223 shift 4294967295 flags 1 Time info 2: v 1282712 tsc 33530585736 time 14014430025 mul 3587552223 shift 4294967295 flags 1 min_ts: 1704906491.986312153 max_ts: 1704906506.001006963 ==== Test Assertion Failure ==== x86_64/xen_shinfo_test.c:1003: cmp_timespec(&min_ts, &vm_ts) <= 0 pid=32724 tid=32724 errno=4 - Interrupted system call 1 0x00000000004030ad: main at xen_shinfo_test.c:1003 2 0x00007fca6b23feaf: ?? ??:0 3 0x00007fca6b23ff5f: ?? ??:0 4 0x0000000000405e04: _start at ??:? VM time too old The test compares wall clock data from shinfo (which is the output of kvm_get_wall_clock_epoch()) against clock_gettime(CLOCK_REALTIME) in the host system before the VM is created. In the example above, it compares shinfo: 1704906491.986255664 vs min_ts: 1704906491.986312153 and fails as the later is greater than the former. While this sounds like a sane test, it doesn't pass reality check: kvm_get_wall_clock_epoch() calculates guest's epoch (realtime when the guest was created) by subtracting kvmclock from the current realtime and the calculation happens when shinfo is setup. The problem is that kvmclock is a raw clock and realtime clock is affected by NTP. This means that if realtime ticks with a slightly reduced frequency, "guest's epoch" calculated by kvm_get_wall_clock_epoch() will actually tick backwards! This is not a big issue from guest's perspective as the guest can't really observe this but this epoch can't be compared with a fixed clock_gettime() on the host. Replace the check with comparing wall clock data from shinfo to KVM_GET_CLOCK. The later gives both realtime and kvmclock so guest's epoch can be calculated by subtraction. Note, the computed epoch may still differ a few nanoseconds from shinfo as different TSC is used and there are rounding errors but 100 nanoseconds margin should be enough to cover it (famous last words). Reported-by: Jan Richter <jarichte@redhat.com> Signed-off-by: Vitaly Kuznetsov <vkuznets@redhat.com> Link: https://lore.kernel.org/r/20240111135901.1785096-1-vkuznets@redhat.com Signed-off-by: Sean Christopherson <seanjc@google.com>
1 parent c2a449a commit a0868e7

File tree

1 file changed

+14
-22
lines changed

1 file changed

+14
-22
lines changed

tools/testing/selftests/kvm/x86_64/xen_shinfo_test.c

Lines changed: 14 additions & 22 deletions
Original file line numberDiff line numberDiff line change
@@ -375,20 +375,6 @@ static void guest_code(void)
375375
GUEST_SYNC(TEST_DONE);
376376
}
377377

378-
static int cmp_timespec(struct timespec *a, struct timespec *b)
379-
{
380-
if (a->tv_sec > b->tv_sec)
381-
return 1;
382-
else if (a->tv_sec < b->tv_sec)
383-
return -1;
384-
else if (a->tv_nsec > b->tv_nsec)
385-
return 1;
386-
else if (a->tv_nsec < b->tv_nsec)
387-
return -1;
388-
else
389-
return 0;
390-
}
391-
392378
static struct vcpu_info *vinfo;
393379
static struct kvm_vcpu *vcpu;
394380

@@ -425,7 +411,6 @@ static void *juggle_shinfo_state(void *arg)
425411

426412
int main(int argc, char *argv[])
427413
{
428-
struct timespec min_ts, max_ts, vm_ts;
429414
struct kvm_xen_hvm_attr evt_reset;
430415
struct kvm_vm *vm;
431416
pthread_t thread;
@@ -443,8 +428,6 @@ int main(int argc, char *argv[])
443428
bool do_eventfd_tests = !!(xen_caps & KVM_XEN_HVM_CONFIG_EVTCHN_2LEVEL);
444429
bool do_evtchn_tests = do_eventfd_tests && !!(xen_caps & KVM_XEN_HVM_CONFIG_EVTCHN_SEND);
445430

446-
clock_gettime(CLOCK_REALTIME, &min_ts);
447-
448431
vm = vm_create_with_one_vcpu(&vcpu, guest_code);
449432

450433
/* Map a region for the shared_info page */
@@ -969,7 +952,6 @@ int main(int argc, char *argv[])
969952
vm_ioctl(vm, KVM_XEN_HVM_SET_ATTR, &evt_reset);
970953

971954
alarm(0);
972-
clock_gettime(CLOCK_REALTIME, &max_ts);
973955

974956
/*
975957
* Just a *really* basic check that things are being put in the
@@ -978,11 +960,16 @@ int main(int argc, char *argv[])
978960
*/
979961
struct pvclock_wall_clock *wc;
980962
struct pvclock_vcpu_time_info *ti, *ti2;
963+
struct kvm_clock_data kcdata;
964+
long long delta;
981965

982966
wc = addr_gpa2hva(vm, SHINFO_REGION_GPA + 0xc00);
983967
ti = addr_gpa2hva(vm, SHINFO_REGION_GPA + 0x40 + 0x20);
984968
ti2 = addr_gpa2hva(vm, PVTIME_ADDR);
985969

970+
vm_ioctl(vm, KVM_GET_CLOCK, &kcdata);
971+
delta = (wc->sec * NSEC_PER_SEC + wc->nsec) - (kcdata.realtime - kcdata.clock);
972+
986973
if (verbose) {
987974
printf("Wall clock (v %d) %d.%09d\n", wc->version, wc->sec, wc->nsec);
988975
printf("Time info 1: v %u tsc %" PRIu64 " time %" PRIu64 " mul %u shift %u flags %x\n",
@@ -991,14 +978,19 @@ int main(int argc, char *argv[])
991978
printf("Time info 2: v %u tsc %" PRIu64 " time %" PRIu64 " mul %u shift %u flags %x\n",
992979
ti2->version, ti2->tsc_timestamp, ti2->system_time, ti2->tsc_to_system_mul,
993980
ti2->tsc_shift, ti2->flags);
981+
printf("KVM_GET_CLOCK realtime: %lld.%09lld\n", kcdata.realtime / NSEC_PER_SEC,
982+
kcdata.realtime % NSEC_PER_SEC);
983+
printf("KVM_GET_CLOCK clock: %lld.%09lld\n", kcdata.clock / NSEC_PER_SEC,
984+
kcdata.clock % NSEC_PER_SEC);
994985
}
995986

996-
vm_ts.tv_sec = wc->sec;
997-
vm_ts.tv_nsec = wc->nsec;
998987
TEST_ASSERT(wc->version && !(wc->version & 1),
999988
"Bad wallclock version %x", wc->version);
1000-
TEST_ASSERT(cmp_timespec(&min_ts, &vm_ts) <= 0, "VM time too old");
1001-
TEST_ASSERT(cmp_timespec(&max_ts, &vm_ts) >= 0, "VM time too new");
989+
990+
TEST_ASSERT(llabs(delta) < 100,
991+
"Guest's epoch from shinfo %d.%09d differs from KVM_GET_CLOCK %lld.%lld",
992+
wc->sec, wc->nsec, (kcdata.realtime - kcdata.clock) / NSEC_PER_SEC,
993+
(kcdata.realtime - kcdata.clock) % NSEC_PER_SEC);
1002994

1003995
TEST_ASSERT(ti->version && !(ti->version & 1),
1004996
"Bad time_info version %x", ti->version);

0 commit comments

Comments
 (0)