Re: 2.6.35-rc1 regression with pvclock and smp guests

Zachary Amsden
2010-08-03T00:00:39Z

[-- 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