Re: 2.6.35-rc1 regression with pvclock and smp guests

Michael Tokarev
2010-10-02T07:35:30Z

02.10.2010 09:35, Zachary Amsden wrote:
[]
> Can you try this patch to see if it helps? I believe it is also safe
> for Xen, but cc'ing to double check.

It makes no visible difference.

For some reason one of my test guests - 2.6.35.6 32bit kernel -
stopped booting completely, always handing at boot somewhere
unless I disable printk.time. Here's the typical boot messages,
up to the hang:

[ 0.000000] Initializing cgroup subsys cpuset
[ 0.000000] Initializing cgroup subsys cpu
[ 0.000000] Linux version 2.6.35-i686 (mjt@gandalf) (gcc version 4.4.5 20100728 (prerelease) (Debian 4.4.4-8) ) #2.6.35.6 SMP Thu Sep 30 12:00:24 MSD 2010
[ 0.000000] BIOS-provided physical RAM map:
[ 0.000000] BIOS-e820: 0000000000000000 - 000000000009f400 (usable)
[ 0.000000] BIOS-e820: 000000000009f400 - 00000000000a0000 (reserved)
[ 0.000000] BIOS-e820: 00000000000f0000 - 0000000000100000 (reserved)
[ 0.000000] BIOS-e820: 0000000000100000 - 000000001fffd000 (usable)
[ 0.000000] BIOS-e820: 000000001fffd000 - 0000000020000000 (reserved)
[ 0.000000] BIOS-e820: 00000000feffd000 - 00000000ff001000 (reserved)
[ 0.000000] BIOS-e820: 00000000fffc0000 - 0000000100000000 (reserved)
[ 0.000000] Notice: NX (Execute Disable) protection cannot be enabled: non-PAE kernel!
[ 0.000000] DMI 2.4 present.
[ 0.000000] last_pfn = 0x1fffd max_arch_pfn = 0x100000
[ 0.000000] x86 PAT enabled: cpu 0, old 0x0, new 0x7010600070106
[ 0.000000] found SMP MP-table at [c00fdbe0] fdbe0
[ 0.000000] init_memory_mapping: 0000000000000000-000000001fffd000
[ 0.000000] RAMDISK: 1fbb5000 - 1fe96000
[ 0.000000] ACPI: RSDP 000fdb90 00014 (v00 BOCHS )
[ 0.000000] ACPI: RSDT 1fffde10 00034 (v01 BOCHS BXPCRSDT 00000001 BXPC 00000001)
[ 0.000000] ACPI: FACP 1ffffe40 00074 (v01 BOCHS BXPCFACP 00000001 BXPC 00000001)
[ 0.000000] ACPI: DSDT 1fffdfd0 01E22 (v01 BXPC BXDSDT 00000001 INTL 20090123)
[ 0.000000] ACPI: FACS 1ffffe00 00040
[ 0.000000] ACPI: SSDT 1fffdf80 00044 (v01 BOCHS BXPCSSDT 00000001 BXPC 00000001)
[ 0.000000] ACPI: APIC 1fffde90 0007A (v01 BOCHS BXPCAPIC 00000001 BXPC 00000001)
[ 0.000000] ACPI: HPET 1fffde50 00038 (v01 BOCHS BXPCHPET 00000001 BXPC 00000001)
[ 0.000000] 0MB HIGHMEM available.
[ 0.000000] 511MB LOWMEM available.
[ 0.000000] mapped low ram: 0 - 1fffd000
[ 0.000000] low ram: 0 - 1fffd000
[ 0.000000] kvm-clock: Using msrs 12 and 11
[ 0.000000] kvm-clock: cpu 0, msr 0:13c60c1, boot clock
[ 0.000000] Zone PFN ranges:
[ 0.000000] DMA 0x00000001 -> 0x00001000
[ 0.000000] Normal 0x00001000 -> 0x0001fffd
[ 0.000000] HighMem empty
[ 0.000000] Movable zone start PFN for each node
[ 0.000000] early_node_map[2] active PFN ranges
[ 0.000000] 0: 0x00000001 -> 0x0000009f
[ 0.000000] 0: 0x00000100 -> 0x0001fffd
[ 0.000000] Using APIC driver default
[ 0.000000] ACPI: PM-Timer IO Port: 0xb008
[ 0.000000] ACPI: LAPIC (acpi_id[0x00] lapic_id[0x00] enabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x01] lapic_id[0x01] enabled)
[ 0.000000] ACPI: IOAPIC (id[0x02] address[0xfec00000] gsi_base[0])
[ 0.000000] IOAPIC[0]: apic_id 2, version 17, address 0xfec00000, GSI 0-23
[ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
[ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level)
[ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
[ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level)
[ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level)
[ 0.000000] Using ACPI (MADT) for SMP configuration information
[ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000
[ 0.000000] SMP: Allowing 2 CPUs, 0 hotplug CPUs
[ 0.000000] PM: Registered nosave memory: 000000000009f000 - 00000000000a0000
[ 0.000000] PM: Registered nosave memory: 00000000000a0000 - 00000000000f0000
[ 0.000000] PM: Registered nosave memory: 00000000000f0000 - 0000000000100000
[ 0.000000] Allocating PCI resources starting at 20000000 (gap: 20000000:deffd000)
[ 0.000000] Booting paravirtualized kernel on KVM
[ 0.000000] setup_percpu: NR_CPUS:8 nr_cpumask_bits:8 nr_cpu_ids:2 nr_node_ids:1
[ 0.000000] PERCPU: Embedded 16 pages/cpu @c1c00000 s43072 r0 d22464 u2097152
[ 0.000000] pcpu-alloc: s43072 r0 d22464 u2097152 alloc=1*4194304
[ 0.000000] pcpu-alloc: [0] 0 1
[ 0.000000] kvm-clock: cpu 0, msr 0:1c0a0c1, primary cpu clock
[ 0.000000] Built 1 zonelists in Zone order, mobility grouping on. Total pages: 129947
[ 0.000000] Kernel command line: acpi_enforce_resources=lax rootfs=nfs root=/usr/rb rootflags=ro,nolock bootrc=/remote/bootrc initrd=lnx/initrd-2.6.35-i686 ip=192.168.88.60:192.168.88.4:192.168.88.4:255.255.255.0 BOOTIF=01-52-54-00-12-34-56 console=tty1 console=ttyS0 BOOT_IMAGE=lnx/vmlinuz-2.6.35-i686
[ 0.000000] PID hash table entries: 2048 (order: 1, 8192 bytes)
[ 0.000000] Dentry cache hash table entries: 65536 (order: 6, 262144 bytes)
[ 0.000000] Inode-cache hash table entries: 32768 (order: 5, 131072 bytes)
[ 0.000000] Enabling fast FPU save and restore... done.
[ 0.000000] Enabling unmasked SIMD FPU exception support... done.
[ 0.000000] Initializing CPU#0
[ 0.000000] Subtract (42 early reservations)
[ 0.000000] #1 [0000001000 - 0000002000] EX TRAMPOLINE
[ 0.000000] #2 [0001000000 - 000144a9e4] TEXT DATA BSS
[ 0.000000] #3 [001fbb5000 - 001fe96000] RAMDISK
[ 0.000000] #4 [000144b000 - 0001451049] BRK
[ 0.000000] #5 [000009f400 - 00000fdbe0] BIOS reserved
[ 0.000000] #6 [00000fdbe0 - 00000fdbf0] MP-table mpf
[ 0.000000] #7 [00000fdce4 - 0000100000] BIOS reserved
[ 0.000000] #8 [00000fdbf0 - 00000fdce4] MP-table mpc
[ 0.000000] #9 [0000002000 - 0000003000] TRAMPOLINE
[ 0.000000] #10 [0000003000 - 0000007000] ACPI WAKEUP
[ 0.000000] #11 [0000007000 - 0000008000] PGTABLE
[ 0.000000] #12 [0001452000 - 0001453000] BOOTMEM
[ 0.000000] #13 [0001453000 - 0001853000] BOOTMEM
[ 0.000000] #14 [000144aa00 - 000144aa04] BOOTMEM
[ 0.000000] #15 [000144aa40 - 000144ab00] BOOTMEM
[ 0.000000] #16 [000144ab00 - 000144ab30] BOOTMEM
[ 0.000000] #17 [0001853000 - 0001854800] BOOTMEM
[ 0.000000] #18 [000144ab40 - 000144ab65] BOOTMEM
[ 0.000000] #19 [000144ab80 - 000144aba7] BOOTMEM
[ 0.000000] #20 [000144abc0 - 000144aca0] BOOTMEM
[ 0.000000] #21 [000144acc0 - 000144ad00] BOOTMEM
[ 0.000000] #22 [000144ad00 - 000144ad40] BOOTMEM
[ 0.000000] #23 [000144ad40 - 000144ad80] BOOTMEM
[ 0.000000] #24 [000144ad80 - 000144adc0] BOOTMEM
[ 0.000000] #25 [000144adc0 - 000144ae00] BOOTMEM
[ 0.000000] #26 [000144ae00 - 000144ae40] BOOTMEM
[ 0.000000] #27 [000144ae40 - 000144ae80] BOOTMEM
[ 0.000000] #28 [000144ae80 - 000144ae90] BOOTMEM
[ 0.000000] #29 [000144aec0 - 000144afcf] BOOTMEM
[ 0.000000] #30 [0001451080 - 000145118f] BOOTMEM
[ 0.000000] #31 [0001c00000 - 0001c10000] BOOTMEM
[ 0.000000] #32 [0001e00000 - 0001e10000] BOOTMEM
[ 0.000000] #33 [00014511c0 - 00014511c4] BOOTMEM
[ 0.000000] #34 [0001451200 - 0001451204] BOOTMEM
[ 0.000000] #35 [0001451240 - 0001451248] BOOTMEM
[ 0.000000] #36 [0001451280 - 0001451288] BOOTMEM
[ 0.000000] #37 [00014512c0 - 0001451368] BOOTMEM
[ 0.000000] #38 [0001451380 - 00014513e8] BOOTMEM
[ 0.000000] #39 [0001854800 - 0001856800] BOOTMEM
[ 0.000000] #40 [0001856800 - 0001896800] BOOTMEM
[ 0.000000] #41 [0001896800 - 00018b6800] BOOTMEM
[ 0.000000] Initializing HighMem for node 0 (00000000:00000000)
[ 0.000000] Memory: 511856k/524276k available (2554k kernel code, 12028k reserved, 930k data, 380k init, 0k highmem)
[ 0.000000] virtual kernel memory layout:
[ 0.000000] fixmap : 0xfff16000 - 0xfffff000 ( 932 kB)
[ 0.000000] pkmap : 0xff800000 - 0xffc00000 (4096 kB)
[ 0.000000] vmalloc : 0xe07fd000 - 0xff7fe000 ( 496 MB)
[ 0.000000] lowmem : 0xc0000000 - 0xdfffd000 ( 511 MB)
[ 0.000000] .init : 0xc1368000 - 0xc13c7000 ( 380 kB)
[ 0.000000] .data : 0xc127ebb7 - 0xc1367488 ( 930 kB)
[ 0.000000] .text : 0xc1000000 - 0xc127ebb7 (2554 kB)
[ 0.000000] Checking if this processor honours the WP bit even in supervisor mode...Ok.
[ 0.000000] Hierarchical RCU implementation.
[ 0.000000] RCU-based detection of stalled CPUs is disabled.
[ 0.000000] Verbose stalled-CPUs detection is disabled.
[ 0.000000] NR_IRQS:512
[ 0.000000] Console: colour VGA+ 80x25
[ 0.000000] console [tty1] enabled
[ 0.000000] console [ttyS0] enabled
[ 0.000000] Detected 3217.252 MHz processor.
[ 0.023332] Calibrating delay loop (skipped) preset value.. 6437.60 BogoMIPS (lpj=10724173)
[ 0.023332] pid_max: default: 32768 minimum: 301
[ 0.023332] Mount-cache hash table entries: 512
[ 0.023447] Initializing cgroup subsys ns
[ 0.024131] Initializing cgroup subsys cpuacct
[ 0.024851] Initializing cgroup subsys devices
[ 0.025580] Initializing cgroup subsys freezer
[ 0.026669] Initializing cgroup subsys net_cls
[ 0.027425] Initializing cgroup subsys blkio
[ 0.030079] mce: CPU supports 10 MCE banks
[ 0.030847] using C1E aware idle routine
[ 0.031517] Performance Events: AMD PMU driver.
[ 0.032313] ... version: 0
[ 0.033335] ... bit width: 48
[ 0.034036] ... generic registers: 4
[ 0.034716] ... value mask: 0000ffffffffffff
[ 0.035542] ... max period: 00007fffffffffff
[ 0.036669] ... fixed-purpose events: 0
[ 0.037521] ... event mask: 000000000000000f
[ 0.041961] ACPI: Core revision 20100428
[ 0.044150] Enabling APIC mode: Flat. Using 1 I/O APICs
[ 0.045964] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
[ 0.046671] CPU0: AMD Athlon(tm) II X2 260 Processor stepping 03
[ 0.049999] APIC calibration not consistent with PM-Timer: 102ms instead of 100ms
[ 0.049999] APIC delta adjusted to PM-Timer: 6248670 (6435422)
[ 0.050298] Booting Node 0, Processors #1 Ok.
[ 0.023332] Initializing CPU#1
[ 0.063333] kvm-clock: cpu 1, msr 0:1e0a0c1, secondary cpu clock
[ 0.063333] Brought up 2 CPUs
[ 0.063333] Total of 2 processors activated (12874.21 BogoMIPS).
[ 0.076666] x86 PAT enabled: cpu 1, old 0x0, new 0x7010600070106
[ 0.116666] devtmpfs: initialized
[ 0.116666] NET: Registered protocol family 16
[ 0.119999] ACPI: bus type pci registered
[ 0.123333] PCI: PCI BIOS revision 2.10 entry at 0xffe77, last bus=0
[ 0.123333] PCI: Using configuration type 1 for base access
[ 0.123333] PCI: Using configuration type 1 for extended access
[ 0.126666] mtrr: your CPUs had inconsistent variable MTRR settings
[ 0.126666] mtrr: your CPUs had inconsistent MTRRdefType settings
[ 0.126666] mtrr: probably your BIOS does not setup all CPUs.
[ 0.126666] mtrr: corrected configuration.
[ 0.136666] bio: create slab <bio-0> at 0
[ 0.153333] ACPI: Interpreter enabled
[ 0.153333] ACPI: (supports S0 S3 S4 S5)
[ 0.153333] ACPI: Using IOAPIC for interrupt routing
[ 0.203333] ACPI: No dock devices found.
[ 0.203333] PCI: Ignoring host bridge windows from ACPI; if necessary, use "pci=use_crs" and report a bug
[ 0.206666] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
[ 0.209999] pci 0000:00:01.3: quirk: [io 0xb000-0xb03f] claimed by PIIX4 ACPI
[ 0.209999] pci 0000:00:01.3: quirk: [io 0xb100-0xb10f] claimed by PIIX4 SMB
[ 0.216666] ACPI: PCI Interrupt Link [LNKA] (IRQs 5 *10 11)
[ 0.219999] ACPI: PCI Interrupt Link [LNKB] (IRQs 5 *10 11)
[ 0.219999] ACPI: PCI Interrupt Link [LNKC] (IRQs 5 10 *11)
[ 0.223333] ACPI: PCI Interrupt Link [LNKD] (IRQs 5 10 *11)
[ 0.223333] HEST: Table is not found!
[ 0.226666] vgaarb: device added: PCI:0000:00:02.0,decodes=io+mem,owns=io+mem,locks=none
[ 0.229999] vgaarb: loaded
[ 0.229999] PCI: Using ACPI for IRQ routing
[ 0.233333] HPET: 3 timers in total, 0 timers will be used for per-cpu timer
[ 0.239999] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0
[ 0.239999] hpet0: 3 comparators, 64-bit 100.000000 MHz counter
[ 0.249999] Switching to clocksource kvm-clock
[ 0.259999] pnp: PnP ACPI init
[ 0.259999] ACPI: bus type pnp registered
[ 0.259999] pnp: PnP ACPI: found 8 devices
[ 0.259999] ACPI: ACPI bus type pnp unregistered
[ 0.259999] PnPBIOS: Disabled
[ 0.259999] NET: Registered protocol family 2
[ 0.259999] IP route cache hash table entries: 4096 (order: 2, 16384 bytes)
[ 0.259999] TCP established hash table entries: 16384 (order: 5, 131072 bytes)
[ 0.259999] TCP bind hash table entries: 16384 (order: 5, 131072 bytes)
[ 0.259999] TCP: Hash tables configured (established 16384 bind 16384)
[ 0.259999] TCP reno registered
[ 0.259999] UDP hash table entries: 256 (order: 1, 8192 bytes)
[ 0.259999] UDP-Lite hash table entries: 256 (order: 1, 8192 bytes)
[ 0.259999] NET: Registered protocol family 1
[ 0.259999] pci 0000:00:00.0: Limiting direct PCI/PCI transfers
[ 0.259999] pci 0000:00:01.0: PIIX3: Enabling Passive Release
[ 0.259999] pci 0000:00:01.0: Activating ISA DMA hang workarounds
[ 0.259999] Unpacking initramfs...
[ 0.259999] Freeing initrd memory: 2948k freed
[ 0.259999] HugeTLB registered 4 MB page size, pre-allocated 0 pages
[ 0.259999] VFS: Disk quotas dquot_6.5.2
[ 0.259999] Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[ 0.259999] msgmni has been set to 1005
[ 0.259999] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 253)
[ 0.259999] io scheduler noop registered
[ 0.259999] io scheduler deadline registered
[ 0.259999] io scheduler cfq registered (default)
[ 0.259999] ERST: Table is not found!
[ 0.259999] isapnp: Scanning for PnP cards...
[ 0.259999] isapnp: No Plug & Play device found
[ 0.259999] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[ 0.259999] serial8250: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
[ 0.259999] 00:06: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
[ 0.259999] PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12
[ 0.259999] serio: i8042 KBD port at 0x60,0x64 irq 1
[ 0.259999] serio: i8042 AUX port at 0x60,0x64 irq 12
[ 0.259999] mice: PS/2 mouse device common for all mice
[ 0.259999] input: PC Speaker as /devices/platform/pcspkr/input/input0
[ 0.259999] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1
[ 0.259999] rtc_cmos 00:01: rtc core: registered rtc_cmos as rtc0
[ 0.259999] rtc0: alarms up to one day, 114 bytes nvram, hpet irqs
[ 0.259999] cpuidle: using governor ladder
[ 0.259999] cpuidle: using governor menu
[ 0.259999] TCP cubic registered
[ 0.259999] NET: Registered protocol family 17
[ 0.259999] Using IPI No-Shortcut mode
[ 0.259999] rtc_cmos 00:01: setting system clock to 2010-10-02 07:27:50 UTC (1286004470)
[ 0.259999] Freeing unused kernel memory: 380k freed
[ 0.259999] Processing INITRAMFS
[ 0.259999] SCSI subsystem initialized
[ 0.259999] scsi0 : ata_piix
[ 0.259999] scsi1 : ata_piix
[ 0.259999] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc000 irq 14
[ 0.259999] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc008 irq 15

Note the time - it is constant after switching to kvmclock.

This is the most typical place where it stops, sometimes it
stops at "Freeing unused kernel memory", sometimes it boots
further and hangs at "Login:" prompt, right after some other
kernel message.

This is bootlog with the last patch (kvmclock-fix-hack-1.patch)
and the previous "bandaid" patch (the kvmclock registration
printk, use-before-init, which obviously makes no difference)
applied.

I just realized I never posted any boot loogs from my systems...
So here it goes :)

Thanks!

/mjt