Home / server / Questions / 936809
Accepted
Jacob Evans
Asked: 2018-10-24 06:39:53 +0800 CST

VMware power-on is delayed on some but not all hosts, same hardware (1 second vs 16 seconds)

  • 772

I'm having a strange issue that I hope someone else has come across it, hostd.log doesn't show any information except to confirm the boot time is slower (16 seconds!).

vmware Power On events

Using this script.

for ($i=1; $i -le 25; $i++)
{
Start-VM -VM $(Get-VM 'vHost01 Test') -Confirm:$false
Start-VM -VM $(Get-VM 'vHost02 Test') -Confirm:$false
Start-VM -VM $(Get-VM 'vHost03 Test') -Confirm:$false
sleep -seconds 2
Stop-VM -VM $(Get-VM 'vHost01 Test') -Confirm:$false
Stop-VM -VM $(Get-VM 'vHost02 Test') -Confirm:$false
Stop-VM -VM $(Get-VM 'vHost03 Test') -Confirm:$false
sleep -seconds 2
}

additional Screenshots to show consistency. enter image description here enter image description here enter image description here

Both systems have local nvme disks, 2.1Ghz gold procs, and are booting a new & empty vm, same hardware versions, same os patch, same everything.

Systems all running VMware ESXi, 6.7.0, 10302608

Each Server is configured exactly the same: (1) SD w/ESXi installed (1) NVMe SSD for Datastore, all datastores are local. (2) Intel Gold 2.1Ghz 6130 Processors 768 GB of DDR4 RAM

Host1

12788-auto-112789-h5c:70032863-28-02-01-13-f9e3 user=vpxuser:VSPHERE.LOCAL\Administrator] State Transition (VM_STATE_OFF -> VM_STATE_POWERING_ON)
2018-10-23T14:26:35.376Z info hostd[2100207] [Originator@6876 sub=Libs opID=14bb9f56-84b2-4978-9cd2-bd86db47993f-112788-auto-112789-h5c:70032863-28-02-01-13-f9e3 user=vpxuser:VSPHERE.LOCAL\Administrator] SIOC: SIOC is notified not to start injector
2018-10-23T14:26:35.376Z warning hostd[2100207] [Originator@6876 sub=Hostsvc.Tpm20Provider opID=14bb9f56-84b2-4978-9cd2-bd86db47993f-112788-auto-112789-h5c:70032863-28-02-01-13-f9e3 user=vpxuser:VSPHERE.LOCAL\Administrator] Unable to retrieve TPM/TXT status. TPM functionality will be unavailable. Failure reason: Unable to get node: Sysinfo error: Not foundSee VMkernel log for details..
2018-10-23T14:26:35.378Z info hostd[2100207] [Originator@6876 sub=Libs opID=14bb9f56-84b2-4978-9cd2-bd86db47993f-112788-auto-112789-h5c:70032863-28-02-01-13-f9e3 user=vpxuser:VSPHERE.LOCAL\Administrator] DictionaryLoad: Cannot open file "/usr/lib/vmware/config": No such file or directory.
2018-10-23T14:26:35.378Z info hostd[2100207] [Originator@6876 sub=Libs opID=14bb9f56-84b2-4978-9cd2-bd86db47993f-112788-auto-112789-h5c:70032863-28-02-01-13-f9e3 user=vpxuser:VSPHERE.LOCAL\Administrator] Could not expand environment variable HOME.
2018-10-23T14:26:35.378Z info hostd[2100207] [Originator@6876 sub=Libs opID=14bb9f56-84b2-4978-9cd2-bd86db47993f-112788-auto-112789-h5c:70032863-28-02-01-13-f9e3 user=vpxuser:VSPHERE.LOCAL\Administrator] DictionaryLoad: Cannot open file "~/.vmware/config": No such file or directory.
2018-10-23T14:26:35.380Z info hostd[2100207] [Originator@6876 sub=Libs opID=14bb9f56-84b2-4978-9cd2-bd86db47993f-112788-auto-112789-h5c:70032863-28-02-01-13-f9e3 user=vpxuser:VSPHERE.LOCAL\Administrator] Found vmx as /bin/vmx
2018-10-23T14:26:35.380Z info hostd[2100207] [Originator@6876 sub=Libs opID=14bb9f56-84b2-4978-9cd2-bd86db47993f-112788-auto-112789-h5c:70032863-28-02-01-13-f9e3 user=vpxuser:VSPHERE.LOCAL\Administrator] Starting vmx as /bin/vmx
2018-10-23T14:26:35.380Z info hostd[2100207] [Originator@6876 sub=vm opID=14bb9f56-84b2-4978-9cd2-bd86db47993f-112788-auto-112789-h5c:70032863-28-02-01-13-f9e3 user=vpxuser:VSPHERE.LOCAL\Administrator] VigorExecVMXExCommon: VM /vmfs/volumes/5b9bb253-6d8a5196-5fdc-ac1f6b0e6418/New Virtual Machine/New Virtual Machine.vmx in directory /vmfs/volumes/5b9bb253-6d8a5196-5fdc-ac1f6b0e6418/New Virtual Machine
2018-10-23T14:26:35.380Z info hostd[2100207] [Originator@6876 sub=vm opID=14bb9f56-84b2-4978-9cd2-bd86db47993f-112788-auto-112789-h5c:70032863-28-02-01-13-f9e3 user=vpxuser:VSPHERE.LOCAL\Administrator] VigorExecVMXExCommon: Exec()'ing /bin/vmx /vmfs/volumes/5b9bb253-6d8a5196-5fdc-ac1f6b0e6418/New Virtual Machine/New Virtual Machine.vmx.
2018-10-23T14:26:35.381Z info hostd[2100207] [Originator@6876 sub=Libs opID=14bb9f56-84b2-4978-9cd2-bd86db47993f-112788-auto-112789-h5c:70032863-28-02-01-13-f9e3 user=vpxuser:VSPHERE.LOCAL\Administrator] Vigor: VMKernel_ForkExec(/bin/vmx, detached=1): status=0 pid=2110313
2018-10-23T14:26:35.765Z info hostd[2099717] [Originator@6876 sub=Vimsvc.ha-eventmgr] Event 223 : New Virtual Machine on  localhost in ha-datacenter is powered on

