Пару гадоў таму Kubernetes у афіцыйным блогу GitHub. З таго часу ён стаў стандартнай тэхналогіяй для разгортвання сэрвісаў. Цяпер Kubernetes кіруе значнай часткай унутраных і публічных службаў. Паколькі нашы кластары выраслі, а патрабаванні да прадукцыйнасці сталі больш цвёрдымі, мы сталі заўважаць, што ў некаторых службах на Kubernetes спарадычна з'яўляюцца затрымкі, якія нельга растлумачыць нагрузкай самога прыкладанні.
Па сутнасці, у дадатках адбываецца быццам выпадковая сеткавая затрымка да 100 мс і больш, што прыводзіць да тайм-аўтаў або паўторным спробам. Чакалася, што службы змогуць адказваць на запыты значна хутчэй за 100 мс. Але гэта немагчыма, калі само злучэнне адбірае столькі часу. Асобна мы назіралі вельмі хуткія запыты MySQL, якія павінны былі займаць мілісекунды, і MySQL сапраўды спраўлялася за мілісекунды, але з пункту гледжання запытвальнага прыкладання адказ займаў 100 мс ці больш.
Адразу стала зразумела, што праблема ўзнікае толькі пры злучэнні з вузлом Kubernetes, нават калі выклік прыходзіў звонку Kubernetes. Прасцей за ўсё прайграць праблему ў цесцю , які запускаецца з любога ўнутранага хаста, тэстуе службу Kubernetes на пэўным порце, і спарадычна рэгіструе вялікую затрымку. У гэтым артыкуле разгледзім, як нам удалося адсачыць прычыну гэтай праблемы.
Ухіляем лішнюю складанасць у ланцужку да збою
Прайграўшы адзін і той жа прыклад, мы хацелі звузіць фокус праблемы і выдаліць лішнія пласты складанасці. Першапачаткова ў плыні паміж Vegeta і pod’амі на Kubernetes было занадта шмат элементаў. Каб вызначыць глыбейшую сеткавую праблему, трэба выключыць некаторыя з іх.
Кліент (Vegeta) стварае TCP-злучэнне з любым вузлом у кластары. Kubernetes працуе як аверлейная сетка (па-над існуючай сеткай дата-цэнтра), якая выкарыстоўвае , гэта значыць инкапсулирует IP-пакеты оверлейной сеткі ўнутр IP-пакетаў дата-цэнтра. Пры падключэнні да першага вузла выконваецца пераўтварэнне сеткавых адрасоў. (NAT) з адсочваннем стану для пераўтварэння IP-адрасу і порта вузла Kubernetes у IP-адрас і порт у аверлейнай сетцы (у прыватнасці, pod’а з дадаткам). Для якія паступілі пакетаў выконваецца зваротная паслядоўнасць дзеянняў. Гэта складаная сістэма з вялікай колькасцю станаў і мноствам элементаў, якія ўвесь час абнаўляюцца і змяняюцца па меры разгортвання і перасоўванні службаў.
ўтыліта tcpdump у тэсце Vegeta дае затрымку падчас поціску рукі TCP (паміж SYN і SYN-ACK). Каб прыбраць гэтую залішнюю складанасць, можна выкарыстоўваць hping3 для простых "пінгаў" пакетамі SYN. Правяраем, ці ёсць затрымка ў пакеце ў адказ, а затым скідаем злучэнне. Мы можам адфільтраваць дадзеныя, уключыўшы толькі пакеты больш за 100 мс, і атрымаць больш просты варыянт прайгравання праблемы, чым поўны тэст сеткавага ўзроўню 7 у Vegeta. Вось "пінгі" вузла Kubernetes з выкарыстаннем TCP SYN/SYN-ACK на "порце вузла" службы (30927) з інтэрвалам 10 мс, адфільтраваныя па самых павольных адказах:
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. Яны ўсё роўна бачаць затрымку, калі мэтавы хост з'яўляецца "дрэнным" (некаторыя горш, чым іншыя).
Цяпер апошняе пытанне: чаму затрымка ўзнікае толькі на серверах 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 да знешняга хаста (што выключае зыходны хост, паколькі пінг уключае як кампанент 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, што ёсць пакет, які трэба апрацаваць. Ядро спыняе іншую працу, перамыкае кантэкст на апрацоўшчык перапыненняў, апрацоўвае пакет, а затым вяртаецца да бягучых задач.
Гэтае пераключэнне кантэксту адбываецца павольна: магчыма, затрымка была незаўважная на 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 мс):
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];[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 ў вызначаны момант часу. Кожны выклік уніз па стэку ў радку падзяляецца кропкай з коскай. У сярэдзіне радкоў мы бачым выкліканы syscall: read(): .... ;do_syscall_64;sys_read; .... Такім чынам, cadvisor марнуе шмат часу на сістэмны выклік read(), які адносіцца да функцый mem_cgroup_* (верхняя частка стэка выклікаў/канец радка).
У трасіроўцы выклікаў няёмка глядзець, што менавіта чытаецца, таму запусцім strace і паглядзім, што робіць cadvisor, і знойдзем сістэмныя выклікі даўжэй 100 мс:
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 вызваляе кантрольную групу памяці. Аднак "памяць" - гэта не проста памяць працэсу. Хоць сама памяць працэсаў больш не выкарыстоўваецца, апыняецца, ядро прызначае яшчэ кэшаванае змесціва, такое як dentries і inodes (метададзеныя каталогаў і файлаў), якія кэшуюцца ў memory cgroup. З апісання праблемы:
cgroups-зомбі: кантрольныя групы, у якіх няма працэсаў і яны выдаленыя, але для якіх усё яшчэ выдзелена памяць (у маім выпадку, з кэша dentry, але яна таксама можа вылучацца з кэша старонак ці tmpfs).
Праверка ядром усіх старонак у кэшы пры вызваленні cgroup можа быць вельмі павольнай, таму абраны лянівы працэс: пачакаць, пакуль гэтыя старонкі будуць зноў запытаны, і ўжо тады, калі памяць сапраўды запатрабуецца, нарэшце, ачысціць cgroup. Да гэтага моманту cgroup па-ранейшаму улічваецца пры зборы статыстыкі.
З пункту гледжання прадукцыйнасці, яны ахвяравалі памяццю дзеля прадукцыйнасці: паскарэнне першапачатковай ачысткі за кошт таго, што застаецца крыху кэшаванай памяці. Гэта нармальна. Калі ядро выкарыстоўвае апошнюю частку кэшаванай памяці, cgroup у канчатковым выніку чысціцца, так што гэта нельга назваць "уцечкай". Нажаль, канкрэтная рэалізацыя механізму пошуку memory.stat у гэтай версіі ядра (4.9), у спалучэнні з вялізным аб'ёмам памяці на нашых серверах, прыводзіць да таго, што для аднаўлення апошніх кэшаваных дадзеных і ачысткі cgroup-зомбі патрабуецца значна больш часу.
Аказваецца, на некаторых нашых вузлах было так шмат cgroup-зомбі, што чытанне і затрымка перавышалі секунду.
Спосаб абыходу праблемы cadvisor - неадкладна вызваліць кэшы dentries/inodes па ўсёй сістэме, што адразу ўхіляе затрымку чытання, а таксама сеткавую затрымку на хасце, бо выдаленне кэша ўключае кэшаваныя старонкі cgroup-зомбі, а яны таксама вызваляюцца. Гэтае не рашэнне, але пацвярджае прычыну праблемы.
Аказалася, што ў навейшых версіях ядра (4.19+) палепшаная прадукцыйнасць выкліку memory.stat, так што пераход на гэта ядро ўхіляў праблему. У той жа час у нас быў інструментар для выяўлення праблемных вузлоў у кластарах Kubernetes, іх хупавага зліву і перазагрузкі. Мы прачасалі ўсе кластары, знайшлі вузлы з дастаткова высокай затрымкай і перазагрузілі іх. Гэта дало нам час для абнаўлення АС на астатніх серверах.
Падводзячы вынік
Паколькі гэты баг спыняў апрацоўку чэргаў NIC RX на сотні мілісекунд, ён адначасова выклікаў і вялікую затрымку на кароткіх злучэннях, і затрымку ў сярэдзіне злучэння, напрыклад, паміж запытамі MySQL і пакетамі ў адказ.
Разуменне і падтрымка прадукцыйнасці самых фундаментальных сістэм, такіх як Kubernetes, мае вырашальнае значэнне для надзейнасці і хуткасці ўсіх сервісаў на іх аснове. Ад паляпшэнняў прадукцыйнасці Kubernetes выйграюць усе якія запускаюцца сістэмы.
Крыніца: habr.com