[Xen-devel] VM start time slows with large number of VMs

["Carb, Brian A" <Brian.Carb@xxxxxxxxxx>]

Hello,

 

We're running Xen Unstable changeset 15468 with SLES10 on a Unisys ES7000/one 56x cpu and 160GB memory.  Xen is built with NR_DYNIRQS=1024 and max_phys_cpus=64, and booted with dom0_mem=1024 and xenheap_megabytes=64. We have 320 para-virtualized SLES10 VMs on external storage.

 

Our script starts a VM, waits for the start to complete, then starts the next: "for i in *.cfg; do xm create $i; done". As more VMs start, the time to start each one increases. I've attached a config file for one of the VMs, as well as a portion of the xend.log which shows timestamps of the events for 2 VMS, vm002 and vm263.

 

The total elapsed time of the start from "create" to "unpaused" for vm002 is 13 seconds, but by the time 262 VMs are started, the start of vm263 has slowed to 238 seconds. The host itself is not sluggish, as we can open putty sessions to and interact with dom0.  However, if we run "xm top", its interface is very unresponsive.  Could writing to the xenstore be taking longer and longer? Could there be possible contention for vmlinuz and initrd since they are being used by every VM to boot? Would it be better to use bootloader/bootentry and store the vmlinuz and initrd within each VM?

 

Any insight would be appreciated.

 

brian carb

unisys corporation, malvern pa

 

----- domU config file 002.cfg -----

kernel = "/boot/vmlinuz-xen"
ramdisk = "/boot/initrd-xen"
root = "/dev/sda2 ro"
disk = [ 'phy:/tmp/xendevs/xen002,sda,w' ]
memory = 512
vcpus = 4
name = 'xen002'
vif = [ 'mac=00:16:3e:0d:a0:01' ]
ip = '10.0.27.2'
netmask = '255.254.0.0'
extra = ' xencons=tty1 3'

----- xend.log -----