Host2 (and host3)

12788-auto-112789-h5c:70032863-28-01-01-82-212a user=vpxuser:VSPHERE.LOCAL\Administrator] State Transition (VM_STATE_OFF -> VM_STATE_POWERING_ON)
2018-10-23T07:26:44.667Z info hostd[2099611] [Originator@6876 sub=Libs opID=14bb9f56-84b2-4978-9cd2-bd86db47993f-112788-auto-112789-h5c:70032863-28-01-01-82-212a user=vpxuser:VSPHERE.LOCAL\Administrator] SIOC: SIOC is notified not to start injector
2018-10-23T07:26:44.667Z warning hostd[2099611] [Originator@6876 sub=Hostsvc.Tpm20Provider opID=14bb9f56-84b2-4978-9cd2-bd86db47993f-112788-auto-112789-h5c:70032863-28-01-01-82-212a user=vpxuser:VSPHERE.LOCAL\Administrator] Unable to retrieve TPM/TXT status. TPM functionality will be unavailable. Failure reason: Unable to get node: Sysinfo error: Not foundSee VMkernel log for details..
2018-10-23T07:26:44.669Z info hostd[2099611] [Originator@6876 sub=Libs opID=14bb9f56-84b2-4978-9cd2-bd86db47993f-112788-auto-112789-h5c:70032863-28-01-01-82-212a user=vpxuser:VSPHERE.LOCAL\Administrator] DictionaryLoad: Cannot open file "/usr/lib/vmware/config": No such file or directory.
2018-10-23T07:26:44.669Z info hostd[2099611] [Originator@6876 sub=Libs opID=14bb9f56-84b2-4978-9cd2-bd86db47993f-112788-auto-112789-h5c:70032863-28-01-01-82-212a user=vpxuser:VSPHERE.LOCAL\Administrator] Could not expand environment variable HOME.
2018-10-23T07:26:44.669Z info hostd[2099611] [Originator@6876 sub=Libs opID=14bb9f56-84b2-4978-9cd2-bd86db47993f-112788-auto-112789-h5c:70032863-28-01-01-82-212a user=vpxuser:VSPHERE.LOCAL\Administrator] DictionaryLoad: Cannot open file "~/.vmware/config": No such file or directory.
2018-10-23T07:26:44.671Z info hostd[2099611] [Originator@6876 sub=Libs opID=14bb9f56-84b2-4978-9cd2-bd86db47993f-112788-auto-112789-h5c:70032863-28-01-01-82-212a user=vpxuser:VSPHERE.LOCAL\Administrator] Found vmx as /bin/vmx
2018-10-23T07:26:44.671Z info hostd[2099611] [Originator@6876 sub=Libs opID=14bb9f56-84b2-4978-9cd2-bd86db47993f-112788-auto-112789-h5c:70032863-28-01-01-82-212a user=vpxuser:VSPHERE.LOCAL\Administrator] Starting vmx as /bin/vmx
2018-10-23T07:26:44.671Z info hostd[2099611] [Originator@6876 sub=vm opID=14bb9f56-84b2-4978-9cd2-bd86db47993f-112788-auto-112789-h5c:70032863-28-01-01-82-212a user=vpxuser:VSPHERE.LOCAL\Administrator] VigorExecVMXExCommon: VM /vmfs/volumes/5b9bb26a-d53a0f08-9b51-ac1f6b0e6454/New Virtual Machine/New Virtual Machine.vmx in directory /vmfs/volumes/5b9bb26a-d53a0f08-9b51-ac1f6b0e6454/New Virtual Machine
2018-10-23T07:26:44.671Z info hostd[2099611] [Originator@6876 sub=vm opID=14bb9f56-84b2-4978-9cd2-bd86db47993f-112788-auto-112789-h5c:70032863-28-01-01-82-212a user=vpxuser:VSPHERE.LOCAL\Administrator] VigorExecVMXExCommon: Exec()'ing /bin/vmx /vmfs/volumes/5b9bb26a-d53a0f08-9b51-ac1f6b0e6454/New Virtual Machine/New Virtual Machine.vmx.
2018-10-23T07:26:44.672Z info hostd[2099611] [Originator@6876 sub=Libs opID=14bb9f56-84b2-4978-9cd2-bd86db47993f-112788-auto-112789-h5c:70032863-28-01-01-82-212a user=vpxuser:VSPHERE.LOCAL\Administrator] Vigor: VMKernel_ForkExec(/bin/vmx, detached=1): status=0 pid=2107626
2018-10-23T07:27:00.067Z info hostd[2100473] [Originator@6876 sub=Vimsvc.ha-eventmgr] Event 131 : New Virtual Machine on  localhost in ha-datacenter is powered on
vmware-esxi

1 Answers

  1. Best Answer

    It was DNS, I'll need to pull a pcap but when rebooting vcenter recently the issue came back, our systems are disconnected from the internet but dns was configured for a public server when doing updates. Changing dns to the internal server and the issue went away, however no new dns requests have been seen.

    • 0