Paar aastat tagasi Kubernetes ametlikus GitHubi ajaveebis. Sellest ajast alates on sellest saanud teenuste juurutamise standardtehnoloogia. Kubernetes haldab nüüd olulist osa sise- ja avalikest teenustest. Kui meie klastrid kasvasid ja jõudlusnõuded karmistusid, hakkasime märkama, et Kubernetese mõnel teenusel esines aeg-ajalt latentsust, mida ei saa seletada rakenduse enda koormusega.
Põhimõtteliselt kogevad rakendused juhuslikku võrgu latentsust kuni 100 ms või rohkem, mille tulemuseks on ajalõppud või korduskatsed. Eeldati, et teenused suudavad taotlustele vastata palju kiiremini kui 100 ms. Kuid see on võimatu, kui ühendus ise võtab nii palju aega. Eraldi jälgisime väga kiireid MySQL päringuid, mis peaksid võtma millisekundeid, ja MySQL täitus millisekunditega, kuid taotleva rakenduse vaatenurgast võttis vastus 100 ms või rohkem aega.
Kohe selgus, et probleem tekkis ainult Kubernetese sõlmega ühenduse loomisel, isegi kui kõne tuli väljastpoolt Kubernetest. Lihtsaim viis probleemi taasesitamiseks on test , mis töötab mis tahes sisemisest hostist, testib Kubernetese teenust konkreetses pordis ja registreerib aeg-ajalt kõrge latentsusaega. Selles artiklis vaatleme, kuidas suutsime selle probleemi põhjuse välja selgitada.
Ebavajaliku keerukuse kõrvaldamine ahelast, mis viib ebaõnnestumiseni
Sama näidet korrates soovisime probleemi fookust kitsendada ja eemaldada ebavajalikud keerukuskihid. Algselt oli Vegeta ja Kubernetese kaunade vahelises voolus liiga palju elemente. Sügavama võrguprobleemi tuvastamiseks peate mõned neist välistama.
Klient (Vegeta) loob TCP-ühenduse klastri mis tahes sõlmega. Kubernetes töötab kattevõrguna (olemasoleva andmekeskuse võrgu peal), mis kasutab , see tähendab, et see kapseldab ülekattevõrgu IP-paketid andmekeskuse IP-pakettide sisse. Ühenduse loomisel esimese sõlmega tehakse võrguaadressi translatsioon (NAT) olekupõhine Kubernetese sõlme IP-aadressi ja pordi tõlkimiseks ülekattevõrgu (täpsemalt rakendusega pod) IP-aadressiks ja pordiks. Sissetulevate pakettide puhul tehakse toimingute vastupidine jada. See on keeruline süsteem, millel on palju olekut ja palju elemente, mida teenuste juurutamisel ja teisaldamisel pidevalt uuendatakse ja muudetakse.
Utiliit tcpdump Vegeta testis on TCP käepigistuse ajal viivitus (SYN ja SYN-ACK vahel). Selle tarbetu keerukuse eemaldamiseks võite kasutada hping3 lihtsate "pingimiste" jaoks SYN-pakettidega. Kontrollime, kas vastuspaketis on viivitust, ja seejärel lähtestame ühenduse. Saame andmeid filtreerida nii, et need hõlmaksid ainult pakette, mis on pikemad kui 100 ms, ja saame probleemi taasesitamiseks lihtsama viisi kui Vegeta täieliku võrgukihi 7 test. Siin on Kubernetese sõlme "pingid", mis kasutavad TCP SYN/SYN-ACK-i teenuse "sõlme pordis" (30927) 10 ms intervalliga, filtreerides kõige aeglasemate vastuste järgi:
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
Saab kohe esimese tähelepaneku teha. Järjekorranumbrite ja ajastuste järgi otsustades on selge, et tegemist ei ole ühekordsete ummikutega. Viivitus sageli koguneb ja lõpuks töödeldakse.
Järgmisena tahame välja selgitada, millised komponendid võivad olla seotud ummikute tekkega. Võib-olla on need mõned sadadest NAT-i iptablesi reeglitest? Või on IPIP-tunneldamisega võrgus probleeme? Üks võimalus selle testimiseks on testida süsteemi iga etappi selle kõrvaldamise teel. Mis juhtub, kui eemaldate NAT-i ja tulemüüri loogika, jättes alles ainult IPIP-osa:
Õnneks teeb Linux IP-ülekattekihile otse juurdepääsu hõlpsaks, kui masin on samas võrgus:
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
Tulemuste järgi otsustades on probleem endiselt alles! See välistab iptablesi ja NAT-i. Nii et probleem on TCP-s? Vaatame, kuidas tavaline ICMP ping läheb:
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
Tulemused näitavad, et probleem pole kuhugi kadunud. Võib-olla on see IPIP tunnel? Lihtsustame testi veelgi:
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
Oleme olukorra lihtsustanud nii, et kaks Kubernetese sõlme saadavad üksteisele mis tahes pakette, isegi ICMP pingi. Nad näevad endiselt latentsust, kui sihthost on "halb" (mõned halvemad kui teised).
Nüüd viimane küsimus: miks toimub viivitus ainult kube-node serverites? Ja kas see juhtub siis, kui kube-sõlm on saatja või vastuvõtja? Õnneks on seda ka üsna lihtne välja selgitada, saates paketi väljaspool Kubernetes asuvat hosti, kuid sama "tuntud halva" adressaadiga. Nagu näete, pole probleem kuhugi 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 käivitame samad päringud eelmisest lähteallika kube-sõlmest välisele hostile (mis välistab lähtehosti, kuna ping sisaldab nii RX-i kui ka TX-komponenti):
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
Uurides latentsuspakettide hõivamist, saime lisateavet. Täpsemalt, et saatja (alumine) näeb seda ajalõppu, kuid saaja (ülemine) mitte – vaadake veergu Delta (sekundites):
Lisaks, kui vaadata erinevust TCP ja ICMP pakettide järjestuses (järjekorranumbrite järgi) saaja poolel, siis saabuvad ICMP paketid alati samas järjestuses, milles need saadeti, kuid erineva ajastusega. Samal ajal vahelduvad TCP-paketid vahel ja osad jäävad kinni. Täpsemalt, kui uurida SYN-pakettide porte, on need saatja poolel korras, vastuvõtja poolel aga mitte.
Seal on väike erinevus, kuidas kaasaegsed serverid (nagu meie andmekeskuse serverid) töötlevad TCP-d või ICMP-d sisaldavaid pakette. Kui pakett saabub, siis võrguadapter "räsib selle ühenduse kohta", see tähendab, et ta üritab jagada ühendused järjekordadeks ja saata iga järjekorda eraldi protsessori tuuma. TCP puhul sisaldab see räsi nii lähte- kui ka sihtkoha IP-aadressi ja porti. Teisisõnu, iga ühendus räsitakse (potentsiaalselt) erinevalt. ICMP puhul räsitakse ainult IP-aadresse, kuna porte pole.
Veel üks uus tähelepanek: sel perioodil näeme ICMP viivitusi kõigis kahe hosti vahelises suhtluses, kuid TCP mitte. See ütleb meile, et põhjus on tõenäoliselt seotud RX-i järjekorra räsimisega: ummikud on peaaegu kindlasti seotud RX-pakettide töötlemisega, mitte vastuste saatmisega.
See välistab pakettide saatmise võimalike põhjuste loendist. Nüüd teame, et pakettide töötlemise probleem on mõne kube-sõlme serveri vastuvõtu poolel.
Pakettide töötlemise mõistmine Linuxi tuumas
Et mõista, miks probleem mõne kube-sõlme serveri vastuvõtjas ilmneb, vaatame, kuidas Linuxi kernel pakette töötleb.
Tulles tagasi lihtsaima traditsioonilise teostuse juurde, võtab võrgukaart paketi vastu ja saadab Linuxi kernel, et seal on pakett, mida tuleb töödelda. Kernel peatab muu töö, lülitub konteksti katkestuste töötlejale, töötleb paketti ja naaseb seejärel praeguste ülesannete juurde.
See kontekstivahetus on aeglane: latentsusaeg ei pruukinud olla 10ndatel 90Mbps võrgukaartidel märgatav, kuid tänapäevastel 10G-kaartidel, mille maksimaalne läbilaskevõime on 15 miljonit paketti sekundis, võib väikese kaheksatuumalise serveri iga tuuma katkestada miljoneid. korda sekundis.
Et mitte pidevalt katkestustega hakkama saada, lisas aastaid tagasi Linux : võrgu API, mida kõik kaasaegsed draiverid kasutavad jõudluse parandamiseks suurel kiirusel. Madalatel kiirustel saab tuum endiselt võrgukaardilt katkestusi vanaviisi. Kui saabub piisavalt pakette, mis ületavad läve, keelab kernel katkestused ja hakkab selle asemel võrguadapterit küsima ja pakette tükkidena korjama. Töötlemine toimub softirqis, see tähendab in pärast süsteemikutseid ja riistvarakatkestusi, kui kernel (erinevalt kasutajaruumist) juba töötab.
See on palju kiirem, kuid põhjustab teistsuguse probleemi. Kui pakette on liiga palju, siis kulub kogu aeg võrgukaardilt pakettide töötlemisele ja kasutajaruumi protsessidel ei ole aega neid järjekordi reaalselt tühjendada (TCP ühendustest lugemine jne). Lõpuks järjekorrad täituvad ja hakkame pakette maha viskama. Tasakaalu leidmiseks määrab kernel eelarve maksimaalsele softirq-kontekstis töödeldavate pakettide arvule. Kui see eelarve on ületatud, äratatakse eraldi lõim ksoftirqd (näete ühte neist ps tuuma kohta), mis käsitleb neid softirq-e väljaspool tavalist syscalli/katkestuse teed. See lõim on ajastatud standardse protsessiplaanija abil, mis püüab ressursse õiglaselt eraldada.
Olles uurinud, kuidas kernel pakette töötleb, näete, et ummikud on teatud tõenäosusega. Kui softirq-kõnesid võetakse vastu harvemini, peavad paketid võrgukaardi RX-järjekorras töötlemiseks mõnda aega ootama. Selle põhjuseks võib olla protsessori tuuma blokeeriv ülesanne või miski muu takistab tuumal softirqi töötamist.
Töötlemise kitsendamine tuumani või meetodini
Softirqi viivitused on praegu vaid oletus. Kuid see on mõistlik ja me teame, et näeme midagi väga sarnast. Nii et järgmine samm on selle teooria kinnitamine. Ja kui see kinnitust leiab, siis leidke hilinemiste põhjus.
Tuleme tagasi 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 varem mainitud, räsitakse need ICMP-paketid ühte RX-i NIC-järjekorda ja neid töötleb üks CPU-tuum. Kui tahame mõista, kuidas Linux töötab, on protsessi jälgimiseks kasulik teada, kus (millisel CPU tuumal) ja kuidas (softirq, ksoftirqd) neid pakette töödeldakse.
Nüüd on aeg kasutada tööriistu, mis võimaldavad teil Linuxi tuuma reaalajas jälgida. Siin kasutasime . See tööriistakomplekt võimaldab teil kirjutada väikeseid C-programme, mis haagivad suvalisi funktsioone kernelisse ja puhverdavad sündmused kasutajaruumi Pythoni programmi, mis suudab neid töödelda ja tulemuse teile tagastada. Kernelis suvaliste funktsioonide sidumine on keeruline asi, kuid utiliit on loodud maksimaalse turvalisuse tagamiseks ja on loodud leidma täpselt selliseid tootmisprobleeme, mida katse- või arenduskeskkonnas pole lihtne reprodutseerida.
Plaan on siin lihtne: me teame, et kernel töötleb neid ICMP pingid, nii et paneme kerneli funktsioonile konksu , mis võtab vastu sissetuleva ICMP kajapäringu paketi ja algatab ICMP kajavastuse saatmise. Saame paketi tuvastada, suurendades icmp_seq numbrit, mis näitab hping3 ülalpool.
Kood tundub keeruline, kuid see pole nii hirmutav, kui tundub. Funktsioon icmp_echo edastab struct sk_buff *skb: See on pakett "kajapäringuga". Saame seda jälgida, jada välja tõmmata echo.sequence (mis on võrreldav icmp_seq autor hping3 выше) ja saatke see kasutajaruumi. Samuti on mugav jäädvustada praeguse protsessi nimi/id. Allpool on tulemused, mida näeme otse, kui kernel töötleb pakette:
TGID PID PROTSESSI NIMETUS 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 swapper/the usperthe 20041me 20086 775 0 0 vahetaja/11 776 0 0 vahetaja/11 777 0 0 pressiesindajad 11
Siinkohal tuleb märkida, et kontekstis softirq süsteemikutseid teinud protsessid kuvatakse "protsessidena", kuigi tegelikult töötleb kernel tuuma kontekstis pakette turvaliselt.
Selle tööriista abil saame seostada konkreetseid protsesse konkreetsete pakettidega, mis näitavad viivitust hping3. Teeme selle lihtsaks grep teatud väärtuste jaoks icmp_seq. Paketid, mis vastavad ülaltoodud icmp_seq väärtustele, märgiti üles koos nende RTT-ga, mida me eespool täheldasime (sulgudes on eeldatavad RTT väärtused pakettide jaoks, mille filtreerisime välja, kuna RTT väärtused olid alla 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 11 ksoftirqd/1954 89 ** ksoftirqd/76 76 ** 11ms 1955 79 76 ksoftirqd /76 11 ** 1956ms 69 76 ksoftirqd/76 11 ** 1957 ms 59 76 ksoftirqd/76 11 ** 1958 ms 49 76 ksoftirqd/76 11 ** (1959 ms) 39 76 ksoftirqd/76 11 ** (1960 ms) 29 76 76 ksoftirqd/11 1961 q19 ms d / 76 76 ** (11 ms) 1962 9 ksoftirqd/10137 10436 ** (2068 ms) -- 10137 10436 cadvisor 2069 76 76 cadvisor 11 2070 75 ksoftirqd/pehme 76 76 ksoftirqd/11 2071/ 65 76 ** 76 ms 11 2072 ksoftirqd/ 55 76 ** 76 ms 11 2073 ksoftirqd/45 76 ** (76 ms) 11 2074 ksoftirqd/35 76 ** (76 ms) 11 2075 ksoftirqd/25 76 **ir 76 ksoftirqd/11 2076 ** 15 76 76 ms ) 11 2077 ksoftirqd/5 XNUMX ** (XNUMX ms)
Tulemused räägivad meile mitmest asjast. Esiteks töödeldakse kõiki neid pakette kontekst ksoftirqd/11. See tähendab, et selle konkreetse masinapaari puhul räsiti ICMP paketid vastuvõtuotsas 11. tuumani. Samuti näeme, et alati, kui tekib ummistus, on pakette, mida töödeldakse süsteemikõne kontekstis cadvisor... Siis ksoftirqd võtab ülesande üle ja töötleb kogunenud järjekorda: täpselt nii palju pakette, mis pärast on kogunenud cadvisor.
Asjaolu, et vahetult enne töötab alati cadvisor, tähendab tema seotust probleemiga. Irooniline, eesmärk - "Analüüsige töötavate konteinerite ressursikasutuse ja jõudlusomadusi", mitte ei põhjusta seda jõudlusprobleemi.
Nagu ka konteinerite muude aspektide puhul, on need kõik väga arenenud tööriistad ja võivad teatud ettenägematutel asjaoludel esineda jõudlusprobleeme.
Mida teeb cadvisor, mis aeglustab pakettide järjekorda?
Nüüd on meil üsna hea arusaam sellest, kuidas krahh toimub, milline protsess seda põhjustab ja millisel protsessoril. Näeme, et kõva blokeerimise tõttu ei ole Linuxi tuumal aega ajastada ksoftirqd. Ja me näeme, et pakette töödeldakse kontekstis cadvisor. Loogiline on seda eeldada cadvisor käivitab aeglase syscalli, mille järel töödeldakse kõiki sel ajal kogunenud pakette:
See on teooria, aga kuidas seda testida? Mida me saame teha, on jälgida protsessori tuuma kogu selle protsessi vältel, leida punkt, kus pakettide arv ületab eelarve ja kutsutakse ksoftirqd, ning seejärel vaadata veidi kaugemale tagasi, et näha, mis täpselt enne seda punkti protsessori tuumas töötas. . See on nagu CPU röntgenülesvõte iga paari millisekundi järel. See näeb välja umbes selline:
Mugavalt saab seda kõike teha olemasolevate vahenditega. Näiteks, kontrollib antud protsessori tuuma kindlal sagedusel ja suudab genereerida töötavale süsteemile kõnede ajakava, mis hõlmab nii kasutajaruumi kui ka Linuxi tuuma. Saate selle kirje võtta ja seda programmi väikese kahvli abil töödelda Brendan Greggilt, mis säilitab virnajälje järjekorra. Saame salvestada üherealised virnajäljed iga 1 ms järel ning seejärel esile tõsta ja salvestada näidise 100 millisekundit enne jälje tabamist 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:
(сотни следов, которые выглядят похожими)
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
Siin on palju asju, kuid peamine on see, et leiame mustri “cadvisor before ksoftirqd”, mida nägime varem ICMP jäljendis. Mida see tähendab?
Iga rida on CPU jälg teatud ajahetkel. Iga rea virna alla tehtud kõne eraldatakse semikooloniga. Ridade keskel näeme, kuidas kutsutakse syscalli: read(): .... ;do_syscall_64;sys_read; .... Seega kulutab cadvisor süsteemikõnele palju aega read()seotud funktsioonidega mem_cgroup_* (kõnede pinu ülaosa/rea lõpp).
Kõnejäljest on ebamugav näha, mida täpselt loetakse, nii et alustame strace ja vaatame, mida cadvisor teeb, ja leiame süsteemikõned, mis on pikemad kui 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>
Nagu arvata võis, näeme siin aeglasi kõnesid read(). Lugemistoimingute sisust ja kontekstist mem_cgroup on selge, et need väljakutsed read() viidata failile memory.stat, mis näitab mälukasutuse ja cgroupi piiranguid (Dockeri ressursside eraldamise tehnoloogia). Cadvisori tööriist küsib seda faili, et hankida konteinerite ressursikasutuse teavet. Kontrollime, kas kernel või cadvisor teeb midagi ootamatut:
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 ~ $
Nüüd saame vea reprodutseerida ja mõista, et Linuxi kernel seisab silmitsi patoloogiaga.
Miks on lugemisoperatsioon nii aeglane?
Selles etapis on teistelt kasutajatelt sarnaste probleemide kohta sõnumeid palju lihtsam leida. Nagu selgus, teatati cadvisor trackeris sellest veast kui , lihtsalt keegi ei märganud, et latentsusaeg kajastub juhuslikult ka võrgupinus. Tõepoolest märgati, et cadvisor kulutas oodatust rohkem protsessori aega, kuid sellele ei antud erilist tähtsust, kuna meie serveritel on palju protsessoriressursse, mistõttu probleemi ei uuritud hoolikalt.
Probleem on selles, et c-rühmad võtavad arvesse mälukasutust nimeruumis (konteineris). Kui kõik protsessid selles c-rühmas väljuvad, vabastab Docker mälu cgroupi. Kuid "mälu" ei ole ainult protsessimälu. Kuigi protsessimälu ennast enam ei kasutata, näib, et kernel määrab endiselt vahemällu salvestatud sisu, näiteks dentries ja inode (kataloogi ja faili metaandmed), mis salvestatakse mälu cgroupi vahemällu. Probleemi kirjeldusest:
zombie cgroups: cgroupid, millel pole protsesse ja mis on kustutatud, kuid millel on siiski mälu eraldatud (minu puhul dentry vahemälust, kuid seda saab eraldada ka lehe vahemälust või tmpfs-ist).
Tuuma kontrollib kõiki vahemälus olevaid lehti c-rühma vabastamisel võib olla väga aeglane, seetõttu valitakse laisk protsess: oodake, kuni neid lehti uuesti küsitakse, ja seejärel tühjendage cgroup lõpuks, kui mälu on tegelikult vaja. Kuni selle hetkeni arvestatakse statistika kogumisel endiselt cgroupi.
Jõudluse seisukohast ohverdasid nad jõudluse nimel mälu: kiirendasid esialgset puhastamist, jättes maha vahemälu. See sobib. Kui kernel kasutab viimast vahemälu, kustutatakse lõpuks c-grupp, mistõttu seda ei saa nimetada "lekkeks". Kahjuks konkreetse rakendamise otsingumehhanismi memory.stat selles kerneli versioonis (4.9) koos meie serverite tohutu mälumahuga tähendab see, et viimaste vahemällu salvestatud andmete taastamine ja cgroup zombide kustutamine võtab palju kauem aega.
Selgub, et mõnel meie sõlmel oli nii palju cgroupi zombisid, et lugemine ja latentsus ületasid sekundi.
Cadvisori probleemi lahendus on vabastada kohe kogu süsteemis olevad dentries/inode vahemälud, mis kõrvaldab kohe hosti lugemislatentsi ja ka võrgu latentsuse, kuna vahemälu tühjendamine lülitab sisse vahemällu salvestatud zombie cgroupi lehed ja vabastab need ka. See ei ole lahendus, kuid see kinnitab probleemi põhjust.
Selgus, et uuemates kerneli versioonides (4.19+) paranes kõnede jõudlus memory.stat, nii et sellele kernelile üleminek lahendas probleemi. Samal ajal olid meil tööriistad Kubernetese klastrite probleemsete sõlmede tuvastamiseks, nende elegantseks tühjendamiseks ja taaskäivitamiseks. Kammisime kõik klastrid läbi, leidsime piisavalt kõrge latentsusega sõlmed ja taaskäivitasime need. See andis meile aega ülejäänud serverite OS-i värskendamiseks.
Kokkuvõtteks
Kuna see viga peatas RX NIC-i järjekorra töötlemise sadadeks millisekunditeks, põhjustas see samaaegselt nii lühikeste ühenduste kõrge latentsuse kui ka keskmise ühenduse latentsuse, näiteks MySQL-i päringute ja vastusepakettide vahel.
Kõige põhilisemate süsteemide (nt Kubernetes) jõudluse mõistmine ja säilitamine on kõigi nendel põhinevate teenuste usaldusväärsuse ja kiiruse jaoks ülioluline. Iga teie käitatav süsteem saab kasu Kubernetese jõudluse täiustustest.
Allikas: www.habr.com