[2007-09-02 05:26:42 8597] DEBUG (XendDomainInfo:78) XendDomainInfo.create(['vm', ['name', 'xen002'], ['memory', 512], ['vcpus', 4], ['on_xend_start', 'ignore'], ['on_xend_stop', 'ignore'], ['image', ['linux', ['kernel', '/boot/vmlinuz-xen'], ['ramdisk', '/boot/initrd-xen'], ['ip', '10.0.27.2:1.2.3.4::255.254.0.0::eth0:off'], ['root', '/dev/sda2 ro'], ['args', ' xencons=tty1 3']]], ['device', ['vbd', ['uname', 'phy:/tmp/xendevs/xen002'], ['dev', 'sda'], ['mode', 'w']]], ['device', ['vif', ['mac', '00:16:3e:0d:a0:01']]]])
[2007-09-02 05:26:42 8597] DEBUG (XendDomainInfo:1418) XendDomainInfo.constructDomain
[2007-09-02 05:26:42 8597] DEBUG (balloon:114) Balloon: 169819872 KiB free; need 2048; done.
[2007-09-02 05:26:43 8597] DEBUG (XendDomain:434) Adding Domain: 16
[2007-09-02 05:26:43 8597] DEBUG (XendDomainInfo:1472) XendDomainInfo.initDomain: 16 256
[2007-09-02 05:26:43 8597] DEBUG (XendDomainInfo:1503) _initDomain:shadow_memory=0x0, memory_static_max=0x20000000, memory_static_min=0x0.
[2007-09-02 05:26:43 8597] DEBUG (balloon:114) Balloon: 169819864 KiB free; need 524288; done.
[2007-09-02 05:26:43 8597] INFO (image:128) buildDomain os=linux dom=16 vcpus=4
[2007-09-02 05:26:43 8597] DEBUG (image:197) domid          = 16
[2007-09-02 05:26:43 8597] DEBUG (image:198) memsize        = 512
[2007-09-02 05:26:43 8597] DEBUG (image:199) image          = /boot/vmlinuz-xen
[2007-09-02 05:26:43 8597] DEBUG (image:200) store_evtchn   = 1
[2007-09-02 05:26:43 8597] DEBUG (image:201) console_evtchn = 2
[2007-09-02 05:26:43 8597] DEBUG (image:202) cmdline        = root=/dev/sda2 ro ip=10.0.27.2:1.2.3.4::255.254.0.0::eth0:off  xencons=tty1 3
[2007-09-02 05:26:43 8597] DEBUG (image:203) ramdisk        = /boot/initrd-xen
[2007-09-02 05:26:43 8597] DEBUG (image:204) vcpus          = 4
[2007-09-02 05:26:43 8597] DEBUG (image:205) features       =
[2007-09-02 05:26:43 8597] INFO (XendDomainInfo:1321) createDevice: vbd : {'uuid': '8d79c4ed-4ddc-afee-9725-f5c2d388a02e', 'bootable': 1, 'driver': 'paravirtualised', 'dev': 'sda', 'uname': 'phy:/tmp/xendevs/xen002', 'mode': 'w'}
[2007-09-02 05:26:43 8597] DEBUG (DevController:115) DevController: writing {'virtual-device': '2048', 'device-type': 'disk', 'protocol': 'x86_64-abi', 'backend-id': '0', 'state': '1', 'backend': '/local/domain/0/backend/vbd/16/2048'} to /local/domain/16/device/vbd/2048.
[2007-09-02 05:26:43 8597] DEBUG (DevController:117) DevController: writing {'domain': 'xen002', 'frontend': '/local/domain/16/device/vbd/2048', 'uuid': '8d79c4ed-4ddc-afee-9725-f5c2d388a02e', 'dev': 'sda', 'state': '1', 'params': '/tmp/xendevs/xen002', 'mode': 'w', 'online': '1', 'frontend-id': '16', 'type': 'phy'} to /local/domain/0/backend/vbd/16/2048.
[2007-09-02 05:26:44 8597] INFO (XendDomainInfo:1321) createDevice: vif : {'mac': '00:16:3e:0d:a0:01', 'uuid': 'bb43e84a-a9a1-7488-1ba4-3b713eff82aa'}
[2007-09-02 05:26:45 8597] DEBUG (DevController:115) DevController: writing {'mac': '00:16:3e:0d:a0:01', 'handle': '0', 'protocol': 'x86_64-abi', 'backend-id': '0', 'state': '1', 'backend': '/local/domain/0/backend/vif/16/0'} to /local/domain/16/device/vif/0.
[2007-09-02 05:26:45 8597] DEBUG (DevController:117) DevController: writing {'domain': 'xen002', 'handle': '0', 'uuid': 'bb43e84a-a9a1-7488-1ba4-3b713eff82aa', 'script': '/etc/xen/scripts/vif-bridge', 'state': '1', 'frontend': '/local/domain/16/device/vif/0', 'mac': '00:16:3e:0d:a0:01', 'online': '1', 'frontend-id': '16', 'type': 'netfront'} to /local/domain/0/backend/vif/16/0.
[2007-09-02 05:26:46 8597] DEBUG (XendDomainInfo:1978) Storing VM details: {'on_xend_stop': 'ignore', 'shadow_memory': '0', 'uuid': 'f146fdfc-e624-f7cb-4baf-0471f01f6014', 'on_reboot': 'restart', 'start_time': '1188725206.15', 'on_poweroff': 'destroy', 'on_xend_start': 'ignore', 'on_crash': 'restart', 'xend/restart_count': '0', 'vcpus': '4', 'vcpu_avail': '15', 'image': "(linux (kernel /boot/vmlinuz-xen) (ramdisk /boot/initrd-xen) (args 'root=/dev/sda2 ro ip=10.0.27.2:1.2.3.4::255.254.0.0::eth0:off  xencons=tty1 3') (notes (FEATURES 'writable_page_tables|writable_descriptor_tables|auto_translated_physmap|pae_pgdir_above_4gb|supervisor_mode_kernel') (VIRT_BASE -2147483648) (GUEST_VERSION 2.6) (PADDR_OFFSET -2147483648) (GUEST_OS linux) (HYPERCALL_PAGE -2145361920) (LOADER generic) (SUSPEND_CANCEL 1) (ENTRY -2145386496) (XEN_VERSION xen-3.0)))", 'name': 'xen002'}
[2007-09-02 05:26:46 8597] DEBUG (XendDomainInfo:823) Storing domain details: {'console/ring-ref': '34194913', 'image/entry': '-2145386496', 'console/port': '2', 'cpu/3/availability': 'online', 'store/ring-ref': '34194914', 'image/loader': 'generic', 'vm': '/vm/f146fdfc-e624-f7cb-4baf-0471f01f6014', 'control/platform-feature-multiprocessor-suspend': '1', 'cpu/2/availability': 'online', 'cpu/1/availability': 'online', 'image/features/writable-descriptor-tables': '1', 'image/virt-base': '-2147483648', 'memory/target': '524288', 'image/guest-version': '2.6', 'image/features/supervisor-mode-kernel': '1', 'image/guest-os': 'linux', 'console/limit': '1048576', 'image/paddr-offset': '-2147483648', 'image/hypercall-page': '-2145361920', 'image/suspend-cancel': '1', 'cpu/0/availability': 'online', 'image/features/pae-pgdir-above-4gb': '1', 'image/features/writable-page-tables': '1', 'image/features/auto-translated-physmap': '1', 'name': 'xen002', 'domid': '16', 'image/xen-version': 'xen-3.0', 'store/port': '1'}
[2007-09-02 05:26:50 8597] DEBUG (DevController:115) DevController: writing {'protocol': 'x86_64-abi', 'state': '1', 'backend-id': '0', 'backend': '/local/domain/0/backend/console/16/0'} to /local/domain/16/device/console/0.
[2007-09-02 05:26:50 8597] DEBUG (DevController:117) DevController: writing {'domain': 'xen002', 'protocol': 'vt100', 'uuid': '8dc5f3eb-5c78-35e1-7876-17c26fc6ad6e', 'frontend': '/local/domain/16/device/console/0', 'state': '1', 'location': '2', 'online': '1', 'frontend-id': '16'} to /local/domain/0/backend/console/16/0.
[2007-09-02 05:26:52 8597] DEBUG (DevController:148) Waiting for devices vif.
[2007-09-02 05:26:53 8597] DEBUG (DevController:153) Waiting for 0.
[2007-09-02 05:26:53 8597] DEBUG (XendDomainInfo:823) Storing domain details: {'console/ring-ref': '34194913', 'image/entry': '-2145386496', 'console/port': '2', 'cpu/3/availability': 'online', 'store/ring-ref': '34194914', 'image/loader': 'generic', 'vm': '/vm/f146fdfc-e624-f7cb-4baf-0471f01f6014', 'control/platform-feature-multiprocessor-suspend': '1', 'cpu/2/availability': 'online', 'cpu/1/availability': 'online', 'image/features/writable-descriptor-tables': '1', 'image/virt-base': '-2147483648', 'memory/target': '524288', 'image/guest-version': '2.6', 'image/features/supervisor-mode-kernel': '1', 'image/guest-os': 'linux', 'console/limit': '1048576', 'image/paddr-offset': '-2147483648', 'image/hypercall-page': '-2145361920', 'image/suspend-cancel': '1', 'cpu/0/availability': 'online', 'image/features/pae-pgdir-above-4gb': '1', 'image/features/writable-page-tables': '1', 'image/features/auto-translated-physmap': '1', 'name': 'xen002', 'domid': '16', 'image/xen-version': 'xen-3.0', 'store/port': '1'}
[2007-09-02 05:26:53 8597] DEBUG (XendDomainInfo:907) XendDomainInfo.handleShutdownWatch
[2007-09-02 05:26:53 8597] DEBUG (DevController:541) hotplugStatusCallback /local/domain/0/backend/vif/16/0/hotplug-status.
[2007-09-02 05:26:53 8597] DEBUG (DevController:555) hotplugStatusCallback 1.
[2007-09-02 05:26:54 8597] DEBUG (DevController:148) Waiting for devices usb.
[2007-09-02 05:26:54 8597] DEBUG (DevController:148) Waiting for devices vbd.
[2007-09-02 05:26:54 8597] DEBUG (DevController:153) Waiting for 2048.
[2007-09-02 05:26:54 8597] DEBUG (DevController:541) hotplugStatusCallback /local/domain/0/backend/vbd/16/2048/hotplug-status.
[2007-09-02 05:26:54 8597] DEBUG (DevController:555) hotplugStatusCallback 1.
[2007-09-02 05:26:54 8597] DEBUG (DevController:148) Waiting for devices irq.
[2007-09-02 05:26:54 8597] DEBUG (DevController:148) Waiting for devices vkbd.
[2007-09-02 05:26:54 8597] DEBUG (DevController:148) Waiting for devices vfb.
[2007-09-02 05:26:55 8597] DEBUG (DevController:148) Waiting for devices console.
[2007-09-02 05:26:55 8597] DEBUG (DevController:153) Waiting for 0.
[2007-09-02 05:26:55 8597] DEBUG (DevController:148) Waiting for devices pci.
[2007-09-02 05:26:55 8597] DEBUG (DevController:148) Waiting for devices ioports.
[2007-09-02 05:26:55 8597] DEBUG (DevController:148) Waiting for devices tap.
[2007-09-02 05:26:55 8597] DEBUG (DevController:148) Waiting for devices vtpm.
[2007-09-02 05:26:55 8597] INFO (XendDomain:1117) Domain xen002 (16) unpaused.

