Johnny Zhang

How To Work With VMware Log Files

(Part 1 - VMotion)

Johnny Zhang


The goal for this document is how to quickly find the needed information for a VMotion event. The example of the log file are collect from VMware ESX 4.1.0 build-348481

and VMware ESXi 4.1.0 build-348481

. There maybe some differences in the earlier version of ESX logs, but the steps should be same.


Log locations:


VMware ESX 4.1.0: We care about hostd logs (/var/log/vmware/hostd*.log). Although the vmkerenl logs locate at /var/log/ will also content some information, we can safely focus on the hostd logs to find the information we need.


VMware ESXi 4.1.0: ESXi has the same hostd logs locate at /var/log/vmware/hostd*.log. However, in current version of ESXi, both vmkernel logs and hostd logs are also put into /var/log/messages*. So you can choose which one you like to work with. (I prefer /var/log/vmware/hostd*.log, since it will have less noise from other logs, and it will return the “grep” faster, just because it has less contents)


VM used in this example: Vmotion-test


Steps to work with the logs:


  1. All we need is the name of the VMotioned VM (in this example “vmotion-test”)

  2. Find the VMotion ID of this incident. The VMotion ID is a unique ID that generated for each VMotion, the ID is consistent across all logs on both source and destination ESX hosts.


“grep -i vmotion-test /var/log/vmware/hostd* | grep -i vmotionprepare | less”

In this command we are looking for the VM named “vmotion-test” from all hostd logs, and looking for the keyword “vmotionprepare” from the out put of the first “grep”. (keep in mind Linux is a case sensitive OS, we put “-i” option for the grep to make our life easier.)


Out put from this command:


hostd-11.log:[2011-04-01 15:14:34.203 F5A5AB90 info 'vm:/vmfs/volumes/4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx' opID=F6FC49D5-000007E6-d] VMotionPrepare (1301685441034055): Sending 'to' srcIp=10.21.51.137 dstIp=10.21.53.102, type=1, encrypted=false, remoteThumbprint=


hostd-11.log:[2011-04-01 15:14:34.203 F5A5AB90 info 'vm:/vmfs/volumes/4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx' opID=F6FC49D5-000007E6-d] VMotionPrepare: srcMgmtIp=10.21.49.137


hostd-11.log:[2011-04-01 15:14:34.203 F5A5AB90 info 'vm:/vmfs/volumes/4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx' opID=F6FC49D5-000007E6-d] VMotionPrepare: dstMgmtIp=10.21.49.138


hostd-11.log:[2011-04-01 15:17:09.134 F5A9BB90 info 'vm:/vmfs/volumes/4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx' opID=F6FC49D5-000008E9-59] VMotionPrepare (1301685587877584): Sending 'from' srcIp=10.21.53.102 dstIp=10.21.51.137, type=1, encrypted=false, remoteThumbprint=


hostd-11.log:[2011-04-01 15:17:09.134 F5A9BB90 info 'vm:/vmfs/volumes/4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx' opID=F6FC49D5-000008E9-59] VMotionPrepare: srcMgmtIp=10.21.49.138


hostd-11.log:[2011-04-01 15:17:09.134 F5A9BB90 info 'vm:/vmfs/volumes/4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx' opID=F6FC49D5-000008E9-59] VMotionPrepare: dstMgmtIp=10.21.49.137


hostd-11.log:[2011-04-01 15:17:58.891 F558AB90 info 'vm:/vmfs/volumes/4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx' opID=F6FC49D5-00000931-68] VMotionPrepare (1301685636815010): Sending 'to' srcIp=10.21.51.137 dstIp=10.21.51.137, type=2, encrypted=false, remoteThumbprint=


hostd-11.log:[2011-04-01 15:17:58.891 F558AB90 info 'vm:/vmfs/volumes/4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx' opID=F6FC49D5-00000931-68] VMotionPrepare: srcMgmtIp=10.21.49.137


hostd-11.log:[2011-04-01 15:17:58.891 F558AB90 info 'vm:/vmfs/volumes/4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx' opID=F6FC49D5-00000931-68] VMotionPrepare: dstMgmtIp=10.21.49.137


hostd-11.log:[2011-04-01 15:17:58.891 F558AB90 info 'vm:/vmfs/volumes/4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx' opID=F6FC49D5-00000931-68] VMotionPrepare: dstVmDirPath=/vmfs/volumes/4cc0989b-5f6597b4-5fa3-001b2132c111/Vmotion-test/



What we are looking for:

We are looking for the vmotion ID, every time there is VMotion triggered, a VMotion ID will be created first. As we can see here, there were three different VMotion happened on this VM named “vmotion-test” With ID 1301685441034055, 1301685587877584, and 1301685636815010. Now depend on which one we want to analyze, we can look into details of each VMotion. (Vcenter has a record of time for each VMotion, we can find the corresponding time on the ESX servers)


What else:

There are some good information we can see from this output. Let's use vmotion ID 1301685441034055 as the example.

Sending 'to' srcIp=10.21.51.137 dstIp=10.21.53.102

As we can see here, the log tells us we are on the source ESX host with the “Sending 'to'” statement. (You will see Sending 'from' on the destination host)

srcIp=10.21.51.137” the source VMotion IP is 10.21.51.137. (Note this is different from the Service Console IP address or management IP address on ESXi)

dstIp=10.21.53.102” The destination host VMotion IP is 10.21.53.102


VMotionPrepare: srcMgmtIp=10.21.49.137

This is the management IP of the source host

VMotionPrepare: dstMgmtIp=10.21.49.138

This is the management IP of the destination host


  1. Now we can find the details. Again use 1301685441034055 as an example

