How vMotion Works

 

오늘은 정상적인 vMotion 수행 시 Source/Destination ESXi Host 및 vCenter에서 로그가 어떻게 기록되는지 알아보고자 합니다.

 

[참조 로그]

vCenter의 vpxd.log --> Log Level을 Verbose로 설정

Source/Destination ESXi의 vmkernel.log

Virtual Machine의 vmware.log

 

[구성 환경]

Source vMotion IP : 192.1681.22 / compesxi02.contoso.com

Destination vMotion IP : 192.168.1.23 / compesxi03.contoso.com

Guest OS : CentOS 7.9

VM Name : test

 

[진행 순서]

vmware.log에서 vMotion은 12개 State로 구분

 

Stage0 → Stage1

 

vmware.log

vmware.log 파일에서 OpId와 MigrationID를 확인

opID=lgfd4abh-18745-auto-egq-h5:70005734-88-01

srcIp=<192.168.1.22>

dstIp=<192.168.1.23>

MigrationID=0x7958EA7F2D34D435(0n8743996508480001077)

2023-04-15T08:52:34.879Z In(05) vmx - VigorTransportProcessClientPayload: opID=lgfd4abh-18745-auto-egq-h5:70005734-88-01-39-6b81 seq=10304: Receiving Migrate.PrepareSource request. 2023-04-15T08:52:34.879Z In(05) vmx - MigrateVMXdrToSpec: type: 1 srcIp=<192.168.1.22> dstIp=<192.168.1.23> mid=7958ea7f2d34d435 uuid=920c4d56-7808-0d0d-4c93-719b81b66bc3 priority=yes checksumMemory=no maxDowntime=0 latencyAware=yes diskOpFile= srcLogIp=<<unknown>> dstLogIp=<<unknown>> ftPrimaryIp=<<unknown>> ftSecondaryIp=<<unknown>>   2023-04-15T08:52:34.879Z In(05) vmx - Received migrate 'to' request for mid id 8743996508480001077, src ip <192.168.1.22>, dst ip <192.168.1.23>(invalidate source config). 2023-04-15T08:52:34.879Z In(05) vmx - MigrateSetInfo: state=1 srcIp=<192.168.1.22> dstIp=<192.168.1.23> mid=8743996508480001077 uuid=920c4d56-7808-0d0d-4c93-719b81b66bc3 priority=high 2023-04-15T08:52:34.879Z In(05) vmx - MigrateSetState: Transitioning from state 0 to 1.

 

vmkernel.log : source

vmware.log에서 확인한 opID와 MigrationID로 로그 시작 위치 확인

opID=lgfd4abh-18745-auto-egq-h5:70005734-88-01

MigrationID=8743996508480001077

2023-04-15T08:52:34.878Z cpu9:1050641 opID=12cebd2d)World: 12077: VC opID lgfd4abh-18745-auto-egq-h5:70005734-88-01-39-6b81 maps to vmkernel opID 12cebd2d 2023-04-15T08:52:34.878Z cpu9:1050641 opID=12cebd2d)Config: 756: "SIOControlFlag2" = 1, Old Value: 0, (Status: 0x0)   2023-04-15T08:52:37.490Z cpu3:1997449 opID=a673558d)Migrate: 319: vmotion: Source vmmLeaderID = 1997450, ts = 8743996508480001077, srcIP = <192.168.1.22> dstIP = <192.168.1.23> Dest wid = 2047460 using SHARED swap, encrypted 2023-04-15T08:52:37.490Z cpu3:1997449 opID=a673558d)Migrate: 662: 8743996508480001077 S: Used default migrate heap of size 61960384 bytes (computed 15204566 bytes) 2023-04-15T08:52:37.490Z cpu3:1997449 opID=a673558d)VMotionStream: 350: 8743996508480001077 S: vMotion stream helper count: 1. 2023-04-15T08:52:37.490Z cpu3:1997449 opID=a673558d)Migrate: 102: 8743996508480001077 S: MigrateState: Starting migration off 2023-04-15T08:52:37.490Z cpu3:1997449 opID=a673558d)Hbr: 3721: Migration start received (worldID=1997450) (migrateType=1) (event=0) (isSource=1) (sharedConfig=1) 2023-04-15T08:52:37.491Z cpu0:2015310)MigrateNet: 1753: 8743996508480001077 S: Successfully bound connection to vmknic vmk0 - '192.168.1.22'

 

