Недавно в нашу компанию «Инфосистемы Джет» пришел заказчик с проблемой долгой реализации создаваемых портов на NSX-T (до 2 минут до момента запуска трафика). Основная боль заключалась в том, что новые поды K8s не всегда укладывались в timeout Health Check'a и процесс начинался опять.
Исходные данные у нас были такие. NSX использовался для построения микросегментированной сети в кластерах Kybernetes + Kyverno. Взаимодействие K8s и NSX было реализовано при помощи плагина VMware NCP. Несмотря на большое количество объектов, в интерфейсе все метрики по утилизации были в «зеленых» значениях, но ощущалось сильное замедление работы UI.
Сбор и обработка данных
В начале процесса диагностики мы решили разделить сущности и понять, на каком этапе возникает замедление при создании порта. Заказчик сделал простой REST-запрос, который создавал порт в сегменте, опрашивал его раз в секунду и ожидал реализации:
https://developer.vmware.com/apis/nsx-vmc-policy/v1.0/policy/api/v1/infra/segments/segment-id/ports/port-id/put/
На этом этапе мы уже увидели «отклонения». При норме < 5 секунд время создания порта колебалось от 30 до 100 секунд.
Таким образом, стало очевидно, что замедление возникает именно на уровне NSX-T. Поэтому остальные сущности мы пока не трогали. Далее началась диагностика со стороны самого NSX по пути следования запроса от Control Plane до ESXi-хоста.
Здесь стоит немного уклониться от темы и рассказать о внутреннем устройстве контроллера NSX-T.
Небольшое отступление с техническими подробностями дела
Management Plane выглядит так:
- Служба Proton — Java-машина, которая предназначена для внешнего взаимодействия с пользователями и другими решениями (REST API и интерфейс). После она передает данные в Central Control Plane (CCP).
- Пользовательский интерфейс (Policy UI014i) реализован в составе Proton и использует службы search (Elastic) для кеширования данных.
- Corfu aka Database-less Database (да-да, разработчик называет это именно так) — журнал транзакций, постоянно реплицирующийся между всеми нодами контроллера и используемый вместо базы данных.
Central Control Plane, он же CloudNet, отвечает за распределение задач между контроллерами и взаимодействие с Local Control Plane. В качестве базы использует UFO Cache (самодельная JSON-образная NoSQL), Falcon Adapter для горизонтального взаимодействия и Pigeon Adapter для вертикального (с LCP).
Local Control Plane — часть CloudNet — предназначен для распределения объектов по Transport Nodes (TN) и синхронизации их изменений.
И снова к проблеме
Возвратимся к диагностике со стороны NSX. Для исключения внешнего влияния и снижения входящего «шума» в API мы отключили большинство внешних систем: мониторинг, аналитику и т. д. Проблема никуда не делась и по-прежнему воспроизводилась.
Для оценки влияния на производительность мы попытались изменить сайзинг контроллеров — максимальный объем памяти и Thread Stack Size Java-машин для основных служб Proton и CloudNet. Но данные изменения не принесли значимого результата.
Примеры «улучшенных» конфигов (сильно увеличенные объемы максимальной памяти и Stack Size):
# Java Additional Parameters
wrapper.java.additional.1=-Xms2g
wrapper.java.additional.26=-Xmx20g
# wrapper.java.additional.1=-agentpath:/usr/yourkit/bin/libyjpagent.so=port=14325,listen=localhost,dir=/var/log/cloudnet,snapshot_name_format={sessionname}-{datetime}-{pid},skip_advanced_port_check
wrapper.java.additional.2=-Dlogging.subcomp=ccp
wrapper.java.additional.3=-XX:+HeapDumpOnOutOfMemoryError
wrapper.java.additional.4=-XX:HeapDumpPath=/image/core/ccp_oom.hprof
wrapper.java.additional.5=-XX:+ExitOnOutOfMemoryError
wrapper.java.additional.6=-XX:+UseG1GC
wrapper.java.additional.7=-XX:+PrintGCDetails
wrapper.java.additional.8=-XX:+PrintGCDateStamps
wrapper.java.additional.9=-Xloggc:/var/log/cloudnet/nsx-ccp-gc
wrapper.java.additional.10=-XX:+UseGCLogFileRotation
wrapper.java.additional.11=-XX:NumberOfGCLogFiles=10
wrapper.java.additional.12=-XX:GCLogFileSize=5M
wrapper.java.additional.13=-Ddeployment.security.TLSv1.1=true
wrapper.java.additional.14=-Ddeployment.security.TLSv1.2=true
wrapper.java.additional.15=-Dlog4j.configurationFile=/opt/vmware/ccp/bin/java/vnetcontroller/log4j2.xml
wrapper.java.additional.16=-XX:+UseStringDeduplication
wrapper.java.additional.17=-XX:MinHeapFreeRatio=20
wrapper.java.additional.18=-XX:MaxHeapFreeRatio=40
wrapper.java.additional.19=-Djdk.nio.maxCachedBufferSize=1048576
wrapper.java.additional.20=-Dio.netty.recycler.maxCapacityPerThread=0
wrapper.java.additional.21=-XX:+PrintGCApplicationStoppedTime
wrapper.java.additional.22=-XX:+PrintGCApplicationConcurrentTime
# systemd-tmpfiles takes care about housekeeping of /var/tmp/ccp, settings are in /usr/lib/tmpfiles.d/nsx-ccp.conf
wrapper.java.additional.23=-Dio.netty.native.workdir=/var/tmp/ccp
wrapper.java.additional.24=-Djava.io.tmpdir=/var/tmp/ccp
wrapper.java.additional.25=-Xss2048k
После длительного исследования логов мы заметили одну интересную особенность — сборщик мусора (GC) в базе CorfuDB часто «спотыкался» при попытке очистить одну из таблиц. Мы предположили, что именно это могло негативно влиять на скорость работы контроллеров.
Например, по упрощенным логам мы видим очень большое количество записей и долгие блокировки при попытке очистки таблицы. При каждой попытке сборщика мусора почистить таблицу возникала задержка более 1000 секунд, а количество записей в ней достигало около 1 млн Удаление устаревших записей не происходило, и размер постоянно рос:
entries(976388), c3ec4373-148f-36f5-810c-2baca3bc8e94, 1346425 DynamicGroupMemberComputationResult
entries(976388), c3ec4373-148f-36f5-810c-2baca3bc8e94, 1332089
entries(976391), c3ec4373-148f-36f5-810c-2baca3bc8e94, 1253532
entries(976388), c3ec4373-148f-36f5-810c-2baca3bc8e94, 1238893
entries(976390), c3ec4373-148f-36f5-810c-2baca3bc8e94, 1234140
entries(976391), c3ec4373-148f-36f5-810c-2baca3bc8e94, 1200773
entries(976388), c3ec4373-148f-36f5-810c-2baca3bc8e94, 1088702
И снова отступление
Оказалось, во внутренней логике NSX-T все группы являются динамическими, и пересчет их членов происходит в реальном времени через таблицу (DynamicGroupMemberComputationResult). При корректной работе количество записей в ней должно соответствовать числу групп (в нашем случае это всего ~13 тыс. групп). Поэтому наш случай однозначно говорил об имеющейся проблеме и необходимости ее решения.
Продолжение истории… Ура, мы нашли корень зла
После непродолжительного исследования подопытного NSX-manager’a мы выяснили: для взаимодействия с CorfuDB используется целая (!) Java-машина (corfudb-tools) со скудным функционалом, который вызывается через corfu_tool_runner.py или напрямую через Java:
usage: corfu_tool_runner.py [-h] [-t TABLE] [--tool TOOL] [--ifname IFNAME]
[--port PORT] [-n NAMESPACE] [-o OPERATION]
[--diskPath DISKPATH] [--keyToEdit KEYTOEDIT]
[--newRecord NEWRECORD]
[--keyToDelete KEYTODELETE] [--numItems NUMITEMS]
[--batchSize BATCHSIZE] [--itemSize ITEMSIZE]
[--tag TAG] [--address ADDRESS] [--lock LOCK]
[--logdir LOGDIR]
Вся печаль заключалась в отсутствии функции Bulk Delete. Таким образом, для удаления каждой записи требовался повторный запуск Java-машины, на который уходило 10–20 секунд. А это давало абсолютно невыполнимый срок для очистки 1 млн записей (около 400 часов).
После «находки» мы изучили различные kbVMware, функционал corfudb-tools и нашли очень полезную функцию ClearTable (именно она и спасла день). По итогу мы просто дропнули таблицу целиком (да-да, vendor approved methods!), и она стала пересчитываться в соответствии с ожиданиями.
Тем не менее очистка записей не дала должного прироста в скорости. Хотя во время работы мы заметили, что при отключенном NCP задержка при создании порта пропадала. После продолжительного и вдумчивого копания в логах мы сместили фокус внимания на другую особенность: размер vm-support с ESXi-хоста составлял около 15 Гб при нормальном размере в 0,5–1 Гб. Именно она оказалась первопричиной проблемы.
Несмотря на нормальные показатели утилизации ресурсов службами NSX-T, в том числе и DFW, при анализе файла выходило следующее:
/commands# cat vsipioctl_info.sh.txt.FRAG-0* > ipctl.all
/commands# ls -hla ipctl.all
-rwxrwxrwx 1 root root 9.6G Apr 21 14:06 ipctl.all
/commands# file ipctl.all
ipctl.all: ASCII text
Как мы видим выше, кэш DFW является текстовым файлом с размером ~10 Гб. Далее для примера более детально разберем один из фильтров воркер ноды в кэше:
world 5226929 vmm0:0000-#VMNAME
port 67111883 0000-#VMNAME
vNic slot 2
name: nic-5226929-eth1-vmware-sfw.2
Часть наборов адресов представлена нормальными группами с адекватным количеством адресов (несколько десятков или сотен). Но при этом присутствуют группы с ненормально большим числом адресов. Например, данная группа — 6648 адреса:
2341033 addrset 00a8283c-d082-44bc-abf2-b5e5fc854785 {
2341034 ip 127.0.5.132,
2341035 ip 169.254.5.133,
...
Она была создана со стороны NCP на базе тегов. Но одновременно мы также видим, что для части адресов записи задублированы в 100+ раз:
/commands# cat nic-5226929-eth1-vmware-sfw.2 | sort | uniq -c | sort -Vk 1 | head -2
105 ip 169.254.0.2,
105 ip 169.254.0.3,
Получается, что на уровне ESXi-хоста каждая из групп преобразуется в плоский массив разрешенных IP/MAC-адресов, то есть одна запись /24 подсети создает 256 записей. Итого: общий набор addrset для данного порта содержит 766 169 записей в 960 различных addrset. Но, по заявлению VMware в configmax, Grouping and Tagging IP Addresses per IP Set 4,000.
Что же привело к возникновению такой ситуации? С одной стороны — K8s, который использует недостаточно строгие теги для наполнения групп объектами. С другой стороны — отсутствие какой-либо проверки на максимальное количество адресов в addrset для DFW NSX’a.
Счастливый конец
После пересмотра критериев использования динамических групп скорость создания порта вернулась к ожидаемой (1–5 секунд) и проблема была решена. А если бы VMware проводил качественную проверку итогового количества адресов в группе, то нашей проблемы не было бы вообще!
https://configmax.esp.vmware.com/guest?vmwareproduct=VMware%20NSX&release=NSX%204.0.0&categories=19-36
В заключение хочется упомянуть, с чем еще мы столкнулись и что починили:
- Невозможность пройти пречек при обновлении с версии 3.2.1 и наличии более 1000 ресурс-пулов на подключенных vCenter из-за сломанной пагинации. Она игнорировала курсор и рекурсивно возвращала одни и те же записи, приводя к OOM на запрашивающей стороне. https://kb.vmware.com/s/article/89437.
- После удаления часть групп так и осталась висеть в интерфейсе со статусом Pending Delete. Мы попробовали удалить их из базы, но они так и остались в UI. Здесь мы выяснили назначение elastic’a в составе контроллера, отвечающего за кэширование инвентори для UI. После удаления объектов из elastic’a «фантомные» группы успешно исчезли.
