• Some users have recently had their accounts hijacked. It seems that the now defunct EVGA forums might have compromised your password there and seems many are using the same PW here. We would suggest you UPDATE YOUR PASSWORD and TURN ON 2FA for your account here to further secure it. None of the compromised accounts had 2FA turned on.
    Once you have enabled 2FA, your account will be updated soon to show a badge, letting other members know that you use 2FA to protect your account. This should be beneficial for everyone that uses FSFT.

Slow Power-On VM response time

jimphreak

jimphreak

[H]ard|Gawd
Joined
Nov 27, 2012
Messages
1,714
I just built a new ESXi 5.5 server and I'm noticing a weird issue with regard to when I manually power on a guest VM.

Every time I manually power on a VM the process takes exactly 45 seconds to complete. I'm referring to the time the VMware task itself takes to complete not how long it takes the guest OS to startup. After that 45 seconds I then see the OS booting normally in the console.

However when I power down a VM the task completes immediate. Since it takes 45 seconds for the task to complete every time I'm assuming it's a setting somewhere but I've never seen this one before on my previous ESXi server builds.
 
That's not a setting, sounds like it's having trouble creating the locks. What is your storage?
 
Ok, so local storage shouldn't struggle with locks at all - single heartbeat region, single metadata update.

What's the host? You doing VT-D or anything unusual? Is this all VMs?
 
It's the same with all VM's, they take EXACTLY 45 seconds for the power-on task to complete before the VM will start to load the OS.

Host is as follows:

Supermicro X10SDV-TLN4F board
Intel Xeon D-1540 CPU
32GB Samsung DDR4-2133 ECC RAM
Samsung SM951 M.2. 512GB SSD
2 x Intel 730 480GB SSDs
16GB SATA DOM SSD (ESXi loaded on this)
IBM ServeRAID M1015

I do have the M1015 in passthrough but it's not currently assigned to any VM's (going to be for my unRAID VM that I haven't created yet).
 
Those are the new Xeon SoCs, right?

Power one on, and once it starts to come up, look at vmkernel (/var/log/vmkernel.log) - what's it say in there?
 
vmkernal.log for that time period.

2015-06-05T18:04:25.614Z cpu14:40668 opID=d2d0b1ae)World: 14296: VC opID 6FF200CA-00000283 maps to vmkernel opID d2d0b1ae
2015-06-05T18:04:25.614Z cpu14:40668 opID=d2d0b1ae)Config: 346: "SIOControlFlag2" = 1, Old Value: 0, (Status: 0x0)
2015-06-05T18:04:25.628Z cpu12:62048)MemSched: vm 62048: 8313: extended swap to 8192 pgs
2015-06-05T18:04:40.005Z cpu0:40669)World: 14296: VC opID 6FF200CA-00000287 maps to vmkernel opID 3f049cb5
2015-06-05T18:04:54.401Z cpu10:40671)World: 14296: VC opID hostd-8eec maps to vmkernel opID 16591777
2015-06-05T18:05:00.002Z cpu10:40671)World: 14296: VC opID hostd-f2eb maps to vmkernel opID 4219ebc9
2015-06-05T18:05:10.846Z cpu0:62048)World: vm 62173: 1462: Starting world vmm0:SPE-ADSVR of type 8
2015-06-05T18:05:10.846Z cpu0:62048)Sched: vm 62173: 6410: Adding world 'vmm0:SPE-ADSVR', group 'host/user', cpu: shares=-3 min=0 minLimit=-1 max=-1, mem: shares=-3 min=0 minLimit=-1 max=-1
2015-06-05T18:05:10.846Z cpu0:62048)Sched: vm 62173: 6425: renamed group 57086 to vm.62048
2015-06-05T18:05:10.846Z cpu0:62048)Sched: vm 62173: 6442: group 57086 is located under group 4
2015-06-05T18:05:10.847Z cpu0:62048)MemSched: vm 62048: 8313: extended swap to 28148 pgs
2015-06-05T18:05:10.859Z cpu0:62048)World: vm 62175: 1462: Starting world vmm1:SPE-ADSVR of type 8
2015-06-05T18:05:10.911Z cpu8:62048)VSCSI: 3868: handle 8202(vscsi0:0):Creating Virtual Device for world 62173 (FSS handle 832202) numBlocks=83886080 (bs=512)
2015-06-05T18:05:10.911Z cpu8:62048)VSCSI: 271: handle 8202(vscsi0:0):Input values: res=0 limit=-1 bw=-1 Shares=-1
2015-06-05T18:05:10.971Z cpu1:62173)VMMVMKCall: 224: Received INIT from world 62173
2015-06-05T18:05:10.980Z cpu12:62173)LSI: 1993: LSI: Initialized rings for scsi0 async=1, record=0 replay=0
2015-06-05T18:05:10.980Z cpu15:62175)VMMVMKCall: 224: Received INIT from world 62175
2015-06-05T18:05:11.001Z cpu1:40669)Config: 346: "SIOControlFlag2" = 0, Old Value: 1, (Status: 0x0)
2015-06-05T18:05:11.558Z cpu4:62173)VSCSI: 2443: handle 8202(vscsi0:0):Reset request on FSS handle 832202 (0 outstanding commands) from (vmm0:SPE-ADSVR)
2015-06-05T18:05:11.558Z cpu0:32939)VSCSI: 2724: handle 8202(vscsi0:0):Reset [Retries: 0/0] from (vmm0:SPE-ADSVR)
2015-06-05T18:05:11.558Z cpu0:32939)VSCSI: 2517: handle 8202(vscsi0:0):Completing reset (0 outstanding commands)
2015-06-05T18:05:15.257Z cpu5:62173)VSCSI: 2443: handle 8202(vscsi0:0):Reset request on FSS handle 832202 (0 outstanding commands) from (vmm0:SPE-ADSVR)
2015-06-05T18:05:15.257Z cpu0:32939)VSCSI: 2724: handle 8202(vscsi0:0):Reset [Retries: 0/0] from (vmm0:SPE-ADSVR)
2015-06-05T18:05:15.257Z cpu0:32939)VSCSI: 2517: handle 8202(vscsi0:0):Completing reset (0 outstanding commands)
2015-06-05T18:05:20.003Z cpu0:40669)World: 14296: VC opID 6FF200CA-00000291 maps to vmkernel opID ba64d8e
Click to expand...


