Re: 2.6.35-rc1 regression with pvclock and smp guests

[Zachary Amsden <zamsden@redhat.com>]

[-- Attachment #1: Type: text/plain, Size: 3909 bytes --]

On 08/02/2010 11:35 AM, Arjan Koers wrote:
> On 2010-08-02 22:26, Zachary Amsden wrote:
>    
>> On 08/02/2010 04:43 AM, Glauber Costa wrote:
>>      
>>> On Sat, Jul 31, 2010 at 01:55:10PM -1000, Zachary Amsden wrote:
>>>
>>>        
>>>> On 07/31/2010 06:36 AM, Arjan Koers wrote:
>>>>
>>>>          
>>>>> On 2010-07-31 13:53, Arjan Koers wrote:
>>>>>
>>>>>            
>>>>>> The kernel boots successfully when CONFIG_PRINTK_TIME is not set.
>>>>>>
>>>>>>
>>>>>>              
>>>>> The problem occurs when this message is printed:
>>>>>
>>>>> [    0.016000] kvm-clock: cpu 1, msr 0:1511c01, secondary cpu clock
>>>>>
>>>>> When I disable that printk, the kernel boots with
>>>>> CONFIG_PRINTK_TIME=y
>>>>>
>>>>> --- a/arch/x86/kernel/kvmclock.c
>>>>> +++ b/arch/x86/kernel/kvmclock.c
>>>>> @@ -131,8 +131,8 @@ static int kvm_register_clock(char *txt)
>>>>>        int low, high;
>>>>>        low = (int)__pa(&per_cpu(hv_clock, cpu)) | 1;
>>>>>        high = ((u64)__pa(&per_cpu(hv_clock, cpu))>>    32);
>>>>> -    printk(KERN_INFO "kvm-clock: cpu %d, msr %x:%x, %s\n",
>>>>> -           cpu, high, low, txt);
>>>>> +    /*printk(KERN_INFO "kvm-clock: cpu %d, msr %x:%x, %s\n",
>>>>> +           cpu, high, low, txt);*/
>>>>>
>>>>>        return native_write_msr_safe(msr_kvm_system_time, low, high);
>>>>>    }
>>>>>
>>>>> So the problem appears to be that the clock of the second CPU
>>>>> is used too soon (or that clock setup should finish earlier).
>>>>>
>>>>>            
>>>> That's almost hilarious.  The printk from setting up the kvm clock
>>>> is invoking the kvm clock before it is setup.
>>>>
>>>> There's no reason other printks couldn't do the same thing, however.
>>>> I think it's safest to keep an initialized flag and check for it
>>>> before attempting to return a meaningful value.
>>>>
>>>>          
>>> I was on vacations, just got back.
>>>
>>> I think it is safe to just patch our own use of it. Before that, all
>>> other
>>> printks will be handled by the main cpu anyway, since it'll be the
>>> only one active
>>> at the moment. The only possible offenders for this are us, and the
>>> cpu initialization
>>> code, which is already fragile in multiple ways anyway.
>>>
>>> A flag would only make things more complicated and dirty
>>>
>>>        
>> Can we just do this?
>>      
>
> Sorry, the patch doesn't help. See line 68 in my debug log:
> 65: ffff880001411c00    1b68905d7 156558001892 6e10a    1b6c0631e       375d47       13c5ce  15655813de60
> 66: ffff880001411c00    1b68905d7 156558001892 6e10a    1b6c0653b       375f64       13c68f  15655813df21
> 67: ffff880001411c00    1b68905d7 156558001892 6e10a    1b6c06746       37616f       13c74a  15655813dfdc
> 68: ffff880001511c00    1967ac192 15654c8d826a 63c6c 3bf58bf0ea18 3bf3f5762886 15695466a1e5  2acea0f4244f
>    

This is a separate bug.  See attached patch (it won't apply, it's part 
of a series, but shows the bug).

> 69: ffff880001411c00    1b6f3fbda 156558264b1e 6e10e    1b6f424aa         28d0          e93  1565582659b1
> 70: ffff880001411c00    1b6f3fbda 156558264b1e 6e10e    1b6f4a1e0         a606         3b4b  156558268669
> 71: ffff880001411c00    1b6f3fbda 156558264b1e 6e10e    1b6f4ba63         be89         440b  156558268f29
> 72: ffff880001411c00    1b6f3fbda 156558264b1e 6e10e    1b6f4d8e7         dd0d         4ef1  156558269a0f
> 73: ffff880001511c00 3bf58bf16356 15655825e74b 40496 3bf58bf4d52c        371d6        13aef  15655827223a
> 74: ffff880001511c00 3bf58bf16356 15655825e74b 40496 3bf58bf4ebec        38896        1430f  156558272a5a
>
> I don't think that pvclock_clocksource_read is receiving
> completely random uninitialized data. The values in shadow
> are wrong, but could be interpreted as valid data
> (shadow.tsc_to_nsec_mul = b6dc43b6, shadow.tsc_shift = ffffffff,
> shadow.flags = 0 and shadow.version is always even).
>    
Copied from the first CPU possibly?

[-- Attachment #2: 0004-Fix-SVM-VMCB-reset.patch --]
[-- Type: text/plain, Size: 1031 bytes --]

From 3823c018162dc708b543cbdc680a4c7d63533fee Mon Sep 17 00:00:00 2001
From: Zachary Amsden <zamsden@redhat.com>
Date: Sat, 29 May 2010 17:52:46 -1000
Subject: [KVM V2 04/25] Fix SVM VMCB reset
Cc: Avi Kivity <avi@redhat.com>,
    Marcelo Tosatti <mtosatti@redhat.com>,
    Glauber Costa <glommer@redhat.com>,
    linux-kernel@vger.kernel.org

On reset, VMCB TSC should be set to zero.  Instead, code was setting
tsc_offset to zero, which passes through the underlying TSC.

Signed-off-by: Zachary Amsden <zamsden@redhat.com>
---
 arch/x86/kvm/svm.c |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)

diff --git a/arch/x86/kvm/svm.c b/arch/x86/kvm/svm.c
index 760c86e..46856d2 100644
--- a/arch/x86/kvm/svm.c
+++ b/arch/x86/kvm/svm.c
@@ -781,7 +781,7 @@ static void init_vmcb(struct vcpu_svm *svm)
 
 	control->iopm_base_pa = iopm_base;
 	control->msrpm_base_pa = __pa(svm->msrpm);
-	control->tsc_offset = 0;
+	guest_write_tsc(&svm->vcpu, 0);
 	control->int_ctl = V_INTR_MASKING_MASK;
 
 	init_seg(&save->es);
-- 
1.7.1