Re: kvm-unit-test failures

[Paolo Bonzini <pbonzini@redhat.com>]

Il 04/09/2014 11:53, Paolo Bonzini ha scritto:
> Il 03/09/2014 20:25, Chris J Arges ha scritto:
>> <snip>
>>> I'm not sure about the reason for the warp, but indeed the offset and
>>> uptime match (I'll check them against the trace tomorrow) so it's "just"
>>> that the VM's TSC base is not taken into account correctly.
>>>
>>> Can you gather another trace with the problematic patch reverted?
>>>
>>> Paolo
>>>
>>
>> Here is the third trace running with 0d3da0d2 reverted from the latest
>> kvm queue branch 11cc9ea3:
>>
>> http://people.canonical.com/~arges/kvm/trace-3.dat.xz
> 
> Thanks!  And---yay!---I reproduced it on another machine.

And my bisection landed on the merge of the timer branch (commit
e7fda6c4c3c1a7d6996dd75fd84670fa0b5d448f).  Here is the log:

$ git bisect bad origin/master
$ git bisect good v3.16
$ git bisect good kvm-3.17-1 # 42cbc04fd3b5e3f9b011bf9fa3ce0b3d1e10b58b

good    [ 6929.863545] loaded kvm module (v3.17-rc1-158-g451fd72219dd)
bad     [ 6971.932790] loaded kvm module (for-linus)
bad     [ 7216.073128] loaded kvm module (v3.16-6426-gae045e245542)
good    [ 7286.198948] loaded kvm module (v3.16-3283-g53ee983378ff)
good    [ 7350.534060] loaded kvm module (v3.16-rc7-1668-gaef4f5b6db65)
good    [ 7439.037038] loaded kvm module (v3.16-4006-g91c2ff7708d4)
good    [ 7481.188637] loaded kvm module (v3.16-rc6-450-g7ba3c21c17d0)
bad     [ 7535.292730] loaded kvm module (v3.16-4635-ge7fda6c4c3c1)
good    [ 7589.722691] loaded kvm module (v3.16-rc5-110-g9b0fd802e8c0)
good    [ 7630.286418] loaded kvm module (v3.16-4467-ged5c41d30ef2)
good    [ 7712.470986] loaded kvm module (v3.16-rc1-35-g885d078bfe92)
good    [ 7763.443626] loaded kvm module (v3.16-rc1-381-g1b0733837a9b)
good    [ 7825.497414] loaded kvm module (v3.16-rc5-116-g7806f60e1d20)
good    [ 7893.174056] loaded kvm module (v3.16-rc1-384-gc6f1224573c3)

This means that:

- Tomasz's patch (commit 0d3da0d26e3c3515997c99451ce3b0ad1a69a36c) is
fine, it just enables the (wrong) master clock more often

- the failure is within that branch.

I then cherry-picked Tomasz's patch during a new bisection, and landed
on one of my original suspects:

commit cbcf2dd3b3d4d990610259e8d878fc8dc1f17d80
Author: Thomas Gleixner <tglx@linutronix.de>
Date:   Wed Jul 16 21:04:54 2014 +0000

    x86: kvm: Make kvm_get_time_and_clockread() nanoseconds based

    Convert the relevant base data right away to nanoseconds instead of
    doing the conversion on every readout. Reduces text size by 160
    bytes.

    Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
    Cc: Gleb Natapov <gleb@kernel.org>
    Cc: kvm@vger.kernel.org
    Acked-by: Paolo Bonzini <pbonzini@redhat.com>
    Signed-off-by: John Stultz <john.stultz@linaro.org>

Again, here is the log:

$ git bisect bad 953dec21aed4038464fec02f96a2f1b8701a5bce
$ git bisect good 1af447bd8cbfb808a320885d214555fb2d32e6e6

good    [ 8384.334892] loaded kvm module (v3.16-rc5-81-g68f6783d2831)
bad     [ 8525.975170] loaded kvm module (v3.16-rc5-99-gf519b1a2e08c)
good    [ 8562.204988] loaded kvm module (v3.16-rc5-90-g41fa4215f8e8)
bad     [ 8629.133287] loaded kvm module (v3.16-rc5-94-g48f18fd6addc)
bad     [ 8772.846612] loaded kvm module (v3.16-rc5-92-gcbcf2dd3b3d4)
good    [ 8836.509602] loaded kvm module (v3.16-rc5-91-gbb0b58127c5a)

Paolo