Pred pár rokmi Kubernetes na oficiálnom blogu GitHub. Odvtedy sa stala štandardnou technológiou nasadzovania služieb. Kubernetes teraz spravuje významnú časť interných a verejných služieb. Ako naše klastre rástli a požiadavky na výkon boli prísnejšie, začali sme si všímať, že niektoré služby na Kubernetes sporadicky zaznamenávali oneskorenie, ktoré sa nedalo vysvetliť zaťažením samotnej aplikácie.
V podstate aplikácie zažívajú zdanlivo náhodnú sieťovú latenciu až 100 ms alebo viac, čo vedie k časovým limitom alebo opakovaným pokusom. Očakávalo sa, že služby budú schopné reagovať na požiadavky oveľa rýchlejšie ako 100 ms. Ale to je nemožné, ak samotné pripojenie trvá toľko času. Samostatne sme pozorovali veľmi rýchle dotazy MySQL, ktoré mali trvať milisekúndy, a MySQL sa dokončilo v milisekúndách, ale z pohľadu žiadajúcej aplikácie odpoveď trvala 100 ms alebo viac.
Okamžite sa ukázalo, že problém sa vyskytol iba pri pripojení k uzlu Kubernetes, aj keď hovor prichádzal mimo Kubernetes. Najjednoduchší spôsob, ako reprodukovať problém, je test , ktorý beží z akéhokoľvek interného hostiteľa, testuje službu Kubernetes na konkrétnom porte a sporadicky zaznamenáva vysokú latenciu. V tomto článku sa pozrieme na to, ako sa nám podarilo zistiť príčinu tohto problému.
Odstránenie zbytočnej zložitosti v reťazci vedúcej k zlyhaniu
Reprodukovaním toho istého príkladu sme chceli zúžiť zameranie problému a odstrániť zbytočné vrstvy zložitosti. Spočiatku bolo v toku medzi Podravkou a Kubernetes príliš veľa prvkov. Ak chcete identifikovať hlbší problém so sieťou, musíte niektoré z nich vylúčiť.
Klient (Vegeta) vytvorí TCP spojenie s akýmkoľvek uzlom v klastri. Kubernetes funguje ako prekryvná sieť (nad existujúcou sieťou dátového centra), ktorá používa , to znamená, že zapuzdruje IP pakety prekryvnej siete do IP paketov dátového centra. Pri pripojení k prvému uzlu sa vykoná preklad sieťovej adresy (NAT) stavový na preklad IP adresy a portu uzla Kubernetes na IP adresu a port v prekryvnej sieti (konkrétne podu s aplikáciou). Pre prichádzajúce pakety sa vykoná opačná postupnosť akcií. Ide o komplexný systém s množstvom stavu a mnohými prvkami, ktoré sa neustále aktualizujú a menia, keď sa služby nasadzujú a presúvajú.
Užitočnosť tcpdump v teste Podravka je oneskorenie pri TCP handshake (medzi SYN a SYN-ACK). Ak chcete odstrániť túto zbytočnú zložitosť, môžete použiť hping3 pre jednoduché „pingy“ s paketmi SYN. Skontrolujeme, či došlo k oneskoreniu v pakete odpovede, a potom resetujeme pripojenie. Dáta môžeme filtrovať tak, aby zahŕňali len pakety väčšie ako 100 ms a získame jednoduchší spôsob, ako reprodukovať problém, než úplný test sieťovej vrstvy 7 v Podravke. Tu sú „pingy“ uzla Kubernetes pomocou TCP SYN/SYN-ACK na službe „port uzla“ (30927) v intervaloch 10 ms, filtrované podľa najpomalších odpovedí:
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
Môže okamžite urobiť prvé pozorovanie. Súdiac podľa poradových čísel a časovania je jasné, že nejde o jednorazové zápchy. Oneskorenie sa často nahromadí a nakoniec sa spracuje.
Ďalej chceme zistiť, ktoré zložky sa môžu podieľať na vzniku preťaženia. Možno sú to niektoré zo stoviek pravidiel iptables v NAT? Alebo sú nejaké problémy s IPIP tunelovaním v sieti? Jedným zo spôsobov, ako to otestovať, je otestovať každý krok systému jeho odstránením. Čo sa stane, ak odstránite NAT a logiku brány firewall a ponecháte iba časť IPIP:
Našťastie Linux uľahčuje priamy prístup k prekryvnej vrstve IP, ak je počítač v rovnakej sieti:
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
Súdiac podľa výsledkov, problém stále zostáva! To nezahŕňa iptables a NAT. Takže problém je v TCP? Pozrime sa, ako prebieha bežný ICMP ping:
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
Výsledky ukazujú, že problém nezmizol. Možno je to tunel IPIP? Zjednodušme si test ďalej:
Posielajú sa všetky pakety medzi týmito dvoma hostiteľmi?
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
Zjednodušili sme situáciu tak, že dva uzly Kubernetes si navzájom posielajú akýkoľvek paket, dokonca aj ICMP ping. Stále vidia latenciu, ak je cieľový hostiteľ „zlý“ (niektoré horšie ako iné).
Teraz posledná otázka: prečo sa oneskorenie vyskytuje iba na serveroch kube-node? A stane sa to, keď je kube-node odosielateľom alebo príjemcom? Našťastie je to tiež celkom ľahké zistiť odoslaním paketu od hostiteľa mimo Kubernetes, ale s rovnakým „známym zlým“ príjemcom. Ako vidíte, problém nezmizol:
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
Potom spustíme rovnaké požiadavky z predchádzajúceho zdrojového uzla kube na externého hostiteľa (čo vylučuje zdrojového hostiteľa, pretože ping obsahuje komponent RX aj 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
Preskúmaním zachytenia paketov latencie sme získali niekoľko ďalších informácií. Konkrétne, že odosielateľ (dole) vidí tento časový limit, ale príjemca (hore) nie - pozri stĺpec Delta (v sekundách):
Okrem toho, ak sa pozriete na rozdiel v poradí TCP a ICMP paketov (podľa sekvenčných čísel) na strane príjemcu, ICMP pakety vždy prichádzajú v rovnakom poradí, v akom boli odoslané, ale s rôznym načasovaním. Zároveň sa TCP pakety niekedy prekladajú a niektoré z nich sa zaseknú. Najmä ak skúmate porty paketov SYN, sú v poriadku na strane odosielateľa, ale nie na strane príjemcu.
Je jemný rozdiel v tom, ako moderné servery (ako tie v našom dátovom centre) spracovávajú pakety obsahujúce TCP alebo ICMP. Keď príde paket, sieťový adaptér ho „zahašuje na pripojenie“, to znamená, že sa pokúsi rozdeliť spojenia do frontov a poslať každý front do samostatného jadra procesora. Pre TCP tento hash zahŕňa zdrojovú aj cieľovú IP adresu a port. Inými slovami, každé spojenie je hašované (potenciálne) inak. V prípade protokolu ICMP sa hašujú iba adresy IP, pretože neexistujú žiadne porty.
Ďalšie nové pozorovanie: počas tohto obdobia vidíme oneskorenia ICMP vo všetkých komunikáciách medzi dvoma hostiteľmi, ale TCP nie. To nám hovorí, že príčina pravdepodobne súvisí s hashovaním frontu RX: preťaženie je takmer určite v spracovaní paketov RX, nie v odosielaní odpovedí.
To eliminuje odosielanie paketov zo zoznamu možných príčin. Teraz vieme, že problém so spracovaním paketov je na strane príjmu na niektorých serveroch kube-node.
Pochopenie spracovania paketov v jadre Linuxu
Aby sme pochopili, prečo sa problém vyskytuje v prijímači na niektorých serveroch kube-node, pozrime sa, ako linuxové jadro spracováva pakety.
Ak sa vrátime k najjednoduchšej tradičnej implementácii, sieťová karta prijme paket a odošle linuxového jadra, že existuje balík, ktorý je potrebné spracovať. Jadro zastaví ďalšiu prácu, prepne kontext na obsluhu prerušenia, spracuje paket a potom sa vráti k aktuálnym úlohám.
Toto prepínanie kontextu je pomalé: latencia nemusela byť badateľná na 10Mbps sieťových kartách v 90-tych rokoch, ale na moderných 10G kartách s maximálnou priepustnosťou 15 miliónov paketov za sekundu môže byť každé jadro malého osemjadrového servera prerušených milióny krát za sekundu.
Aby sa neustále nevybavovali prerušenia, pred mnohými rokmi sa pridal Linux : Sieťové API, ktoré používajú všetky moderné ovládače na zlepšenie výkonu pri vysokých rýchlostiach. Pri nízkych rýchlostiach jadro stále prijíma prerušenia zo sieťovej karty starým spôsobom. Akonáhle príde dostatok paketov, ktoré prekročia prahovú hodnotu, jadro zakáže prerušenia a namiesto toho začne žiadať sieťový adaptér a vyberať pakety po častiach. Spracovanie sa vykonáva v softirq, to znamená v po systémových volaniach a hardvérových prerušeniach, keď je jadro (na rozdiel od užívateľského priestoru) už spustené.
Je to oveľa rýchlejšie, ale spôsobuje to iný problém. Ak je paketov priveľa, všetok čas sa strávi spracovaním paketov zo sieťovej karty a procesy používateľského priestoru nemajú čas tieto fronty skutočne vyprázdniť (čítanie z TCP spojení atď.). Nakoniec sa rady zaplnia a začneme zhadzovať pakety. V snahe nájsť rovnováhu jadro nastaví rozpočet pre maximálny počet paketov spracovaných v kontexte softirq. Po prekročení tohto rozpočtu sa prebudí samostatné vlákno ksoftirqd (jedného z nich uvidíte v ps na jadro), ktorý spracováva tieto softirq mimo normálnej cesty systémového volania/prerušenia. Toto vlákno je naplánované pomocou štandardného plánovača procesov, ktorý sa pokúša spravodlivo alokovať zdroje.
Po preštudovaní toho, ako jadro spracováva pakety, môžete vidieť, že existuje určitá pravdepodobnosť preťaženia. Ak sú volania softirq prijímané menej často, pakety budú musieť nejaký čas počkať na spracovanie vo fronte RX na sieťovej karte. Môže to byť spôsobené nejakou úlohou, ktorá blokuje jadro procesora, alebo niečo iné bráni jadru spustiť softirq.
Zúženie spracovania na jadro alebo metódu
Oneskorenia Softirq sú zatiaľ len odhadom. Ale dáva to zmysel a vieme, že vidíme niečo veľmi podobné. Ďalším krokom je teda potvrdenie tejto teórie. A ak sa to potvrdí, potom nájdite dôvod oneskorení.
Vráťme sa k našim pomalým paketom:
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
Ako bolo uvedené vyššie, tieto ICMP pakety sú hashované do jedného frontu RX NIC a spracovávané jedným jadrom CPU. Ak chceme pochopiť, ako Linux funguje, je užitočné vedieť, kde (na akom jadre CPU) a ako (softirq, ksoftirqd) sú tieto balíky spracované, aby sme mohli proces sledovať.
Teraz je čas použiť nástroje, ktoré vám umožnia monitorovať jadro Linuxu v reálnom čase. Tu sme použili . Táto sada nástrojov vám umožňuje písať malé programy v jazyku C, ktoré zachytávajú ľubovoľné funkcie v jadre a vyrovnávajú udalosti do programu Python v užívateľskom priestore, ktorý ich dokáže spracovať a vrátiť vám výsledok. Zapojenie ľubovoľných funkcií do jadra je ošemetná záležitosť, ale tento nástroj je navrhnutý pre maximálnu bezpečnosť a je navrhnutý tak, aby presne vystopoval tie druhy produkčných problémov, ktoré sa nedajú ľahko reprodukovať v testovacom alebo vývojovom prostredí.
Plán je jednoduchý: vieme, že jadro spracováva tieto ICMP pingy, takže zavesíme na funkciu jadra , ktorý akceptuje prichádzajúci paket ICMP echo request a inicializuje odosielanie ICMP echo odpovede. Paket môžeme identifikovať zvýšením čísla icmp_seq, ktoré sa zobrazí hping3 vyššie.
kód vyzerá to komplikovane, ale nie je to také strašidelné, ako sa zdá. Funkcia icmp_echo prenáša struct sk_buff *skb: Toto je paket s "echo request". Môžeme to sledovať, vytiahnuť sekvenciu echo.sequence (čo je v porovnaní s icmp_seq od hping3 выше) a odošlite ho do používateľského priestoru. Je tiež vhodné zachytiť aktuálny názov/id procesu. Nižšie sú uvedené výsledky, ktoré vidíme priamo, kým jadro spracováva pakety:
TGID PID NÁZOV PROCESU ICMP_SEQ 0 0 swapper/11 770 0 0 výmenník/11 771 0 0 výmenník/11 772 0 0 výmenník/11 773 0 0 swapper/11 774 20041 20086 prometheus 775 0 0 výmenník/11 776 0 0 výmenník/11 777 0 0 výmenník/11 778 4512 4542 lúčov 779
Tu treba poznamenať, že v kontexte softirq procesy, ktoré vykonali systémové volania, sa budú javiť ako "procesy", aj keď v skutočnosti je to jadro, ktoré bezpečne spracováva pakety v kontexte jadra.
Pomocou tohto nástroja môžeme priradiť špecifické procesy ku konkrétnym balíkom, ktoré vykazujú oneskorenie hping3. Poďme si to zjednodušiť grep na tomto zachytení pre určité hodnoty icmp_seq. Pakety zodpovedajúce vyššie uvedeným hodnotám icmp_seq boli označené spolu s ich RTT, ktoré sme pozorovali vyššie (v zátvorkách sú očakávané hodnoty RTT pre pakety, ktoré sme odfiltrovali kvôli hodnotám RTT nižším ako 50 ms):
TGID PID NÁZOV PROCESU ICMP_SEQ ** RTT -- 10137 10436 cadvisor 1951 10137 10436 cadvisor 1952 76 76 ksoftirqd/11 1953 ** 99 ms 76 76 ksoftirqd/11 1954 ** 89 ms 76 76 ksoftirqd/11 1955 ** 79 ms 76 76 ksoftirqd/11 1956 ** 69 ms 76 76 ksoftirqd/11 1957 ** 59 ms 76 76 ksoftirqd/11 1958** (49 ms) 76 76 ksoftirqd/11 1959** (39 ms) 76 76 ksoftirqd/11 1960** (29 ms) 76 76 ksoftirqd/11 1961** (19 ms) 76 76 ksoftirqd/11 1962** (9 ms) -- 10137 10436 cadvisor 2068 10137 10436 cadvisor 2069 76 76 ksoftirqd/11 2070 ** 75 ms 76 76 ksoftirqd/11 2071 ** 65 ms 76 76 ksoftirqd/11 2072 ** 55 ms 76 76 ksoftirqd/11 2073 ** (45 ms) 76 76 ksoftirqd/11 2074 ** (35 ms) 76 76 ksoftirqd/11 2075 ** (25 ms) 76 76 ksoftirqd/11 2076 ** (15 ms) 76 76 ksoftirqd/11 2077 ** (5 ms)
Výsledky nám hovoria niekoľko vecí. Po prvé, všetky tieto balíčky sú spracované kontextom ksoftirqd/11. To znamená, že pre túto konkrétnu dvojicu počítačov boli pakety ICMP hašované do jadra 11 na prijímacom konci. Vidíme tiež, že vždy, keď dôjde k zaseknutiu, existujú pakety, ktoré sú spracované v kontexte systémového volania cadvisor, potom ksoftirqd prevezme úlohu a spracuje nahromadený front: presne taký počet paketov, ktorý sa nahromadil potom cadvisor.
Skutočnosť, že bezprostredne predtým to vždy funguje cadvisor, znamená jeho zapojenie do problému. Iróniou osudu, účel - „analyzovať využitie zdrojov a výkonnostné charakteristiky spustených kontajnerov“ namiesto toho, aby spôsobili tento problém s výkonom.
Rovnako ako v prípade iných aspektov kontajnerov, sú to všetko vysoko pokročilé nástroje a možno očakávať, že za určitých nepredvídaných okolností budú mať problémy s výkonom.
Čo robí cadvisor, že spomaľuje front paketov?
Teraz už celkom dobre rozumieme tomu, ako k zlyhaniu dochádza, aký proces ho spôsobuje a na ktorom procesore. Vidíme, že kvôli tvrdému blokovaniu linuxové jadro nemá čas plánovať ksoftirqd. A vidíme, že pakety sú spracovávané v kontexte cadvisor. Je logické predpokladať, že cadvisor spustí pomalé systémové volanie, po ktorom sa spracujú všetky v tom čase nazhromaždené pakety:
Toto je teória, ale ako ju otestovať? Čo môžeme urobiť, je sledovať jadro CPU počas tohto procesu, nájsť bod, kde počet paketov prekračuje rozpočet a volá sa ksoftirqd, a potom sa pozrieť trochu ďalej, aby sme videli, čo presne bežalo na jadre CPU tesne pred týmto bodom. . Je to ako röntgenovanie CPU každých pár milisekúnd. Bude to vyzerať asi takto:
To všetko sa dá pohodlne urobiť pomocou existujúcich nástrojov. Napríklad, kontroluje dané jadro procesora v určenej frekvencii a môže generovať plán volaní bežiaceho systému, vrátane užívateľského priestoru a linuxového jadra. Tento záznam môžete vziať a spracovať pomocou malej vidlice programu od Brendana Gregga, ktorý zachováva poradie stopy zásobníka. Môžeme uložiť jednoriadkové stopy zásobníka každú 1 ms a potom zvýrazniť a uložiť vzorku 100 milisekúnd predtým, ako sa stopa objaví 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
Tu sú výsledky:
(сотни следов, которые выглядят похожими)
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
Je tu veľa vecí, ale hlavná vec je, že nájdeme vzor „cadvisor before ksoftirqd“, ktorý sme videli skôr v ICMP tracere. Čo to znamená?
Každý riadok je stopa CPU v určitom časovom bode. Každé volanie v zásobníku na riadku je oddelené bodkočiarkou. V strede riadkov vidíme, ako sa volá syscall: read(): .... ;do_syscall_64;sys_read; .... Takže cadvisor trávi veľa času systémovým volaním read()súvisiace s funkciami mem_cgroup_* (horná časť zásobníka hovorov/koniec riadku).
Je nepohodlné vidieť v stope hovoru, čo presne sa číta, takže poďme na to strace a pozrime sa, čo robí cadvisor a nájdeme systémové volania dlhšie ako 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>
Ako sa dalo očakávať, vidíme tu pomalé hovory read(). Z obsahu operácií čítania a kontextu mem_cgroup je jasné, že tieto výzvy read() pozrite si súbor memory.stat, ktorý zobrazuje využitie pamäte a limity cgroup (technológia izolácie zdrojov Docker). Nástroj cadvisor sa dotazuje na tento súbor, aby získal informácie o využití prostriedkov pre kontajnery. Pozrime sa, či je to jadro alebo cadvisor, ktorý robí niečo neočakávané:
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 ~ $
Teraz môžeme reprodukovať chybu a pochopiť, že jadro Linuxu čelí patológii.
Prečo je operácia čítania taká pomalá?
V tejto fáze je oveľa jednoduchšie nájsť správy od iných používateľov o podobných problémoch. Ako sa ukázalo, v cadvisor trackeri bola táto chyba nahlásená ako , len si nikto nevšimol, že latencia sa náhodne odráža aj v zásobníku siete. Skutočne sa zistilo, že cadvisor spotrebovával viac času CPU, ako sa očakávalo, ale tomu sa neprikladal veľký význam, pretože naše servery majú veľa zdrojov CPU, takže problém nebol dôkladne preskúmaný.
Problém je v tom, že cgroups berú do úvahy využitie pamäte v rámci menného priestoru (kontajnera). Keď všetky procesy v tejto cgroup skončia, Docker uvoľní pamäťovú cgroup. „Pamäť“ však nie je len pamäť procesov. Aj keď sa samotná pamäť procesu už nepoužíva, zdá sa, že jadro stále priraďuje obsah vyrovnávacej pamäte, ako sú dentry a inodes (metaúdaje adresárov a súborov), ktoré sú uložené v pamäti cgroup. Z popisu problému:
zombie cgroups: cgroups, ktoré nemajú žiadne procesy a boli vymazané, ale stále majú pridelenú pamäť (v mojom prípade z dentry cache, ale môže byť alokovaná aj z cache stránky alebo tmpfs).
Kontrola jadra všetkých stránok vo vyrovnávacej pamäti pri uvoľňovaní cgroup môže byť veľmi pomalá, takže je zvolený lenivý proces: počkajte, kým budú tieto stránky znova vyžiadané, a potom konečne vymažte cgroup, keď bude pamäť skutočne potrebná. Až do tohto bodu sa cgroup stále berie do úvahy pri zhromažďovaní štatistík.
Z hľadiska výkonu obetovali pamäť pre výkon: zrýchlili počiatočné čistenie tým, že ponechali časť pamäte vo vyrovnávacej pamäti. Toto je fajn. Keď jadro použije poslednú časť pamäte cache, cgroup sa nakoniec vymaže, takže to nemožno nazvať „únikom“. Bohužiaľ, špecifická implementácia vyhľadávacieho mechanizmu memory.stat v tejto verzii jadra (4.9) v kombinácii s obrovským množstvom pamäte na našich serveroch znamená, že obnovenie najnovších údajov z vyrovnávacej pamäte a vymazanie zombie cgroup trvá oveľa dlhšie.
Ukázalo sa, že niektoré z našich uzlov mali toľko zombie cgroup, že čítanie a latencia presiahli sekundu.
Riešením problému s cadvisorom je okamžité uvoľnenie vyrovnávacej pamäte dentries/inodes v celom systéme, čo okamžite eliminuje latenciu čítania, ako aj oneskorenie siete na hostiteľovi, pretože vymazaním vyrovnávacej pamäte sa zapnú vo vyrovnávacej pamäti uložené zombie stránky cgroup a tie sa tiež uvoľnia. Toto nie je riešenie, ale potvrdzuje príčinu problému.
Ukázalo sa, že v novších verziách jadra (4.19+) sa výkon hovorov zlepšil memory.stat, takže prechod na toto jadro problém vyriešil. Zároveň sme mali nástroje na detekciu problematických uzlov v klastroch Kubernetes, ich elegantné vyprázdnenie a reštartovanie. Prečesali sme všetky klastre, našli uzly s dostatočne vysokou latenciou a reštartovali ich. To nám poskytlo čas na aktualizáciu OS na zostávajúcich serveroch.
Sčítanie
Pretože táto chyba zastavila spracovanie frontu RX NIC na stovky milisekúnd, súčasne spôsobila vysokú latenciu pri krátkych pripojeniach a strednú latenciu pripojenia, napríklad medzi požiadavkami MySQL a paketmi odpovedí.
Pochopenie a udržiavanie výkonu najzákladnejších systémov, ako je Kubernetes, je rozhodujúce pre spoľahlivosť a rýchlosť všetkých služieb, ktoré sú na nich založené. Každý systém, ktorý používate, ťaží z vylepšení výkonu Kubernetes.
Zdroj: hab.com