Хабрахабр

[Перевод] Отлаживаем сетевые задержки в Kubernetes

С тех пор он стал стандартной технологией для развёртывания сервисов. Пару лет назад Kubernetes уже обсуждался в официальном блоге GitHub. Поскольку наши кластеры выросли, а требования к производительности стали более жёсткими, мы стали замечать, что в некоторых службах на Kubernetes спорадически появляются задержки, которые нельзя объяснить нагрузкой самого приложения. Теперь Kubernetes управляет значительной частью внутренних и публичных служб.

Ожидалось, что службы смогут отвечать на запросы гораздо быстрее 100 мс. По сути, в приложениях происходит будто случайная сетевая задержка до 100 мс и более, что приводит к тайм-аутам или повторным попыткам. Отдельно мы наблюдали очень быстрые запросы MySQL, которые должны были занимать миллисекунды, и MySQL действительно справлялась за миллисекунды, но с точки зрения запрашивающего приложения ответ занимал 100 мс или больше.
Сразу стало понятно, что проблема возникает только при соединении с узлом Kubernetes, даже если вызов приходил извне Kubernetes. Но это невозможно, если само соединение отнимает столько времени. В этой статье рассмотрим, как нам удалось отследить причину этой проблемы. Проще всего воспроизвести проблему в тесте Vegeta, который запускается с любого внутреннего хоста, тестирует службу Kubernetes на определённом порту, и спорадически регистрирует большую задержку.

Воспроизведя один и тот же пример, мы хотели сузить фокус проблемы и удалить лишние слои сложности. Первоначально в потоке между Vegeta и pod'ами на Kubernetes было слишком много элементов. Чтобы определить более глубокую сетевую проблему, нужно исключить некоторые из них.

Kubernetes работает как оверлейная сеть (поверх существующей сети дата-центра), которая использует IPIP, то есть инкапсулирует IP-пакеты оверлейной сети внутрь IP-пакетов дата-центра. Клиент (Vegeta) создаёт TCP-соединение с любым узлом в кластере. Для поступивших пакетов выполняется обратная последовательность действий. При подключении к первому узлу выполняется преобразование сетевых адресов Network Address Translation (NAT) с отслеживанием состояния для преобразования IP-адреса и порта узла Kubernetes в IP-адрес и порт в оверлейной сети (в частности, pod'а с приложением). Это сложная система с большим количеством состояний и множеством элементов, которые постоянно обновляются и изменяются по мере развёртывания и перемещения служб.

Чтобы убрать эту излишнюю сложность, можно использовать hping3 для простых «пингов» пакетами SYN. Утилита tcpdump в тесте Vegeta даёт задержку во время рукопожатия TCP (между SYN и SYN-ACK). Мы можем отфильтровать данные, включив только пакеты более 100 мс, и получить более простой вариант воспроизведения проблемы, чем полный тест сетевого уровня 7 в Vegeta. Проверяем, есть ли задержка в ответном пакете, а затем сбрасываем соединение. Вот «пинги» узла Kubernetes с использованием TCP SYN/SYN-ACK на «порту узла» службы (30927) с интервалом 10 мс, отфильтрованные по самым медленным ответам:

16. theojulienne@shell ~ $ sudo hping3 172. 27 -S -p 30927 -i u10000 | egrep --line-buffered 'rtt=[0-9]\.' 47.

16. len=46 ip=172. 27 ttl=59 DF id=0 sport=30927 flags=SA seq=1485 win=29200 rtt=127. 47. 1 ms

16. len=46 ip=172. 27 ttl=59 DF id=0 sport=30927 flags=SA seq=1486 win=29200 rtt=117. 47. 0 ms

16. len=46 ip=172. 27 ttl=59 DF id=0 sport=30927 flags=SA seq=1487 win=29200 rtt=106. 47. 2 ms

16. len=46 ip=172. 27 ttl=59 DF id=0 sport=30927 flags=SA seq=1488 win=29200 rtt=104. 47. 1 ms

16. len=46 ip=172. 27 ttl=59 DF id=0 sport=30927 flags=SA seq=5024 win=29200 rtt=109. 47. 2 ms

16. len=46 ip=172. 27 ttl=59 DF id=0 sport=30927 flags=SA seq=5231 win=29200 rtt=109. 47. 2 ms

По порядковым номерам и таймингам видно, что это не одноразовые заторы. Сразу может сделать первое наблюдение. Задержка часто накапливается, и в конечном итоге обрабатывается.

Может, это какие-то из сотен правил iptables в NAT? Далее мы хотим выяснить, какие компоненты могут быть причастны к появлению затора. Один из способов проверить это — проверить каждый шаг системы, исключив его. Или какие-то проблемы с туннелированием IPIP в сети? Что произойдёт, если убрать NAT и логику брандмауэра, оставив только часть IPIP:

К счастью, Linux позволяет легко обращаться непосредственно к оверлейному слою IP, если машина входит в ту же сеть:

125. theojulienne@kube-node-client ~ $ sudo hping3 10. 64 -S -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}\.' 20.

