Re: 2.6.35-rc1 regression with pvclock and smp guests

[Arjan Koers <0h61vkll2ly8@xutrox.com>]

On 2010-07-31 18:36, 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).


Moving the printk after native_write_msr_safe seems to solve the
problem:

diff --git a/arch/x86/kernel/kvmclock.c b/arch/x86/kernel/kvmclock.c
index eb9b76c..ca43ce3 100644
--- a/arch/x86/kernel/kvmclock.c
+++ b/arch/x86/kernel/kvmclock.c
@@ -128,13 +128,15 @@ static struct clocksource kvm_clock = {
 static int kvm_register_clock(char *txt)
 {
 	int cpu = smp_processor_id();
-	int low, high;
+	int low, high, ret;
+
 	low = (int)__pa(&per_cpu(hv_clock, cpu)) | 1;
 	high = ((u64)__pa(&per_cpu(hv_clock, cpu)) >> 32);
+	ret = native_write_msr_safe(msr_kvm_system_time, low, high);
 	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);
+	return ret;
 }

 #ifdef CONFIG_X86_LOCAL_APIC



The debug log looks correct now:
67: ffff880001411a80     1b7772acb f797e782af86 7c82a2     1b7dd17c9 65ecfe 246717  f797e7a7169d
68: ffff880001411a80     1b8730d76 f797e7dca389 7c82b2     1b8892871 161afb  7e519  f797e7e488a2
69: ffff880001411a80     1b8730d76 f797e7dca389 7c82b2     1b8893281 16250b  7e8b1  f797e7e48c3a
70: ffff880001411a80     1b8730d76 f797e7dca389 7c82b2     1b8893c47 162ed1  7ec2e  f797e7e48fb7
71: ffff880001511a80 2b55ba387fb14 f797e7ef37af e7c292 2b55ba388196a   1e56    ad5  f797e7ef4284
72: ffff880001411a80     1b8a96765 f797e7f00c69 7c82b6     1b8a9fed0   976b   3613  f797e7f0427c
73: ffff880001411a80     1b8a96765 f797e7f00c69 7c82b6     1b8ab712f  209ca   ba5b  f797e7f0c6c4
74: ffff880001411a80     1b8a96765 f797e7f00c69 7c82b6     1b8abd861  270fc   df36  f797e7f0eb9f
75: ffff880001411a80     1b8a96765 f797e7f00c69 7c82b6     1b8ac3348  2cbe3   ffad  f797e7f10c16
76: ffff880001511a80 2b55ba3b9c85c f797e8010094 e7c332 2b55ba3bc258a  25d2e   d823  f797e801d8b7
77: ffff880001511a80 2b55ba3ce41f9 f797e8085071 e7c366 2b55ba3cec05b   7e62   2d23  f797e8087d94
78: ffff880001411a80     1b8d56d8c f797e7ffc53e 7c82b8     1b8eef620 198894  91e88  f797e808e3c6
79: ffff880001411a80     1b8d56d8c f797e7ffc53e 7c82b8     1b8ef182e 19aaa2  92ab2  f797e808eff0
80: ffff880001411a80     1b8d56d8c f797e7ffc53e 7c82b8     1b8f1d2ad 1c6521  a2429  f797e809e967


The only strange thing remaining is that the time for the first printk
isn't what I expected:
	[    0.016000] kvm-clock: cpu 1, msr 0:1511a81, secondary cpu clock
When I added some extra printk's immediately after that one, the
time on those was correct.

Here's a partial boot log:
...
[    0.000000] Console: colour VGA+ 80x25
[    0.000000] console [tty0] enabled
[    0.000000] hpet clockevent registered
[    0.000000] Detected 2799.950 MHz processor.
[    0.016000] Calibrating delay loop (skipped) preset value.. 5599.90 BogoMIPS (lpj=11199800)
[    0.016000] pid_max: default: 32768 minimum: 301
[    0.016000] Mount-cache hash table entries: 256
[    0.016000] using C1E aware idle routine
[    0.016000] Performance Events: AMD PMU driver.
[    0.016000] ... version:                0
[    0.016000] ... bit width:              48
[    0.016000] ... generic registers:      4
[    0.016000] ... value mask:             0000ffffffffffff
[    0.016004] ... max period:             00007fffffffffff
[    0.016406] ... fixed-purpose events:   0
[    0.016744] ... event mask:             000000000000000f
[    0.021404] Freeing SMP alternatives: 12k freed
[    0.021836] ACPI: Core revision 20100428
[    0.023882] Setting APIC routing to flat
[    0.025659] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
[    0.026129] CPU0: AMD Athlon(tm) II X2 240 Processor stepping 02
[    0.028000] Booting Node   0, Processors  #1 Ok.
[    0.016000] kvm-clock: cpu 1, msr 0:1511a81, secondary cpu clock
[    0.036812] Brought up 2 CPUs
[    0.036820] Total of 2 processors activated (11199.80 BogoMIPS).
[    0.036802] x86 PAT enabled: cpu 1, old 0x0, new 0x7010600070106
[    0.040357] NET: Registered protocol family 16
[    0.044159] ACPI: bus type pci registered
...