* FYI: hyperv_clock selftest has random failures
@ 2022-05-25 14:35 Maxim Levitsky
2022-05-25 14:59 ` Vitaly Kuznetsov
0 siblings, 1 reply; 2+ messages in thread
From: Maxim Levitsky @ 2022-05-25 14:35 UTC (permalink / raw)
To: kvm@vger.kernel.org; +Cc: Vitaly Kuznetsov, Paolo Bonzini
Just something I noticed today. Happens on both AMD and Intel, kvm/queue.
Likely the test needs lower tolerancies.
I'll investigate this later
This is on my AMD machine (3970X):
[mlevitsk@starship ~/Kernel/master/src/tools/testing/selftests/kvm]$while true ; do ./x86_64/hyperv_clock ; done
==== Test Assertion Failure ====
x86_64/hyperv_clock.c:199: delta_ns * 100 < (t2 - t1) * 100
pid=66218 tid=66218 errno=0 - Success
1 0x000000000040255d: host_check_tsc_msr_rdtsc at hyperv_clock.c:199
2 (inlined by) main at hyperv_clock.c:223
3 0x00007f0f2822d55f: ?? ??:0
4 0x00007f0f2822d60b: ?? ??:0
5 0x0000000000402744: _start at ??:?
Elapsed time does not match (MSR=471600, TSC=461024)
==== Test Assertion Failure ====
x86_64/hyperv_clock.c:199: delta_ns * 100 < (t2 - t1) * 100
pid=66269 tid=66269 errno=0 - Success
1 0x000000000040255d: host_check_tsc_msr_rdtsc at hyperv_clock.c:199
2 (inlined by) main at hyperv_clock.c:223
3 0x00007f296522d55f: ?? ??:0
4 0x00007f296522d60b: ?? ??:0
5 0x0000000000402744: _start at ??:?
Elapsed time does not match (MSR=460700, TSC=475361)
==== Test Assertion Failure ====
x86_64/hyperv_clock.c:234: false
pid=66652 tid=66652 errno=4 - Interrupted system call
1 0x00000000004026e7: main at hyperv_clock.c:234
2 0x00007fdab782d55f: ?? ??:0
3 0x00007fdab782d60b: ?? ??:0
4 0x0000000000402744: _start at ??:?
Failed guest assert: delta_ns * 100 < (t2 - t1) * 100 at x86_64/hyperv_clock.c:74
==== Test Assertion Failure ====
x86_64/hyperv_clock.c:199: delta_ns * 100 < (t2 - t1) * 100
pid=67112 tid=67112 errno=0 - Success
1 0x000000000040255d: host_check_tsc_msr_rdtsc at hyperv_clock.c:199
2 (inlined by) main at hyperv_clock.c:223
3 0x00007f3095c2d55f: ?? ??:0
4 0x00007f3095c2d60b: ?? ??:0
5 0x0000000000402744: _start at ??:?
Elapsed time does not match (MSR=469600, TSC=484418)
==== Test Assertion Failure ====
x86_64/hyperv_clock.c:234: false
pid=67146 tid=67146 errno=4 - Interrupted system call
1 0x00000000004026e7: main at hyperv_clock.c:234
2 0x00007f81b802d55f: ?? ??:0
3 0x00007f81b802d60b: ?? ??:0
4 0x0000000000402744: _start at ??:?
Failed guest assert: delta_ns * 100 < (t2 - t1) * 100 at x86_64/hyperv_clock.c:74
==== Test Assertion Failure ====
x86_64/hyperv_clock.c:199: delta_ns * 100 < (t2 - t1) * 100
pid=67179 tid=67179 errno=0 - Success
1 0x000000000040255d: host_check_tsc_msr_rdtsc at hyperv_clock.c:199
2 (inlined by) main at hyperv_clock.c:223
3 0x00007f1fb522d55f: ?? ??:0
4 0x00007f1fb522d60b: ?? ??:0
5 0x0000000000402744: _start at ??:?
Elapsed time does not match (MSR=470300, TSC=461134)
==== Test Assertion Failure ====
x86_64/hyperv_clock.c:234: false
pid=67459 tid=67459 errno=4 - Interrupted system call
1 0x00000000004026e7: main at hyperv_clock.c:234
2 0x00007f330dc2d55f: ?? ??:0
3 0x00007f330dc2d60b: ?? ??:0
4 0x0000000000402744: _start at ??:?
Failed guest assert: delta_ns * 100 < (t2 - t1) * 100 at x86_64/hyperv_clock.c:74
==== Test Assertion Failure ====
x86_64/hyperv_clock.c:234: false
pid=67622 tid=67622 errno=4 - Interrupted system call
1 0x00000000004026e7: main at hyperv_clock.c:234
2 0x00007f9da422d55f: ?? ??:0
3 0x00007f9da422d60b: ?? ??:0
4 0x0000000000402744: _start at ??:?
Failed guest assert: delta_ns * 100 < (t2 - t1) * 100 at x86_64/hyperv_clock.c:74
==== Test Assertion Failure ====
x86_64/hyperv_clock.c:199: delta_ns * 100 < (t2 - t1) * 100
pid=68043 tid=68043 errno=0 - Success
1 0x000000000040255d: host_check_tsc_msr_rdtsc at hyperv_clock.c:199
2 (inlined by) main at hyperv_clock.c:223
3 0x00007f3ba2c2d55f: ?? ??:0
4 0x00007f3ba2c2d60b: ?? ??:0
5 0x0000000000402744: _start at ??:?
Elapsed time does not match (MSR=482900, TSC=468989)
==== Test Assertion Failure ====
x86_64/hyperv_clock.c:199: delta_ns * 100 < (t2 - t1) * 100
pid=68118 tid=68118 errno=0 - Success
1 0x000000000040255d: host_check_tsc_msr_rdtsc at hyperv_clock.c:199
2 (inlined by) main at hyperv_clock.c:223
3 0x00007f25ef62d55f: ?? ??:0
4 0x00007f25ef62d60b: ?? ??:0
5 0x0000000000402744: _start at ??:?
Elapsed time does not match (MSR=362300, TSC=379772)
==== Test Assertion Failure ====
x86_64/hyperv_clock.c:234: false
pid=68233 tid=68233 errno=4 - Interrupted system call
1 0x00000000004026e7: main at hyperv_clock.c:234
2 0x00007f7e94c2d55f: ?? ??:0
3 0x00007f7e94c2d60b: ?? ??:0
4 0x0000000000402744: _start at ??:?
Failed guest assert: delta_ns * 100 < (t2 - t1) * 100 at x86_64/hyperv_clock.c:74
==== Test Assertion Failure ====
x86_64/hyperv_clock.c:199: delta_ns * 100 < (t2 - t1) * 100
pid=68609 tid=68609 errno=0 - Success
1 0x000000000040255d: host_check_tsc_msr_rdtsc at hyperv_clock.c:199
2 (inlined by) main at hyperv_clock.c:223
3 0x00007f69a3a2d55f: ?? ??:0
4 0x00007f69a3a2d60b: ?? ??:0
5 0x0000000000402744: _start at ??:?
Elapsed time does not match (MSR=475800, TSC=466334)
This is on my Intel machine:
[mlevitsk@worklaptop ~/Kernel/master/src/tools/testing/selftests/kvm]$while true ; do ./x86_64/hyperv_clock ; done
==== Test Assertion Failure ====
x86_64/hyperv_clock.c:234: false
pid=52204 tid=52204 errno=4 - Interrupted system call
1 0x00000000004026e7: main at hyperv_clock.c:234
2 0x00007fd2baa2d55f: ?? ??:0
3 0x00007fd2baa2d60b: ?? ??:0
4 0x0000000000402744: _start at ??:?
Failed guest assert: delta_ns * 100 < (t2 - t1) * 100 at x86_64/hyperv_clock.c:74
==== Test Assertion Failure ====
x86_64/hyperv_clock.c:234: false
pid=52517 tid=52517 errno=4 - Interrupted system call
1 0x00000000004026e7: main at hyperv_clock.c:234
2 0x00007f832a02d55f: ?? ??:0
3 0x00007f832a02d60b: ?? ??:0
4 0x0000000000402744: _start at ??:?
Failed guest assert: delta_ns * 100 < (t2 - t1) * 100 at x86_64/hyperv_clock.c:74
==== Test Assertion Failure ====
x86_64/hyperv_clock.c:199: delta_ns * 100 < (t2 - t1) * 100
pid=52598 tid=52598 errno=0 - Success
1 0x000000000040255d: host_check_tsc_msr_rdtsc at hyperv_clock.c:199
2 (inlined by) main at hyperv_clock.c:223
3 0x00007f52bd02d55f: ?? ??:0
4 0x00007f52bd02d60b: ?? ??:0
5 0x0000000000402744: _start at ??:?
Elapsed time does not match (MSR=263000, TSC=269964)
==== Test Assertion Failure ====
x86_64/hyperv_clock.c:199: delta_ns * 100 < (t2 - t1) * 100
pid=52645 tid=52645 errno=0 - Success
1 0x000000000040255d: host_check_tsc_msr_rdtsc at hyperv_clock.c:199
2 (inlined by) main at hyperv_clock.c:223
3 0x00007f398d22d55f: ?? ??:0
4 0x00007f398d22d60b: ?? ??:0
5 0x0000000000402744: _start at ??:?
Elapsed time does not match (MSR=530300, TSC=521275)
==== Test Assertion Failure ====
x86_64/hyperv_clock.c:199: delta_ns * 100 < (t2 - t1) * 100
pid=52762 tid=52762 errno=0 - Success
1 0x000000000040255d: host_check_tsc_msr_rdtsc at hyperv_clock.c:199
2 (inlined by) main at hyperv_clock.c:223
3 0x00007fdaac62d55f: ?? ??:0
4 0x00007fdaac62d60b: ?? ??:0
5 0x0000000000402744: _start at ??:?
Elapsed time does not match (MSR=263800, TSC=267716)
==== Test Assertion Failure ====
x86_64/hyperv_clock.c:199: delta_ns * 100 < (t2 - t1) * 100
pid=52787 tid=52787 errno=0 - Success
1 0x000000000040255d: host_check_tsc_msr_rdtsc at hyperv_clock.c:199
2 (inlined by) main at hyperv_clock.c:223
3 0x00007f029322d55f: ?? ??:0
4 0x00007f029322d60b: ?? ??:0
5 0x0000000000402744: _start at ??:?
Elapsed time does not match (MSR=342200, TSC=332493)
==== Test Assertion Failure ====
x86_64/hyperv_clock.c:234: false
pid=52968 tid=52968 errno=4 - Interrupted system call
1 0x00000000004026e7: main at hyperv_clock.c:234
2 0x00007f133202d55f: ?? ??:0
3 0x00007f133202d60b: ?? ??:0
4 0x0000000000402744: _start at ??:?
Failed guest assert: delta_ns * 100 < (t2 - t1) * 100 at x86_64/hyperv_clock.c:74
==== Test Assertion Failure ====
x86_64/hyperv_clock.c:199: delta_ns * 100 < (t2 - t1) * 100
pid=53349 tid=53349 errno=0 - Success
1 0x000000000040255d: host_check_tsc_msr_rdtsc at hyperv_clock.c:199
2 (inlined by) main at hyperv_clock.c:223
3 0x00007f28fbc2d55f: ?? ??:0
4 0x00007f28fbc2d60b: ?? ??:0
5 0x0000000000402744: _start at ??:?
Elapsed time does not match (MSR=265300, TSC=257886)
==== Test Assertion Failure ====
x86_64/hyperv_clock.c:234: false
pid=53460 tid=53460 errno=4 - Interrupted system call
1 0x00000000004026e7: main at hyperv_clock.c:234
2 0x00007f7a0542d55f: ?? ??:0
3 0x00007f7a0542d60b: ?? ??:0
4 0x0000000000402744: _start at ??:?
Failed guest assert: delta_ns * 100 < (t2 - t1) * 100 at x86_64/hyperv_clock.c:74
==== Test Assertion Failure ====
x86_64/hyperv_clock.c:199: delta_ns * 100 < (t2 - t1) * 100
pid=53847 tid=53847 errno=0 - Success
1 0x000000000040255d: host_check_tsc_msr_rdtsc at hyperv_clock.c:199
2 (inlined by) main at hyperv_clock.c:223
3 0x00007f7d53c2d55f: ?? ??:0
4 0x00007f7d53c2d60b: ?? ??:0
5 0x0000000000402744: _start at ??:?
Elapsed time does not match (MSR=578800, TSC=527827)
Best regards,
Maxim Levitsky
^ permalink raw reply [flat|nested] 2+ messages in thread
* Re: FYI: hyperv_clock selftest has random failures
2022-05-25 14:35 FYI: hyperv_clock selftest has random failures Maxim Levitsky
@ 2022-05-25 14:59 ` Vitaly Kuznetsov
0 siblings, 0 replies; 2+ messages in thread
From: Vitaly Kuznetsov @ 2022-05-25 14:59 UTC (permalink / raw)
To: Maxim Levitsky; +Cc: Paolo Bonzini, kvm@vger.kernel.org
Maxim Levitsky <mlevitsk@redhat.com> writes:
> Just something I noticed today. Happens on both AMD and Intel, kvm/queue.
>
> Likely the test needs lower tolerancies.
>
> I'll investigate this later
>
> This is on my AMD machine (3970X):
>
> [mlevitsk@starship ~/Kernel/master/src/tools/testing/selftests/kvm]$while true ; do ./x86_64/hyperv_clock ; done
> ==== Test Assertion Failure ====
> x86_64/hyperv_clock.c:199: delta_ns * 100 < (t2 - t1) * 100
> pid=66218 tid=66218 errno=0 - Success
> 1 0x000000000040255d: host_check_tsc_msr_rdtsc at hyperv_clock.c:199
> 2 (inlined by) main at hyperv_clock.c:223
> 3 0x00007f0f2822d55f: ?? ??:0
> 4 0x00007f0f2822d60b: ?? ??:0
> 5 0x0000000000402744: _start at ??:?
> Elapsed time does not match (MSR=471600, TSC=461024)
...
Here the test is:
r1 = rdtsc()
m1 = KVM_GET_MSRS (HV_X64_MSR_TIME_REF_COUNT)
nop_loop()
r2 = rdtsc()
m2 = KVM_GET_MSRS (HV_X64_MSR_TIME_REF_COUNT)
and then we compare the difference between rdtsc()-s and
HV_X64_MSR_TIME_REF_COUNT changes with 1% tolerance (r2-r1 vs m2-m1).
It would probably increase accuracy if we do
r1_1 = rdtsc()
KVM_GET_MSRS (HV_X64_MSR_TIME_REF_COUNT)
r1_2 = rdtsc()
nop_loop()
r2_1 = rdtsc()
KVM_GET_MSRS (HV_X64_MSR_TIME_REF_COUNT)
r2_2 = rdtsc()
and compare (r2_2 + r2_1)/2 - (r2_1 + r2_2)/2 vs m2-m1.
and also increase tolerance to say 5%.
> ==== Test Assertion Failure ====
> x86_64/hyperv_clock.c:234: false
> pid=66652 tid=66652 errno=4 - Interrupted system call
> 1 0x00000000004026e7: main at hyperv_clock.c:234
> 2 0x00007fdab782d55f: ?? ??:0
> 3 0x00007fdab782d60b: ?? ??:0
> 4 0x0000000000402744: _start at ??:?
> Failed guest assert: delta_ns * 100 < (t2 - t1) * 100 at x86_64/hyperv_clock.c:74
Same story as above but from within the guest (rdmsr() istead of
KVM_GET_MSRS). We can probably employ the same idea to increate the
accuracy.
--
Vitaly
^ permalink raw reply [flat|nested] 2+ messages in thread
end of thread, other threads:[~2022-05-25 15:00 UTC | newest]
Thread overview: 2+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2022-05-25 14:35 FYI: hyperv_clock selftest has random failures Maxim Levitsky
2022-05-25 14:59 ` Vitaly Kuznetsov
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox