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

3. 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