Pari vuotta sitten Kubernetes virallisessa GitHub-blogissa. Siitä lähtien siitä on tullut palvelujen käyttöönoton standarditekniikka. Kubernetes hallinnoi nyt merkittävää osaa sisäisistä ja julkisista palveluista. Kun klusterimme kasvoivat ja suorituskykyvaatimukset tiukenivat, aloimme huomata, että joissakin Kubernetesin palveluissa esiintyi satunnaisesti latenssia, jota ei voitu selittää itse sovelluksen kuormituksella.
Käytännössä sovellukset kokevat satunnaisen verkon latenssin jopa 100 ms tai enemmän, mikä johtaa aikakatkaisuihin tai uudelleen yrityksiin. Palveluiden odotettiin pystyvän vastaamaan pyyntöihin paljon nopeammin kuin 100 ms. Mutta tämä on mahdotonta, jos itse yhteys vie niin paljon aikaa. Erikseen havaitsimme erittäin nopeita MySQL-kyselyitä, joiden pitäisi kestää millisekunteja, ja MySQL valmistui millisekunneissa, mutta pyytävän sovelluksen näkökulmasta vastaus kesti 100 ms tai enemmän.
Välittömästi kävi selväksi, että ongelma ilmeni vain Kubernetesin solmuun yhdistettäessä, vaikka puhelu olisi tullut Kubernetesin ulkopuolelta. Helpoin tapa toistaa ongelma on testi , joka toimii mistä tahansa sisäisestä isännästä, testaa Kubernetes-palvelua tietyssä portissa ja rekisteröi satunnaisesti korkean viiveen. Tässä artikkelissa tarkastellaan, kuinka pystyimme jäljittämään tämän ongelman syyn.
Poistaa tarpeettoman monimutkaisuuden ketjusta, joka johtaa epäonnistumiseen
Toistamalla saman esimerkin halusimme kaventaa ongelman painopistettä ja poistaa tarpeettomia monimutkaisia kerroksia. Aluksi Vegetan ja Kubernetes-palojen välisessä virtauksessa oli liikaa elementtejä. Syvemmän verkko-ongelman tunnistamiseksi sinun on suljettava pois jotkin niistä.
Asiakas (Vegeta) luo TCP-yhteyden minkä tahansa klusterin solmun kanssa. Kubernetes toimii peittoverkkona (nykyisen datakeskusverkon päällä), joka käyttää , eli se kapseloi peittoverkon IP-paketit datakeskuksen IP-pakettien sisään. Kun muodostat yhteyden ensimmäiseen solmuun, verkko-osoitteen muunnos suoritetaan (NAT) tilallinen kääntääkseen Kubernetes-solmun IP-osoitteen ja portin IP-osoitteeksi ja portiksi peittoverkossa (erityisesti sovelluksen sisältävässä podissa). Saapuville paketeille suoritetaan käänteinen toimintosarja. Se on monimutkainen järjestelmä, jossa on paljon tilaa ja monia elementtejä, joita päivitetään ja muutetaan jatkuvasti, kun palveluja otetaan käyttöön ja siirretään.
Apuohjelma tcpdump Vegeta-testissä on viive TCP-kättelyn aikana (SYN:n ja SYN-ACKin välillä). Voit poistaa tämän tarpeettoman monimutkaisuuden käyttämällä hping3 yksinkertaisia "ping-viestejä" SYN-pakettien kanssa. Tarkistamme, onko vastauspaketissa viivettä, ja nollaamme sitten yhteyden. Voimme suodattaa tiedot sisältämään vain yli 100 ms:n pituiset paketit ja saamme helpomman tavan toistaa ongelma kuin Vegetan koko verkkokerroksen 7 testi. Tässä ovat Kubernetes-solmun "pingit", jotka käyttävät TCP SYN/SYN-ACK -toimintoa palvelun "solmuportissa" (30927) 10 ms:n välein, suodatettuina hitaimpien vastausten mukaan:
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
Voi tehdä heti ensimmäisen havainnon. Järjestysnumeroista ja ajoituksista päätellen on selvää, että kyseessä eivät ole kertaluonteiset ruuhkat. Viive kertyy usein ja lopulta käsitellään.
Seuraavaksi haluamme selvittää, mitkä komponentit voivat olla osallisena ruuhkien esiintymisessä. Ehkä nämä ovat joitain NAT:n sadoista iptables-säännöistä? Vai onko IPIP-tunneloinnin kanssa ongelmia verkossa? Yksi tapa tarkistaa tämä on testata järjestelmän jokaista vaihetta poistamalla se. Mitä tapahtuu, jos poistat NAT- ja palomuurilogiikan jättäen vain IPIP-osan:
Onneksi Linuxin avulla on helppo päästä suoraan IP-peittokerrokseen, jos kone on samassa verkossa:
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
Tulosten perusteella ongelma on edelleen olemassa! Tämä ei sisällä iptablesia ja NATia. Eli ongelma on TCP? Katsotaan kuinka tavallinen ICMP-ping sujuu:
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
Tulokset osoittavat, että ongelma ei ole poistunut. Ehkä tämä on IPIP-tunneli? Yksinkertaistetaan testiä entisestään:
Lähetetäänkö kaikki paketit näiden kahden isännän välillä?
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
Olemme yksinkertaistaneet tilannetta niin, että kaksi Kubernetes-solmua lähettävät toisilleen minkä tahansa paketin, jopa ICMP-pingin. He näkevät silti latenssin, jos kohdeisäntä on "huono" (jotkut huonommin kuin toiset).
Nyt viimeinen kysymys: miksi viive esiintyy vain kube-solmupalvelimissa? Ja tapahtuuko se, kun kube-solmu on lähettäjä vai vastaanottaja? Onneksi tämä on myös melko helppo selvittää lähettämällä paketti Kubernetesin ulkopuolelta, mutta samalla "tunnetulla huonolla" vastaanottajalla. Kuten näet, ongelma ei ole hävinnyt:
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
Suoritamme sitten samat pyynnöt edellisestä lähdekube-solmusta ulkoiselle isännälle (joka ei sisällä lähdeisäntää, koska ping sisältää sekä RX- että TX-komponentin):
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
Tutkimalla latenssipakettien sieppauksia saimme lisätietoja. Tarkemmin sanottuna lähettäjä (alhaalla) näkee tämän aikakatkaisun, mutta vastaanottaja (ylhäällä) ei – katso Delta-sarake (sekunneissa):
Lisäksi, jos tarkastellaan eroa TCP- ja ICMP-pakettien järjestyksessä (järjestysnumeroiden mukaan) vastaanottajapuolella, ICMP-paketit saapuvat aina samassa järjestyksessä kuin ne lähetettiin, mutta eri ajoituksella. Samaan aikaan TCP-paketit joskus limittyvät, ja osa niistä juuttuu. Erityisesti jos tarkastelet SYN-pakettien portteja, ne ovat järjestyksessä lähettäjän puolella, mutta eivät vastaanottajan puolella.
Siinä on hienovarainen ero nykyaikaiset palvelimet (kuten konesalissamme) käsittelevät TCP:tä tai ICMP:tä sisältäviä paketteja. Kun paketti saapuu, verkkosovitin "hajauttaa sen yhteyskohtaisesti", eli se yrittää jakaa yhteydet jonoihin ja lähettää jokaisen jonon erilliseen prosessoriytimeen. TCP:ssä tämä hash sisältää sekä lähteen että kohde-IP-osoitteen ja portin. Toisin sanoen jokainen yhteys on hajautettu (mahdollisesti) eri tavalla. ICMP:ssä vain IP-osoitteet hajautetaan, koska portteja ei ole.
Toinen uusi havainto: tänä aikana näemme ICMP-viiveitä kaikessa kahden isännän välisessä tiedonsiirrossa, mutta TCP ei. Tämä kertoo meille, että syy liittyy todennäköisesti RX-jonon hajautukseen: ruuhka on lähes varmasti RX-pakettien käsittelyssä, ei vastausten lähettämisessä.
Tämä eliminoi pakettien lähettämisen mahdollisten syiden luettelosta. Tiedämme nyt, että pakettien käsittelyongelma on joidenkin kube-solmupalvelimien vastaanottopuolella.
Pakettien käsittelyn ymmärtäminen Linux-ytimessä
Ymmärtääksemme, miksi ongelma ilmenee joidenkin kube-solmupalvelimien vastaanottimessa, katsotaan kuinka Linux-ydin käsittelee paketteja.
Palaten yksinkertaisimpaan perinteiseen toteutukseen, verkkokortti vastaanottaa paketin ja lähettää Linux-ytimen, että siellä on paketti, joka on käsiteltävä. Ydin pysäyttää muun työn, vaihtaa kontekstin keskeytyskäsittelijään, käsittelee paketin ja palaa sitten nykyisiin tehtäviin.
Tämä kontekstin vaihto on hidasta: latenssi ei ehkä ollut havaittavissa 10 Mbps verkkokorteissa 90-luvulla, mutta nykyaikaisilla 10G-korteilla, joiden maksimikapasiteetti on 15 miljoonaa pakettia sekunnissa, pienen kahdeksanytimisen palvelimen jokainen ydin voi katketa miljoonia. kertaa sekunnissa.
Jotta keskeytyksiä ei jatkuvasti käsitellä, Linux lisättiin monta vuotta sitten : Verkkosovellusliittymä, jota kaikki nykyaikaiset ohjaimet käyttävät parantaakseen suorituskykyä suurilla nopeuksilla. Pienillä nopeuksilla ydin vastaanottaa edelleen keskeytyksiä verkkokortilta vanhalla tavalla. Kun tarpeeksi paketteja saapuu, jotka ylittävät kynnyksen, ydin poistaa keskeytykset käytöstä ja alkaa sen sijaan pollata verkkosovitinta ja poimia paketteja paloina. Käsittely suoritetaan softirqissa, eli in järjestelmäkutsujen ja laitteiston keskeytysten jälkeen, kun ydin (toisin kuin käyttäjätila) on jo käynnissä.
Tämä on paljon nopeampi, mutta aiheuttaa toisenlaisen ongelman. Jos paketteja on liikaa, koko aika kuluu pakettien käsittelyyn verkkokortilta, eikä käyttäjätilaprosesseilla ole aikaa tyhjentää näitä jonoja (TCP-yhteyksistä lukeminen jne.). Lopulta jonot täyttyvät ja alamme pudottaa paketteja. Tasapainon löytämiseksi ydin asettaa budjetin softirq-kontekstissa käsiteltyjen pakettien enimmäismäärälle. Kun tämä budjetti ylittyy, herätetään erillinen lanka ksoftirqd (näet yhden niistä ps per ydin), joka käsittelee nämä softirqs normaalin syscall/keskeytyspolun ulkopuolella. Tämä säie ajoitetaan käyttämällä tavallista prosessin ajastinta, joka yrittää jakaa resurssit oikeudenmukaisesti.
Kun olet tutkinut, kuinka ydin käsittelee paketteja, voit nähdä, että ruuhkautumisen todennäköisyys on tietty. Jos softirq-puheluita vastaanotetaan harvemmin, paketit joutuvat odottamaan jonkin aikaa, jotta ne käsitellään verkkokortin RX-jonossa. Tämä voi johtua siitä, että jokin tehtävä estää prosessorin ytimen, tai jokin muu estää ydintä toimimasta softirq.
Käsittelyn rajaaminen ytimeen tai menetelmään
Softirq-viiveet ovat toistaiseksi vain arvauksia. Mutta se on järkevää, ja tiedämme, että näemme jotain hyvin samanlaista. Joten seuraava askel on vahvistaa tämä teoria. Ja jos se vahvistetaan, niin etsi syy viivästyksiin.
Palataan hitaisiin paketteihimme:
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
Kuten aiemmin mainittiin, nämä ICMP-paketit tiivistetään yhdeksi RX NIC -jonoksi ja niitä käsittelee yksi CPU-ydin. Jos haluamme ymmärtää, miten Linux toimii, on hyödyllistä tietää missä (millä CPU-ytimellä) ja miten (softirq, ksoftirqd) näitä paketteja käsitellään prosessin seuraamiseksi.
Nyt on aika käyttää työkaluja, joiden avulla voit seurata Linux-ydintä reaaliajassa. Täällä käytimme . Tämän työkalusarjan avulla voit kirjoittaa pieniä C-ohjelmia, jotka kiinnittävät mielivaltaisia toimintoja ytimeen ja puskuroivat tapahtumat käyttäjätilan Python-ohjelmaan, joka voi käsitellä ne ja palauttaa tuloksen sinulle. Mielivaltaisten funktioiden kytkeminen ytimeen on monimutkainen asia, mutta apuohjelma on suunniteltu maksimaalista turvallisuutta varten ja se on suunniteltu jäljittämään juuri sellaisia tuotantoongelmia, joita ei ole helppo toistaa testi- tai kehitysympäristössä.
Suunnitelma tässä on yksinkertainen: tiedämme, että ydin käsittelee nämä ICMP-pingit, joten laitamme koukun ytimen toimintoon , joka hyväksyy saapuvan ICMP-kaikupyyntöpaketin ja aloittaa ICMP-kaikuvastauksen lähettämisen. Voimme tunnistaa paketin lisäämällä icmp_seq-lukua, joka näyttää hping3 edellä.
Koodi näyttää monimutkaiselta, mutta se ei ole niin pelottavaa kuin miltä näyttää. Toiminto icmp_echo lähettää struct sk_buff *skb: Tämä on paketti, jossa on "kaikupyyntö". Voimme seurata sitä, vetää sarjan esiin echo.sequence (johon verrattuna icmp_seq tekijältä hping3 выше) ja lähetä se käyttäjätilaan. On myös kätevää kaapata nykyinen prosessin nimi/tunnus. Alla on tulokset, jotka näemme suoraan, kun ydin käsittelee paketteja:
TGID PID-PROSESSIN 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 swapper/20041 20086 775prothe 0 0 11 776 vaihtaja/0 0 11 777 0 swapperi/0 11 778 4512 puhuja-raportit 4542
Tässä yhteydessä on syytä huomata, että softirq järjestelmäkutsuja tehneet prosessit näkyvät "prosesseina", vaikka itse asiassa ydin käsittelee paketit turvallisesti ytimen yhteydessä.
Tällä työkalulla voimme liittää tiettyjä prosesseja tiettyihin paketteihin, jotka näyttävät viiveen hping3. Tehdään siitä yksinkertainen grep tässä sieppauksessa tietyille arvoille icmp_seq. Yllä olevia icmp_seq-arvoja vastaavat paketit merkittiin muistiin yhdessä niiden RTT:n kanssa, jonka havaitsimme edellä (suluissa ovat odotetut RTT-arvot paketeille, jotka suodatimme pois alle 50 ms:n RTT-arvojen vuoksi):
TGID PID-PROSESSIN NIMI ICMP_SEQ ** RTT -- 10137 10436 cadvisor 1951 10137 10436 cadvisor 1952 76 76 ksoftirqd/11 1953 ** 99ms 76 76 11 ksoftirqd/1954 89 ** 76ms 76 11 1955 ksoftirqd qd/79 76 ** 76ms 11 1956 ksoftirqd/ 69 76 ** 76 ms 11 1957 ksoftirqd/59 76 ** 76 ms 11 1958 ksoftirqd/49 76 ** (76 ms) 11 1959 ksoftirqd/39 76 ** (76 ms) 11 ms 1960 29 76 76 ** 11 1961 19 76 76 ms 11 ksoft irqd/ 1962 9 ** (10137 ms) 10436 2068 ksoftirqd/10137 10436 ** (2069 ms) -- 76 76 cadvisor 11 2070 75 cadvisor 76 76 11 ksoftirqd ** 2071 q65 d/76 softirqd d/76 11 ** 2072 ms 55 76 ksoftirqd/ 76 11 ** 2073 ms 45 76 ksoftirqd/76 11 ** (2074 ms) 35 76 ksoftirqd/76 11 ** (2075 ms) 25 76 ksoftirqd/76 11 ** ir 2076 ksoftirqd/15 76 ** 76 d/11 ms ) 2077 5 ksoftirqd/XNUMX XNUMX ** (XNUMX ms)
Tulokset kertovat meille useita asioita. Ensinnäkin kaikki nämä paketit käsitellään kontekstin mukaan ksoftirqd/11. Tämä tarkoittaa, että tässä koneparissa ICMP-paketit hajautettiin ytimeen 11 vastaanottopäässä. Näemme myös, että aina kun on tukoksia, on paketteja, jotka käsitellään järjestelmäkutsun yhteydessä cadvisor. sitten ksoftirqd ottaa tehtävän hoitaakseen ja käsittelee kertyneen jonon: täsmälleen sen jälkeen, kun paketteja on kertynyt cadvisor.
Se, että juuri ennen se toimii aina cadvisor, viittaa hänen osallisuutensa ongelmaan. Ironista kyllä, tarkoitus - "analysoi käynnissä olevien säilöjen resurssien käyttöä ja suorituskykyominaisuuksia" sen sijaan, että aiheutat tämän suorituskykyongelman.
Kuten muutkin konttien ominaisuudet, nämä ovat kaikki erittäin kehittyneitä työkaluja, ja niiden voidaan odottaa kokevan suorituskykyongelmia joissakin odottamattomissa olosuhteissa.
Mitä cadvisor tekee, mikä hidastaa pakettijonoa?
Meillä on nyt melko hyvä käsitys siitä, miten kaatuminen tapahtuu, mikä prosessi aiheuttaa sen ja missä suorittimessa. Näemme, että kovan estämisen vuoksi Linux-ytimellä ei ole aikaa ajoittaa ksoftirqd. Ja näemme, että paketteja käsitellään kontekstissa cadvisor. On loogista olettaa niin cadvisor käynnistää hitaan syscallin, jonka jälkeen kaikki tuolloin kertyneet paketit käsitellään:
Tämä on teoria, mutta miten sitä testataan? Voimme jäljittää prosessorin ytimen koko tämän prosessin ajan, löytää pisteen, jossa pakettien määrä ylittää budjetin ja ksoftirqd kutsutaan, ja sitten katsoa hieman kauemmaksi nähdäksemme mitä tarkalleen suorittimen ytimessä oli käynnissä juuri ennen sitä kohtaa. . Se on kuin prosessorin röntgenkuvaus muutaman millisekunnin välein. Se näyttää suunnilleen tältä:
Kätevästi kaikki tämä voidaan tehdä olemassa olevilla työkaluilla. Esimerkiksi, tarkistaa tietyn suorittimen ytimen tietyllä taajuudella ja voi luoda aikataulun puheluista käynnissä olevaan järjestelmään, mukaan lukien sekä käyttäjätila että Linux-ydin. Voit ottaa tämän tietueen ja käsitellä sitä ohjelman pienellä haarukalla Brendan Greggiltä, joka säilyttää pinojäljen järjestyksen. Voimme tallentaa yksiriviset pinojäljet 1 ms välein ja sitten korostaa ja tallentaa näytteen 100 millisekuntia ennen kuin jäljitys osuu 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
Tässä tulokset:
(сотни следов, которые выглядят похожими)
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
Täällä on paljon asioita, mutta tärkeintä on, että löydämme "cadvisor before ksoftirqd" -mallin, jonka näimme aiemmin ICMP-tracerissa. Mitä se tarkoittaa?
Jokainen rivi on suorittimen jäljitys tietyllä hetkellä. Jokainen rivin puhelu on erotettu puolipisteellä. Rivien keskellä näemme syscallin olevan nimeltään: read(): .... ;do_syscall_64;sys_read; .... Joten cadvisor viettää paljon aikaa järjestelmäkutsussa read()toimintoihin liittyvää mem_cgroup_* (puhelupinon yläreuna/linjan loppu).
On hankalaa nähdä puhelujäljestä, mitä tarkalleen luetaan, joten ajataan strace ja katsotaan mitä cadvisor tekee ja löydetään yli 100 ms:n pituiset järjestelmäkutsut:
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>
Kuten arvata saattaa, näemme täällä hitaita puheluita read(). Lukutoimintojen sisällöstä ja kontekstista mem_cgroup on selvää, että nämä haasteet read() viitata tiedostoon memory.stat, joka näyttää muistin käytön ja cgroup-rajat (Dockerin resurssien eristystekniikka). Cadvisor-työkalu kyselee tätä tiedostoa saadakseen säiliöiden resurssien käyttötiedot. Tarkistetaan, tekeekö ydin tai cadvisor jotain odottamatonta:
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 ~ $
Nyt voimme toistaa virheen ja ymmärtää, että Linux-ytimessä on patologia.
Miksi lukutoiminto on niin hidas?
Tässä vaiheessa on paljon helpompi löytää viestejä muilta käyttäjiltä vastaavista ongelmista. Kuten kävi ilmi, cadvisor-seurannassa tämä vika ilmoitettiin nimellä , kukaan ei vain huomannut, että latenssi näkyy satunnaisesti myös verkkopinossa. Todellisuudessa havaittiin, että cadvisor kulutti odotettua enemmän CPU-aikaa, mutta tälle ei annettu suurta painoarvoa, koska palvelimillamme on paljon CPU-resursseja, joten ongelmaa ei tutkittu huolellisesti.
Ongelmana on, että c-ryhmät ottavat huomioon muistin käytön nimiavaruudessa (säilössä). Kun kaikki tämän c-ryhmän prosessit poistuvat, Docker vapauttaa muistin c-ryhmän. "Muisti" ei kuitenkaan ole vain prosessimuisti. Vaikka itse prosessimuistia ei enää käytetä, näyttää siltä, että ydin osoittaa edelleen välimuistissa olevia sisältöjä, kuten dentriejä ja inodeja (hakemisto- ja tiedostometadata), jotka tallennetaan muistin c-ryhmään. Ongelman kuvauksesta:
zombie cgroups: c-ryhmät, joissa ei ole prosesseja ja jotka on poistettu, mutta joilla on edelleen muistia varattu (minun tapauksessani dentry-välimuistista, mutta se voidaan varata myös sivun välimuistista tai tmpfs:stä).
Ytimen tarkistus kaikista välimuistissa olevista sivuista c-ryhmän vapauttamisen yhteydessä voi olla hyvin hidasta, joten valitaan laiska prosessi: odota, kunnes näitä sivuja pyydetään uudelleen, ja lopuksi tyhjennä c-ryhmä, kun muistia todella tarvitaan. Tähän asti cgroup otetaan huomioon tilastojen keräämisessä.
Suorituskyvyn näkökulmasta he uhrasivat muistia suorituskyvyn vuoksi: nopeuttaivat alkuperäistä puhdistusta jättämällä välimuistia taakseen. Tämä on hyvä. Kun ydin käyttää viimeistä välimuistia, c-ryhmä tyhjennetään lopulta, joten sitä ei voida kutsua "vuodoksi". Valitettavasti erityistä täytäntöönpanoa hakumekanismi memory.stat Tässä ytimen versiossa (4.9) yhdistettynä valtavaan muistimäärään palvelimillamme kestää paljon kauemmin viimeisimpien välimuistitietojen palauttaminen ja cgroup zombien tyhjentäminen.
Osoittautuu, että joissakin solmuissamme oli niin paljon cgroup-zombeja, että luku- ja latenssi ylittivät sekunnin.
Ratkaisu cadvisor-ongelmaan on vapauttaa välittömästi dentries/inode-välimuistit kaikkialla järjestelmässä, mikä eliminoi välittömästi lukuviiveen sekä verkkoviiveen isännässä, koska välimuistin tyhjentäminen käynnistää välimuistissa olevat zombie-cgroup-sivut ja vapauttaa myös ne. Tämä ei ole ratkaisu, mutta se vahvistaa ongelman syyn.
Kävi ilmi, että uudemmissa ytimen versioissa (4.19+) puhelun suorituskyky parani memory.stat, joten tähän ytimeen vaihtaminen korjasi ongelman. Samaan aikaan meillä oli työkalut ongelmallisten solmujen havaitsemiseen Kubernetes-klustereissa, tyhjentämään ne sulavasti ja käynnistämään ne uudelleen. Kampaamme kaikki klusterit, löysimme solmut, joilla oli riittävän korkea latenssi, ja käynnistimme ne uudelleen. Tämä antoi meille aikaa päivittää jäljellä olevien palvelimien käyttöjärjestelmä.
Yhteenvetona
Koska tämä virhe pysäytti RX NIC -jonon käsittelyn sadoiksi millisekunneiksi, se aiheutti samanaikaisesti sekä korkean viiveen lyhyissä yhteyksissä että keskipitkän yhteyden viiveen, kuten MySQL-pyyntöjen ja vastauspakettien välillä.
Perusteellisten järjestelmien, kuten Kubernetesin, ymmärtäminen ja suorituskyvyn ylläpitäminen on kriittistä kaikkien niihin perustuvien palvelujen luotettavuuden ja nopeuden kannalta. Jokainen käyttämäsi järjestelmä hyötyy Kubernetesin suorituskyvyn parannuksista.
Lähde: will.com