And here is the hostd.log file for that same time period:

2015-06-05T18:04:25.612Z [305C2B70 verbose 'Default' opID=6FF200CA-00000283 user=root] AdapterServer: target='vim.VirtualMachine:6', method='powerOn'
2015-06-05T18:04:25.612Z [305C2B70 info 'Vimsvc.TaskManager' opID=6FF200CA-00000283 user=root] Task Created : haTask-6-vim.VirtualMachine.powerOn-234315436
2015-06-05T18:04:25.613Z [30940B70 verbose 'Vmsvc.vm:/vmfs/volumes/556cf4c0-ac9e0c62-b240-0025905cf4ec/SPE-ADSVR/Server 2012 R2.vmx' opID=6FF200CA-00000283 user=root] Power on request received
2015-06-05T18:04:25.613Z [30940B70 verbose 'Vmsvc.vm:/vmfs/volumes/556cf4c0-ac9e0c62-b240-0025905cf4ec/SPE-ADSVR/Server 2012 R2.vmx' opID=6FF200CA-00000283 user=root] Reconfigure ethernet backing if required
2015-06-05T18:04:25.613Z [30940B70 info 'Vimsvc.ha-eventmgr' opID=6FF200CA-00000283 user=root] Event 135 : SPE-ADSVR on host localhost.spe in ha-datacenter is starting
2015-06-05T18:04:25.614Z [30940B70 info 'Vmsvc.vm:/vmfs/volumes/556cf4c0-ac9e0c62-b240-0025905cf4ec/SPE-ADSVR/Server 2012 R2.vmx' opID=6FF200CA-00000283 user=root] State Transition (VM_STATE_OFF -> VM_STATE_POWERING_ON)
2015-06-05T18:04:25.614Z [30940B70 verbose 'Hostsvc.HaHost' opID=6FF200CA-00000283 user=root] ModeMgr::Begin: op = normal, current = normal, count = 4
2015-06-05T18:04:25.614Z [30940B70 verbose 'Vmsvc.vm:/vmfs/volumes/556cf4c0-ac9e0c62-b240-0025905cf4ec/SPE-ADSVR/Server 2012 R2.vmx' opID=6FF200CA-00000283 user=root] Invoking interceptor:3-ha-vmsvc
SIOC: SIOC is notified not to start injector
2015-06-05T18:04:25.614Z [30940B70 verbose 'Vmsvc.vm:/vmfs/volumes/556cf4c0-ac9e0c62-b240-0025905cf4ec/SPE-ADSVR/Server 2012 R2.vmx' opID=6FF200CA-00000283 user=root] Done invoking interceptor:3-ha-vmsvc
2015-06-05T18:04:25.617Z [30940B70 verbose 'Hostsvc' opID=6FF200CA-00000283 user=root] Security domain hostd6 not found
2015-06-05T18:04:25.619Z [30940B70 info 'Libs' opID=6FF200CA-00000283 user=root] Starting vmx as /bin/vmx
2015-06-05T18:04:25.619Z [30940B70 info 'Libs' opID=6FF200CA-00000283 user=root] Starting vmx as /bin/vmx
2015-06-05T18:04:25.620Z [30940B70 verbose 'Vmsvc.vm:/vmfs/volumes/556cf4c0-ac9e0c62-b240-0025905cf4ec/SPE-ADSVR/Server 2012 R2.vmx' opID=6FF200CA-00000283 user=root] Vigor client state callback 1 success
2015-06-05T18:04:25.620Z [30940B70 info 'vm:/vmfs/volumes/556cf4c0-ac9e0c62-b240-0025905cf4ec/SPE-ADSVR/Server 2012 R2.vmx' opID=6FF200CA-00000283 user=root] VMHS: VM /vmfs/volumes/556cf4c0-ac9e0c62-b240-0025905cf4ec/SPE-ADSVR/Server 2012 R2.vmx in directory /vmfs/volumes/556cf4c0-ac9e0c62-b240-0025905cf4ec/SPE-ADSVR
2015-06-05T18:04:25.620Z [30940B70 info 'vm:/vmfs/volumes/556cf4c0-ac9e0c62-b240-0025905cf4ec/SPE-ADSVR/Server 2012 R2.vmx' opID=6FF200CA-00000283 user=root] VMHS: Exec()'ing /bin/vmx.
2015-06-05T18:04:25.623Z [30940B70 info 'Libs' opID=6FF200CA-00000283 user=root] VMHS: VMKernel_ForkExec(/bin/vmx, detached=1): status=0 pid=62048
2015-06-05T18:04:25.623Z [30940B70 info 'Libs' opID=6FF200CA-00000283 user=root] VmdbAddConnection: cnxPath=/db/connection/#2a/, cnxIx=9
2015-06-05T18:04:25.623Z [30940B70 info 'Libs' opID=6FF200CA-00000283 user=root] Vmdb_AddConnectionAsync_Secure: registered VERSION completion callback, cnx = /db/connection/#2a/
2015-06-05T18:04:25.623Z [30940B70 verbose 'Vmsvc.vm:/vmfs/volumes/556cf4c0-ac9e0c62-b240-0025905cf4ec/SPE-ADSVR/Server 2012 R2.vmx' opID=6FF200CA-00000283 user=root] PowerOn request queued
2015-06-05T18:04:25.624Z [30981B70 verbose 'Default' opID=6FF200CA-00000285 user=root] AdapterServer: target='vmodl.query.PropertyCollector:ha-property-collector', method='waitForUpdates'
2015-06-05T18:04:25.624Z [2F581B70 verbose 'Default' opID=6FF200CA-00000284 user=root] AdapterServer: target='vmodl.query.PropertyCollector:ha-property-collector', method='createFilter'
2015-06-05T18:04:25.636Z [30B40B70 verbose 'Default' opID=6FF200CA-00000286 user=root] AdapterServer: target='vmodl.query.PropertyCollector:ha-property-collector', method='waitForUpdates'
2015-06-05T18:04:26.634Z [30981B70 verbose 'Default' opID=6FF200CA-00000287 user=root] AdapterServer: target='vmodl.query.PropertyCollector:ha-property-collector', method='waitForUpdates'
2015-06-05T18:04:26.949Z [30981B70 verbose 'Solo.HttpSvc.HTTPService'] HTTP Response: Auto-completing at 567472/567472 bytes
2015-06-05T18:04:41.711Z [30981B70 verbose 'Solo.HttpSvc.HTTPService'] HTTP Response: Auto-completing at 567579/567579 bytes
2015-06-05T18:04:48.990Z [30981B70 verbose 'Solo.HttpSvc.HTTPService'] HTTP Response: Auto-completing at 567579/567579 bytes
2015-06-05T18:04:50.684Z [2F880B70 info 'vm:/vmfs/volumes/556cf4c0-ac9e0c62-b240-0025905cf4ec/SPE-ADSVR/Server 2012 R2.vmx'] Mounting VM begun.
2015-06-05T18:04:50.684Z [2F880B70 verbose 'Vmsvc.vm:/vmfs/volumes/556cf4c0-ac9e0c62-b240-0025905cf4ec/SPE-ADSVR/Server 2012 R2.vmx'] Vigor client state callback 2 success
2015-06-05T18:04:50.684Z [2F880B70 info 'vm:/vmfs/volumes/556cf4c0-ac9e0c62-b240-0025905cf4ec/SPE-ADSVR/Server 2012 R2.vmx'] Mounting virtual machine paths on connection: /db/connection/#2a/.
2015-06-05T18:04:50.686Z [2F880B70 info 'Libs'] VmdbCnxControlCb: registered SUBSCRIBE completion callback, cnx = /db/connection/#2a/
2015-06-05T18:04:51.042Z [30981B70 verbose 'Hostsvc.ResourcePool ha-root-pool'] Root pool capacity changed from 13540MHz/28527MB to 13540MHz/28525MB
2015-06-05T18:04:54.376Z [30B40B70 verbose 'Solo.HttpSvc.HTTPService'] HTTP Response: Auto-completing at 567579/567579 bytes
2015-06-05T18:05:02.179Z [30940B70 verbose 'SoapAdapter'] Responded to service state request
2015-06-05T18:05:02.307Z [30940B70 verbose 'Solo.HttpSvc.HTTPService'] HTTP Response: Auto-completing at 567781/567781 bytes
2015-06-05T18:05:10.790Z [30940B70 info 'Vmsvc.vm:/vmfs/volumes/556cf4c0-ac9e0c62-b240-0025905cf4ec/SPE-ADSVR/Server 2012 R2.vmx'] Upgrade is required for virtual machine, version: 8
2015-06-05T18:05:10.790Z [2F880B70 info 'Libs'] VigorClientStartMountCb Succeeeded
2015-06-05T18:05:10.791Z [2F880B70 info 'vm:/vmfs/volumes/556cf4c0-ac9e0c62-b240-0025905cf4ec/SPE-ADSVR/Server 2012 R2.vmx'] Mounting VM complete.
2015-06-05T18:05:10.791Z [2F880B70 verbose 'Vmsvc.vm:/vmfs/volumes/556cf4c0-ac9e0c62-b240-0025905cf4ec/SPE-ADSVR/Server 2012 R2.vmx'] Vigor client state callback 3 success
2015-06-05T18:05:10.807Z [2F581B70 verbose 'Default' opID=6FF200CA-00000288 user=root] AdapterServer: target='vmodl.query.PropertyCollector:ha-property-collector', method='waitForUpdates'
2015-06-05T18:05:10.908Z [2F581B70 verbose 'Vmsvc.vm:/vmfs/volumes/556cf4c0-ac9e0c62-b240-0025905cf4ec/SPE-ADSVR/Server 2012 R2.vmx'] MKS ready for connections: true
2015-06-05T18:05:11.001Z [2F880B70 info 'vm:Vix: [34297 foundryVMPowerOps.c:980]: FoundryVMPowerStateChangeCallback: /vmfs/volumes/556cf4c0-ac9e0c62-b240-0025905cf4ec/SPE-ADSVR/Server 2012 R2.vmx'] vmx/execState/val = poweredOn.
2015-06-05T18:05:11.001Z [2F880B70 info 'vm:Vix: [34297 foundryVMPowerOps.c:1176]: FoundryVMPowerStateChangeCallback: /vmfs/volumes/556cf4c0-ac9e0c62-b240-0025905cf4ec/SPE-ADSVR/Server 2012 R2.vmx'] opening automation socket.
2015-06-05T18:05:11.001Z [2F880B70 info 'vm:/vmfs/volumes/556cf4c0-ac9e0c62-b240-0025905cf4ec/SPE-ADSVR/Server 2012 R2.vmx'] Disconnect check in progress.
2015-06-05T18:05:11.001Z [2F581B70 info 'vm:/vmfs/volumes/556cf4c0-ac9e0c62-b240-0025905cf4ec/SPE-ADSVR/Server 2012 R2.vmx'] Connected to testAutomation-fd, remote end sent pid: 62048
2015-06-05T18:05:11.001Z [30981B70 info 'Hostsvc'] Decremented SIOC Injector Flag2
2015-06-05T18:05:11.001Z [30B40B70 verbose 'Vmsvc.vm:/vmfs/volumes/556cf4c0-ac9e0c62-b240-0025905cf4ec/SPE-ADSVR/Server 2012 R2.vmx'] registering Vigor callbacks
2015-06-05T18:05:11.016Z [30B40B70 verbose 'Vmsvc.vm:/vmfs/volumes/556cf4c0-ac9e0c62-b240-0025905cf4ec/SPE-ADSVR/Server 2012 R2.vmx'] sleepState value is 0
2015-06-05T18:05:11.016Z [30B40B70 verbose 'Vmsvc.vm:/vmfs/volumes/556cf4c0-ac9e0c62-b240-0025905cf4ec/SPE-ADSVR/Server 2012 R2.vmx'] ToolsNamespaceGenerationInfo callback received. VM state = VM_STATE_POWERING_ON
2015-06-05T18:05:11.017Z [30B40B70 verbose 'Vmsvc.vm:/vmfs/volumes/556cf4c0-ac9e0c62-b240-0025905cf4ec/SPE-ADSVR/Server 2012 R2.vmx'] Ignored toolsManifestInfo update of size 0
2015-06-05T18:05:11.018Z [30981B70 info 'Vimsvc.ha-eventmgr'] Event 136 : SPE-ADSVR on localhost.spe in ha-datacenter is powered on
2015-06-05T18:05:11.018Z [30981B70 info 'Vmsvc.vm:/vmfs/volumes/556cf4c0-ac9e0c62-b240-0025905cf4ec/SPE-ADSVR/Server 2012 R2.vmx'] State Transition (VM_STATE_POWERING_ON -> VM_STATE_ON)
2015-06-05T18:05:11.018Z [2F581B70 verbose 'Hostsvc'] Received state change for VM '6'
2015-06-05T18:05:11.019Z [30981B70 verbose 'Vmsvc.vm:/vmfs/volumes/556cf4c0-ac9e0c62-b240-0025905cf4ec/SPE-ADSVR/Server 2012 R2.vmx'] Actual VM overhead: 55853056 bytes
2015-06-05T18:05:11.019Z [2F581B70 info 'Guestsvc.GuestFileTransferImpl'] Entered VmPowerStateListener
2015-06-05T18:05:11.019Z [2F581B70 info 'Guestsvc.GuestFileTransferImpl'] VmPowerStateListener succeeded
2015-06-05T18:05:11.019Z [2F581B70 info 'Hbrsvc'] Replicator: powerstate change VM: 6 Old: 0 New: 1
2015-06-05T18:05:11.036Z [30981B70 verbose 'Vmsvc.vm:/vmfs/volumes/556cf4c0-ac9e0c62-b240-0025905cf4ec/SPE-ADSVR/Server 2012 R2.vmx'] Time to gather config: 16 (msecs)
2015-06-05T18:05:11.036Z [2FBC2B70 verbose 'Hbrsvc'] Replicator: ReconfigListener triggered for config VM 6
2015-06-05T18:05:11.038Z [30981B70 info 'Vimsvc.TaskManager'] Task Completed : haTask-6-vim.VirtualMachine.powerOn-234315436 Status success
2015-06-05T18:05:11.038Z [2F581B70 verbose 'Hbrsvc'] Replicator: Remove group no matching entry for VM (id=6)
2015-06-05T18:05:11.039Z [2FBC2B70 verbose 'Hbrsvc'] Replicator: VmReconfig ignoring VM 6 not configured for replication
2015-06-05T18:05:11.812Z [305C2B70 verbose 'Default' opID=6FF200CA-00000289 user=root] AdapterServer: target='vmodl.query.PropertyCollector:ha-property-collector', method='waitForUpdates'
2015-06-05T18:05:11.847Z [2FBC2B70 verbose 'Default' opID=6FF200CA-0000028A user=root] AdapterServer: target='vim.SessionManager:ha-sessionmgr', method='acquireCloneTicket'
2015-06-05T18:05:11.867Z [30B40B70 verbose 'Default' opID=6FF200CA-0000028B user=root] AdapterServer: target='vmodl.query.PropertyCollector.Filter:session[f91d6833-4401-190a-37bb-0a2716bad296]52ae2394-cfa9-6a7d-7809-1c944950f777', method='destroy'
2015-06-05T18:05:12.124Z [30B40B70 info 'Vimsvc.ha-eventmgr' opID=hostd-3728] Event 137 : User root@192.168.4.50 logged in as VMware-client
2015-06-05T18:05:12.258Z [30B40B70 verbose 'Locale' opID=hostd-0b88] Default resource used for 'privilege.Datastore.UpdateVirtualMachineMetadata.label' expec
Click to expand...
 
