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
...
--
To unsubscribe from this list: send the line "unsubscribe kvm" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