125. len=40 ip=10. 64 ttl=64 DF id=0 sport=0 flags=RA seq=7346 win=0 rtt=127. 20. 3 ms

125. len=40 ip=10. 64 ttl=64 DF id=0 sport=0 flags=RA seq=7347 win=0 rtt=117. 20. 3 ms

125. len=40 ip=10. 64 ttl=64 DF id=0 sport=0 flags=RA seq=7348 win=0 rtt=107. 20. 2 ms

Это исключает iptables и NAT. Судя по результатам, проблема всё ещё остаётся! Посмотрим, как идёт обычный ICMP-пинг: Значит, проблема в TCP?

125. theojulienne@kube-node-client ~ $ sudo hping3 10. 64 --icmp -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}\.' 20.

125. len=28 ip=10. 64 ttl=64 id=42594 icmp_seq=104 rtt=110. 20. 0 ms

125. len=28 ip=10. 64 ttl=64 id=49448 icmp_seq=4022 rtt=141. 20. 3 ms

125. len=28 ip=10. 64 ttl=64 id=49449 icmp_seq=4023 rtt=131. 20. 3 ms

125. len=28 ip=10. 64 ttl=64 id=49450 icmp_seq=4024 rtt=121. 20. 2 ms

125. len=28 ip=10. 64 ttl=64 id=49451 icmp_seq=4025 rtt=111. 20. 2 ms

125. len=28 ip=10. 64 ttl=64 id=49452 icmp_seq=4026 rtt=101. 20. 1 ms

125. len=28 ip=10. 64 ttl=64 id=50023 icmp_seq=4343 rtt=126. 20. 8 ms

125. len=28 ip=10. 64 ttl=64 id=50024 icmp_seq=4344 rtt=116. 20. 8 ms

125. len=28 ip=10. 64 ttl=64 id=50025 icmp_seq=4345 rtt=106. 20. 8 ms

125. len=28 ip=10. 64 ttl=64 id=59727 icmp_seq=9836 rtt=106. 20. 1 ms

Возможно, это туннель IPIP? Результаты показывают, что проблема не исчезла. Давайте ещё упростим тест:

Все пакеты отправляются между этими двумя хостами?

16. theojulienne@kube-node-client ~ $ sudo hping3 172. 27 --icmp -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}\.' 47.

16. len=46 ip=172. 27 ttl=61 id=41127 icmp_seq=12564 rtt=140. 47. 9 ms

16. len=46 ip=172. 27 ttl=61 id=41128 icmp_seq=12565 rtt=130. 47. 9 ms

16. len=46 ip=172. 27 ttl=61 id=41129 icmp_seq=12566 rtt=120. 47. 8 ms

16. len=46 ip=172. 27 ttl=61 id=41130 icmp_seq=12567 rtt=110. 47. 8 ms

16. len=46 ip=172. 27 ttl=61 id=41131 icmp_seq=12568 rtt=100. 47. 7 ms

