Troubleshooting vMotion

5 min readNov 22, 2019

Это перевод статьи Niels Hagoort Troubleshooting vMotion. Публикуется с разрешения автора.

В предыдущих статьях мы рассмотрели vMotion процесс (vMotion под капотом) и варианты использования сетей с высокой пропускной способностью для сокращения времени живой миграции (Как оптимизировать vMotion для сокращения времени миграции?). Эта статья посвящена отладке процесса живой миграции, что делать для устранении неполадок vMotion, что делать если динамическая миграция не работает. Каковы же типичные причины неудачных миграций? Какие логи посмотреть? Давайте разберем, как вы можете устранять неполадки и предотвращать сбои операций vMotion.

Типичные причины неудачных миграций

Ниже перечислены распространенные сбои и причины, которые приводят к неудачной живой миграции.

Проблемы в сети vMotion:

ESXi хосты не могут пинговать друг друга или таймаут превышает 20 секунд.
Несоответствие MTU между интерфейсом VMkernel и сетевым уровнем (т.е. коммутаторами и маршрутизаторами).
Неправильная настройка сетей VMotion на ESXi хостах.

Сторадж:

Хранилище недоступно или произошел ADP (All Paths Down).
Таймаут ввода-вывода 20 секунд или более.

vMotion прошел успешно, но есть проблемы с гостевыми ОС:

Сеть ВМ недоступна — нет соединения на 2 уровне у целевого ESXi хоста.

Переподписка ресурсов:

Не может быть выделена память.
Происходит своппинг, блокирующий vMotion.

Убедитесь, что вы выполнили все требования для vMotion. В том числе, основную причину проблем с vMotion, связанную с сетевым подключением или несоответствиями MTU. Если вы не можете точно определить проблему, будет полезно заглянуть в логи vSphere, чтобы разобраться, что же произошло.

Логи vSphere

Более глубокое изучение логов vSphere может быть полезно для понимания причин сбоя живой миграции. vMotion процесс использует компоненты и vCenter Server и ESXi. Пять различных процессов участвуют в vMtoion, их логи записываются, соответственно в пять файлов.

vCenter Daemon (VPXD), vCenter Agent (VPXA) и Host Daemon (hostd) являются уровнем управления (Control Plane) для vMotion процесса. “Data Plane” — процессы VMX и VMkernel. Первый шаг — найти идентификатор операции (opID) в этих логах. Этот opID соответствует идентификатору миграции (Migration ID). Используя эти два идентификатора, мы можем следить за процессом vMotion, просматривая соответствующие логи.

Operation ID

Чтобы найдите “Operation ID” процесса vMotion в логах VPXD на vCenter Server, вам нужно подключиться к VCSA (vCenter Server Appliance), перейти к bash и выполнить команду:

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

Теперь, когда вы получили идентификатор операции (opID), вы можете использовать opID, чтобы найти идентификатор миграции в логе hostd на ESXi хосте. Гораздо проще искать, когда вы знаете, исходный и целевой ESXi хосты. Этот пример показывает лог обычного vMotion и Storage vMotion (XvMotion) с идентификатором операции, который мы нашли с помощью предыдущей команды.

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

Вывод с исходного ESXi хоста:

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

Вывод с целевого ESXi хоста:

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

Теперь, когда у нас есть идентификатор миграции, мы можем использовать его для получения информации о процессе vMotion для этой конкретной живой миграции из vmkernel лога. Используйте следующую команду на исходном и целевом ESXi хосте:

grep VMotion /var/log/vmkernel*

Вывод команды показывает нам интересные данные о процессе vMotion, такие как средняя пропускная способность, используемая для передачи данных.

Вывод с исходного ESXi хоста:

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.

Вывод с целевого ESXi хоста:

019-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. Используя root доступ к ESXi хосту , вы можете перейти в соответствующую папку. Моя тестовая виртуальная машина находится на vSAN, поэтому я использовал путь /vmfs/volume/vsanDatastore. Использование следующей команды показывает еще больше информации о живой миграции, такой как IP-адреса источника и цели:

grep "3117907752192811422" vmware.log

Вывод:

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 прошла успешно. Показанные логи содержат много подробной информации, которая поможет вам лучше понять процесс vMotion. Если что-то пошло не так, эти логи станут хорошим инструментом для поиска возможной причины.