vpxd.log

vmware.log에서 확인한 opID로 Task 시작 로그 확인

2023-04-15T08:52:35.722Z info vpxd[07296] [Originator@6876 sub=vpxLro opID=lgfd4abh-18745-auto-egq-h5:70005734-88-01] [VpxLRO] -- BEGIN lro-783889 -- vm-1013 -- vim.VirtualMachine.relocate -- 525183a9-bece-3a06-29ed-b7d125b3b826(52235c64-5e68-3844-e1d2-96ee26d1b305)   2023-04-15T08:52:35.728Z info vpxd[07296] [Originator@6876 sub=VmProv opID=lgfd4abh-18745-auto-egq-h5:70005734-88-01] Local-VC Host Migrate of poweredOn VM 'test' (vm-1013, ds:///vmfs/volumes/642e536a-5c6bdcef-fdd9-000c292e88b6/test/test.vmx) on host-31 (192.168.1.22) in pool resgroup-12 with ds ds:///vmfs/volumes/642e536a-5c6bdcef-fdd9-000c292e88b6/ to host-34 (192.168.1.23) in pool resgroup-12 with ds ds:///vmfs/volumes/642e536a-5c6bdcef-fdd9-000c292e88b6/ with migId 8743996508480001077   ## There are network prechecks where network pings and MUT checks are done. This happens VMK's during Stage 0 and 1 2023-04-15T08:52:35.741Z verbose vpxd[07296] [Originator@6876 sub=VmProv opID=lgfd4abh-18745-auto-egq-h5:70005734-88-01] Use default management IP for NFC copy   2023-04-15T08:52:35.744Z verbose vpxd[07296] [Originator@6876 sub=Default opID=lgfd4abh-18745-auto-egq-h5:70005734-88-01] MigrateUtil::GetStreamIps: srcVNic vmk0 has speed 10000 2023-04-15T08:52:35.744Z verbose vpxd[07296] [Originator@6876 sub=Default opID=lgfd4abh-18745-auto-egq-h5:70005734-88-01] MigrateUtil::GetStreamIps: dstVNic vmk0 has speed 10000 2023-04-15T08:52:35.744Z verbose vpxd[07296] [Originator@6876 sub=Default opID=lgfd4abh-18745-auto-egq-h5:70005734-88-01] MigrateUtil::GetStreamIps: Added 192.168.1.22->192.168.1.23   ## This is the time when VMX files are accessed and created for source and destination VM 2023-04-15T08:52:35.767Z verbose vpxd[07296] [Originator@6876 sub=TxnMgr opID=lgfd4abh-18745-auto-egq-h5:70005734-88-01] [VMOTION_RECOVER] VpxdTxnManager received request to mark VM ID vm-1013 with state 1, src URL ds:///vmfs/volumes/642e536a-5c6bdcef-fdd9-000c292e88b6/test/test.vmx, dest URL ds:///vmfs/volumes/642e536a-5c6bdcef-fdd9-000c292e88b6/test/test.vmx 2023-04-15T08:52:35.767Z verbose vpxd[07296] [Originator@6876 sub=VmProv opID=lgfd4abh-18745-auto-egq-h5:70005734-88-01] Preparing source for VMotion

 

Stage1 → Stage2

 

vmware.log

2023-04-15T08:52:34.903Z In(05) vmx - VigorTransport_ServerSendResponse opID=lgfd4abh-18745-auto-egq-h5:70005734-88-01-39-6b81 seq=10304: Completed Migrate request. 2023-04-15T08:52:37.487Z In(05) vmx - VigorTransportProcessClientPayload: opID=lgfd4abh-18745-auto-egq-h5:70005734-88-01-9b-6b89 seq=10313: Receiving Migrate.MigrateSource request. 2023-04-15T08:52:37.487Z In(05) vmx - Received migrate 'start' request for mig id 8743996508480001077, dest world id 2047460. 2023-04-15T08:52:37.487Z In(05) vmx - MigrateSetState: Transitioning from state 1 to 2.

 

vpxd.log

2023-04-15T08:52:35.863Z verbose vpxd[07296] [Originator@6876 sub=VmProv opID=lgfd4abh-18745-auto-egq-h5:70005734-88-01] Successfully prepared VMotion on source   2023-04-15T08:52:35.868Z verbose vpxd[07296] [Originator@6876 sub=VmProv opID=lgfd4abh-18745-auto-egq-h5:70005734-88-01] Preparing destination for VMotion 2023-04-15T08:52:35.894Z verbose vpxd[07296] [Originator@6876 sub=VmProv opID=lgfd4abh-18745-auto-egq-h5:70005734-88-01] Initiating VMotion on destination 2023-04-15T08:52:38.411Z verbose vpxd[07296] [Originator@6876 sub=Vmomi opID=lgfd4abh-18745-auto-egq-h5:70005734-88-01] [ClientAdapterBase::InvokeOnSoap] Invoke done (compesxi03.contoso.com, vim.host.VMotionManager.initiateDestination) 2023-04-15T08:52:38.411Z verbose vpxd[07296] [Originator@6876 sub=VmProv opID=lgfd4abh-18745-auto-egq-h5:70005734-88-01] VMotion dstwid = 2047460   2023-04-15T08:52:38.420Z verbose vpxd[07296] [Originator@6876 sub=VmProv opID=lgfd4abh-18745-auto-egq-h5:70005734-88-01] Initiating VMotion on source vim.HostSystem:host-31 2023-04-15T08:52:38.422Z verbose vpxd[07296] [Originator@6876 sub=Vmomi opID=lgfd4abh-18745-auto-egq-h5:70005734-88-01] [ClientAdapterBase::InvokeOnSoap] Invoke done (compesxi02.contoso.com, vim.host.VMotionManager.initiateSourceEx) 2023-04-15T08:52:38.422Z verbose vpxd[07296] [Originator@6876 sub=VmProv opID=lgfd4abh-18745-auto-egq-h5:70005734-88-01] VMotion successfully initiated on source

 

vmkernel.log : source

vMotion을 하기 위한 연결이 생성

2023-04-15T08:52:37.492Z cpu10:1049204)MigrateNet: vm 1049204: 3232: Accepted connection from <::ffff:192.168.1.23> 2023-04-15T08:52:37.492Z cpu10:1049204)MigrateNet: vm 1049204: 3320: dataSocket 0x43135faca640 receive buffer size is 563272 2023-04-15T08:52:37.492Z cpu10:1049204)VMotionServer: 305: Remote machine is ESX 6.5 or newer. 2023-04-15T08:52:37.492Z cpu0:2015310)VMotion: 6793: 8743996508480001077 S: Using 1 threads for streaming 2023-04-15T08:52:37.492Z cpu0:2015310)MigrateNet: 1753: 8743996508480001077 S: Successfully bound connection to vmknic vmk0 - '192.168.1.22' 2023-04-15T08:52:37.492Z cpu0:2015310)VMotionUtil: 5180: 8743996508480001077 S: Stream connection 1 added.

 

