Info
Content

[번역] Troubleshooting vMotion

출처 : https://blogs.vmware.com/vsphere/2019/09/troubleshooting-vmotion.html

이전 블로그 게시물에서는 vMotion 프로세스(The vMotion Process Under the Hood)와 높은 대역폭 네트워크를 활용하여 실시간 마이그레이션 시간을 단축하는 방법을 살펴보았다. 이 글은 실시간 마이그레이션이 성공하지 못할 경우 vMotion 문제를 해결할 때 수행할 작업에 대한 자세한 정보를 얻기 위해 작성되었다. 마이그레이션이 실패한 대표적인 이유는 무엇인가? 조사해야 할 로그는? 문제를 해결하고 vMotion 작업이 실패하는 것을 방지하는 방법을 살펴봅겠다.

공통 장애

실시간 이동이 실패하는 일반적인 실패와 패턴은 다음과 같다.

  • vMotion 네트워크 연결 문제
    • ESXi 호스트는 20초 후에 ping 또는 시간 초과가 발생할 수 없음
    • VMkernel 인터페이스와 네트워크 계층(예: 스위치 및 라우터) 간의 MTU 불일치
    • ESXi 호스트에서 vMotion을 사용하도록 설정된 네트워크의 구성 잘못
  • 스토리지
    • 데이터스토어에 연결할 수 없거나, APD가 발생함(모든 경로 다운)
    • I/O의 시간 초과 20초 이상
  • vMotion에 성공했지만 게스트 문제가 발생함
    • VM 네트워크에 연결할 수 없음 - 대상 ESXi 호스트에 L2 연결 없음
  • 리소스가 오버 커밋됨
    • 메모리를 오랫동안 할당할 수 없음
    • 스와핑이 오래 걸려서 vMotion 시간 초과로 이어짐

모든 vMotion 요구 사항을 충족했는지 확인한다. 여기에는 네트워크 연결 또는 MTU 불일치의 vMotion 문제의 주요 이유가 포함된다. 이 문제를 정확히 파악할 수 없는 경우 vSphere 로그를 검토해서 어떤 일이 발생했는지 확인하는 것이 유용할 수 있다.

vSphere 로그

vSphere 로그를 자세히 들여다보면 실시간 마이그레이션이 실패하는 원인이 무엇인지 확인하는 데 유용하다. vMotion 프로세스는 vCenter Server 및 ESXi 구성 요소를 모두 사용한다. 다섯 가지 다른 로그 파일에 로그하는 다섯 가지 프로세스가 있다.

processes-logs.png


vCenter Daemon(VPXD), vCenter Agent(VPXA) 및 Host Daemon(hostd)은 vMotion 프로세스의 제어 영역이다. '데이터 평면'은 VMX 프로세스 및 VMkernel에 있다. 첫 번째 단계는 이러한 로그에서 Operation ID(opID)를 찾는 것이다. 이 opID는 Migration ID에 매핑된다. 이 두 개의 식별자를 사용해서, 해당 로그 파일을 확인해서 vMotion 프로세스 따라갈 수 있다.

Operation ID

vCenter Server 인스턴스의 VPXD 로그에서 vMotion 프로세스의 "작업 ID"를 찾으십시오. VCSA(vCenter Server Appliance) 인스턴스의 콘솔에 연결하고 바시 쉘로 이동하십시오. 다음 명령을 실행할 수 있음:

grep "relocate" /var/log/vmware/vpxd/vpxd-*.log | grep BEGIN

이 명령의 출력은 Operation ID를 포함하는 로그 항목을 노출한다.

/var/log/vmware/vpxd/vpxd-214.log:2019-09-24T15:38:10.042Z info vpxd[29243] [Originator@6876 sub=vpxLro opID=jzlgfw8g-11824-auto-94h-h5:70003561-20] [VpxLRO] — BEGIN task-8031 — vm-269 — vim.VirtualMachine.relocate — 52b17681-35d1-998b-da39-de07b7925dda(520681db-25b7-c5d6-44d7-6a056620e043)

Migration ID

이제 Operation ID(opID)를 검색했다. 이것을 사용해서 ESXi 호스트의 hostd 로그 파일에서 opID를 이용해서 Migration ID를 찾는다.  관련된 소스 및 대상 ESXi 호스트를 알고 있을 때 유용하다. 이 예는 이전 명령을 사용해서 찾은 Operation ID를 사용하는 컴퓨팅 및 스토리지 vMotion(XvMotion) 이다.

grep jzlgfw8g-11824-auto-94h-h5:70003561-20 /var/log/hostd.log | grep -i migrate

Source ESXi host output:

2019-09-24T15:38:47.070Z info hostd[2100388] [Originator@6876 sub=Vcsvc.VMotionSrc.3117907752192811422 opID=jzlgfw8g-11824-auto-94h-h5:70003561-20-01-10-e036 user=vpxuser:VSPHERE.LOCAL\Administrator] VMotionEntry: migrateType = 1 2019-09-24T15:38:47.072Z info hostd[2100388] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/b86202d8-fb958817-0000-000000000000/NH-DC-02/NH-DC-02.vmx opID=jzlgfw8g-11824-auto-94h-h5:70003561-20-01-10-e036 user=vpxuser:VSPHERE.LOCAL\Administrator] VigorMigrateNotifyCb:: hostlog state changed from success to none

Destination ESXi host output:

2019-09-24T15:38:47.136Z info hostd[2099828] [Originator@6876 sub=Vcsvc.VMotionDst.3117907752192811422 opID=jzlgfw8g-11824-auto-94h-h5:70003561-20-01-2c-3c35 user=vpxuser:VSPHERE.LOCAL\Administrator] VMotionEntry: migrateType = 1

VMkernel 항목

이제 Migration ID를 확보했으므로, 이것을 사용해서 vmkernel 로그 파일에서 특정 실시간 마이그레이션에 대한 vMotion 프로세스의 정보를 추출할 수 있다. 소스 및 대상 ESXi 호스트에서 다음 명령을 사용한다.

grep VMotion /var/log/vmkernel*

출력은 vMotion 프로세스에서 데이터 전송에 사용되는 평균 대역폭과 같은 몇 가지 흥미로운 데이터 포인트를 보여준다.

Source ESXi host output:

2019-09-24T15:38:47.402Z cpu13:46101760)VMotionUtil: 5199: 3117907752192811422 S: Stream connection 1 added.
2019-09-24T15:38:47.445Z cpu8:46092538)XVMotion: 2062: Allocating pool 0.
2019-09-24T15:38:47.445Z cpu8:46092538)XVMotion: 642: Bitmap page: len = 16384, pgLen = 1, bitSet = 3001, bitClear = 13383.
2019-09-24T15:38:47.445Z cpu8:46092538)XVMotion: 642: Bitmap block: len = 131072, pgLen = 4, bitSet = 131072, bitClear = 0.
2019-09-24T15:38:47.445Z cpu8:46092538)VMotion: 8134: 3117907752192811422 S: Requiring explicit resume handshake.
2019-09-24T15:38:47.445Z cpu13:46101760)XVMotion: 3384: 3117907752192811422 S: Starting XVMotion stream.
2019-09-24T15:39:34.622Z cpu14:46101762)VMotion: 5426: 3117907752192811422 S: Disk copy complete, no bandwidth estimate.
2019-09-24T15:39:34.905Z cpu24:46092539)VMotion: 5281: 3117907752192811422 S: Stopping pre-copy: only 37 pages left to send, which can be sent within the switchover time goal of 0.500 seconds (network bandwidth ~185.134 MB/s, 1536000% t2d)
2019-09-24T15:39:34.965Z cpu13:46101760)VMotionSend: 5095: 3117907752192811422 S: Sent all modified pages to destination (network bandwidth ~281.100 MB/s)
2019-09-24T15:39:35.140Z cpu15:46101757)XVMotion: 642: Bitmap page: len = 16384, pgLen = 1, bitSet = 3001, bitClear = 13383.
2019-09-24T15:39:35.140Z cpu15:46101757)XVMotion: 642: Bitmap block: len = 131072, pgLen = 4, bitSet = 131072, bitClear = 0.

Destination ESXi host output:

2019-09-24T15:38:47.397Z cpu15:2099283)VMotionUtil: 5199: 3117907752192811422 D: Stream connection 1 added.
2019-09-24T15:38:47.440Z cpu3:3543984)XVMotion: 2062: Allocating pool 0.
2019-09-24T15:38:47.440Z cpu3:3543984)XVMotion: 642: Bitmap page: len = 16384, pgLen = 1, bitSet = 3001, bitClear = 13383.
2019-09-24T15:38:47.440Z cpu3:3543984)XVMotion: 642: Bitmap block: len = 131072, pgLen = 4, bitSet = 131072, bitClear = 0.
2019-09-24T15:38:47.440Z cpu3:3543984)VMotion: 8134: 3117907752192811422 D: Requiring explicit resume handshake.
2019-09-24T15:39:34.907Z cpu3:3543984)VMotionRecv: 761: 3117907752192811422 D: Estimated network bandwidth 205.138 MB/s during pre-copy
2019-09-24T15:39:34.960Z cpu3:3543984)VMotionRecv: 2961: 3117907752192811422 D: DONE paging in
2019-09-24T15:39:34.960Z cpu3:3543984)VMotionRecv: 2969: 3117907752192811422 D: Estimated network bandwidth 200.096 MB/s during page-in
2019-09-24T15:39:35.059Z cpu6:3543972)VMotion: 6675: 3117907752192811422 D: Received all changed pages.
2019-09-24T15:39:35.067Z cpu1:3543972)VMotion: 6454: 3117907752192811422 D: Resume handshake successful
2019-09-24T15:39:35.082Z cpu6:3543980)XVMotion: 642: Bitmap page: len = 16384, pgLen = 1, bitSet = 3001, bitClear = 13383.
2019-09-24T15:39:35.082Z cpu6:3543980)XVMotion: 642: Bitmap block: len = 131072, pgLen = 4, bitSet = 131072, bitClear = 0.

가상 시스템 로그 파일 항목

가상 시스템 로그 파일은 vmx 파일과 vmdk 파일도 포함하고 있는 가상 시스템의 홈 폴더에 있다. ESXi 호스트에서 root로 액세스 사용하면 적절한 폴더로 이동할 수 있다. 테스트 VM이 vSAN에 있으므로 symlink /vmfs/volumes/vsanDatastore를 사용해서 가상 시스템 홈 디렉토리를 찾는다. 다음 명령을 사용하면 소스 및 대상 IP 주소와 같은 실시간 마이그레이션에 대한 자세한 정보를 볼 수 있다.

grep "3117907752192811422" vmware.log

Output:

2019-09-24T15:38:47.280Z| vmx| I125: Received migrate ‘from’ request for mid id 3117907752192811422, src ip <192.168.200.93>.
2019-09-24T15:38:47.280Z| vmx| I125: MigrateSetInfo: state=8 srcIp=<192.168.200.93> dstIp=<192.168.200.91> mid=3117907752192811422 uuid=4c4c4544-004a-4c10-8044-c7c04f4d4e32 priority=high
2019-09-24T15:38:47.282Z| vmx| I125: MigID: 3117907752192811422
2019-09-24T15:39:34.971Z| vmx| I125: Migrate_Open: Restoring from <192.168.200.93> with migration id 3117907752192811422
2019-09-24T15:39:35.023Z| vmx| I125: Migrate_Open: Restoring from <192.168.200.93> with migration id 3117907752192811422

이 글은 모범적인 vMotion 작업이 성공적이었음에도, 어떤 로그 항목이 사용되는지 보여주기 위한 것이다. 표시된 로그 항목에는 프로세스를 수행하는 데 도움이 되는 많은 상세 정보가 포함되어 있다. 만약 무언가가 실패한다면, 이 로그들은 가능한 원인을 찾기 위한 좋은 자원이 될 것이다.

추가 자료

구강사의 간단 요약

  • VCAP-DCV 시험에 vMotion 문제가 나온다 <- 그 만큼 많이 사용하고, 많은 상황이 발생한다는 것
  • 1)네트워크 구성, 2)스토리지, 3)리소스 할당 등의 원인으로 문제가 발생할 수 있음
  • 5개의 로그 파일을 본다 : 추가로 해당 VM 디렉토리에 있는 vmware.log 도 본다.
  • Operation ID(opID)를 찾고 -> opID로 Migration ID 를 찾고 -> Migration ID로 VMkernel에서 관련 항목을 찾고 -> MigrationID로 VM의 vmware.log에서 찾는다

 

 

No Comments
Back to top