Mõned aastad tagasi arutleti Kubernetes'e üle ametlikus GitHubi blogis. Sellest ajast on see saanud standardtehnoloogiaks teenuste käitamiseks. Nüüd haldab Kubernetes märkimisväärset osa sise- ja avalikest teenustest. Kuna meie klastrid on kasvanud ja jõudlusnõuded rangemaks muutunud, oleme hakanud tähele panema, et mõnedes Kubernetes'e teenustes ilmnevad sporaadiilised latentsused, mida ei saa seletada rakenduse enda koormusega. Sisuliselt esinevad rakendustes juhuslikud võrgu latentsused kuni 100 ms ja rohkem, mis toovad kaasa aegumisi või korduskatseid. Oodati, et teenused suudavad päringutele vastata palju kiiremini kui 100 ms. Kuid see pole võimalik, kui ühendus ise võtab nii kaua aega. Samuti oleme märganud MySQL-i väga kiireid päringuid, millele oleks pidanud kuluma millisekundid, ja MySQL tõesti suutis vastata millisekunditega, kuid küsiva rakenduse vaatenurgast võttis vastamine 100 ms või rohkem.

Selgelt oli näha, et probleem tekib ainult Kubernetes'e sõlme ühendamisel, isegi kui päring tuli Kubernetes'est välja. Probleemi on kõige lihtsam korrata testis

, mis käivitub igalt sisemiselt, testib Kubernetes'e teenust teatud sadamal ja sporaadiiliselt registreerib suurt latentsust. Selles artiklis vaatleme, kuidas me suutsime selle probleemi põhjuse jälile jõuda. VegetaEemaldame ebaolulise keerukuse rikke ahelas

Korrates sama näidet, tahtsime probleemi fookust kitsendada ja eemaldada liigsed keerukuse kihid. Alguses oli Kubernetes'e pod'ide ja Vegeta vahelises voos liiga palju elemente. Sügava võrgu probleemi määratlemiseks tuleb mõned neist välja jätta.

Klient (Vegeta) loob TCP-ühenduse iga sõlmega klastris. Kubernetes töötab ülekatte võrgu (olemasoleva andmekeskuse võrgu kohal), mis kasutab

IPIP , see tähendab, et kapseldab ülekatte võrgu IP-pakette andmekeskuse IP-pakettidesse. Esimese sõlmega ühendamisel toimub aadresside muundurNetwork Address Translation (NAT), mille abil muudetakse Kubernetes'e sõlme IP-aadress ja port ülekatte võrgu IP-aadressiks ja port asjakohasele pod'ile (konkreetset rakendust arvestades). Vastuvõetud pakettide puhul toimub vastupidine protsess. See on keeruline süsteem, millel on palju olekuid ja elemente, mis pidevalt uuenevad ja muutuvad teenuste juurutamisel ja liigutamisel. Vegeta testis ladestub latentsus TCP käepigistuse ajal (SYN ja SYN-ACK vahel). Selle liigse keerukuse eemaldamiseks on võimalik kasutada

Tööriist tcpdump lihtsate SYN-pingude jaoks. Kontrollime, kas vastava paketi latentsus on olemas, ja seejärel katki ühenduse. Saame andmeid filtreerida, lubades rohkem kui 100 ms pakette, ning saada lihtsam reprodutseerimise versioon kui täispikk võrgu taseme 7 test Vegetas. Siin on "pings" Kubernetes'e sõlmele, kasutades TCP SYN/SYN-ACK "teenuse sõlme" sadamal (30927) 10 ms intervalliga, filtreeritud aeglaste vastuste järgi: hping3 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

Esimese vaatlusena võib kohe näha, et järjestuse ja ajastuse põhjal on selge, et need pole ühekordsed ummistused. Latentsus koguneb tihti ja lõpuks töödeldakse see.

Edasi tahame välja selgitada, millised komponendid võivad ummistuse tekkimisse sekkuda. Kas need võiksid olla mõned sajad iptables reegleid NAT-is? Või mõned probleemid IPIP tunneldamisel võrgus? Üks võimalus seda kontrollida on iga süsteemi sammu kontrollimine, väljaarvamine. Mis juhtub, kui eemaldame NAT-i ja tulemüüriloogika, jättes alles ainult IPIP osa:

Õnneks võimaldab Linux hõlpsalt juurdepääsu otse IP ülekande kihile, kui masin kuulub samasse võrku:

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

Tulemustest lähtudes on probleem endiselt olemas! See välistab iptables ja NAT. Nii et probleem on TCP-s? Vaatame, kuidas tavaline ICMP-ping järgneb:

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