vmkernel.log : destination

Destination 쪽도 마찬가지로 vMotion을 하기 위한 연결이 생성

2023-04-15T08:52:38.746Z cpu4:1049210)MigrateNet: vm 1049210: 3232: Accepted connection from <::ffff:192.168.1.22> 2023-04-15T08:52:38.746Z cpu4:1049210)MigrateNet: vm 1049210: 3320: dataSocket 0x4313e22c7a70 receive buffer size is 563272 2023-04-15T08:52:38.746Z cpu4:1049210)VMotionServer: 305: Remote machine is ESX 6.5 or newer. 2023-04-15T08:52:38.746Z cpu11:2047473)MigrateNet: 1753: 8743996508480001077 D: Successfully bound connection to vmknic vmk0 - '192.168.1.23' 2023-04-15T08:52:38.747Z cpu1:2047474)VMotion: 6793: 8743996508480001077 D: Using 1 threads for streaming 2023-04-15T08:52:38.747Z cpu4:1049210)MigrateNet: vm 1049210: 3232: Accepted connection from <::ffff:192.168.1.22> 2023-04-15T08:52:38.747Z cpu4:1049210)MigrateNet: vm 1049210: 3320: dataSocket 0x4313e20db350 receive buffer size is 563272 2023-04-15T08:52:38.747Z cpu4:1049210)VMotionServer: 305: Remote machine is ESX 6.5 or newer. 2023-04-15T08:52:38.747Z cpu4:1049210)VMotionUtil: 5180: 8743996508480001077 D: Stream connection 1 added.

 

Stage2 → Stage3

 

vmware.log

2023-04-15T08:52:37.494Z In(05) vmx - MigratePrepareEventLog: Prepare multiwriter disk handoff complete. 2023-04-15T08:52:37.496Z In(05) vmx - MigratePrepareEventLog: Prepare destination complete. 2023-04-15T08:52:37.496Z In(05) vmx - MigratePrepareEventLog: Prepare vPMem Regions complete. 2023-04-15T08:52:37.496Z In(05) vmx - MigratePrepareEventLog: vPMem DLC update complete. 2023-04-15T08:52:37.496Z In(05) vmx - MigratePrepareEventLog: Prepare event complete. 2023-04-15T08:52:37.496Z In(05) vmx - MigrateSetState: Transitioning from state 2 to 3.

 

vpxd.log

vCenter를 data transfer를 위한 statelock을 update하고 Destination 쪽에 vmx 파일 생성

2023-04-15T08:52:50.196Z verbose vpxd[07296] [Originator@6876 sub=StateLock opID=lgfd4abh-18745-auto-egq-h5:70005734-88-01] Updating statelock data for entity test. Old parent: compesxi02.contoso.com; New parent: compesxi03.contoso.com 2023-04-15T08:52:50.196Z verbose vpxd[07296] [Originator@6876 sub=DAS opID=lgfd4abh-18745-auto-egq-h5:70005734-88-01] Move VM: [vim.VirtualMachine:vm-1013,test], Old Host: [vim.HostSystem:host-31,compesxi02.contoso.com], Old Cluster: [vim.ClusterComputeResource:domain-c11,Cluster], New Host: [vim.HostSystem:host-34,compesxi03.contoso.com], New Cluster: [vim.ClusterComputeResource:domain-c11,Cluster] 2023-04-15T08:52:50.196Z verbose vpxd[07296] [Originator@6876 sub=DAS opID=lgfd4abh-18745-auto-egq-h5:70005734-88-01] Move VM: [vim.VirtualMachine:vm-1013,test], Powered-On: true, Protected: true, Source DAS Enabled: true, Target DAS Enabled: true, Same-Cluster: true Action index: 31   2023-04-15T08:52:50.196Z verbose vpxd[07296] [Originator@6876 sub=InvtVmDb opID=lgfd4abh-18745-auto-egq-h5:70005734-88-01] Saving fields for [vim.VirtualMachine:vm-1013,test] ds:///vmfs/volumes/642e536a-5c6bdcef-fdd9-000c292e88b6/test/test.vmx 3   2023-04-15T08:52:50.199Z verbose vpxd[07234] [Originator@6876 sub=alarmMo opID=lgfd4abh-18745-auto-egq-h5:70005734-88-01] [ProcessEntityRelocated] Entity has been relocated: vm-1013

 

vmkernel.log : source

2023-04-15T08:52:47.857Z cpu13:1997450)VMotion: 4746: 8743996508480001077 S: Stopping pre-copy: only 451 pages left to send, which can be sent within the switchover time goal of 0.500 seconds (network bandwidth ~367.878 MB/s, 230002% t2d)

 

vmkernel.log : destination

2023-04-15T08:52:49.161Z cpu1:2047474)VMotionRecv: 780: 8743996508480001077 D: Estimated network bandwidth 367.884 MB/s during pre-copy

 

Stage3 → Stage4

 

vmware.log

2023-04-15T08:52:47.906Z In(05) vcpu-0 - MigrateSetState: Transitioning from state 3 to 4. 2023-04-15T08:52:47.906Z In(05) vcpu-0 - Migrate: Preparing to suspend. 2023-04-15T08:52:47.906Z In(05) vcpu-0 - Migrate: VM starting stun, waiting 100 seconds for go/no-go message.

 

vmkernel.log : source

Guest OS의 modified page를 모두 보냈기 때문에 이제 Source 쪽 VM을 Power Down 하기 전 작업이 완료

2023-04-15T08:52:48.045Z cpu0:2015310)VMotionSend: 5055: 8743996508480001077 S: Sent all modified pages to destination (network bandwidth ~122.353 MB/s)

 

vmkernel.log : destination

2023-04-15T08:52:49.249Z cpu1:2047474)Migrate: 102: 8743996508480001077 D: MigrateState: Transferring cpt data 2023-04-15T08:52:49.277Z cpu1:2047474)Migrate: 102: 8743996508480001077 D: MigrateState: Loading cpt data 2023-04-15T08:52:49.281Z cpu11:2047473)NetDVS: 5818: Restore checkpoints to shadows legacy successful 2023-04-15T08:52:49.281Z cpu11:2047473)VMotionSend: 3974: 8743996508480001077 D: Processed changeBitmap: encodingType=1 dataLength=5128 remotePages=641 2023-04-15T08:52:49.281Z cpu11:2047473)Migrate: 102: 8743996508480001077 D: MigrateState: transfering changed pages 2023-04-15T08:52:49.301Z cpu1:2047474)VMotionRecv: 3245: 8743996508480001077 D: DONE paging in 2023-04-15T08:52:49.301Z cpu1:2047474)VMotionRecv: 3253: 8743996508480001077 D: Estimated network bandwidth 111.814 MB/s during page-in

 

Stage4 → Stage5

 

vmware.log

Checkpoint 보관 완료

2023-04-15T08:52:47.998Z In(05) vcpu-0 - Progress 3% (none) ... ... ... 2023-04-15T08:52:48.021Z In(05) vcpu-0 - Progress 101% (none) 2023-04-15T08:52:48.021Z In(05) vcpu-0 - Migrate: VM successfully stunned. 2023-04-15T08:52:48.022Z In(05) vcpu-0 - MigrateSetState: Transitioning from state 4 to 5. 2023-04-15T08:52:48.022Z In(05) vcpu-0 - Closing all the disks of the VM. 2023-04-15T08:52:48.039Z In(05) worker-1997456 - Migrate: Remote Log: Destination waited for 10.57 seconds. 2023-04-15T08:52:48.039Z In(05) worker-1997456 - Migrate: Remote Log: Beginning checkpoint restore. 2023-04-15T08:52:48.039Z In(05) worker-1997456 - Migrate: Remote Log: Switching to checkpoint state.

 

vmkernel.log : destination

2023-04-15T08:52:49.492Z cpu1:2047458)VSCSI: 4752: handle 8793773739876353(GID:8193)(vscsi0:0):Creating Virtual Device for world 2047460 (FSS handle 11001408820) numBlocks=33554432 (bs=512) 2023-04-15T08:52:49.493Z cpu1:2047458)VSCSI: 273: handle 8793773739876353(GID:8193)(vscsi0:0):Input values: res=0 limit=-2 bw=-1 Shares=1000

 

Stage5 → Stage6

 

vmware.log

2023-04-15T08:52:48.444Z In(05) vmx - MigrateSetStateFinished: type=1 new state=6 2023-04-15T08:52:48.444Z In(05) vmx - MigrateSetState: Transitioning from state 5 to 6. 2023-04-15T08:52:48.444Z In(05) vmx - Migrate: Powering off 2023-04-15T08:52:48.444Z In(05) vmx - VigorTransport_ServerSendResponse opID=lgfd4abh-18745-auto-egq-h5:70005734-88-01-9b-6b89 seq=10313: Completed Migrate request with messages. 2023-04-15T08:52:48.444Z In(05) vmx - Stopping VCPU threads...

 

vmkernel.log : source

Source 쪽에 VM의 Network Port 비활성화

2023-04-15T08:52:48.447Z cpu1:1997449)NetPort: 1810: disabled port 0x400000d 2023-04-15T08:52:48.447Z cpu1:1997449)Net: 3614: disconnected client from port 0x400000d 2023-04-15T08:52:48.448Z cpu1:1997449)Hbr: 3815: Migration end received (worldID=1997450) (migrateType=1) (event=1) (isSource=1) (sharedConfig=1)

 

vmkernel.log : destination

이제 Destination 쪽의 VM에 Network 연결