grep -i 1301685441034055 hostd* | less” (You don't have to put “less”, just a habit of my own)

In this command, we are grepping for all logs related to VMotion ID 1301685441034055.


Out put from this command: (Long out put, I will go one section at a time)

hostd-11.log:[2011-04-01 15:14:34.135 F5A5AB90 info 'VMotion' opID=F6FC49D5-000007E6-d] PrepareSourceEx [1301685441034055], VM = '32'


hostd-11.log:[2011-04-01 15:14:34.135 F5A5AB90 info 'VMotionSrc (1301685441034055)' opID=F6FC49D5-000007E6-d] VMotionEntry: migrateType = 1


hostd-11.log:[2011-04-01 15:14:34.203 F5A5AB90 verbose 'VMotionSrc (1301685441034055)' opID=F6FC49D5-000007E6-d] JrnlCreate: Created 1301685274.0


hostd-11.log:[2011-04-01 15:14:34.203 F5A5AB90 info 'vm:/vmfs/volumes/4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx' opID=F6FC49D5-000007E6-d] VMotionPrepare (1301685441034055): Sending 'to' srcIp=10.21.51.137 dstIp=10.21.53.102, type=1, encrypted=false, remoteThumbprint=


hostd-11.log:[2011-04-01 15:14:34.205 F5A5AB90 verbose 'VMotionSrc (1301685441034055)' opID=F6FC49D5-000007E6-d] Migration changed state from NONE to BEGIN


hostd-11.log:[2011-04-01 15:14:34.205 F5A5AB90 info 'VMotion' opID=F6FC49D5-000007E6-d] Completed scheduling PrepareSourceEx [1301685441034055].


hostd-11.log:[2011-04-01 15:14:34.231 F5549B90 verbose 'vm:/vmfs/volumes/4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx'] VMotionCmdCb [1301685441034055] 'to': done


hostd-11.log:[2011-04-01 15:14:34.231 F5549B90 info 'vm:/vmfs/volumes/4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx'] VMotionCmdCb [1301685441034055] : Prepare task completed successfully


hostd-11.log:[2011-04-01 15:14:35.055 F5549B90 info 'VMotion' opID=F6FC49D5-000007E6-a1] InitiateSource [1301685441034055], WID = 6947903



opID is “operation ID” some what new from engineering that to act as a debugging aid. You may not see those in the earlier version of ESX logs. This is very nice for support or whoever need to look into the logs, since this ID is designed to consistent across ESX server and vCenter logs as well. In this example you can see there are many different opIDs for the same VMotion ID.

migrateType” There are 6 different type of migrations. For what we care, the first three are:

  • migrateType = 1 VMotion

  • migrateType = 2 Storage VMotion (FSR)

  • migrateType = 3 Fault Tolerant (FT)

JrnlCreate” Every VMotion will have a journal create, in case any migration failure, the source host can rollback with the journal. The VMotion journal management is 5 steps process

  • Create

  • Begin

  • PutWID

  • End

  • Delete

Migration changed state from NONE to BEGIN

This is the beginning of the VMotion process

VmotionCmdCb” VMotion command call back is a process that update VMDB on the ESX host with the path to the VM's configuration file and vmdk files in case there was some changes on the VM. (As you can see it followed by the path to the vmx file)

InitiateSource [1301685441034055], WID = 6947903

After all the preparation and checking now the VMotion process need to find the world ID of the VM which is 6947903 in our case.


Out Put Continued:


hostd-11.log:[2011-04-01 15:14:35.221 F5549B90 verbose 'VMotionSrc (1301685441034055)' opID=F6FC49D5-000007E6-a1] JrnlBegin: VM objID=32 srcIp=10.21.51.137 migrateType=MIGRATE_TYPE_VMOTION


hostd-11.log:[2011-04-01 15:14:35.243 F5549B90 verbose 'VMotionSrc (1301685441034055)' opID=F6FC49D5-000007E6-a1] JrnlPutWid: Wrote wid=4868


hostd-11.log:[2011-04-01 15:14:35.243 F5549B90 info 'vm:/vmfs/volumes/4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx' opID=F6FC49D5-000007E6-a1] VMotionInitiateSrc (1301685441034055): wid=6947903


hostd-11.log:[2011-04-01 15:14:35.244 F5549B90 verbose 'VMotionSrc (1301685441034055)' opID=F6FC49D5-000007E6-a1] Migration changed state from BEGIN to MIGRATING


hostd-11.log:[2011-04-01 15:14:35.261 F579CB90 verbose 'vm:/vmfs/volumes/4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx'] VMotionCmdCb [1301685441034055] 'start': done


hostd-11.log:[2011-04-01 15:14:39.143 F558AB90 info 'VMotionSrc (1301685441034055)'] ResolveCb: VMX reports needsUnregister = true for migrateType MIGRATE_TYPE_VMOTION


hostd-11.log:[2011-04-01 15:14:39.143 F558AB90 info 'VMotionSrc (1301685441034055)'] ResolveCb: Succeeded


hostd-11.log:[2011-04-01 15:14:39.143 F558AB90 verbose 'VMotionSrc (1301685441034055)'] Migration changed state from MIGRATING to UNREGISTERING


hostd-11.log:[2011-04-01 15:14:39.143 F558AB90 verbose 'VMotionSrc (1301685441034055)'] Finish called


hostd-11.log:[2011-04-01 15:14:41.232 F558AB90 verbose 'VMotionSrc (1301685441034055)'] Migration changed state from UNREGISTERING to DONE


hostd-11.log:[2011-04-01 15:14:41.390 F558AB90 verbose 'VMotionSrc (1301685441034055)'] JrnlEnd: Wrote active=0


hostd-11.log:[2011-04-01 15:14:41.416 F558AB90 verbose 'VMotionSrc (1301685441034055)'] JrnlEnd: Finished journal


hostd-11.log:[2011-04-01 15:14:41.416 F558AB90 verbose 'VMotionSrc (1301685441034055)'] [JrnlFilePersistenceProvider::DeleteJournal] Deleting /var/lib/vmware/hostd/journal/1301685274.0.


hostd-11.log:[2011-04-01 15:14:41.416 F558AB90 verbose 'VMotionSrc (1301685441034055)'] JrnlDelete: Deleted journal


hostd-11.log:[2011-04-01 15:14:41.416 F558AB90 info 'VMotionSrc (1301685441034055)'] CompleteOp: Vmotion task succeeded with result:


hostd-11.log:[2011-04-01 15:14:42.468 F5A5AB90 info 'VMotion' opID=F6FC49D5-000007E6-38] CompleteSource [1301685441034055]



migrateType=MIGRATE_TYPE_VMOTION” Once again, it shows the migration type.

JrnlPutWid: Wrote wid=4868

Create a Journal world ID for this VM.

Migration changed state from BEGIN to MIGRATING

We passed the first 10%, now we are moving the memory from one host to another


The normal VMotion process is like this:

  • 00% - 05% - copy VM files (and initial pool switch if necessary)


  • 05% - 10% - copy or reconfigure VM config file


  • 10% - 95% - progress reported by destination


  • 95% - 100% - any other time needed by source, plus final sync


Storage VMotion process:

  • 00% - 00% - copy VM files (and initial pool switch if necessary)


  • 00% - 01% - copy VM config file


  • 01% - 10% - progress reported by destination


  • 10% - 10% - any other time needed by source, plus sync


  • 10% - 90% - copy disks


  • 90% - 99% - reparent/commit disks


  • 99% - 100% - delete source disks, plus final sync


VMotionCmdCb [1301685441034055] 'start': done

We are now at 95% Which the memory is moved over to the other host.

ResolveCb: VMX reports needsUnregister = true for migrateType MIGRATE_TYPE_VMOTION

Now we need to unregister the VM from this host.

ResolveCb: Succeeded Resolve the status of the VMotion operation when the VMX reports that it has completed. And here the VMX file reported success. 

Migration changed state from MIGRATING to UNREGISTERING

We are now in the unregister process.

'VMotionSrc (1301685441034055)'] Migration changed state from UNREGISTERING to DONE