pikk=28 ip=10.125.20.64 ttl=64 id=49448 icmp_jada=4022 rtt=141.3 ms

pikk=28 ip=10.125.20.64 ttl=64 id=49449 icmp_jada=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

Tulemused näitavad, et probleem ei ole kadunud. Kas see on IPIP tunnel? Lihtsustame testi veel:

Kas kõik paketid saadetakse nende kahe hosti vahel?

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

Lihtsustasime olukorda kahe Kubernetes sõlmest, kes saadavad üksteisele mõnda paketti, isegi ICMP pings. Nad näevad ikkagi viivitust, kui sihtkoht on 'halb' (mõned on halvemad kui teised).

Nüüd viimane küsimus: miks viivitus tekib ainult kube-node serverites? Ja see juhtub, kui kube-node on saatja või vastuvõtja? Õnneks on seda samuti üsna lihtne välja selgitada, saates paketi Kubernetesest väljaspoolt hostist, kuid sama 'tuntud halvale' vastuvõtjale. Nagu näeme, probleem ei ole kadunud:

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

Seejärel teeme sama päringud eelnevalt kui kube-node välismaise hostini (mis välistab algse hosti, kuna ping sisaldab RX ja TX komponente):

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 statistika ---
22352 paketti edastatud, 22350 paketti saadud, 1% pakettide kadu
ringreis min/avg/max = 0.2/7.6/1010.6 ms

Uurides viivitusega paketide jääke, saime lisainfot. Täpsemalt, et saatja (all) näeb seda ajaviivitust, kuid vastuvõtja (üles) ei näe — vt Delta (sekundites) veerg:

Lisaks, kui vaadata TCP ja ICMP pakettide järjekorra erinevust (järjekorranumbrite kaupa) vastuvõtja poolel, siis ICMP paketid saabuvad alati samas järjekorras, nagu nad saadeti, kuid erineva ajaga. Samas TCP paketid mõnikord vahelduvad, ja osa neist jääb kinni. Eriti, kui uurida SYN paketid, siis saatja poolel nad tulevad järjekorras, kuid vastuvõtja poolel ei tule.

On õhuke erinevus selles, kuidas võrgukaardid kaasaegsetel serveritel (nagu meie andmekeskuses) käsitlevad pakette, mis sisaldavad TCP või ICMP. Kui pakett saabub, siis võrguadapter 'häkkib selle ühenduse järgi', st üritab jagada ühendusi järjekordadesse ja saata iga järjekord erinevale protsessorituumale. TCP puhul hõlmab see häkkimine nii algset kui ka lõpp-IP aadressi ja porti. Teisisõnu, iga ühendus häkkitakse (võimalikult) erinevalt. ICMP puhul häkkitakse ainult IP-aadresse, kuna portide pole.

Veel üks uus tähelepanek: selle perioodi jooksul näeme ICMP viivitusi kõikide kahe hosti vaheliste kommunikatsioonide puhul, kuid TCP ei näe. See ütleb meile, et põhjus on tõenäoliselt seotud RX järjekordade häkkimisega: peaaegu kindlalt on ummik tekkimas RX paketide töötlemisel, mitte vastuste saatmisel.

See välistab pakettide saatmise võimalike põhjuste hulgas. Nüüd teame, et paketitöötluse probleem on mõnel kube-node serveril vastuvõtmise pool.

Uurime paketitöötlust Linuxi tuumas

Kuna saame aru, miks probleem esineb mõne kube-node serveri vastuvõtjal, vaatame, kuidas Linuxi tuum süsteemide pakette töötleb.

Tulles tagasi kõige lihtsama traditsioonilise rakenduse juurde, võrgukaart saabub pakett ja saadab katkestuse Linuxi tuumale, et öelda, et on pakett, mida tuleb töödelda. Tuum peatab muu töö, vahetab konteksti katkestuse käsitlejale, töötleb paketti ja naaseb seejärel oma praeguste ülesannete juurde.

See konteksti vahetus toimub aeglaselt: võib-olla viivitus ei olnud märgatav 10-megabitistel võrgukaartidel 90ndate aastatel, kuid kaasaegsetel 10G kaartidel, mille maksimaalne läbilaskevõime on 15 miljonit paketti sekundis, võib iga väikese kaheksatuumalise serveri tuum katkestada miljoneid kordi sekundis.