2023-04-15T08:52:49.526Z cpu8:2047619)Net: 2184: connected test eth0 to VM Network, portID 0x400000d 2023-04-15T08:52:49.529Z cpu8:2047619)Vmxnet3: 14062: indLROPktToGuest: 1, vcd->umkShared->vrrsSelected: 2 port 0x400000d 2023-04-15T08:52:49.529Z cpu8:2047619)Vmxnet3: 14329: Using default queue delivery for vmxnet3 for port 0x400000d 2023-04-15T08:52:49.529Z cpu8:2047619)Vmxnet3: 1727: UPT feature is disabled. 2023-04-15T08:52:49.529Z cpu8:2047619)NetPort: 1543: enabled port 0x400000d with mac 00:50:56:b2:e1:4d 2023-04-15T08:52:49.533Z cpu8:2047460)VMotion: 6188: 8743996508480001077 D: Received all changed pages. 2023-04-15T08:52:49.577Z cpu8:2047460)Migrate: 102: 8743996508480001077 D: MigrateState: Complete 2023-04-15T08:52:49.581Z cpu8:2047460)VMotion: 5963: 8743996508480001077 D: Resume handshake successful

 

Stage6 → Stage7

 

vmware.log

Source 쪽의 VM은 Power Off 되는 지점

2023-04-15T08:52:48.448Z In(05) vmx - Migrate: cleaning up migration state. 2023-04-15T08:52:48.448Z In(05) vmx - MigrateSetState: Transitioning from state 6 to 0. 2023-04-15T08:52:48.448Z In(05) vmx - SVMotion_PowerOff: Not running Storage vMotion. Nothing to do   2023-04-15T08:52:48.472Z Wa(03) vmx - VMX has left the building: 0.

 

Stage0 → Stage8

이 단계는 Source 쪽의 VM이 Power Off 되고 나서 Destination 쪽의 VM이 Power On 되어 신규 vmware.log가 기록되기 시작

 

vmware.log

2023-04-15T08:52:38.624Z In(05) vmx - Received migrate 'from' request for mid id 8743996508480001077, src ip <192.168.1.22>. 2023-04-15T08:52:38.625Z In(05) vmx - MigrateSetInfo: state=8 srcIp=<192.168.1.22> dstIp=<192.168.1.23> mid=8743996508480001077 uuid=49184d56-f006-65a0-a642-6f16d3b555c4 priority=high 2023-04-15T08:52:38.625Z In(05) vmx - MigrateSetState: Transitioning from state 0 to 8.

 

vmkernel.log : destination

Destination 쪽에서 Power On 되는 VM과 연관된 Thread인 World가 생성

2023-04-15T08:52:38.664Z cpu9:2047458)World: vm 2047460: 6957: Starting world vmm0:test of type 8 2023-04-15T08:52:38.664Z cpu9:2047458)Sched: vm 2047460: 6591: Adding world 'vmm0:test', group 'host/user', cpu: shares=-3 min=0 minLimit=-1 max=-1, mem: shares=-3 min=0 minLimit=-1 max=-1 2023-04-15T08:52:38.664Z cpu9:2047458)Sched: vm 2047460: 6606: renamed group 8283932 to vm.2047458 2023-04-15T08:52:38.664Z cpu9:2047458)Sched: vm 2047460: 6623: group 8283932 is located under group 4

 

Stage8 → Stage9

 

vmware.log

Destination 쪽 VM이 준비가 되었고, Source 로부터 Data 수신 대기

2023-04-15T08:52:38.717Z In(05) vmx - MigratePlatformInitMigration:  DiskOp file set to /vmfs/volumes/642e536a-5c6bdcef-fdd9-000c292e88b6/test/test-diskOp.tmp 2023-04-15T08:52:38.723Z In(05) vmx - MigrateWaitForData: waiting for data. 2023-04-15T08:52:38.723Z In(05) vmx - MigrateSetState: Transitioning from state 8 to 9.

 

vmkernel.log : destination

2023-04-15T08:52:38.723Z cpu9:2047458)Hbr: 3721: Migration start received (worldID=2047460) (migrateType=1) (event=0) (isSource=0) (sharedConfig=1)

 

Stage9 → Stage10

 

vmware.log