The VM is now unregistered from the source host.

JrnlDelete: Deleted journal

The journal is ended and deleted.

CompleteOp: Vmotion task succeeded with result” The VM was successfully moved away from the source host.


On The Destination Host:


[2011-04-01 19:17:20.154 6AF47B90 verbose 'VMotionDst (1301685441034055)' opID=F6FC49D5-000007E6-8b] JrnlBegin: VM objID=672 srcIp=10.21.51.137 migrateType=MIGRATE_TYPE_VMOTION


[2011-04-01 19:17:20.168 6AF47B90 info 'vm:/vmfs/volumes/4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx' opID=F6FC49D5-000007E6-8b] VMotionPrepare (1301685441034055): Sending 'from' srcIp=10.21.51.137 dstIp=10.21.53.102, type=1, encrypted=false, remoteThumbprint=


[2011-04-01 19:17:20.169 6AF47B90 info 'VMotionDst (1301685441034055)' opID=F6FC49D5-000007E6-8b] Initiate: Waiting for WID


[2011-04-01 19:17:20.654 6AF47B90 verbose 'VMotionDst (1301685441034055)' opID=F6FC49D5-000007E6-8b] JrnlPutWid: Wrote wid=6947903


[2011-04-01 19:17:20.654 6AF47B90 info 'VMotionDst (1301685441034055)' opID=F6FC49D5-000007E6-8b] Initiate: Got WID 6947903


[2011-04-01 19:17:20.654 6AF47B90 verbose 'VMotionDst (1301685441034055)' opID=F6FC49D5-000007E6-8b] Migration changed state from BEGIN to MIGRATING


[2011-04-01 19:17:20.654 6A625B90 verbose 'vm:/vmfs/volumes/4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx'] VMotionCmdCb [1301685441034055] 'from': done


[2011-04-01 19:17:21.693 6A694B90 info 'VMotionDst (1301685441034055)'] ResolveCb: VMX reports needsUnregister = false for migrateType MIGRATE_TYPE_VMOTION


[2011-04-01 19:17:21.693 6A694B90 info 'VMotionDst (1301685441034055)'] ResolveCb: Succeeded


[2011-04-01 19:17:21.693 6A694B90 verbose 'VMotionDst (1301685441034055)'] Migration changed state from MIGRATING to DONE


[2011-04-01 19:17:21.693 6A694B90 verbose 'VMotionDst (1301685441034055)'] Finish called


[2011-04-01 19:17:21.693 6A694B90 verbose 'VMotionDst (1301685441034055)'] Set dest task result vm downtime to 226017


[2011-04-01 19:17:21.693 6A694B90 verbose 'VMotionDst (1301685441034055)'] Set dest task result stuntime 0


[2011-04-01 19:17:21.694 6A694B90 verbose 'VMotionDst (1301685441034055)'] Set dest task result pageSrcTime to 0


