Highlighted
Contributor
Contributor

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

Jump to solution

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!).

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

    }

Screenshots to show consistency.

B3azV.png

fU0r2.png

EimXR.png

All 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

Tags (1)
0 Kudos
1 Solution

Accepted Solutions
Highlighted
Contributor
Contributor

The issue was DNS and (specifically licensing check), configuring a local/fast DNS server solved the delays.

View solution in original post

0 Kudos
3 Replies
Highlighted
Expert
Expert

Quick and logic questions:

All hosts are configured exactly the same? Did you check it with Host Profiles for example?

Also, did you test your local disks, I mean, the real IOPS with any tool like FIFO or something?

-------------------------------------------------------- "I greet each challenge with expectation"
0 Kudos
Highlighted
Contributor
Contributor

I get 646 MB/s on the disks, no issues there.

I don't use host profiles, the servers are default except for power options set to performance.

0 Kudos
Highlighted
Contributor
Contributor

The issue was DNS and (specifically licensing check), configuring a local/fast DNS server solved the delays.

View solution in original post

0 Kudos