That is REALLY strange. Anything in the vmware.log for that VM? Do you have a spinning disk that you could try?
 
I don't see a vmware.log.

I don't have any spinning disks but I can try putting that VM on one of the Intel 730's and see what that does.
 
Oh I see. Let me SSH in and see. I was accessing all the other logs through a web browser.
 
Ok found it but there's no real format to the log I don't even know how to read it.

Also, moved a VM to one of the Intel 730's and it does the exact same thing.
 
Yeah, just snag and post the top 50 lines of the latest (shut it down and start it again) - that should capture anythig odd.
 
That's very strange. A few interesting lines in there - I'm wondering if it doesn't understand the new SoCs quite yet, based on one line, but it immediately falls back on a "Default Intel with X features" mode...
 
lopoetve said:
That's very strange. A few interesting lines in there - I'm wondering if it doesn't understand the new SoCs quite yet, based on one line, but it immediately falls back on a "Default Intel with X features" mode...
Click to expand...

Possibly. VMware is pretty slow with their drivers. In fact I still can't even find a VIB to be able to install the two 10Gig NICs on my board so that they are usable in ESXi right now.
 
Yeah, I know - I haven't had a chance to get my build server up to see if I can compile those for you (forgot that my current one is BSD based).
 
lopoetve said:
Yeah, I know - I haven't had a chance to get my build server up to see if I can compile those for you (forgot that my current one is BSD based).
Click to expand...

Lol I completely forgot that was you. I appreciate all the support up to this point. But I'm starting to regret not switching over to Hyper-V.
 
ESX is still better (I run both), but it's not kind with bleeding edge hardware at times.
 
I haven't run Hyper-V but I know a lot of people who do now a days. What is it to you that still separates ESXi from Hyper-V?
 
General manageability (unless using SCVMM), performance (it's still a touch better than Hyper-V, especially on marginal hardware), memory management is better on highly utilized environments, guest OS compatibility, advanced features (FT), better network management (I'm not super fond of Hyper-V, or windows for that matter, advanced networking).

It's 95% as good, but there's that last 5%. Now, I worked at VMware, so I'm certainly more familiar with it than hyper-v from that alone, but it's also simpler and easier to get started with. I currently have 4 ESXi hosts, and 2 Hyper-V (and 2 XenServer coming soon).
 
I see. I appreciate your perspective.

However for me and my home network I'm not sure most (or any) of those differences would affect me. But one thing that I know is already affecting me is having 2 of my 4 NICs unusable and I'm curious to see if I'd have this guest startup issue on Hyper-V. I have a 64GB SATA DOM on its way so maybe I'll give Hyper-V a quick test next week.
 
You must log in or register to reply here.
Back
Top