Et mitte pidevalt katkestus töötlemisega tegeleda, lisati Linuxi mitmeid aastaid tagasi NAPI: võrguprogrammeerimise API, mida kõik kaasaegsed draiverid kasutavad kõrgel kiirusel töö efektiivsuse tõstmiseks. Madalatel kiirusel tuum ikka veel aktsepteerib katkestusi võrkaartilt vana meetodi järgi. Kui saabub piisav hulk pakette, mis ületab künnist, lülitab tuum katkestused välja ja hakkab selle asemel võrguadapterit küsitlema, võttes pakette portfellides. Töötlemine toimub softirq kontekstis, st programmeerimise katkestuste kontekstis pärast süsteemikõnesid ja riistvara katkestusi, mil tuum (erinevalt kasutajaruumi) on juba käivitatud.

See on palju kiirem, kuid tekitab teise probleemi. Kui pakette on liiga palju, siis kulub kogu aeg võrkaartilt pakettide töötlemiseks ja kasutajaruumi protsessid ei suuda neid järjekordi tõhusalt tühjendada (nt TCP-ühendustest lugemine). Lõpuks täituvad järjekorrad ja hakkame pakette viskama. Üritades leida tasakaalu, määrab tuum maksimaalse pakettide töötlemise eelarve softirq kontekstis. Kui see eelarve ületatakse, ärkab eraldi niit ksoftirqd (te näete ühte neist ps iga tuuma jaoks), mis töötleb neid softirq väljaspool tavapärast süstemikõne/katkestuse teed. See niit on planeeritud standardse protsesside planeerijaga, mis üritab õiglaselt ressursse jaotada.

Uurides, kuidas tuum pakette töötleb, võib märgata, et siin on teatud tõenäosus ummikute tekkeks. Kui softirq kõnesid tuleb harva, peavad paketid ootama töötlemist RX järjekorras võrkaartil. Võib-olla juhtub see seetõttu, et mõni ülesanne blokeerib CPU tuuma või midagi muud takistab tuuma softirq käivitamast.

Vähendame töötlemist tuuma või meetodi

softirq viivitused on seni vaid oletus. Kuid see on mõttekas ja me teame, et meil on midagi väga sarnast. Seega järgmine samm on selle teooria kinnitamine. Ja kui see kinnitub, siis leida viivituste põhjus.

Naaseme meie aeglaste pakettide juurde:

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

Nagu eelnevalt arutatud, hashitakse need ICMP paketid ühte NIC RX järjekorda ja töötleb üks CPU tuum. Kui soovime mõista, kuidas Linux töötab, on kasulik teada, kus (millisel CPU tuumal) ja kuidas (softirq, ksoftirqd) neid pakette töödeldakse, et jälgida protsessi.

Nüüd on aeg kasutada tööriistu, mis võimaldavad reaalajas jälgida Linuxi tuuma tööd. Siin kasutasime bcc. See tööriistade komplekt võimaldab kirjutada väikeseid C programme, mis haaravad juhuslikud funktsioonid tuumas ja puhverdavad sündmusi kasutajaruumi Python programmi, mis võib neid töödelda ja tulemuse teile tagasi saata. Arbitraarsed funktsioonid tuumas on keeruline teema, kuid utiliit on projekteeritud maksimaalse turvalisuse tagamiseks ja mõeldud jälgima selliseid tootmisprobleeme, mida ei ole lihtne korrata testimis- või arenduskeskkonnas.

Kava on lihtne: me teame, et tuum töötleb neid ICMP pingeid, seega paneme hooki tuuma funktsioonile icmp_echo, mis aktsepteerib sisenenud ICMP-paketti „echo request” ja käivitab ICMP vastuse „echo response” saatmise. Saame paketti identifitseerida icmp_seq arvu suurenemise järgi, mis näitab hping3 kõrgem.

Kood bcc skripti väljanägemine võib tunduda keeruline, kuid see ei ole nii hirmus, kui tundub. Funktsioon icmp_echo edastab struct sk_buff *skb: see on „echo request” paketiga. Saame seda jälgida, et välja võtta jada echo.sequence (mis võrduvad icmp_seq hping3-st üle), ja saata see kasutajaruumi. Samuti on mugav haarata käimasoleva protsessi nimi/identifikaator. Allpool on tulemused, mida näeme otse pakettide töötlemise ajal tuuma poolt:

TGID    PID     PROTSESSI NIMI    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

Siin on oluline märkida, et kontekstis softirq kuvatakse süsteemikõnesid teinud protsessid kui „protsessid”, kuigi tegelikult töötleb tuum turvaliselt pakette tuuma kontekstis.