16. len=46 ip=172. 27 ttl=61 id=9062 icmp_seq=31443 rtt=134. 47. 2 ms

16. len=46 ip=172. 27 ttl=61 id=9063 icmp_seq=31444 rtt=124. 47. 2 ms

16. len=46 ip=172. 27 ttl=61 id=9064 icmp_seq=31445 rtt=114. 47. 2 ms

16. len=46 ip=172. 27 ttl=61 id=9065 icmp_seq=31446 rtt=104. 47. 2 ms

Они всё равно видят задержку, если целевой хост является «плохим» (некоторые хуже, чем другие). Мы упростили ситуацию до двух узлов Kubernetes, отправляющих друг другу любой пакет, даже пинг ICMP.

И она происходит, когда kube-node является отправителем или получателем? Теперь последний вопрос: почему задержка возникает только на серверах kube-node? Как видим, проблема не исчезла: К счастью, это тоже довольно легко выяснить, отправляя пакет с хоста за пределами Kubernetes, но с тем же «известным плохим» получателем.

16. theojulienne@shell ~ $ sudo hping3 172. 27 -p 9876 -S -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}\.' 47.

16. len=46 ip=172. 27 ttl=61 DF id=0 sport=9876 flags=RA seq=312 win=0 rtt=108. 47. 5 ms

16. len=46 ip=172. 27 ttl=61 DF id=0 sport=9876 flags=RA seq=5903 win=0 rtt=119. 47. 4 ms

16. len=46 ip=172. 27 ttl=61 DF id=0 sport=9876 flags=RA seq=6227 win=0 rtt=139. 47. 9 ms

16. len=46 ip=172. 27 ttl=61 DF id=0 sport=9876 flags=RA seq=7929 win=0 rtt=131. 47. 2 ms

Затем выполним те же запросы от предыдущего исходного kube-node к внешнему хосту (что исключает исходный хост, поскольку пинг включает как компонент RX, так и TX):

16. theojulienne@kube-node-client ~ $ sudo hping3 172. 44 -p 9876 -S -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}\.'
^C
--- 172. 33. 33. 16. 2/7. 44 hping statistic ---
22352 packets transmitted, 22350 packets received, 1% packet loss
round-trip min/avg/max = 0. 6 ms
6/1010.

В частности, что отправитель (внизу) видит этот тайм-аут, а получатель (вверху) не видит — см. Изучив захваты пакетов с задержкой, мы получили некоторую дополнительную информацию. столбец Delta (в секундах):

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

Когда поступает пакет, сетевой адаптер «хэширует его по соединению», то есть пытается разбить соединения по очередям и отправить каждую очередь на отдельное процессорное ядро. Есть тонкая разница в том, как сетевые карты современных серверов (как в нашем дата-центре) обрабатывают пакеты, содержащие TCP или ICMP. Другими словами, каждое соединение хэшируется (потенциально) по-разному. Для TCP этот хэш включает в себя как исходный, так и конечный IP-адрес и порт. Для ICMP хэшируются только IP-адреса, так как нет портов.

Это говорит нам о том, что причина, вероятно, связана с хэшированием очередей RX: почти наверняка затор возникает в обработке пакетов RX, а не в отправке ответов. Ещё одно новое наблюдение: в течение этого периода мы видим задержки ICMP на всех коммуникациях между двумя хостами, а у TCP нет.

Теперь мы знаем, что проблема с обработкой пакетов находится на стороне приёма на некоторых серверах kube-node. Это исключает из списка возможных причин отправку пакетов.

Чтобы понять, почему проблема возникает у получателя на некоторых серверах kube-node, давайте посмотрим, как ядро Linux обрабатывает пакеты.

Ядро останавливает другую работу, переключает контекст на обработчик прерываний, обрабатывает пакет, а затем возвращается к текущим задачам. Возвращаясь к самой простой традиционной реализации, сетевая карта получает пакет и отправляет прерывание ядру Linux, что есть пакет, который нужно обработать.

