Преди няколко години 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 адреса и порта в мрежата с наслагване (по-специално, под с приложението). За входящите пакети се извършва обратната последователност от действия. Това е сложна система с много състояния и много елементи, които постоянно се актуализират и променят, докато услугите се разгръщат и преместват.
Полезност tcpdump в теста Vegeta има забавяне по време на TCP ръкостискането (между SYN и SYN-ACK). За да премахнете тази ненужна сложност, можете да използвате hping3 за прости „пингове“ със SYN пакети. Проверяваме дали има забавяне в пакета за отговор и след това нулираме връзката. Можем да филтрираме данните, така че да включват само пакети, по-големи от 100 ms, и да получим по-лесен начин за възпроизвеждане на проблема от пълния мрежов слой 7 на Vegeta. Ето Kubernetes възел "pings" с помощта на TCP SYN/SYN-ACK на услугата "node port" (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 пинг:
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-възел към външния хост (което изключва хоста източник, тъй като 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 hping statistic ---
22352 packets transmitted, 22350 packets received, 1% packet loss
round-trip min/avg/max = 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, че има пакет, който трябва да бъде обработен. Ядрото спира друга работа, превключва контекста към манипулатора на прекъсвания, обработва пакета и след това се връща към текущите задачи.
Това превключване на контекста е бавно: латентността може да не е била забележима на 10Mbps мрежови карти през 90-те години, но на модерни 10G карти с максимална пропускателна способност от 15 милиона пакета в секунда, всяко ядро на малък осемядрен сървър може да бъде прекъснато милиони пъти в секунда.
За да не обработва непрекъснато прекъсванията, преди много години добави Linux : Мрежов API, който всички съвременни драйвери използват за подобряване на производителността при високи скорости. При ниски скорости ядрото все още получава прекъсвания от мрежовата карта по стария начин. След като пристигнат достатъчно пакети, които надхвърлят прага, ядрото деактивира прекъсванията и вместо това започва да проверява мрежовия адаптер и да събира пакети на парчета. Обработката се извършва в softirq, тоест в след системни повиквания и хардуерни прекъсвания, когато ядрото (за разлика от потребителското пространство) вече работи.
Това е много по-бързо, но причинява различен проблем. Ако има твърде много пакети, тогава цялото време се изразходва за обработка на пакети от мрежовата карта и процесите в потребителското пространство нямат време действително да изпразнят тези опашки (четене от TCP връзки и т.н.). В крайна сметка опашките се запълват и започваме да пускаме пакети. В опит да намери баланс, ядрото определя бюджет за максималния брой пакети, обработени в контекста на softirq. След като този бюджет бъде надвишен, се събужда отделна нишка ksoftirqd (ще видите един от тях в ps на ядро), който обработва тези softirqs извън нормалния път на syscall/прекъсване. Тази нишка е планирана с помощта на стандартния планировчик на процеси, който се опитва да разпредели справедливо ресурсите.
След като сте проучили как ядрото обработва пакети, можете да видите, че има известна вероятност от задръстване. Ако 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 пакети се хешират в една RX NIC опашка и се обработват от едно ядро на процесора. Ако искаме да разберем как работи Linux, е полезно да знаем къде (на кое процесорно ядро) и как (softirq, ksoftirqd) се обработват тези пакети, за да проследим процеса.
Сега е време да използвате инструменти, които ви позволяват да наблюдавате ядрото на Linux в реално време. Тук използвахме . Този набор от инструменти ви позволява да пишете малки C програми, които закачат произволни функции в ядрото и буферират събитията в Python програма в потребителското пространство, която може да ги обработи и да ви върне резултата. Закачането на произволни функции в ядрото е сложен въпрос, но помощната програма е предназначена за максимална сигурност и е проектирана да проследява точно този вид производствени проблеми, които не се възпроизвеждат лесно в среда за тестване или разработка.
Планът тук е прост: ние знаем, че ядрото обработва тези ICMP ping, така че ще поставим кука на функцията на ядрото , който приема входящ пакет с ICMP ехо заявка и инициира изпращане на ICMP ехо отговор. Можем да идентифицираме пакет, като увеличим номера на icmp_seq, който се показва hping3 по-висок.
Код изглежда сложно, но не е толкова страшно, колкото изглежда. функция icmp_echo предава struct sk_buff *skb: Това е пакет с "ехо заявка". Можем да го проследим, да извадим последователността echo.sequence (което се сравнява с icmp_seq от hping3 выше) и го изпратете в потребителското пространство. Също така е удобно да заснемете името/идентификационния номер на текущия процес. По-долу са резултатите, които виждаме директно, докато ядрото обработва пакети:
TGID PID ИМЕ НА ПРОЦЕС 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 суапър/11 777 0 0 11 swapper/778 4512 4542 779 spokes-report-s XNUMX
Тук трябва да се отбележи, че в контекста softirq процесите, които са извършили системни извиквания, ще се показват като "процеси", когато всъщност ядрото е това, което безопасно обработва пакетите в контекста на ядрото.
С този инструмент можем да свържем конкретни процеси с конкретни пакети, които показват забавяне на hping3. Нека го направим просто grep върху това улавяне за определени стойности icmp_seq. Пакетите, съответстващи на горните стойности на icmp_seq, бяха отбелязани заедно с техните RTT, които наблюдавахме по-горе (в скоби са очакваните RTT стойности за пакети, които филтрирахме поради RTT стойности, по-малки от 50 ms):
TGID PID ИМЕ НА ПРОЦЕС 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 ksoftir qd/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 11 ksoft irqd/ 1961 19 ** (76ms) 76 11 ksoftirqd/1962 9 ** (10137ms) -- 10436 2068 cadvisor 10137 10436 2069 cadvisor 76 76 11 ksoftirqd/2070 75 ** 76ms 76 11 ksoftir qd/2071 65 ** 76ms 76 11 ksoftirqd/ 2072 55 ** 76ms 76 11 ksoftirqd/2073 45 ** (76ms) 76 11 ksoftirqd/2074 35 ** (76ms) 76 11 ksoftirqd/2075 25 ** (76ms) 76 11 ksoftirqd/2076 15 ** (76 г-жа ) 76 11 ksoftirqd/2077 5 ** (XNUMXms)
Резултатите ни казват няколко неща. Първо, всички тези пакети се обработват от контекста ksoftirqd/11. Това означава, че за тази конкретна двойка машини ICMP пакетите са хеширани до ядро 11 в приемащия край. Виждаме също, че когато има задръстване, има пакети, които се обработват в контекста на системното повикване cadvisor... Тогава ksoftirqd поема задачата и обработва натрупаната опашка: точно броя на пакетите, които са се натрупали след това cadvisor.
Фактът, че непосредствено преди това винаги работи cadvisor, предполага участието му в проблема. По ирония на съдбата целта - "анализирайте използването на ресурси и характеристиките на производителността на работещите контейнери", вместо да причинявате този проблем с производителността.
Както при други аспекти на контейнерите, всички те са много напреднали инструменти и може да се очаква да изпитате проблеми с производителността при някои непредвидени обстоятелства.
Какво прави cadvisor, което забавя опашката на пакетите?
Вече имаме доста добра представа за това как възниква сривът, какъв процес го причинява и на кой процесор. Виждаме, че поради твърдото блокиране ядрото на Linux няма време за планиране ksoftirqd. И виждаме, че пакетите се обработват в контекст cadvisor. Логично е да се предположи, че cadvisor стартира бавно системно извикване, след което всички пакети, натрупани по това време, се обработват:
Това е теория, но как да я проверим? Това, което можем да направим, е да проследим ядрото на процесора през целия този процес, да намерим точката, в която броят на пакетите надвишава бюджета и се извиква ksoftirqd, и след това да погледнем малко по-назад, за да видим какво точно се е изпълнявало на ядрото на процесора точно преди тази точка . Това е като рентгеново облъчване на процесора на всеки няколко милисекунди. Ще изглежда нещо подобно:
Удобно е, че всичко това може да се направи със съществуващите инструменти. Например, проверява дадено процесорно ядро на определена честота и може да генерира график на извиквания към работещата система, включително както потребителското пространство, така и ядрото на Linux. Можете да вземете този запис и да го обработите с помощта на малък форк на програмата от Brendan Gregg, което запазва реда на проследяването на стека. Можем да запазваме проследявания на стека от един ред на всеки 1 ms и след това да маркираме и запазваме проба 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];[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 трасиращия инструмент. Какво означава?
Всеки ред е следа на процесора в определен момент от време. Всяко извикване надолу по стека на ред е разделено с точка и запетая. В средата на редовете виждаме извикването на 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] <... futex resumed> ) = 0 <0.156784>
[pid 10432] <... futex resumed> ) = 0 <0.258285>
[pid 10137] <... futex resumed> ) = 0 <0.678382>
[pid 10384] <... futex resumed> ) = 0 <0.762328>
[pid 10436] <... read resumed> "cache 154234880nrss 507904nrss_h"..., 4096) = 658 <0.179438>
[pid 10384] <... futex resumed> ) = 0 <0.104614>
[pid 10436] <... futex resumed> ) = 0 <0.175936>
[pid 10436] <... read resumed> "cache 0nrss 0nrss_huge 0nmapped_"..., 4096) = 577 <0.228091>
[pid 10427] <... read resumed> "cache 0nrss 0nrss_huge 0nmapped_"..., 4096) = 577 <0.207334>
[pid 10411] <... epoll_ctl resumed> ) = 0 <0.118113>
[pid 10382] <... pselect6 resumed> ) = 0 (Timeout) <0.117717>
[pid 10436] <... read resumed> "cache 154234880nrss 507904nrss_h"..., 4096) = 660 <0.159891>
[pid 10417] <... futex resumed> ) = 0 <0.917495>
[pid 10436] <... futex resumed> ) = 0 <0.208172>
[pid 10417] <... futex resumed> ) = 0 <0.190763>
[pid 10417] <... read resumed> "cache 0nrss 0nrss_huge 0nmapped_"..., 4096) = 576 <0.154442>
Както може да очаквате, тук виждаме бавни повиквания read(). От съдържанието на операциите за четене и контекста mem_cgroup ясно е, че тези предизвикателства read() обърнете се към файла memory.stat, което показва използването на паметта и ограниченията на cgroup (технологията за изолиране на ресурси на Docker). Инструментът cadvisor отправя заявки към този файл, за да получи информация за използването на ресурсите за контейнери. Нека проверим дали ядрото или cadvisor правят нещо неочаквано:
theojulienne@kube-node-bad ~ $ time cat /sys/fs/cgroup/memory/memory.stat >/dev/null
real 0m0.153s
user 0m0.000s
sys 0m0.152s
theojulienne@kube-node-bad ~ $
Сега можем да възпроизведем грешката и да разберем, че ядрото на Linux е изправено пред патология.
Защо операцията за четене е толкова бавна?
На този етап е много по-лесно да намерите съобщения от други потребители за подобни проблеми. Както се оказа, в програмата за проследяване на cadvisor този бъг беше докладван като , просто никой не забеляза, че латентността също се отразява на случаен принцип в мрежовия стек. Наистина беше забелязано, че cadvisor консумира повече процесорно време от очакваното, но това не беше отдадено на голямо значение, тъй като нашите сървъри имат много процесорни ресурси, така че проблемът не беше внимателно проучен.
Проблемът е, че cgroups отчита използването на паметта в пространството от имена (контейнера). Когато всички процеси в тази cgroup излязат, Docker освобождава cgroup памет. „Паметта“ обаче не е просто памет на процеса. Въпреки че самата памет на процеса вече не се използва, изглежда, че ядрото все още присвоява кеширано съдържание, като dentries и inodes (метаданни на директория и файл), които се кешират в cgroup памет. От описанието на проблема:
zombie cgroups: cgroups, които нямат процеси и са изтрити, но все още имат разпределена памет (в моя случай от dentry кеша, но може да бъде разпределена и от кеша на страниците или tmpfs).
Проверката на ядрото на всички страници в кеша при освобождаване на cgroup може да бъде много бавна, така че е избран мързеливият процес: изчакайте, докато тези страници бъдат поискани отново, и след това най-накрая изчистете cgroup, когато паметта действително е необходима. До този момент cgroup все още се взема предвид при събиране на статистика.
От гледна точка на производителността, те пожертваха паметта за производителност: ускориха първоначалното почистване, като оставиха част от кешираната памет. Това е добре. Когато ядрото използва последната част от кешираната памет, cgroup в крайна сметка се изчиства, така че не може да се нарече "теч". За съжаление, специфичното изпълнение на механизма за търсене memory.stat в тази версия на ядрото (4.9), съчетано с огромното количество памет на нашите сървъри, означава, че възстановяването на най-новите кеширани данни и изчистването на зомбитата на cgroup отнема много повече време.
Оказва се, че някои от нашите възли имат толкова много зомбита на cgroup, че четенето и латентността надхвърлят секунда.
Заобиколното решение на проблема с cadvisor е незабавно да се освободят кешовете на dentries/inodes в цялата система, което незабавно елиминира забавянето при четене, както и мрежовото забавяне на хоста, тъй като изчистването на кеша включва кешираните страници на зомби cgroup и ги освобождава също. Това не е решение, но потвърждава причината за проблема.
Оказа се, че в по-новите версии на ядрото (4.19+) производителността на разговорите е подобрена memory.stat, така че преминаването към това ядро реши проблема. В същото време разполагахме с инструменти за откриване на проблемни възли в клъстери на Kubernetes, елегантно източване и рестартиране. Прегледахме всички клъстери, намерихме възли с достатъчно висока латентност и ги рестартирахме. Това ни даде време да актуализираме операционната система на останалите сървъри.
Резюмиране
Тъй като този бъг спря обработката на опашката на RX NIC за стотици милисекунди, той едновременно причини както висока латентност при къси връзки, така и средна латентност на връзката, като например между MySQL заявки и пакети с отговори.
Разбирането и поддържането на производителността на най-фундаменталните системи, като Kubernetes, е от решаващо значение за надеждността и скоростта на всички базирани на тях услуги. Всяка система, която управлявате, се възползва от подобренията в производителността на Kubernetes.
Източник: www.habr.com