...

... [vms xen003 to xen262 deleted]

...

[2007-09-02 17:44:28 8597] DEBUG (XendDomainInfo:78) XendDomainInfo.create(['vm', ['name', 'xen263'], ['memory', 512], ['vcpus', 4], ['on_xend_start', 'ignore'], ['on_xend_stop', 'ignore'], ['image', ['linux', ['kernel', '/boot/vmlinuz-xen'], ['ramdisk', '/boot/initrd-xen'], ['ip', '10.0.29.63:1.2.3.4::255.254.0.0::eth0:off'], ['root', '/dev/sda2 ro'], ['args', ' xencons=tty1 3']]], ['device', ['vbd', ['uname', 'phy:/tmp/xendevs/xen263'], ['dev', 'sda'], ['mode', 'w']]], ['device', ['vif', ['mac', '00:16:3e:0d:a0:01']]]])
[2007-09-02 17:44:28 8597] DEBUG (XendDomainInfo:1418) XendDomainInfo.constructDomain
[2007-09-02 17:44:28 8597] DEBUG (balloon:114) Balloon: 32978616 KiB free; need 2048; done.
[2007-09-02 17:44:28 8597] DEBUG (XendDomain:434) Adding Domain: 277
[2007-09-02 17:44:28 8597] DEBUG (XendDomainInfo:1472) XendDomainInfo.initDomain: 277 256
[2007-09-02 17:44:29 8597] DEBUG (XendDomainInfo:1503) _initDomain:shadow_memory=0x0, memory_static_max=0x20000000, memory_static_min=0x0.
[2007-09-02 17:44:29 8597] DEBUG (balloon:114) Balloon: 32978608 KiB free; need 524288; done.
[2007-09-02 17:44:29 8597] INFO (image:128) buildDomain os=linux dom=277 vcpus=4
[2007-09-02 17:44:29 8597] DEBUG (image:197) domid          = 277
[2007-09-02 17:44:29 8597] DEBUG (image:198) memsize        = 512
[2007-09-02 17:44:29 8597] DEBUG (image:199) image          = /boot/vmlinuz-xen
[2007-09-02 17:44:29 8597] DEBUG (image:200) store_evtchn   = 1
[2007-09-02 17:44:29 8597] DEBUG (image:201) console_evtchn = 2
[2007-09-02 17:44:29 8597] DEBUG (image:202) cmdline        = root=/dev/sda2 ro ip=10.0.29.63:1.2.3.4::255.254.0.0::eth0:off  xencons=tty1 3
[2007-09-02 17:44:29 8597] DEBUG (image:203) ramdisk        = /boot/initrd-xen
[2007-09-02 17:44:29 8597] DEBUG (image:204) vcpus          = 4
[2007-09-02 17:44:29 8597] DEBUG (image:205) features       =
[2007-09-02 17:44:30 8597] INFO (XendDomainInfo:1321) createDevice: vbd : {'uuid': '9d639202-73af-64ec-451d-3abe0fc57bc7', 'bootable': 1, 'driver': 'paravirtualised', 'dev': 'sda', 'uname': 'phy:/tmp/xendevs/xen263', 'mode': 'w'}
[2007-09-02 17:44:30 8597] DEBUG (DevController:115) DevController: writing {'virtual-device': '2048', 'device-type': 'disk', 'protocol': 'x86_64-abi', 'backend-id': '0', 'state': '1', 'backend': '/local/domain/0/backend/vbd/277/2048'} to /local/domain/277/device/vbd/2048.
[2007-09-02 17:44:30 8597] DEBUG (DevController:117) DevController: writing {'domain': 'xen263', 'frontend': '/local/domain/277/device/vbd/2048', 'uuid': '9d639202-73af-64ec-451d-3abe0fc57bc7', 'dev': 'sda', 'state': '1', 'params': '/tmp/xendevs/xen263', 'mode': 'w', 'online': '1', 'frontend-id': '277', 'type': 'phy'} to /local/domain/0/backend/vbd/277/2048.
[2007-09-02 17:44:30 8597] INFO (XendDomainInfo:1321) createDevice: vif : {'mac': '00:16:3e:0d:a0:01', 'uuid': 'a126d815-fd4a-332b-c881-235a7e003cfb'}
[2007-09-02 17:45:02 8597] DEBUG (DevController:115) DevController: writing {'mac': '00:16:3e:0d:a0:01', 'handle': '0', 'protocol': 'x86_64-abi', 'backend-id': '0', 'state': '1', 'backend': '/local/domain/0/backend/vif/277/0'} to /local/domain/277/device/vif/0.
[2007-09-02 17:45:02 8597] DEBUG (DevController:117) DevController: writing {'domain': 'xen263', 'handle': '0', 'uuid': 'a126d815-fd4a-332b-c881-235a7e003cfb', 'script': '/etc/xen/scripts/vif-bridge', 'state': '1', 'frontend': '/local/domain/277/device/vif/0', 'mac': '00:16:3e:0d:a0:01', 'online': '1', 'frontend-id': '277', 'type': 'netfront'} to /local/domain/0/backend/vif/277/0.
[2007-09-02 17:45:56 8597] DEBUG (XendDomainInfo:1978) Storing VM details: {'on_xend_stop': 'ignore', 'shadow_memory': '0', 'uuid': '8f8f9839-dd61-b9cd-89a6-f66bb3d41726', 'on_reboot': 'restart', 'start_time': '1188769556.11', 'on_poweroff': 'destroy', 'on_xend_start': 'ignore', 'on_crash': 'restart', 'xend/restart_count': '0', 'vcpus': '4', 'vcpu_avail': '15', 'image': "(linux (kernel /boot/vmlinuz-xen) (ramdisk /boot/initrd-xen) (args 'root=/dev/sda2 ro ip=10.0.29.63:1.2.3.4::255.254.0.0::eth0:off  xencons=tty1 3') (notes (FEATURES 'writable_page_tables|writable_descriptor_tables|auto_translated_physmap|pae_pgdir_above_4gb|supervisor_mode_kernel') (VIRT_BASE -2147483648) (GUEST_VERSION 2.6) (PADDR_OFFSET -2147483648) (GUEST_OS linux) (HYPERCALL_PAGE -2145361920) (LOADER generic) (SUSPEND_CANCEL 1) (ENTRY -2145386496) (XEN_VERSION xen-3.0)))", 'name': 'xen263'}
[2007-09-02 17:45:58 8597] DEBUG (XendDomainInfo:823) Storing domain details: {'console/ring-ref': '5227479', 'image/entry': '-2145386496', 'console/port': '2', 'cpu/3/availability': 'online', 'store/ring-ref': '5227480', 'image/loader': 'generic', 'vm': '/vm/8f8f9839-dd61-b9cd-89a6-f66bb3d41726', 'control/platform-feature-multiprocessor-suspend': '1', 'cpu/2/availability': 'online', 'cpu/1/availability': 'online', 'image/features/writable-descriptor-tables': '1', 'image/virt-base': '-2147483648', 'memory/target': '524288', 'image/guest-version': '2.6', 'image/features/supervisor-mode-kernel': '1', 'image/guest-os': 'linux', 'console/limit': '1048576', 'image/paddr-offset': '-2147483648', 'image/hypercall-page': '-2145361920', 'image/suspend-cancel': '1', 'cpu/0/availability': 'online', 'image/features/pae-pgdir-above-4gb': '1', 'image/features/writable-page-tables': '1', 'image/features/auto-translated-physmap': '1', 'name': 'xen263', 'domid': '277', 'image/xen-version': 'xen-3.0', 'store/port': '1'}
[2007-09-02 17:47:25 8597] DEBUG (DevController:115) DevController: writing {'protocol': 'x86_64-abi', 'state': '1', 'backend-id': '0', 'backend': '/local/domain/0/backend/console/277/0'} to /local/domain/277/device/console/0.
[2007-09-02 17:47:25 8597] DEBUG (DevController:117) DevController: writing {'domain': 'xen263', 'protocol': 'vt100', 'uuid': 'd0da45dd-1a00-da65-61dd-66dadd6e9897', 'frontend': '/local/domain/277/device/console/0', 'state': '1', 'location': '2', 'online': '1', 'frontend-id': '277'} to /local/domain/0/backend/console/277/0.
[2007-09-02 17:47:26 8597] DEBUG (XendDomainInfo:823) Storing domain details: {'console/ring-ref': '5227479', 'image/entry': '-2145386496', 'console/port': '2', 'cpu/3/availability': 'online', 'store/ring-ref': '5227480', 'image/loader': 'generic', 'vm': '/vm/8f8f9839-dd61-b9cd-89a6-f66bb3d41726', 'control/platform-feature-multiprocessor-suspend': '1', 'cpu/2/availability': 'online', 'cpu/1/availability': 'online', 'image/features/writable-descriptor-tables': '1', 'image/virt-base': '-2147483648', 'memory/target': '524288', 'image/guest-version': '2.6', 'image/features/supervisor-mode-kernel': '1', 'image/guest-os': 'linux', 'console/limit': '1048576', 'image/paddr-offset': '-2147483648', 'image/hypercall-page': '-2145361920', 'image/suspend-cancel': '1', 'cpu/0/availability': 'online', 'image/features/pae-pgdir-above-4gb': '1', 'image/features/writable-page-tables': '1', 'image/features/auto-translated-physmap': '1', 'name': 'xen263', 'domid': '277', 'image/xen-version': 'xen-3.0', 'store/port': '1'}
[2007-09-02 17:47:27 8597] DEBUG (XendDomainInfo:907) XendDomainInfo.handleShutdownWatch
[2007-09-02 17:48:23 8597] DEBUG (DevController:148) Waiting for devices vif.
[2007-09-02 17:48:23 8597] DEBUG (DevController:153) Waiting for 0.
[2007-09-02 17:48:23 8597] DEBUG (DevController:541) hotplugStatusCallback /local/domain/0/backend/vif/277/0/hotplug-status.
[2007-09-02 17:48:23 8597] DEBUG (DevController:555) hotplugStatusCallback 1.
[2007-09-02 17:48:24 8597] DEBUG (DevController:148) Waiting for devices usb.
[2007-09-02 17:48:24 8597] DEBUG (DevController:148) Waiting for devices vbd.
[2007-09-02 17:48:24 8597] DEBUG (DevController:153) Waiting for 2048.
[2007-09-02 17:48:25 8597] DEBUG (DevController:541) hotplugStatusCallback /local/domain/0/backend/vbd/277/2048/hotplug-status.
[2007-09-02 17:48:25 8597] DEBUG (DevController:555) hotplugStatusCallback 1.
[2007-09-02 17:48:25 8597] DEBUG (DevController:148) Waiting for devices irq.
[2007-09-02 17:48:25 8597] DEBUG (DevController:148) Waiting for devices vkbd.
[2007-09-02 17:48:25 8597] DEBUG (DevController:148) Waiting for devices vfb.
[2007-09-02 17:48:26 8597] DEBUG (DevController:148) Waiting for devices console.
[2007-09-02 17:48:26 8597] DEBUG (DevController:153) Waiting for 0.
[2007-09-02 17:48:26 8597] DEBUG (DevController:148) Waiting for devices pci.
[2007-09-02 17:48:26 8597] DEBUG (DevController:148) Waiting for devices ioports.
[2007-09-02 17:48:26 8597] DEBUG (DevController:148) Waiting for devices tap.
[2007-09-02 17:48:26 8597] DEBUG (DevController:148) Waiting for devices vtpm.
[2007-09-02 17:48:26 8597] INFO (XendDomain:1117) Domain xen263 (277) unpaused.

_______________________________________________
Xen-devel mailing list
Xen-devel@xxxxxxxxxxxxxxxxxxx
http://lists.xensource.com/xen-devel