Это переключение контекста происходит медленно: возможно, задержка была незаметна на 10-мегабитных сетевых картах в 90-е годы, но на современных картах 10G с максимальной пропускной способностью 15 миллионов пакетов в секунду каждое ядро маленького восьмиядерного сервера может прерываться миллионы раз в секунду.

На низких скоростях ядро всё еще принимает прерывания от сетевой карты старым способом. Чтобы не заниматься постоянно обработкой прерываний, много лет назад в Linux добавили NAPI: сетевой API, который используют все современные драйверы для повышения производительности на высоких скоростях. Обработка выполняется в softirq, то есть в контексте программных прерываний после системных вызовов и аппаратных прерываний, когда ядро (в отличие от пользовательского пространства) уже запущено. Как только приходит достаточное количество пакетов, которое превышает порог, ядро отключает прерывания и вместо этого начинает опрашивать сетевой адаптер и забирать пакеты порциями.

Если пакетов слишком много, то всё время уходит на обработку пакетов из сетевой карты, а процессы пользовательского пространства не успевают фактически опустошить эти очереди (чтение из TCP-соединений и т. д.). Это намного быстрее, но вызывает другую проблему. Пытаясь найти баланс, ядро устанавливает бюджет на максимальное количество пакетов, обрабатываемых в контексте softirq. В конце концов очереди заполняются, и мы начинает отбрасывать пакеты. Этот поток планируется с помощью стандартного планировщика процессов, который пытается справедливо распределять ресурсы. Как только этот бюджет превышен, пробуждается отдельный поток ksoftirqd (вы увидите один из них в ps для каждого ядра), который обрабатывает эти softirq за пределами обычного пути syscall/interrupt.

Если вызовы softirq поступают реже, пакетам придётся некоторое время ждать обработки в очереди RX на сетевой карте. Изучив, как ядро обрабатывает пакеты, можно заметить, что здесь есть определённая вероятность появления заторов. Возможно, это происходит из-за какой-то задачи, блокирующей ядро процессора, или что-то другое мешает ядру запускать softirq.

Задержки softirq — это пока лишь предположение. Но оно имеет смысл, и мы знаем, что у нас наблюдается что-то очень похожее. Поэтому следующий шаг — подтвердить эту теорию. И если она подтвердится, то найти причину задержек.

Вернёмся к нашим медленным пакетам:

16. len=46 ip=172. 32 ttl=61 id=29573 icmp_seq=1953 rtt=99. 53. 3 ms

16. len=46 ip=172. 32 ttl=61 id=29574 icmp_seq=1954 rtt=89. 53. 3 ms

16. len=46 ip=172. 32 ttl=61 id=29575 icmp_seq=1955 rtt=79. 53. 2 ms

16. len=46 ip=172. 32 ttl=61 id=29576 icmp_seq=1956 rtt=69. 53. 1 ms

16. len=46 ip=172. 32 ttl=61 id=29577 icmp_seq=1957 rtt=59. 53. 1 ms

16. len=46 ip=172. 32 ttl=61 id=29790 icmp_seq=2070 rtt=75. 53. 7 ms

16. len=46 ip=172. 32 ttl=61 id=29791 icmp_seq=2071 rtt=65. 53. 6 ms

16. len=46 ip=172. 32 ttl=61 id=29792 icmp_seq=2072 rtt=55. 53. 5 ms

Если мы хотим понять работу Linux, полезно знать, где (на каком ядре CPU) и как (softirq, ksoftirqd) обрабатываются эти пакеты, чтобы отследить процесс. Как обсуждалось ранее, эти пакеты ICMP хэшируются в одну очередь NIC RX и обрабатываются одним ядром CPU.

Здесь мы использовали bcc. Теперь пришло время использовать инструменты, которые позволяют в реальном времени отслеживать работу ядра Linux. Хуки для произвольных функций в ядре — сложное дело, но утилита спроектирована на максимальную безопасность и предназначена для отслеживания именно таких проблем продакшна, которые непросто воспроизвести в среде тестирования или разработки. Этот набор инструментов позволяет писать небольшие программки на C, которые перехватывают произвольные функции в ядре и буферизуют события в программу Python пользовательского пространства, которая может обрабатывать их и возвращать вам результат.