[2011-04-01 19:17:21.694 6A694B90 verbose 'VMotionDst (1301685441034055)'] Set dest task result remotePageFaults 0


[2011-04-01 19:17:21.734 6A694B90 verbose 'VMotionDst (1301685441034055)'] JrnlEnd: Wrote active=0


[2011-04-01 19:17:21.738 6A694B90 verbose 'VMotionDst (1301685441034055)'] JrnlEnd: Finished journal


[2011-04-01 19:17:21.738 6A694B90 verbose 'VMotionDst (1301685441034055)'] [JrnlFilePersistenceProvider::DeleteJournal] Deleting /var/lib/vmware/hostd/journal/1301685439.0.


[2011-04-01 19:17:21.739 6A694B90 verbose 'VMotionDst (1301685441034055)'] JrnlDelete: Deleted journal


[2011-04-01 19:17:21.739 6A694B90 info 'VMotionDst (1301685441034055)'] CompleteOp: Vmotion task succeeded with result: (vim.host.VMotionManager.VMotionResult) {


[2011-04-01 19:17:32.842 6ACFEB90 info 'VMotion' opID=F6FC49D5-000007E6-45] CompleteDestination [1301685441034055]



We will skip the duplications.

ResolveCb: VMX reports needsUnregister = false for migrateType MIGRATE_TYPE_VMOTION

Here, since this is destination host, which the VM will be running, that's why needsUnregister = false.

Set dest task result vm downtime to 226017

This is the “down” time for the VM during VMotion (You will not see this in versions before 4.1, but I will show you where you can find the information later) The down time is in microsecond, so for my VMotion test, the down time was 0.226 seconds.

Set dest task result vm downtime to 226017

” “ Set dest task result pageSrcTime to 0

” “Set dest task result remotePageFaults 0

Because my test VM has nothing in it, so the page in time was really fast. You may see different numbers depends on how busy is the VM, but nothing to be alert of if you see something different.

CompleteOp: Vmotion task succeeded with result: (vim.host.VMotionManager.VMotionResult)” “ CompleteDestination” VMotion process finished on destination host.


VMware.log files:


You may see many vmware.log files under the VM directory, use the same VMotion ID to find which logs is useful to us. As summing you are in the VM's directory already


grep -i 1301685441034055 vmware* | less” Here is the output


vmware-1.log:Apr 01 15:14:34.205: vmx| Received migrate 'to' request for mid id 1301685441034055, src ip <10.21.51.137>, dst ip <10.21.53.102>.


vmware-1.log:Apr 01 15:14:34.230: vmx| MigrateSetInfo: state=1 srcIp=<10.21.51.137> dstIp=<10.21.53.102> mid=1301685441034055 uuid=34353939-3630-4d58-5138-353141344d36 priority=high


vmware-1.log:Apr 01 15:14:35.244: vmx| Received migrate 'start' request for mig id 1301685441034055, dest world id 6947903.


vmware-1.log:Apr 01 15:14:35.691: vmx| Migrate_Open: Migrating to <10.21.53.102> with migration id 1301685441034055


vmware-2.log:Apr 01 19:17:20.422: vmx| Received migrate 'from' request for mid id 1301685441034055, src ip <10.21.51.137>.


vmware-2.log:Apr 01 19:17:20.423: vmx| MigrateSetInfo: state=7 srcIp=<10.21.51.137> dstIp=<10.21.53.102> mid=1301685441034055 uuid=34353939-3630-4d58-5139-30334132594b priority=high


vmware-2.log:Apr 01 19:17:21.369: vmx| Migrate_Open: Restoring from <10.21.51.137> with migration id 1301685441034055


vmware-2.log:Apr 01 19:17:21.472: vmx| Migrate_Open: Restoring from <10.21.51.137> with migration id 1301685441034055



We can see there are two logs that may help us vmware-1.log and vmware-2.log. It shows the information we already know from hostd log. Now let's take a closer look at the vmware.log file.

less vmware-1.log” and find the starting point “/1301685441034055” this should lead us to the starting point


Apr 01 15:14:34.205: vmx| Received migrate 'to' request for mid id 1301685441034055, src ip <10.21.51.137>, dst ip <10.21.53.102>.


Apr 01 15:14:34.230: vmx| MigrateSetInfo: state=1 srcIp=<10.21.51.137> dstIp=<10.21.53.102> mid=1301685441034055 uuid=34353939-3630-4d58-5138-353141344d36 priority=high


Apr 01 15:14:34.230: vmx| MigrateSetState: Transitioning from state 0 to 1.


Apr 01 15:14:35.244: vmx| VMXVmdbCbVmVmxMigrate: Got SET callback for /vm/#_VMX/vmx/migrateState/cmd/##1_72/op/=start


Apr 01 15:14:35.244: vmx| VMXVmdbVmVmxMigrateGetStartParam: mid=49fe042527747 dstwid=6947903


Apr 01 15:14:35.244: vmx| Received migrate 'start' request for mig id 1301685441034055, dest world id 6947903.



The VMotion process will wait for the destination world ID before start to migrate.


Apr 01 15:14:35.534: vcpu-0| Migrate: Preparing to suspend.


Apr 01 15:14:35.534: vcpu-0| CPT current = 0, requesting 1


Apr 01 15:14:35.534: vcpu-0| Migrate: VM stun started, waiting 100 seconds for go/no-go message.



By default, the VMotion time out set 100 seconds, if the destination host's VMotion network cannot be reached more than 100 seconds, the VMotion will fail.


Apr 01 15:14:35.930: vmx| Migrate: Powering off


Apr 01 15:14:35.930: vmx| Stopping VCPU threads...


Apr 01 15:14:35.931: vcpu-0| VMMon_WaitForExit: vcpu-0: worldID=4868


Apr 01 15:14:35.931: vcpu-1| VMMon_WaitForExit: vcpu-1: worldID=4870


Apr 01 15:14:37.094: mks| Ending MKSRole pseudocalls, state was 1


Apr 01 15:14:37.094: mks| Async MKS thread is exiting


Apr 01 15:14:37.094: vmx| Vix: [104867 mainDispatch.c:907]: VMAutomation_PowerOff: Powering off.


Apr 01 15:14:37.118: vmx| VMXVmdb_SetToolsVersionState: status value set to 'ok'


Apr 01 15:14:37.118: vmx| Migrate: cleaning up migration state.


Apr 01 15:14:37.118: vmx| MigrateSetState: Transitioning from state 5 to 0.


Apr 01 15:14:37.120: vmx| MKSHostOps_HideCursor before defineCursor!


Apr 01 15:14:37.125: vmx| Virtual Device for scsi0:0 was already successfully destroyed


Apr 01 15:14:37.150: vmx| MKS local poweroff



We should able to tell from the logs, after the migration, there are some clean up steps. Stopping the VCPU threads, and power off the MKS (mouse, keyboard, screen)


Apr 01 15:14:39.046: vmx| VMX idle exit


Apr 01 15:14:39.055: vmx| VMIOP: Exit


Apr 01 15:14:39.056: vmx| Vix: [104867 mainDispatch.c:652]: VMAutomation_LateShutdown()


Apr 01 15:14:39.056: vmx| Vix: [104867 mainDispatch.c:602]: VMAutomationCloseListenerSocket. Closing listener socket.


Apr 01 15:14:39.065: vmx| Flushing VMX VMDB connections


Apr 01 15:14:39.075: vmx| VMX exit (0).


Apr 01 15:14:39.075: vmx| AIOMGR-S : stat o=2 r=6 w=0 i=0 br=98304 bw=0


Apr 01 15:14:39.075: vmx| VMX has left the building: 0.



More clean up updating VMDB, and at the end “VMX has left the building: 0.

This is not a bad message. You will see this for every VMotion process. Just show the VMotion completed.


VPXD logs:


The logs are located in %ALLUSERSPROFILE%\Application Data\VMware\VMware VirtualCenter\Logs, which translates to C:\Documents and Settings\All Users\Application Data\VMware\VirtualCenter\logs in Windows 2003 and C:\ProgramData\VMware\VMware VirtualCenter\Logs in Windows 2008.


We do the same grep with vpxd-xx.log

grep -i 1301685441034055 vpxd*.log | less” Here we got the vCenter information for this VMotion process


vpxd-83.log:[2011-04-01 15:17:21.040 03364 info 'App' opID=F6FC49D5-000007E6] [MIGRATE] (1301685441034055) VMotion started


vpxd-83.log:[2011-04-01 15:17:21.040 03364 info 'App' opID=F6FC49D5-000007E6] [MIGRATE] (1301685441034055) VM: Vmotion-test (/vpx/vm/#369/)


vpxd-83.log:[2011-04-01 15:17:21.040 03364 info 'App' opID=F6FC49D5-000007E6] [MIGRATE] (1301685441034055) host: bs-bcs-h137.bsl.vmware.com (/vpx/host/#261/) -> bs-bcs-h138.bsl.vmware.com (/vpx/host/#227/)


vpxd-83.log:[2011-04-01 15:17:21.040 03364 info 'App' opID=F6FC49D5-000007E6] [MIGRATE] (1301685441034055) pool: Resources (/vpx/resgroup/#27/) -> Resources (/vpx/resgroup/#27/)


vpxd-83.log:[2011-04-01 15:17:21.483 03364 info 'App' opID=F6FC49D5-000007E6] [MIGRATE] (1301685441034055) config: sanfs://vmfs_uuid:4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx -> sanfs://vmfs_uuid:4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx


vpxd-83.log:[2011-04-01 15:17:21.483 03364 info 'App' opID=F6FC49D5-000007E6] [MIGRATE] (1301685441034055) vmotion IP: 10.21.51.137 -> 10.21.53.102


vpxd-83.log:[2011-04-01 15:17:21.483 03364 info 'App' opID=F6FC49D5-000007E6] [MIGRATE] (1301685441034055) mgmt IP: 10.21.49.137 -> 10.21.49.138


MIGRATE] (1301685441034055) VM: Vmotion-test (/vpx/vm/#369/)

Here we can see the virtual machine ID in vCenter database (#369)


host: bs-bcs-h137.bsl.vmware.com (/vpx/host/#261/) -> bs-bcs-h138.bsl.vmware.com (/vpx/host/#227/)

In vCenter 4.1 the log is nice enough to give you the host ID in vCenter database. In our case, bs-bcs-h137 (#261) is the source and bs-bcs-h138 (#227) is the destination


config: sanfs://vmfs_uuid:4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx -> sanfs://vmfs_uuid:4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx

Once again we can see this is a VMotion process, since the path to the configuration file did not change. Storage VMotion will have different path.


What Else Is Useful?

ESX/ESXi hosts will keep a list of VMotion until a reboot occur. You can find the list under /proc


ESX: /proc/vmware/migration/history


less -RS /proc/vmware/migration/history”


id status | Total PreCopy Quiesce CptXfer CptLoad PageIn DownTime


1301685636815010 (#3) vm 4881: Ok migrating to <10.21.51.137> | 3.609013 1.500298 N/A N/A N/A N/A N/A


1301685636815010 (#2) vm 4894: Ok migrating from <10.21.51.137> | 3.890556 N/A N/A N/A 0.281297 N/A N/A


1301685587877584 (#1) vm 4881: Ok migrating from <10.21.53.102> | 1.554031 0.755715 N/A 0.133118 0.368116 0.001499 0.503789


1301685441034055 (#0) vm 4868: Ok migrating to <10.21.53.102> | 0.666448 0.277901 0.159037 0.037974 N/A 0.005203 N/A



The part we are interested in is the last column, which is the down time of the VM during VMotion. So why we are seeing “N/A” here? Because this is the source host, it will not know the down time of the migration. This is another way to find out which one is the source host and which one is the destination host. If you look at the line above (in bold) you can see the downtime for that VMotion was 0.5 seconds


ESXi: /proc/migration/rawTS


Labels: edit post
6 Responses


  1. Anonymous Says:

    Its really a good one keep posting new log analysis that would help people like us good job, 5 stars for this blog


  2. Anonymous Says:

    Its really informative, thanks for this blog


  3. Gans Says:

    really nice info ..and also we can check the vmotion history by login in to the datastore in which the VM is running and search the vmware log of the VM grep -i MigrateSetInfo vmware*


  4. Anonymous Says:

    What the hell is with the page layout.


Post a Comment

There was an error in this gadget