2023-04-15T08:52:49.293Z In(05) vmx - MigrateWaitForData: Waited for 10.57 seconds. 2023-04-15T08:52:49.293Z In(05) vmx - MigrateRPC_DrainPendingWork: Draining pending remote user messages before restore... 2023-04-15T08:52:49.293Z In(05) vmx - MigrateRPC_DrainPendingWork: All pending work completed. 2023-04-15T08:52:49.293Z In(05) vmx - MigrateSetState: Transitioning from state 10 to 11.

 

vmkernel.log : destination

Source로부터 modified page 수신 완료

2023-04-15T08:52:49.533Z cpu8:2047460)VMotion: 6188: 8743996508480001077 D: Received all changed pages. 2023-04-15T08:52:49.577Z cpu8:2047460)Migrate: 102: 8743996508480001077 D: MigrateState: Complete 2023-04-15T08:52:49.581Z cpu8:2047460)VMotion: 5963: 8743996508480001077 D: Resume handshake successful

 

Stage11 → Stage12

 

vmware.log

2023-04-15T08:52:49.577Z In(05) vmx - MigrateSetStateFinished: type=2 new state=12 2023-04-15T08:52:49.577Z In(05) vmx - MigrateSetState: Transitioning from state 11 to 12.

 

vmkernel.log : destination

Migration 완료

2023-04-15T08:52:50.118Z cpu8:2047619)Hbr: 3815: Migration end received (worldID=2047460) (migrateType=1) (event=1) (isSource=0) (sharedConfig=1)

 

Stage12 → Stage0

 

vmware.log

2023-04-15T08:52:50.118Z In(05) vcpu-0 - SVGA: Registering MemSpace at 0xe8000000(0xe8000000) and 0xfe000000(0xfe000000) 2023-04-15T08:52:50.118Z In(05) vcpu-0 - SVGA: FIFO is already mapped 2023-04-15T08:52:50.118Z In(05) vcpu-0 - Vix: [mainDispatch.c:4206]: VMAutomation_ReportPowerOpFinished: statevar=0, newAppState=1872, success=1 additionalError=0 2023-04-15T08:52:50.118Z In(05) vcpu-0 - Vix: [mainDispatch.c:4123]: VMAutomationReportPowerStateChange: Reporting power state change (opcode=0, err=0). 2023-04-15T08:52:50.118Z In(05) vcpu-0 - Vix: [mainDispatch.c:4123]: VMAutomationReportPowerStateChange: Reporting power state change (opcode=2, err=0). 2023-04-15T08:52:50.118Z In(05) vcpu-0 - Transitioned vmx/execState/val to poweredOn 2023-04-15T08:52:50.118Z In(05) vcpu-0 - SCSIFilterSBDAttachCBRC: device scsi0:0 is not SBD. Skipping CBRC attach SBD way. 2023-04-15T08:52:50.118Z In(05) vcpu-0 - Migrate: cleaning up migration state. 2023-04-15T08:52:50.118Z In(05) vcpu-0 - VigorTransport_ServerSendResponse opID=lgfd4abh-18745-auto-egq-h5:70005734-88-01-89-dcc4 seq=6: Completed Bootstrap request. 2023-04-15T08:52:50.118Z In(05) vcpu-0 - Migrate: Final status reported through Vigor. 2023-04-15T08:52:50.118Z In(05) vcpu-0 - MigrateSetState: Transitioning from state 12 to 0.

 

Summary

Migration Operation 완료 후 아래 보고서 기록