Мы можем идентифицировать пакет по увеличению номера icmp_seq, который показывает hping3 выше. План здесь простой: мы знаем, что ядро обрабатывает эти пинги ICMP, поэтому поставим хук на функцию ядра icmp_echo, которая принимает входящий ICMP-пакет "echo request" и инициирует отправку ICMP-ответа "echo response".

Функция icmp_echo передаёт struct sk_buff *skb: это пакет с запросом "echo request". Код скрипта bcc выглядит сложным, но он не такой страшный, как кажется. Также удобно захватить текущее имя процесса/идентификатор. Мы можем отследить его, вытащить последовательность echo.sequence (которая сопоставляется с icmp_seq от hping3 выше), и отправить её в пользовательское пространство. Ниже показаны результаты, которые мы видим непосредственно во время обработки пакетов ядром:

TGID PID PROCESS NAME ICMP_SEQ
0 0 swapper/11 770
0 0 swapper/11 771
0 0 swapper/11 772
0 0 swapper/11 773
0 0 swapper/11 774
20041 20086 prometheus 775
0 0 swapper/11 776
0 0 swapper/11 777
0 0 swapper/11 778
4512 4542 spokes-report-s 779

Тут нужно заметить, что в контексте softirq процессы, которые сделали системные вызовы, отобразятся как «процессы», хотя на самом деле это ядро безопасно обрабатывает пакеты в контексте ядра.

Делаем простой grep на этом захвате для определённых значений icmp_seq. С этим инструментом можем установить связь конкретных процессов с конкретными пакетами, которые показывают задержку в hping3. Пакеты, соответствующие вышеуказанным значениям icmp_seq, были отмечены вместе с их RTT, которые мы наблюдали выше (в скобках указаны ожидаемые значения RTT у пакетов, которые мы отфильтровали из-за значений RTT менее 50 мс):

TGID PID PROCESS NAME ICMP_SEQ ** RTT
--
10137 10436 cadvisor 1951
10137 10436 cadvisor 1952
76 76 ksoftirqd/11 1953 ** 99ms
76 76 ksoftirqd/11 1954 ** 89ms
76 76 ksoftirqd/11 1955 ** 79ms
76 76 ksoftirqd/11 1956 ** 69ms
76 76 ksoftirqd/11 1957 ** 59ms
76 76 ksoftirqd/11 1958 ** (49ms)
76 76 ksoftirqd/11 1959 ** (39ms)
76 76 ksoftirqd/11 1960 ** (29ms)
76 76 ksoftirqd/11 1961 ** (19ms)
76 76 ksoftirqd/11 1962 ** (9ms)
--
10137 10436 cadvisor 2068
10137 10436 cadvisor 2069
76 76 ksoftirqd/11 2070 ** 75ms
76 76 ksoftirqd/11 2071 ** 65ms
76 76 ksoftirqd/11 2072 ** 55ms
76 76 ksoftirqd/11 2073 ** (45ms)
76 76 ksoftirqd/11 2074 ** (35ms)
76 76 ksoftirqd/11 2075 ** (25ms)
76 76 ksoftirqd/11 2076 ** (15ms)
76 76 ksoftirqd/11 2077 ** (5ms)

Результаты говорят нам о нескольких вещах. Во-первых, все эти пакеты обрабатывает контекст ksoftirqd/11. Это значит, что для этой конкретной пары машин ICMP-пакеты хэшировались на ядро 11 у принимающей стороны. Мы также видим, что при каждом заторе присутствуют пакеты, которые обрабатываются в контексте системного вызова cadvisor. Затем ksoftirqd берёт задачу на себя и отрабатывает накопленную очередь: именно то количество пакетов, которое накопилось после cadvisor.

