Why is there a 1.7 second delay during boot in ubuntu 13.10 dmesg after kvm-clock?

Discussion in 'Linux Virtual Machine' started by maxmus, Feb 12, 2014.

  1. maxmus

    maxmus Bit poster

    Messages:
    5
    Host: Parallels Desktop for Mac Build 8.0.18615 (Revision 948847; Wed, 27 Nov 2013)
    Guest: Ubuntu 13.10 amd64, kernel 3.11.0-15-generic, ntpdate package is removed

    Actual dmesg output (with a 1.7 second boot delay):
    [ 0.000000] kvm-clock: cpu 0, msr 0:ffe7001, boot clock
    [ 1.712557] [ffffea0000000000-ffffea00003fffff] PMD -> [ffff88000ec00000-ffff88000effffff] on node 0

    Expected dmesg output (without 1.7 second boot delay):
    [ 0.000000] kvm-clock: cpu 0, msr 0:ffe7001, boot clock
    [ 0.000000] [ffffea0000000000-ffffea00003fffff] PMD -> [ffff88000ec00000-ffff88000effffff] on node 0

    Regression:
    1. Time = Sync from Mac OS X
    2. Time = Do not sync
    Result: no difference

    Other VM's seem to have a lot shorter kvm-clock boot process, f.e. Suse:
    Code:
    [    0.000000] kvm-clock: cpu 0, msr 0:7d3a81, boot clock
    [    0.000000] kvm-clock: cpu 0, msr 0:1206a81, primary cpu clock
    [    0.012000] kvm-clock: cpu 1, msr 0:1306a81, secondary cpu clock
    [    0.160082] Switching to clocksource kvm-clock
    source: http://doc.opensuse.org/products/dr...ibvirt.config.html#sec.kvm.managing.clock.kvm

    Other example, Debian:
    Code:
    [    0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00
    [    0.000000] kvm-clock: cpu 0, msr 0:3fff2001, boot clock
    [    0.000000] kvm-clock: cpu 0, msr 0:3fff2001, primary cpu clock
    [    0.000000] kvm-stealtime: cpu 0, msr 3fc0e040
    [    0.260023] Switched to clocksource kvm-clock
    source: https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=731317

    Why is there a 1.7 second delay in Ubuntu's kernel 3.11.0-15 boot process within this Parallels KVM environment?

    Any ideas how to speed up the boot process of this guest OS?


    First part of dmesg output:
    Code:
    [    0.000000] Initializing cgroup subsys cpuset
    [    0.000000] Initializing cgroup subsys cpu
    [    0.000000] Initializing cgroup subsys cpuacct
    [    0.000000] Linux version 3.11.0-15-generic (buildd@roseapple) (gcc version 4.8.1 (Ubuntu/Linaro 4.8.1-10ubuntu8) ) #25-Ubuntu SMP Thu Jan 30 17:22:01 UTC 2014 (Ubuntu 3.11.0-15.25-generic 3.11.10)
    [    0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz-3.11.0-15-generic root=UUID=868ae17e-b0c5-4697-9fda-03acb0d163a3 ro text
    [    0.000000] KERNEL supported cpus:
    [    0.000000]   Intel GenuineIntel
    [    0.000000]   AMD AuthenticAMD
    [    0.000000]   Centaur CentaurHauls
    [    0.000000] Disabled fast string operations
    [    0.000000] e820: BIOS-provided physical RAM map:
    [    0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
    [    0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved
    [    0.000000] BIOS-e820: [mem 0x00000000000dc000-0x00000000000fffff] reserved
    [    0.000000] BIOS-e820: [mem 0x0000000000100000-0x000000000ffeffff] usable
    [    0.000000] BIOS-e820: [mem 0x000000000fff0000-0x000000000fffefff] ACPI data
    [    0.000000] BIOS-e820: [mem 0x000000000ffff000-0x000000000fffffff] ACPI NVS
    [    0.000000] BIOS-e820: [mem 0x00000000fd000000-0x00000000fd7fffff] reserved
    [    0.000000] BIOS-e820: [mem 0x00000000fec00000-0x00000000fec00fff] reserved
    [    0.000000] BIOS-e820: [mem 0x00000000fee00000-0x00000000fee00fff] reserved
    [    0.000000] BIOS-e820: [mem 0x00000000ffc00000-0x00000000ffffffff] reserved
    [    0.000000] NX (Execute Disable) protection: active
    [    0.000000] SMBIOS 2.3 present.
    [    0.000000] DMI: Parallels Software International Inc. Parallels Virtual Platform/Parallels Virtual Platform, BIOS 8.0.18615.948847 10/26/2007
    [    0.000000] Hypervisor detected: KVM
    [    0.000000] e820: update [mem 0x00000000-0x00000fff] usable ==> reserved
    [    0.000000] e820: remove [mem 0x000a0000-0x000fffff] usable
    [    0.000000] No AGP bridge found
    [    0.000000] e820: last_pfn = 0xfff0 max_arch_pfn = 0x400000000
    [    0.000000] MTRR default type: uncachable
    [    0.000000] MTRR fixed ranges enabled:
    [    0.000000]   00000-9FFFF write-back
    [    0.000000]   A0000-BFFFF uncachable
    [    0.000000]   C0000-C7FFF write-protect
    [    0.000000]   C8000-EFFFF uncachable
    [    0.000000]   F0000-FFFFF write-protect
    [    0.000000] MTRR variable ranges enabled:
    [    0.000000]   0 base 000000000 mask FF0000000 write-back
    [    0.000000]   1 disabled
    [    0.000000]   2 disabled
    [    0.000000]   3 disabled
    [    0.000000]   4 disabled
    [    0.000000]   5 disabled
    [    0.000000]   6 disabled
    [    0.000000]   7 disabled
    [    0.000000] x86 PAT enabled: cpu 0, old 0x7040600070406, new 0x7010600070106
    [    0.000000] found SMP MP-table at [mem 0x000ff100-0x000ff10f] mapped at [ffff8800000ff100]
    [    0.000000] Scanning 1 areas for low memory corruption
    [    0.000000] Base memory trampoline at [ffff880000099000] 99000 size 24576
    [    0.000000] init_memory_mapping: [mem 0x00000000-0x000fffff]
    [    0.000000]  [mem 0x00000000-0x000fffff] page 4k
    [    0.000000] BRK [0x01fd1000, 0x01fd1fff] PGTABLE
    [    0.000000] BRK [0x01fd2000, 0x01fd2fff] PGTABLE
    [    0.000000] BRK [0x01fd3000, 0x01fd3fff] PGTABLE
    [    0.000000] init_memory_mapping: [mem 0x0fc00000-0x0fdfffff]
    [    0.000000]  [mem 0x0fc00000-0x0fdfffff] page 2M
    [    0.000000] init_memory_mapping: [mem 0x0c000000-0x0fbfffff]
    [    0.000000]  [mem 0x0c000000-0x0fbfffff] page 2M
    [    0.000000] init_memory_mapping: [mem 0x00100000-0x0bffffff]
    [    0.000000]  [mem 0x00100000-0x001fffff] page 4k
    [    0.000000]  [mem 0x00200000-0x0bffffff] page 2M
    [    0.000000] init_memory_mapping: [mem 0x0fe00000-0x0ffeffff]
    [    0.000000]  [mem 0x0fe00000-0x0ffeffff] page 4k
    [    0.000000] BRK [0x01fd4000, 0x01fd4fff] PGTABLE
    [    0.000000] RAMDISK: [mem 0x0f1e9000-0x0f385fff]
    [    0.000000] ACPI: RSDP 00000000000e8000 00024 (v02 PRLS  )
    [    0.000000] ACPI: XSDT 000000000fff0040 00034 (v01 PRLS   PRLS_OEM 00000001 INTL 20051216)
    [    0.000000] ACPI: FACP 000000000fff0100 000F4 (v03 PRLS   PRLS_OEM 00000001 INTL 20051216)
    [    0.000000] ACPI: DSDT 000000000fff0480 04377 (v02 PRLS   PRLSACPI 00001001 INTL 20051216)
    [    0.000000] ACPI: FACS 000000000fff0200 00040
    [    0.000000] ACPI: APIC 000000000fff0240 00216 (v01 PRLS   PRLS_OEM 00000001 INTL 20051216)
    [    0.000000] ACPI: Local APIC address 0xfee00000
    [    0.000000] No NUMA configuration found
    [    0.000000] Faking a node at [mem 0x0000000000000000-0x000000000ffeffff]
    [    0.000000] Initmem setup node 0 [mem 0x00000000-0x0ffeffff]
    [    0.000000]   NODE_DATA [mem 0x0ffeb000-0x0ffeffff]
    [    0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00
    [    0.000000] kvm-clock: cpu 0, msr 0:ffe7001, boot clock
    [    1.712557]  [ffffea0000000000-ffffea00003fffff] PMD -> [ffff88000ec00000-ffff88000effffff] on node 0
    [    1.712566] Zone ranges:
    [    1.712570]   DMA      [mem 0x00001000-0x00ffffff]
    [    1.712571]   DMA32    [mem 0x01000000-0xffffffff]
    [    1.712572]   Normal   empty
    [    1.712575] Movable zone start for each node
    [    1.712576] Early memory node ranges
    [    1.712577]   node   0: [mem 0x00001000-0x0009efff]
    [    1.712578]   node   0: [mem 0x00100000-0x0ffeffff]
    [    1.712580] On node 0 totalpages: 65422
    [    1.712583]   DMA zone: 64 pages used for memmap
    [    1.712584]   DMA zone: 21 pages reserved
    [    1.712586]   DMA zone: 3998 pages, LIFO batch:0
    [    1.712687]   DMA32 zone: 960 pages used for memmap
    [    1.712688]   DMA32 zone: 61424 pages, LIFO batch:15
    [    1.713883] ACPI: PM-Timer IO Port: 0x4008
    ...
    
    Afterwards there is another clock message in the dmesg output:
    Code:
    [    1.733599] kvm-clock: cpu 0, msr 0:ffe7001, primary cpu clock
    
    The switching to clocksource message is finally there after 1.95 seconds:
    Code:
    [    1.953470] Switched to clocksource kvm-clock
    
    At 2.35 second the system clock is set from rtc_cmos clock:
    Code:
    [    2.350050] rtc_cmos 00:02: setting system clock to 2014-02-11 18:09:19 UTC (1392142159)
    
    Full dmesg output: http://pastebin.com/8sQHL4zN
     
    Last edited: Feb 13, 2014

Share This Page