Re: kvm-unit-test failures

[Chris J Arges <chris.j.arges@canonical.com>]

On 08/31/2014 11:05 AM, Paolo Bonzini wrote:
> Il 29/08/2014 23:05, Chris J Arges ha scritto:
>> And indeed there is a condition where matched && already_matched are
>> both true. In this case we don't zero or increment nr_vcpus_matched_tsc.
>> Incrementing nr_vcpus_matched_tsc in that last else clause allows the
>> test to pass; however this is identical to the  logic before the patch.
> 
> Can you please trace the test using trace-cmd
> (http://www.linux-kvm.org/page/Tracing) and send the output?
> 
> Paolo
> 

Paolo,

I have posted the trace data here:
http://people.canonical.com/~arges/kvm/trace.dat.xz

Here is the output from the actual test case:
enabling apic
enabling apic
kvm-clock: cpu 0, msr 0x:44d4c0
kvm-clock: cpu 0, msr 0x:44d4c0
Wallclock test, threshold 5
Seconds get from host:     1409687073
Seconds get from kvmclock: 1409333034
Offset:                    -354039
offset too large!
Check the stability of raw cycle ...
Worst warp -354462672821748
Total vcpus: 2
Test  loops: 10000000
Total warps:  1
Total stalls: 0
Worst warp:   -354462672821748
Raw cycle is not stable
Monotonic cycle test:
Worst warp -354455286691490
Total vcpus: 2
Test  loops: 10000000
Total warps:  1
Total stalls: 0
Worst warp:   -354455286691490
Measure the performance of raw cycle ...
Total vcpus: 2
Test  loops: 10000000
TSC cycles:  1234719818
Measure the performance of adjusted cycle ...
Total vcpus: 2
Test  loops: 10000000
TSC cycles:  1234750103

I also enabled dynamic debugging on arch/x86/kvm/x86.c (on a separate run):
[354558.460867] kvm_get_time_scale: base_khz 1000000 => 2593993, shift
2, mul 2785278775
[354558.461034] kvm: new tsc generation 1, clock 0
[354558.461812] kvm_get_time_scale: base_khz 1000000 => 2593993, shift
2, mul 2785278775
[354558.461846] kvm: matched tsc offset for 0
[354558.477542] kvm: matched tsc offset for 0
[354558.477614] kvm: matched tsc offset for 0
[354558.513729] kvm: matched tsc offset for 0
[354558.541724] kvm: matched tsc offset for 0
[354558.741532] kvm_get_time_scale: base_khz 2593993 => 1000000, shift
-1, mul 3311471770
[354558.742551] kvm_get_time_scale: base_khz 2593993 => 1000000, shift
-1, mul 3311471770

Also I ensured that this was reproducible with the latest qemu, and
these results were gathered with the latest version as of today.

Any other places to look into?

--chris j arges