Compute
How vMotion Works
haewon83
2023. 4. 16. 11:27
오늘은 정상적인 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. |