Преди няколко години Kubernetes в официалния блог на GitHub. Оттогава той стана стандартна технология за разгръщане на услуги. Сега Kubernetes управлява значителна част от вътрешните и публични услуги. Тъй като нашите клъстери нараснаха и изискванията към производителността станаха по-строги, започнахме да забелязваме, че в някои услуги на Kubernetes спорадично се появяват закъснения, които не могат да бъдат обяснени от натоварването на самото приложение.
По същество, в приложенията се наблюдава случайно мрежово закъснение до 100 ms и повече, което води до таймаути или повторни опити. Очакваше се услугите да могат да отговорят на заявките много по-бързо от 100 ms. Но това е невъзможно, ако самото свързване отнема толкова време. Поотделно наблюдавахме много бързи MySQL заявки, които трябваше да отнемат милисекунди, и MySQL наистина се справяше с милисекунди, но от гледна точка на заявяващото приложение, отговорът отнемаше 100 ms или повече.
Бързо стана ясно, че проблемът възниква само при свързване с възел на Kubernetes, дори когато заявката идва отвън Kubernetes. Най-лесно е да се възпроизведе проблемът в теста , който се стартира от всяка вътрешна хост, тества услугата Kubernetes на определен порт и спорадично регистрира големи закъснения. В тази статия ще разгледаме как успяхме да проследим причината за този проблем.
Премахване на излишната сложност в веригата към провала
Възпроизвеждайки същия пример, искахме да стесним фокуса на проблема и да премахнем излишните слоеве сложност. Първоначално в потока между Vegeta и подовете в Kubernetes имаше твърде много елементи. За да определим по-дълбок мрежов проблем, трябваше да изключим някои от тях.
Клиентът (Vegeta) създава TCP свързване с който и да е възел в клъстера. Kubernetes функционира като оверлейна мрежа (върху съществуващата мрежа на дата центъра), която използва , тоест инкапсулира IP пакети от оверлейната мрежа в IP пакети на дата центъра. При свързване с първия възел, се извършва преобразуване на мрежовите адреси. (NAT) с мониторинг на състоянието за преобразуване на IP адреса и порта на Kubernetes възела в IP адрес и порт в оверлейната мрежа (в частност, на pod с приложението). За пристигащите пакети се изпълнява обратната последователност. Това е сложна система с много състояния и множество елементи, които постоянно се обновяват и променят по време на разгръщането и движението на услугите.
Утилита tcpdump в теста Vegeta предизвиква забавяне по време на TCP ръкостискане (между SYN и SYN-ACK). За да премахнем тази излишна сложност, можем да използваме hping3 за простички «пинги» с пакети SYN. Проверяваме за забавяне в отговорния пакет и след това нулираме връзката. Можем да филтрираме данните, като включим само пакети над 100 ms, и да получим по-опростен вариант за възпроизвеждане на проблема, отколкото пълния тест на мрежовото ниво 7 в Vegeta. Ето «пингите» на Kubernetes възела, използвайки TCP SYN/SYN-ACK на «възловия порт» на услугата (30927) с интервал от 10 ms, филтрирани по най-бавните отговори:
theojulienne@shell ~ $ sudo hping3 172.16.47.27 -S -p 30927 -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}.'
len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flags=SA seq=1485 win=29200 rtt=127.1 ms
len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flags=SA seq=1486 win=29200 rtt=117.0 ms
len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flags=SA seq=1487 win=29200 rtt=106.2 ms
len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flags=SA seq=1488 win=29200 rtt=104.1 ms
len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flags=SA seq=5024 win=29200 rtt=109.2 ms
len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flags=SA seq=5231 win=29200 rtt=109.2 ms
Веднага можем да направим първото наблюдение. По последователностите и тайминга се вижда, че това не са еднократни задръствания. Забавянето често се натрупва и в крайна сметка се обработва.
Следващата стъпка е да разберем кои компоненти могат да бъдат отговорни за появата на задръстването. Може би това са някои от стотици правила на iptables в NAT? Или пък имаме проблеми с тунелирането на IPIP в мрежата? Един от начините да го проверим е да прегледаме всяка стъпка на системата, като я изключим. Какво ще стане, ако премахнем NAT и логиката на защитната стена, оставяйки само част от IPIP:
За щастие, Linux позволява лесен достъп до оверлейния слой IP, ако машината е в същата мрежа:
theojulienne@kube-node-client ~ $ sudo hping3 10.125.20.64 -S -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}.'
len=40 ip=10.125.20.64 ttl=64 DF id=0 sport=0 flags=RA seq=7346 win=0 rtt=127.3 ms
len=40 ip=10.125.20.64 ttl=64 DF id=0 sport=0 flags=RA seq=7347 win=0 rtt=117.3 ms
len=40 ip=10.125.20.64 ttl=64 DF id=0 sport=0 flags=RA seq=7348 win=0 rtt=107.2 ms
Според резултатите, проблемът все още съществува! Това изключва iptables и NAT. Значи проблемът е в TCP? Нека да видим как ще протече обикновения ICMP ping:
theojulienne@kube-node-client ~ $ sudo hping3 10.125.20.64 --icmp -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}.'
len=28 ip=10.125.20.64 ttl=64 id=42594 icmp_seq=104 rtt=110.0 ms
len=28 ip=10.125.20.64 ttl=64 id=49448 icmp_seq=4022 rtt=141.3 ms
len=28 ip=10.125.20.64 ttl=64 id=49449 icmp_seq=4023 rtt=131.3 ms
len=28 ip=10.125.20.64 ttl=64 id=49450 icmp_seq=4024 rtt=121.2 ms
len=28 ip=10.125.20.64 ttl=64 id=49451 icmp_seq=4025 rtt=111.2 ms
len=28 ip=10.125.20.64 ttl=64 id=49452 icmp_seq=4026 rtt=101.1 ms
len=28 ip=10.125.20.64 ttl=64 id=50023 icmp_seq=4343 rtt=126.8 ms
len=28 ip=10.125.20.64 ttl=64 id=50024 icmp_seq=4344 rtt=116.8 ms
len=28 ip=10.125.20.64 ttl=64 id=50025 icmp_seq=4345 rtt=106.8 ms
len=28 ip=10.125.20.64 ttl=64 id=59727 icmp_seq=9836 rtt=106.1 ms
Резултатите показват, че проблемът не е изчезнал. Може би е тунел IPIP? Нека да опростим теста:
Всички пакети ли се изпращат между тези два хоста?
theojulienne@kube-node-client ~ $ sudo hping3 172.16.47.27 --icmp -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}.'
len=46 ip=172.16.47.27 ttl=61 id=41127 icmp_seq=12564 rtt=140.9 ms
len=46 ip=172.16.47.27 ttl=61 id=41128 icmp_seq=12565 rtt=130.9 ms
len=46 ip=172.16.47.27 ttl=61 id=41129 icmp_seq=12566 rtt=120.8 ms
len=46 ip=172.16.47.27 ttl=61 id=41130 icmp_seq=12567 rtt=110.8 ms
len=46 ip=172.16.47.27 ttl=61 id=41131 icmp_seq=12568 rtt=100.7 ms
len=46 ip=172.16.47.27 ttl=61 id=9062 icmp_seq=31443 rtt=134.2 ms
len=46 ip=172.16.47.27 ttl=61 id=9063 icmp_seq=31444 rtt=124.2 ms
len=46 ip=172.16.47.27 ttl=61 id=9064 icmp_seq=31445 rtt=114.2 ms
len=46 ip=172.16.47.27 ttl=61 id=9065 icmp_seq=31446 rtt=104.2 ms
Упрощихме ситуацията до два възела Kubernetes, изпращащи си всякакви пакети, дори ICMP ping. Те все още виждат закъснение, ако целевият хост е "лош" (някои са по-лоши от други).
Сега последния въпрос: защо закъснението възниква само на сървърите kube-node? И то се случва, когато kube-node е изпращач или получател? За радост, това също е доста лесно да се разбере, като се изпрати пакет от хост извън Kubernetes, но с същия "известен лош" получател. Както виждаме, проблемът не е изчезнал:
theojulienne@shell ~ $ sudo hping3 172.16.47.27 -p 9876 -S -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}.'
len=46 ip=172.16.47.27 ttl=61 DF id=0 sport=9876 flags=RA seq=312 win=0 rtt=108.5 ms
len=46 ip=172.16.47.27 ttl=61 DF id=0 sport=9876 flags=RA seq=5903 win=0 rtt=119.4 ms
len=46 ip=172.16.47.27 ttl=61 DF id=0 sport=9876 flags=RA seq=6227 win=0 rtt=139.9 ms
len=46 ip=172.16.47.27 ttl=61 DF id=0 sport=9876 flags=RA seq=7929 win=0 rtt=131.2 ms
След това ще изпълним същите заявки от предходния изходен kube-node към външен хост (което изключва изходния хост, тъй като ping включва както компонент RX, така и TX):
theojulienne@kube-node-client ~ $ sudo hping3 172.16.33.44 -p 9876 -S -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}.'
^C
--- 172.16.33.44 хпинг статистика ---
22352 пакета предадени, 22350 пакета получени, 1% загуба на пакети
време за обратна връзка мин/средно/макс = 0.2/7.6/1010.6 ms
Изучавайки захващането на пакети със забавяне, получихме допълнителна информация. По-специално, изпращачът (вдясно) вижда този таймаут, докато получателят (вляво) не го вижда — вижте колоната Delta (в секунди):
Освен това, ако погледнем различията в реда на пакетите TCP и ICMP (по номера на пакета) от страната на получателя, пакетите ICMP винаги пристигат в същата последователност, в която са изпратени, но с различно време. Докато пакетите TCP понякога се редуват и част от тях се забавят. По-специално, ако разгледаме портовете на пакета SYN, от страната на изпращача те са в ред, а от страната на получателя не са.
Има фина разлика в начина, по който на съвременните сървъри (като в нашия дата център) обработват пакети, съдържащи TCP или ICMP. Когато пристигне пакет, мрежовият адаптер „хешира го по свързване“, т.е. се опитва да разпредели връзките по опашки и да изпрати всяка опашка на отделно ядро на процесора. За TCP този хеш включва както изходния, така и крайния IP адрес и порт. С други думи, всяка връзка се хешира (потенциално) по различен начин. За ICMP се хешират само IP адресите, тъй като няма портове.
Друго ново наблюдение: през този период виждаме забавяния на ICMP при всички комуникации между двата хоста, докато при TCP не наблюдаваме. Това ни показва, че причината вероятно е свързана с хеширане на RX опашки: почти сигурно заторът възниква в обработката на RX пакети, а не в изпращането на отговори.
Това изключва възможността проблемът да е в изпращането на пакети. Сега знаем, че проблемът с обработката на пакети е от страна на приемането на определени сървъри kube-node.
Разглеждаме обработката на пакети в ядрото на Linux
За да разберем защо проблемът се проявява у получателя на определени сървъри kube-node, нека видим как ядрото на Linux обработва пакетите.
Връщайки се към най-простата традиционна имплементация, мрежовата карта получава пакет и изпраща на ядрото на Linux, което означава, че пакетът трябва да бъде обработен. Ядрото спира да изпълнява друга работа, превключва контекста към обработвача на прекъсвания, обработва пакета и след това се връща към текущите задачи.
Тази смяна на контекста става бавно: възможно е забавянето да е било незабележимо на 10-гигабитни мрежови карти в 90-те години, но на съвременните 10G карти с максимална пропускателна способност от 15 милиона пакета в секунда, всяко ядро на малък осемядрен сървър може да бъде прекъсвано милиони пъти в секунда.
За да не се налага постоянно обработване на прекъсвания, преди много години в Linux беше добавен : мрежов API, който всички съвременни драйвери използват за подобряване на производителността при високи скорости. При ниски скорости ядрото все още приема прекъсвания от мрежовата карта по стария начин. Когато дойде достатъчно количество пакети, което надвишава прага, ядрото деактивира прекъсванията и вместо това започва да опитва мрежовия адаптер и да взима пакетите на порции. Обработката се извършва в softirq, т.е. в след системните повиквания и хардуерните прекъсвания, когато ядрото (в отличие от потребителското пространство) вече е стартирано.
Това е много по-бързо, но създава друг проблем. Ако пакетите са твърде много, всичкото време отива за обработка на пакети от мрежовата карта, а процесите в потребителското пространство не успяват действително да опразнят тези опашки (четене от TCP връзки и т.н.). В крайна сметка опашките се запълват и започваме да отхвърляме пакети. Опитвайки се да намери баланс, ядрото установява бюджет за максималния брой пакети, обработвани в контекста на softirq. Когато този бюджет бъде надминат, се събужда отделен поток ksoftirqd (ще видите един от тях в ps за всяко ядро), който обработва тези softirq извън обичайния път syscall/interrupt. Този поток се планира с помощта на стандартния планировчик на процеси, който се опитва да разпредели ресурсите справедливо.
Изследвайки как ядрото обработва пакети, може да се забележи, че тук има определена вероятност за появата на задръствания. Ако повикванията на softirq постъпват по-рядко, пакетите ще трябва да изчакат известно време за обработка в опашката RX на мрежовата карта. Възможно е това да се случва заради някаква задача, блокираща ядрото на процесора, или нещо друго пречи на ядрото да стартира softirq.
Стесняваме обработката до ядрото или метода
Забавления softirq са все още само хипотеза. Но тя има смисъл и знаем, че наблюдаваме нещо много подобно. Следователно, следващата стъпка е да потвърдим тази теория. И ако се потвърди, да намерим причината за забавянията.
Нека се върнем към нашите бавни пакети:
len=46 ip=172.16.53.32 ttl=61 id=29573 icmp_seq=1953 rtt=99.3 ms
len=46 ip=172.16.53.32 ttl=61 id=29574 icmp_seq=1954 rtt=89.3 ms
len=46 ip=172.16.53.32 ttl=61 id=29575 icmp_seq=1955 rtt=79.2 ms
len=46 ip=172.16.53.32 ttl=61 id=29576 icmp_seq=1956 rtt=69.1 ms
len=46 ip=172.16.53.32 ttl=61 id=29577 icmp_seq=1957 rtt=59.1 ms
len=46 ip=172.16.53.32 ttl=61 id=29790 icmp_seq=2070 rtt=75.7 ms
len=46 ip=172.16.53.32 ttl=61 id=29791 icmp_seq=2071 rtt=65.6 ms
len=46 ip=172.16.53.32 ttl=61 id=29792 icmp_seq=2072 rtt=55.5 ms
Както бе обсъдено по-рано, тези ICMP пакети се хешират в една опашка NIC RX и се обработват от едно ядро на CPU. Ако искаме да разберем как работи Linux, е полезно да знаем къде (на кое ядро на CPU) и как (softirq, ksoftirqd) се обработват тези пакети, за да проследим процеса.
Сега е време да използваме инструменти, които позволяват в реално време да следим работата на ядрото на Linux. Тук използвахме . Този набор от инструменти позволява писането на малки програми на C, които прихващат произволни функции в ядрото и буферизира събития в Python програма в потребителското пространство, която може да ги обработи и да върне резултата. Хукването на произволни функции в ядрото е сложна работа, но инструментът е проектиран с максимална безопасност и е предназначен за проследяване на такива производствени проблеми, които не е лесно да се воспроизведат в тестова или развойна среда.
Планът тук е прост: знаем, че ядро обработва тези ICMP пингове, затова ще поставим хук на функцията на ядрото , която приема входящ ICMP пакет „echo request“ и инициира изпращането на ICMP отговор „echo response“. Можем да идентифицираме пакета по увеличаването на номера на icmp_seq, който показва hping3 над.
Код изглежда сложен, но не е толкова страшен, колкото изглежда. Функция icmp_echo передаёт struct sk_buff *skb: това е пакет с запрос „echo request“. Можем да го проследим, да извадим последователността 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 процесите, които правят системни повиквания, ще се покажат като "процеси", макар че всъщност ядрото безопасно обработва пакети в контекста на ядрото.
С този инструмент можем да установим връзка между конкретни процеси и конкретни пакети, които показват закъснение в hping3. Извършваме прост grep на този улов за определени стойности icmp_seq. Пакетите, които съответстват на посочените по-горе стойности icmp_seq, бяха маркирани заедно с тяхното RTT, което наблюдавахме по-горе (в скобите са посочените очаквани стойности RTT на пакетите, които филтрирахме заради стойности на RTT под 50 ms):
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 на всеки няколко милисекунди. Ще изглежда приблизително така:
Удобно е, че всичко това може да се направи с наличните инструменти. Например, с определена периодичност проверява конкретно ядро на CPU и може да генерира графика на обажданията на работната система, включително и пространството на потребителя, и ядрото на Linux. Може да вземем тази записи и да я обработим с помощта на малък форк на програмата от Брендан Грегг, който запазва реда на трасировката на стека. Можем да запазваме едноредови трасировки на стека на всеки 1 мс и след това да изолираме и запазим образец за 100 милисекунди преди да влезе в трасировката ksoftirqd:
# 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];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];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];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];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 в определен момент. Всеки извикване в стека е разделено с точка и запетая. В средата на линиите виждаме извиквания syscall: read(): .... ;do_syscall_64;sys_read; .... Така cadvisor прекарва много време в системен повик. read(), свързано с функциите mem_cgroup_* (горната част на стека на извикванията/края на реда).
В трасировката на извикванията е неудобно да се види какво точно се чете, затова ще стартираме strace и ще разгледаме какво прави cadvisor, за да открием системните извиквания, които отнемат повече от 100 ms:
theojulienne@kube-node-bad ~ $ sudo strace -p 10137 -T -ff 2>&1 | egrep '<0.[1-9]'
[pid 10436] ) = 0
[pid 10432] ) = 0
[pid 10137] ) = 0
[pid 10384] ) = 0
[pid 10436] "cache 154234880nrss 507904nrss_h"..., 4096) = 658
[pid 10384] ) = 0
[pid 10436] ) = 0
[pid 10436] "cache 0nrss 0nrss_huge 0nmapped_"..., 4096) = 577
[pid 10427] "cache 0nrss 0nrss_huge 0nmapped_"..., 4096) = 577
[pid 10411] ) = 0
[pid 10382] ) = 0 (Timeout)
[pid 10436] "cache 154234880nrss 507904nrss_h"..., 4096) = 660
[pid 10417] ) = 0
[pid 10436] ) = 0
[pid 10417] ) = 0
[pid 10417] "cache 0nrss 0nrss_huge 0nmapped_"..., 4096) = 576
Както можеше да се очаква, тук виждаме бавни извиквания read(). От съдържанието на операциите за четене и контекста mem_cgroup вижда се, че тези извиквания read() се отнасят до файла memory.stat, който показва използването на паметта и ограниченията на cgroup (технология за изолация на ресурси в Docker). Инструментът cadvisor опитва да прочете този файл, за да получи информация за ресурсното използване на контейнерите. Нека проверим дали ядрото или cadvisor прави нещо неочаквано:
theojulienne@kube-node-bad ~ $ time cat /sys/fs/cgroup/memory/memory.stat >/dev/null
реално 0m0.153s
потребител 0m0.000s
система 0m0.152s
theojulienne@kube-node-bad ~ $
Сега можем да повторим бъга и разбираме, че ядрото на Linux се сблъсква с патология.
Какво прави операциите за четене толкова бавни?
На този етап е много по-лесно да се намерят съобщения от други потребители за подобни проблеми. Както се оказа, в трекера на cadvisor е било докладвано за този бъг като , просто никой не е забелязал, че забавянето случайно се отразява и в мрежовия стек. Наистина е било забелязано, че cadvisor консумира повече процесорно време, отколкото беше очаквано, но не му обърнаха особено внимание, тъй като нашите сървъри имат много ресурс на процесора, затова проблема не беше проучен подробно.
Проблемът е, че контролни групи (cgroups) отчитат използването на паметта в пространството на имена (контейнера). Когато всички процеси в тази cgroup приключат, Docker освобождава контролна група памет. Въпреки това „паметта“ не е просто памет на процеса. Въпреки че самата памет на процесите вече не се използва, се оказва, че ядрото задава още кеширано съдържание, като dentries и inodes (метаданни на директории и файлове), които се кешират в memory cgroup. От описанието на проблема:
cgroups-зомби: контролни групи, в които няма процеси и те са премахнати, но за които все още е отделена памет (в моя случай, от кеша на dentry, но може също така да бъде отделена от кеша на страниците или tmpfs).
Проверка на ядрото на всички страници в кеша при освобождаване на cgroup може да бъде много бавна, затова е избран мързелив процес: да се изчака, докато тези страници отново бъдат поискани, и едва тогава, когато паметта наистина бъде необходима, накрая да се почисти cgroup. До този момент cgroup все още се взима предвид при събирането на статистика.
От гледна точка на производителността, те sacrifice памет за сметка на производителността: ускоряване на първичното почистване благодарение на остатъка от малко кеширана памет. Това е приемливо. Когато ядрото използва последната част от кешираната памет, cgroup в крайна сметка се изчиства, така че не може да се нарече "изтичане". За съжаление, конкретната реализация на механизма за търсене memory.stat в тази версия на ядрото (4.9), в комбинация с огромния обем памет на нашите сървъри, води до това, че възстановяването на последните кеширани данни и почистването на cgroup-зомби отнема много повече време.
Оказа се, че на някои от нашите възли е имало толкова много cgroup-зомби, че четенето и забавянето надхвърляха секундата.
Начинът за заобикаляне на проблема с cadvisor е незабавното освобождаване на кешовете dentries/inodes в цялата система, което веднага премахва забавянето при четене, както и мрежовото забавяне на хоста, тъй като изтриването на кеша включва кешираните страници на cgroup-зомби, а те също се освобождават. Това не е решение, но потвърджава причината за проблема.
Оказа се, че в по-новите версии на ядрото (4.19+) производителността на извикването е подобрена, memory.stat, така че преминаването на това ядро решава проблема. В същото време имахме инструменти за откриване на проблемни възли в клъстери Kubernetes, техния елегантен слив и рестартиране. Проверихме всички клъстери, намерихме възли с доста високо забавяне и ги рестартирахме. Това ни даде време за обновление на ОС на останалите сървъри.
В обобщение
Тъй като този бъг спираше обработката на опашките NIC RX за стотици милисекунди, той едновременно предизвикваше голямо забавяне на кратките съединения и забавяне в средата на съединението, например между MySQL заявки и отговорни пакети.
Разбирането и поддръжката на производителността на най-основните системи, като Kubernetes, е от решаващо значение за надеждността и бързината на всички услуги на тяхна база. Всички системи, които се стартират, печелят от подобренията на производителността на Kubernetes.
Източник: habr.com