Selle tööriistaga saame luua seose konkreetsete protsesside ja konkreetselt pakettide vahel, mis näitavad viivitust hping3. Teeme lihtsa grep selle saadud väärtuste korral icmp_seq. Pakette, mis vastavad ülaltoodud icmp_seq väärtustele, on jälgitud koos nende RTT-ga, mida me ülal vaatlesime (nurgas on ära toodud oodatud RTT väärtused pakettide puhul, mille oleme välistanud etteantud RTT väärtuste tõttu, mis on väiksemad kui 50 ms):

TGID    PID     PROTSESSI NIMI    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)

Tulemused räägivad meile mitmest asjast. Esiteks, kõik need paketid töödeldakse kontekstis ksoftirqd/11. See tähendab, et selle spetsiifilise masinate paari puhul hääletatakse ICMP paketid vastuvõtva poole 11. tuumale. Samuti näeme, et igas ummikus on pakette, mida töödeldakse süsteemikõnede kontekstis cadvisor. Siis ksoftirqd võtab ülesande enda peale ja töötleb kogunenud järjekorra: täpselt nii palju pakette, kui on kogunenud pärast cadvisor.

Tõsiasi, et enne seda töötab alati cadvisor, viitab sellele, et ta on probleemi osaline. Ironiseeriv on see, et tema eesmärk cadvisor on "analüüsida konteinerite ressursikasutust ja jõudluse iseloomu", mitte põhjustada seda jõudlusprobleemi.

Nagu teiste konteineritööde aspektide puhul, on see kõik ülimalt arenenud tööriist, millelt võib tõsiselt oodata jõudlusprobleeme mõnedes ettenägematutes oludes.

Mis teeb cadvisor, mis takistab pakettide järjekorda?

Nüüd on meil üsna hea arusaam, kuidas tõrge toimub, milline protsess seda põhjustab ja millisel CPU-l. Näeme, et jäiga blokeerimise tõttu ei jõua Linuxi tuum õigel ajal ülesandeid ajastada ksoftirqd. Ja me näeme, et paketid töödeldakse kontekstis cadvisor. Loogiliselt võiks eeldada, et cadvisor käivitab aeglase syscall'i, pärast mida töödeldakse kõik kogunenud paketid:

See on teooria, kuid kuidas seda kontrollida? Mida me saame teha, on jälgida CPU tuuma tööd kogu selle protsessi vältel, leida punkt, kus pakettide arv ületab eelarvet ja aktiveerib ksoftirqd, ning siis vaadata veidi varem - mis töötas tuumal just enne seda hetke. See on nagu röntgenpilt CPU-st iga paari millisekundi tagant. See näeb välja umbes nii:

Hea on see, et kogu seda saab teha olemasolevate tööriistadega. Näiteks perf record kontrollib määratud ajavahemike järel antud tuuma CPU-d ja suudab genereerida käivitusgraafiku, mis hõlmab nii kasutajaruumi kui ka Linuxi tuuma. Saame selle salvestuse võtta ja töödelda väikese muutmisprogrammi kaudu FlameGraph Brendan Greggilt, mis salvestab hunniku jälgimise järjekorra. Saame salvestada ühe realise jälgimise iga 1 ms ja siis eraldada ja salvestada näidise 100 millisekundi jooksul enne seda, kui jälgimist tabab 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

Siin on tulemused:

(sajad jäljed, mis näevad välja sarnased)

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 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

Siin on palju, aga peamine, et leiame mustri „cadvisor enne ksoftirqd“, mida oleme varem näinud ICMP jälgijas. Mida see tähendab?

Iga rida on kiiprocessori jälgimine kindlal ajahetkel. Iga allapoole suunatud kutsumine real eraldatakse semikooloniga. Ridade keskel näeme kutsutud süsteهkõnnet: read(): .... ;do_syscall_64;sys_read; .... Seega kulutab cadvisor palju aega süsteemikutse read(), mis on seotud funktsioonidega mem_cgroup_* (kõrge positsioon kutsumise virnas/lehe lõpp).

Kutsumiste jälgimisel on ebamugav näha, mida täpselt loetakse, seetõttu käivitame strace ja vaatame, mida cadvisor teeb, ning leiame süsteemikutse, mis kestab üle 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

