Received-SPF: pass (google.com: domain of linux-kernel+bounces-42403-linux.lists.archive=gmail.com@vger.kernel.org designates 2604:1380:4601:e00::3 as permitted sender) client-ip=2604:1380:4601:e00::3;
From: Vitaly Kuznetsov <vkuznets@redhat.com>
To: kvm@vger.kernel.org, Paolo Bonzini <pbonzini@redhat.com>, Sean
 Christopherson <seanjc@google.com>
Cc: David Woodhouse <dwmw@amazon.co.uk>, Jan Richter <jarichte@redhat.com>,
 linux-kernel@vger.kernel.org
Subject: Re: [PATCH] KVM: selftests: Compare wall time from xen shinfo
 against KVM_GET_CLOCK
In-Reply-To: <20240111135901.1785096-1-vkuznets@redhat.com>
References: <20240111135901.1785096-1-vkuznets@redhat.com>
Date: Mon, 29 Jan 2024 10:04:50 +0100
Message-ID: <877cjs8q8d.fsf@redhat.com>
Precedence: bulk
MIME-Version: 1.0
Content-Type: text/plain

Vitaly Kuznetsov <vkuznets@redhat.com> writes:

> 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>
> ---
>  .../selftests/kvm/x86_64/xen_shinfo_test.c    | 36 ++++++++-----------
>  1 file changed, 14 insertions(+), 22 deletions(-)
>
> diff --git a/tools/testing/selftests/kvm/x86_64/xen_shinfo_test.c b/tools/testing/selftests/kvm/x86_64/xen_shinfo_test.c
> index 9ec9ab60b63e..5e1ad243d95d 100644
> --- a/tools/testing/selftests/kvm/x86_64/xen_shinfo_test.c
> +++ b/tools/testing/selftests/kvm/x86_64/xen_shinfo_test.c
> @@ -375,20 +375,6 @@ static void guest_code(void)
>  	GUEST_SYNC(TEST_DONE);
>  }
>  
> -static int cmp_timespec(struct timespec *a, struct timespec *b)
> -{
> -	if (a->tv_sec > b->tv_sec)
> -		return 1;
> -	else if (a->tv_sec < b->tv_sec)
> -		return -1;
> -	else if (a->tv_nsec > b->tv_nsec)
> -		return 1;
> -	else if (a->tv_nsec < b->tv_nsec)
> -		return -1;
> -	else
> -		return 0;
> -}
> -
>  static struct vcpu_info *vinfo;
>  static struct kvm_vcpu *vcpu;
>  
> @@ -425,7 +411,6 @@ static void *juggle_shinfo_state(void *arg)
>  
>  int main(int argc, char *argv[])
>  {
> -	struct timespec min_ts, max_ts, vm_ts;
>  	struct kvm_xen_hvm_attr evt_reset;
>  	struct kvm_vm *vm;
>  	pthread_t thread;
> @@ -443,8 +428,6 @@ int main(int argc, char *argv[])
>  	bool do_eventfd_tests = !!(xen_caps & KVM_XEN_HVM_CONFIG_EVTCHN_2LEVEL);
>  	bool do_evtchn_tests = do_eventfd_tests && !!(xen_caps & KVM_XEN_HVM_CONFIG_EVTCHN_SEND);
>  
> -	clock_gettime(CLOCK_REALTIME, &min_ts);
> -
>  	vm = vm_create_with_one_vcpu(&vcpu, guest_code);
>  
>  	/* Map a region for the shared_info page */
> @@ -969,7 +952,6 @@ int main(int argc, char *argv[])
>  	vm_ioctl(vm, KVM_XEN_HVM_SET_ATTR, &evt_reset);
>  
>  	alarm(0);
> -	clock_gettime(CLOCK_REALTIME, &max_ts);
>  
>  	/*
>  	 * Just a *really* basic check that things are being put in the
> @@ -978,11 +960,16 @@ int main(int argc, char *argv[])
>  	 */
>  	struct pvclock_wall_clock *wc;
>  	struct pvclock_vcpu_time_info *ti, *ti2;
> +	struct kvm_clock_data kcdata;
> +	long long delta;
>  
>  	wc = addr_gpa2hva(vm, SHINFO_REGION_GPA + 0xc00);
>  	ti = addr_gpa2hva(vm, SHINFO_REGION_GPA + 0x40 + 0x20);
>  	ti2 = addr_gpa2hva(vm, PVTIME_ADDR);
>  
> +	vm_ioctl(vm, KVM_GET_CLOCK, &kcdata);
> +	delta = (wc->sec * NSEC_PER_SEC + wc->nsec) - (kcdata.realtime - kcdata.clock);
> +
>  	if (verbose) {
>  		printf("Wall clock (v %d) %d.%09d\n", wc->version, wc->sec, wc->nsec);
>  		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[])
>  		printf("Time info 2: v %u tsc %" PRIu64 " time %" PRIu64 " mul %u shift %u flags %x\n",
>  		       ti2->version, ti2->tsc_timestamp, ti2->system_time, ti2->tsc_to_system_mul,
>  		       ti2->tsc_shift, ti2->flags);
> +		printf("KVM_GET_CLOCK realtime: %lld.%09lld\n", kcdata.realtime / NSEC_PER_SEC,
> +		       kcdata.realtime % NSEC_PER_SEC);
> +		printf("KVM_GET_CLOCK clock: %lld.%09lld\n", kcdata.clock / NSEC_PER_SEC,
> +		       kcdata.clock % NSEC_PER_SEC);
>  	}
>  
> -	vm_ts.tv_sec = wc->sec;
> -	vm_ts.tv_nsec = wc->nsec;
>  	TEST_ASSERT(wc->version && !(wc->version & 1),
>  		    "Bad wallclock version %x", wc->version);
> -	TEST_ASSERT(cmp_timespec(&min_ts, &vm_ts) <= 0, "VM time too old");
> -	TEST_ASSERT(cmp_timespec(&max_ts, &vm_ts) >= 0, "VM time too new");
> +
> +	TEST_ASSERT(llabs(delta) < 100,
> +		    "Guest's epoch from shinfo %d.%09d differs from KVM_GET_CLOCK %lld.%lld",
> +		    wc->sec, wc->nsec, (kcdata.realtime - kcdata.clock) / NSEC_PER_SEC,
> +		    (kcdata.realtime - kcdata.clock) % NSEC_PER_SEC);
>  
>  	TEST_ASSERT(ti->version && !(ti->version & 1),
>  		    "Bad time_info version %x", ti->version);

Ping?

-- 
Vitaly