По иронии, предназначение cadvisor — «анализировать использование ресурсов и характеристики производительности запущенных контейнеров», а не вызывать эту проблему с производительностью. Тот факт, что непосредственно перед этим всегда работает cadvisor, подразумевает его причастность в проблеме.

Как и с другими аспектами работы контейнеров, это всё крайне передовой инструментарий, от которого вполне можно ожидать проблем с производительностью в некоторых непредвиденных обстоятельствах.

Теперь у нас есть довольно хорошее понимание, как происходит сбой, какой процесс его вызывает и на каком CPU. Мы видим, что из-за жёсткой блокировки ядро Linux не успевает вовремя запланировать ksoftirqd. И мы видим, что пакеты обрабатываются в контексте cadvisor. Логично предположить, что cadvisor запускает медленный syscall, после которого обрабатываются все скопившиеся в это время пакеты:

Что мы можем сделать, так это проследить работу ядра CPU на протяжении всего этого процесса, найти точку, где происходит превышение бюджета на количество пакетов и вызывается ksoftirqd, а затем посмотреть чуть раньше — что именно работало на ядре CPU непосредственно перед этим моментом. Это теория, но как её проверить? Он будет выглядеть примерно так: Это как рентгеновский снимок CPU каждые несколько миллисекунд.

Например, perf record с указанной периодичностью проверяет заданное ядро CPU и может генерировать график вызовов работающей системы, включая и пространство пользователя, и ядро Linux. Удобно, что всё это можно сделать существующими инструментами. Мы можем сохранять однострочные трассировки стека каждые 1 мс, а затем выделить и сохранить образец за 100 миллисекунд перед тем, как в трассировку попадает ksoftirqd: Можно взять эту запись и обработать её с помощью небольшого форка программы FlameGraph от Брендана Грегга, который сохраняет порядок трассировки стека.

# record 999 times a second, or every 1ms with some offset so not to align exactly with timers
sudo perf record -C 11 -g -F 999
# take that recording and make a simpler stack trace.
sudo perf script 2>/dev/null | ./FlameGraph/stackcollapse-perf-ordered.pl | grep ksoftir -B 100

Вот результаты:

(сотни следов, которые выглядят похожими)

cadvisor;[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];entry_SYSCALL_64_after_swapgs;do_syscall_64;sys_read;vfs_read;seq_read;memcg_stat_show;mem_cgroup_nr_lru_pages;mem_cgroup_node_nr_lru_pages cadvisor;[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];entry_SYSCALL_64_after_swapgs;do_syscall_64;sys_read;vfs_read;seq_read;memcg_stat_show;mem_cgroup_nr_lru_pages;mem_cgroup_node_nr_lru_pages cadvisor;[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];entry_SYSCALL_64_after_swapgs;do_syscall_64;sys_read;vfs_read;seq_read;memcg_stat_show;mem_cgroup_iter cadvisor;[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];entry_SYSCALL_64_after_swapgs;do_syscall_64;sys_read;vfs_read;seq_read;memcg_stat_show;mem_cgroup_nr_lru_pages;mem_cgroup_node_nr_lru_pages cadvisor;[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];entry_SYSCALL_64_after_swapgs;do_syscall_64;sys_read;vfs_read;seq_read;memcg_stat_show;mem_cgroup_nr_lru_pages;mem_cgroup_node_nr_lru_pages ksoftirqd/11;ret_from_fork;kthread;kthread;smpboot_thread_fn;smpboot_thread_fn;run_ksoftirqd;__do_softirq;net_rx_action;ixgbe_poll;ixgbe_clean_rx_irq;napi_gro_receive;netif_receive_skb_internal;inet_gro_receive;bond_handle_frame;__netif_receive_skb_core;ip_rcv_finish;ip_rcv;ip_forward_finish;ip_forward;ip_finish_output;nf_iterate;ip_output;ip_finish_output2;__dev_queue_xmit;dev_hard_start_xmit;ipip_tunnel_xmit;ip_tunnel_xmit;iptunnel_xmit;ip_local_out;dst_output;__ip_local_out;nf_hook_slow;nf_iterate;nf_conntrack_in;generic_packet;ipt_do_table;set_match_v4;ip_set_test;hash_net4_kadt;ixgbe_xmit_frame_ring;swiotlb_dma_mapping_error;hash_net4_test ksoftirqd/11;ret_from_fork;kthread;kthread;smpboot_thread_fn;smpboot_thread_fn;run_ksoftirqd;__do_softirq;net_rx_action;gro_cell_poll;napi_gro_receive;netif_receive_skb_internal;inet_gro_receive;__netif_receive_skb_core;ip_rcv_finish;ip_rcv;ip_forward_finish;ip_forward;ip_finish_output;nf_iterate;ip_output;ip_finish_output2;__dev_queue_xmit;dev_hard_start_xmit;dev_queue_xmit_nit;packet_rcv;tpacket_rcv;sch_direct_xmit;validate_xmit_skb_list;validate_xmit_skb;netif_skb_features;ixgbe_xmit_frame_ring;swiotlb_dma_mapping_error;__dev_queue_xmit;dev_hard_start_xmit;__bpf_prog_run;__bpf_prog_run