Nagu eeldatud, näeme siin aeglaseid kutseid read(). Lugemisoperatsioonide sisust ja kontekstist mem_cgroup , on selge, et need kutsejad read() on seotud faili memory.stat, mis näitab mälu kasutamist ja piiranguid cgroup (Docker'i ressursi isolatsiooni tehnoloogia) jaoks. Cadvisor tööriist küsib selle faili kohta ressursikasutuse andmeid konteinerite kohta. Vaatame, kas probleem on tuumas või teeb cadvisor midagi ootamatut:

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

reaalne 0m0.153s
kasutaja 0m0.000s
süsteem 0m0.152s
theojulienne@kube-node-bad ~ $

Nüüd saame vea uuesti korrata ja mõistame, et Linuxi tuum seisab silmitsi patoloogiaga.

Mis põhjustab lugemise operatsiooni nii aeglaselt?

Selles etapis on palju lihtsam leida teiste kasutajate sõnumeid sarnaste probleemide kohta. Selgub, et cadvisor jälgija oletab, et probleem on liialdases CPU kasutamises, lihtsalt keegi ei pannud tähele, et viivitus kajastub ka võrgu stegis. Tõepoolest täheldati, et cadvisor tarbib rohkem protsessorivõimet, kui oodata, kuid sellele ei pööratud suurt tähelepanu, kuna meie serveritel on palju protsessorivõimet, seega ei uuritud probleemi süvitsi.

Probleem seisneb selles, et kontrollgrupid (cgroups) arvestavad mälu kasutamist konteinerite nimiruumi sees. Kui kõik protsessid selles cgroup'is lõpetatakse, vabastab Docker mälu kontrollgrupi. Siiski ei ole 'mälu' lihtsalt protsessi mälu. Kuigi protsesside mälu ei ole enam kasutusel, osutub, et tuum määrab endiselt vahemälu sisu, nagu dentries ja inodes (kaustade ja failide metaandmed), mis salvestatakse mälu cgroup'i. Probleemi kirjelduse kohaselt:

cgroups-zombid: kontrollgrupid, kus pole protsesse ja need on kõrvaldatud, kuid mille jaoks on endiselt eraldatud mälu (minu puhul dentry vahemälust, kuid see võib olla eraldatud lehekülgede või tmpfs vahemälust).

Tuum kontrollib kõiki lehti vahemälus cgroup'i vabastamisel, see võib olla väga aeglane, seetõttu on valitud laisk protsess: oodata, kuni need lehed taaskäideldakse, ja alles siis, kui mälu on tõeliselt vajalik, lõpuks puhastada cgroup. Seni arvestatakse cgroup endiselt statistika kogumisel.

Toimivuse seisukohalt on nad ohvriks toonud mälu toimivuse nimel: esialgse puhastamise kiirus, kuna jääb alles natuke vahemälu. See on okei. Kui tuum kasutab viimast osa vahemälust, puhastatakse cgroup lõpuks, seega ei saa seda nimetada "lekkeks". Kahjuks viib konkreetne rakendusotsingumehhanism memory.stat selles tuuma versioonis (4.9), koos meie serverite tohutu mälumahuga, selleni, et viimaste vahemälustatud andmete taastamine ja cgroup-zombide puhastamine võtab palju rohkem aega.

Selgub, et mõnes meie sõlmes oli nii palju cgroup-zombisid, et lugemisaeg ja viivitus ületasid ühe sekundi.

Probleemi vältimise viis cadvisoriga on kohe vabastada dentries/inodes kogu süsteemis vahemälu, mis kõrvaldab viivituse lugemisel ja ka võrgu viivituse hostis, kuna vahemälu kustutamine hõlmab ka cgroup-zombide vahemälustatud lehekülgi, mis saavad samuti vabastatud. See ei ole lahendus, kuid kinnitab probleemi põhjuse.

Selgus, et uutes tuuma versioonides (4.19+) on kõne tootlikkus paranenud memory.stat, seega tuumale üleminek kõrvaldas probleemi. Samal ajal oli meil tööriistad Kubernetes'e klastrite probleemsete sõlmede tuvastamiseks, nende elegantne tühjendamine ja taaskäivitamine. Lävitasime kõik klastrid, leidsime sõlmed koos piisavalt kõrge viivitusega ja taaskäivitasime need. See andis meile aega operatsioonisüsteemi uuendamiseks ülejäänud serverites.

Kokkuvõtteks

Kuna see viga peatas NIC RX järjekordade töötlemise sadade millisekundite jooksul, põhjustas see samal ajal suurt viivitust lühikestes ühendustes ning keskel, näiteks MySQL päringute ja vastuspakettide vahel.

Mõistmine ja toetamine kõige fundamentaalsemate süsteemide nagu Kubernetes tootlikkust on ülioluline, et tagada kõikide nende põhjal töötavate teenuste usaldusväärsus ja kiirus. Kubernetes'e tootlikkuse parandustest saavad kasu kõik jooksutatud süsteemid.

Allikas: habr.com