2023-04-15T08:52:50.118Z cpu13:2047470)VMotion: 2199: 8743996508480001077 D: VMotion bandwidth in last 1s: 353 MB/s, 10s: 377 MB/s, 2023-04-15T08:52:50.120Z cpu8:2047460)----------------  ----------------  ----------------  ----------------  ---------------- 2023-04-15T08:52:50.120Z cpu8:2047460)            name       reserved,KB   peakReserved,KB          alloc,KB      peakAlloc,KB 2023-04-15T08:52:50.120Z cpu8:2047460)----------------  ----------------  ----------------  ----------------  ---------------- 2023-04-15T08:52:50.120Z cpu8:2047460)             VMM             42920             50492             12188             12188 2023-04-15T08:52:50.120Z cpu8:2047460)          PFRAME             16420             16420              8180              8180 2023-04-15T08:52:50.120Z cpu8:2047460)      SWAP_CACHE               512               512               512               512 2023-04-15T08:52:50.120Z cpu8:2047460)       CANDIDATE                 4                 4                 4                 4 2023-04-15T08:52:50.120Z cpu8:2047460)  CHECKPOINT_BUF               256               256                 0                 0 2023-04-15T08:52:50.120Z cpu8:2047460)      PSHARE_P2M                20                20                20                20 2023-04-15T08:52:50.120Z cpu8:2047460)            CBRC                 0                 0                 0                 0 2023-04-15T08:52:50.120Z cpu8:2047460)           FTCPT                 0                 0                 0                 0 2023-04-15T08:52:50.120Z cpu8:2047460)      ASYNCREMAP                 4                 4                 4                 4 2023-04-15T08:52:50.120Z cpu8:2047460)   VMMEMSERVICES                96                96                96                96 2023-04-15T08:52:50.120Z cpu8:2047460)FSR_UNSHARED_GBL                 0                 0                 0                 0 2023-04-15T08:52:50.120Z cpu8:2047460)----------------  ----------------  ----------------  ----------------  ---------------- 2023-04-15T08:52:50.120Z cpu8:2047460)------------  ------------  ------------  ------------  ------------  ------------------------------ 2023-04-15T08:52:50.120Z cpu8:2047460)      min,KB        max,KB   minLimit,KB       eMin,KB   rMinPeak,KB                            name 2023-04-15T08:52:50.120Z cpu8:2047460)------------  ------------  ------------  ------------  ------------  ------------------------------ 2023-04-15T08:52:50.120Z cpu8:2047460)           0            -1            -1        122756        129512                       host/user 2023-04-15T08:52:50.120Z cpu8:2047460)------------  ------------  ------------  ------------  ------------  ------------------------------ 2023-04-15T08:52:50.120Z cpu8:2047460)           0            -1         91448         89400         96156                      vm.2047458 2023-04-15T08:52:50.120Z cpu8:2047460)        1892            -1            -1          1892          1892            uwWorldStore.2047458 2023-04-15T08:52:50.120Z cpu8:2047460)           0            -1            -1          1316          1316              worldGroup.2047458 2023-04-15T08:52:50.120Z cpu8:2047460)       11892            -1            -1         13136         13684                      uw.2047458 2023-04-15T08:52:50.120Z cpu8:2047460)           0            -1            -1           136           136                 vsiHeap.2047458 2023-04-15T08:52:50.120Z cpu8:2047460)        2384            -1            -1          2384          2384                      pt.2047458 2023-04-15T08:52:50.120Z cpu8:2047460)           0            -1            -1           280           280              cartelheap.2047458 2023-04-15T08:52:50.120Z cpu8:2047460)           0            -1            -1             0             0               uwshmempt.2047458 2023-04-15T08:52:50.120Z cpu8:2047460)           0            -1            -1           136           136        uwAsyncRemapHeap.2047458 2023-04-15T08:52:50.120Z cpu8:2047460)        4096          4096          4096          4096          4096                 uwCrypt.2047458 2023-04-15T08:52:50.120Z cpu8:2047460)           8            -1            -1             8             8                uwregbmp.2047458 2023-04-15T08:52:50.120Z cpu8:2047460)           0            -1            -1             0             0                     vmm.2047458 2023-04-15T08:52:50.120Z cpu8:2047460)       60232            -1            -1         60232         67804                 vmmanon.2047458 2023-04-15T08:52:50.120Z cpu8:2047460)         528            -1            -1           528           528                   vmcpt.2047460 2023-04-15T08:52:50.120Z cpu8:2047460)         512            -1            -1           512           512               vmmregbmp.2047458 2023-04-15T08:52:50.120Z cpu8:2047460)         512            -1            -1           512           512               vmmmigbmp.2047458 2023-04-15T08:52:50.120Z cpu8:2047460)        4096          4096          4096          4096          4096                vmmCrypt.2047458 2023-04-15T08:52:50.120Z cpu8:2047460)           0            -1            -1           136           136       vmmAsyncRemapHeap.2047458 2023-04-15T08:52:50.120Z cpu8:2047460)------------  ------------  ------------  ------------  ------------  ------------------------------ 2023-04-15T08:52:50.144Z cpu9:2047624)Swap: vm 2047460: 5134: Finish swapping in migration swap file. (faulted 0 pages). Success.