Что это значит? Здесь много чего, но главное, что мы находим шаблон «cadvisor перед ksoftirqd», который видели раньше в трейсере ICMP.

Каждый вызов вниз по стеку в строке разделяется точкой с запятой. Каждая строка — это трассировка CPU в определённый момент времени. ;do_syscall_64;sys_read; .... В середине строк мы видим вызываемый syscall: read(): .... Таким образом, cadvisor тратит много времени на системный вызов read(), относящийся к функциям mem_cgroup_* (верхняя часть стека вызовов/конец строки).

В трассировке вызовов неудобно смотреть, что именно читается, поэтому запустим strace и посмотрим, что делает cadvisor, и найдём системные вызовы дольше 100 мс:

futex resumed> ) = 0 <0. theojulienne@kube-node-bad ~ $ sudo strace -p 10137 -T -ff 2>&1 | egrep '<0\.[1-9]'
[pid 10436] <... futex resumed> ) = 0 <0. 156784>
[pid 10432] <... futex resumed> ) = 0 <0. 258285>
[pid 10137] <... futex resumed> ) = 0 <0. 678382>
[pid 10384] <... read resumed> "cache 154234880\nrss 507904\nrss_h"..., 4096) = 658 <0. 762328>
[pid 10436] <... futex resumed> ) = 0 <0. 179438>
[pid 10384] <... futex resumed> ) = 0 <0. 104614>
[pid 10436] <... read resumed> "cache 0\nrss 0\nrss_huge 0\nmapped_"..., 4096) = 577 <0. 175936>
[pid 10436] <... read resumed> "cache 0\nrss 0\nrss_huge 0\nmapped_"..., 4096) = 577 <0. 228091>
[pid 10427] <... epoll_ctl resumed> ) = 0 <0. 207334>
[pid 10411] <... pselect6 resumed> ) = 0 (Timeout) <0. 118113>
[pid 10382] <... read resumed> "cache 154234880\nrss 507904\nrss_h"..., 4096) = 660 <0. 117717>
[pid 10436] <... futex resumed> ) = 0 <0. 159891>
[pid 10417] <... futex resumed> ) = 0 <0. 917495>
[pid 10436] <... futex resumed> ) = 0 <0. 208172>
[pid 10417] <... read resumed> "cache 0\nrss 0\nrss_huge 0\nmapped_"..., 4096) = 576 <0. 190763>
[pid 10417] <... 154442>

Из содержимого операций чтения и контекста mem_cgroup видно, что эти вызовы read() относятся к файлу memory.stat, который показывает использование памяти и ограничения cgroup (технология изоляции ресурсов в Docker). Как и можно было предположить, здесь мы видим медленные вызовы read(). Давайте проверим, это ядро или cadvisor делает что-то неожиданное: Инструмент cadvisor опрашивает этот файл, чтобы получить сведения об использовании ресурсов для контейнеров.

theojulienne@kube-node-bad ~ $ time cat /sys/fs/cgroup/memory/memory.stat >/dev/null

153s
user 0m0. real 0m0. 152s
theojulienne@kube-node-bad ~ $ 000s
sys 0m0.

Теперь мы можем воспроизвести баг и понимаем, что ядро Linux сталкивается с патологией.

На этом этапе гораздо проще найти сообщения других пользователей о подобных проблемах. Как оказалось, в трекере cadvisor об этом баге сообщали как о проблеме излишнего использования CPU, просто никто не заметил, что задержка также случайным образом отражается в сетевом стеке. Действительно было замечено, что cadvisor потребляет больше процессорного времени, чем ожидалось, но этому не придали особого значения, ведь у наших серверов много процессорных ресурсов, так что проблему тщательно не изучали.

Когда все процессы в этой cgroup завершаются, Docker освобождает контрольную группу памяти. Проблема заключается в том, что контрольные группы (cgroups) учитывают использование памяти внутри пространства имён (контейнера). Хотя сама память процессов больше не используется, оказывается, ядро назначает ещё кэшированное содержимое, такое как dentries и inodes (метаданные каталогов и файлов), которые кэшируются в memory cgroup. Однако «память» — это не просто память процесса. Из описания проблемы:

cgroups-зомби: контрольные группы, в которых нет процессов и они удалены, но для которых всё ещё выделена память (в моём случае, из кэша dentry, но она также может выделяться из кэша страниц или tmpfs).

Проверка ядром всех страниц в кэше при освобождении cgroup может быть очень медленной, поэтому выбран ленивый процесс: подождать, пока эти страницы будут снова запрошены, и уже тогда, когда память действительно потребуется, наконец, очистить cgroup. До этого момента cgroup по-прежнему учитывается при сборе статистики.

Это нормально. С точки зрения производительности, они пожертвовали памятью ради производительности: ускорение первоначальной очистки за счёт того, что остаётся немного кэшированной памяти. К сожалению, конкретная реализация механизма поиска memory.stat в этой версии ядра (4. Когда ядро использует последнюю часть кэшированной памяти, cgroup в конечном итоге очищается, так что это нельзя назвать «утечкой». 9), в сочетании с огромным объёмом памяти на наших серверах, приводит к тому, что для восстановления последних кэшированных данных и очистки cgroup-зомби требуется гораздо больше времени.

Оказывается, на некоторых наших узлах было так много cgroup-зомби, что чтение и задержка превышали секунду.

Это не решение, но подтверждает причину проблемы. Способ обхода проблемы cadvisor — немедленно освободить кэши dentries/inodes по всей системе, что сразу устраняет задержку чтения, а также сетевую задержку на хосте, так как удаление кэша включает кэшированные страницы cgroup-зомби, а они тоже освобождаются.

19+) улучшена производительность вызова memory.stat, так что переход на это ядро устранял проблему. Оказалось, что в более новых версиях ядра (4. Мы прочесали все кластеры, нашли узлы с достаточно высокой задержкой и перезагрузили их. В то же время у нас был инструментарий для обнаружения проблемных узлов в кластерах Kubernetes, их изящного слива и перезагрузки. Это дало нам время для обновления ОС на остальных серверах.

Поскольку этот баг останавливал обработку очередей NIC RX на сотни миллисекунд, он одновременно вызывал и большую задержку на коротких соединениях, и задержку в середине соединения, например, между запросами MySQL и ответными пакетами.

От улучшений производительности Kubernetes выигрывают все запускаемые системы. Понимание и поддержка производительности самых фундаментальных систем, таких как Kubernetes, имеет решающее значение для надёжности и скорости всех сервисов на их основе.

Теги
Показать больше

Похожие статьи

Добавить комментарий

Ваш адрес email не будет опубликован. Обязательные поля помечены *

Кнопка «Наверх»
Закрыть