Prije par godina Kubernetes na zvaničnom GitHub blogu. Od tada je to postala standardna tehnologija za implementaciju usluga. Kubernetes sada upravlja značajnim dijelom internih i javnih usluga. Kako su naši klasteri rasli, a zahtjevi za performansama postajali sve strožiji, počeli smo primjećivati da neki servisi na Kubernetesu sporadično doživljavaju kašnjenje koje se ne može objasniti opterećenjem same aplikacije.
U suštini, aplikacije doživljavaju naizgled nasumično kašnjenje mreže do 100 ms ili više, što rezultira vremenskim prekidima ili ponovnim pokušajima. Od servisa se očekivalo da će moći odgovoriti na zahtjeve mnogo brže od 100 ms. Ali to je nemoguće ako sama veza traje toliko vremena. Odvojeno, primijetili smo vrlo brze MySQL upite koji su trebali trajati milisekunde, a MySQL se završio za milisekunde, ali iz perspektive aplikacije koja je tražila, odgovor je trajao 100 ms ili više.
Odmah je postalo jasno da je problem nastao samo pri povezivanju na Kubernetes čvor, čak i ako je poziv došao izvan Kubernetesa. Najlakši način za reprodukciju problema je test , koji se pokreće sa bilo kog internog hosta, testira Kubernetes uslugu na određenom portu i sporadično registruje veliko kašnjenje. U ovom članku ćemo pogledati kako smo uspjeli pronaći uzrok ovog problema.
Uklanjanje nepotrebne složenosti u lancu koja vodi do neuspjeha
Reproducirajući isti primjer, željeli smo suziti fokus problema i ukloniti nepotrebne slojeve složenosti. U početku je bilo previše elemenata u toku između Vegete i Kubernetes mahuna. Da biste identificirali dublji mrežni problem, morate isključiti neke od njih.
Klijent (Vegeta) kreira TCP vezu sa bilo kojim čvorom u klasteru. Kubernetes radi kao preklapajuća mreža (na vrhu postojeće mreže data centara) koja koristi , odnosno enkapsulira IP pakete mreže preklapanja unutar IP paketa data centra. Prilikom povezivanja na prvi čvor, vrši se translacija mrežne adrese (NAT) sa stanjem za prevođenje IP adrese i porta Kubernetes čvora u IP adresu i port u mreži preklapanja (konkretno, pod sa aplikacijom). Za dolazne pakete vrši se obrnuti niz akcija. To je složen sistem s puno stanja i mnogo elemenata koji se stalno ažuriraju i mijenjaju kako se usluge postavljaju i premještaju.
Utility tcpdump u Vegeta testu postoji kašnjenje tokom TCP rukovanja (između SYN i SYN-ACK). Da biste uklonili ovu nepotrebnu složenost, možete koristiti hping3 za jednostavne “pingove” sa SYN paketima. Provjeravamo da li postoji kašnjenje u paketu odgovora, a zatim resetujemo vezu. Možemo filtrirati podatke tako da uključimo samo pakete veće od 100 ms i dobijemo lakši način da se reproducira problem od potpunog mrežnog sloja 7 testa u Vegeti. Evo "pingova" Kubernetes čvora koristeći TCP SYN/SYN-ACK na servisu "node port" (30927) u intervalima od 10 ms, filtriranih prema najsporijim odgovorima:
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
Može odmah napraviti prvo zapažanje. Sudeći po redoslijedu i tajmingu, jasno je da se ne radi o jednokratnim gužvama. Kašnjenje se često akumulira i na kraju se obrađuje.
Zatim želimo saznati koje komponente mogu biti uključene u pojavu zagušenja. Možda su ovo neka od stotina iptables pravila u NAT-u? Ili ima problema sa IPIP tuneliranjem na mreži? Jedan od načina da se ovo testira je testiranje svakog koraka sistema eliminacijom. Šta se događa ako uklonite NAT i logiku firewall-a, ostavljajući samo IPIP dio:
Srećom, Linux olakšava direktan pristup sloju IP preklapanja ako je mašina na istoj mreži:
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
Sudeći po rezultatima, problem i dalje ostaje! Ovo isključuje iptables i NAT. Dakle, problem je TCP? Pogledajmo kako ide običan 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
Rezultati pokazuju da problem nije nestao. Možda je ovo IPIP tunel? Hajde da dodatno pojednostavimo test:
Da li se svi paketi šalju između ova dva hosta?
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
Situaciju smo pojednostavili na dva Kubernetes čvora koji jedan drugom šalju bilo koji paket, čak i ICMP ping. I dalje vide kašnjenje ako je ciljni host "loš" (neki gori od drugih).
Sada zadnje pitanje: zašto se kašnjenje javlja samo na serverima kube-node? I da li se to dešava kada je kube-čvor pošiljalac ili primalac? Srećom, ovo je takođe prilično lako shvatiti slanjem paketa sa hosta izvan Kubernetesa, ali sa istim „poznatim lošim“ primaocem. Kao što vidite, problem nije nestao:
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
Zatim ćemo pokrenuti iste zahtjeve iz prethodnog izvornog kube-čvora na vanjski host (koji isključuje izvorni host budući da ping uključuje i RX i TX komponentu):
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
Ispitivanjem hvatanja paketa sa kašnjenjem dobili smo neke dodatne informacije. Konkretno, da pošiljalac (dole) vidi ovo vremensko ograničenje, ali primalac (gore) ne - vidi kolonu Delta (u sekundama):
Osim toga, ako pogledate razliku u redoslijedu TCP i ICMP paketa (po rednim brojevima) na strani primatelja, ICMP paketi uvijek stižu istim redoslijedom u kojem su poslani, ali s različitim vremenskim rasporedom. U isto vrijeme, TCP paketi se ponekad prepliću, a neki od njih zaglave. Konkretno, ako ispitate portove SYN paketa, oni su u redu na strani pošiljaoca, ali ne i na strani primaoca.
Postoji suptilna razlika u tome kako moderni serveri (poput onih u našem data centru) obrađuju pakete koji sadrže TCP ili ICMP. Kada paket stigne, mrežni adapter ga "hešira po konekciji", odnosno pokušava da razbije veze u redove i pošalje svaki red na zasebnu procesorsku jezgru. Za TCP, ovaj hash uključuje i izvornu i odredišnu IP adresu i port. Drugim riječima, svaka veza je (potencijalno) različito heširana. Za ICMP se heširaju samo IP adrese, jer nema portova.
Još jedno novo zapažanje: tokom ovog perioda vidimo ICMP kašnjenja u svim komunikacijama između dva hosta, ali TCP ne. Ovo nam govori da je uzrok vjerovatno povezan sa heširanjem RX reda: zagušenje je gotovo sigurno u obradi RX paketa, a ne u slanju odgovora.
Ovo eliminiše slanje paketa sa liste mogućih uzroka. Sada znamo da je problem obrade paketa na strani primanja na nekim kube-node serverima.
Razumijevanje obrade paketa u Linux kernelu
Da bismo razumeli zašto se problem javlja na prijemniku na nekim serverima kube čvora, pogledajmo kako Linux kernel obrađuje pakete.
Vraćajući se na najjednostavniju tradicionalnu implementaciju, mrežna kartica prima paket i šalje Linux kernel da postoji paket koji treba obraditi. Kernel zaustavlja drugi rad, prebacuje kontekst na rukovalac prekida, obrađuje paket, a zatim se vraća na trenutne zadatke.
Ovo prebacivanje konteksta je sporo: kašnjenje možda nije bilo primjetno na mrežnim karticama od 10 Mbps 90-ih, ali na modernim 10G karticama s maksimalnom propusnošću od 15 miliona paketa u sekundi, svako jezgro malog servera s osam jezgara može biti prekinuto milionima puta u sekundi.
Kako ne bi stalno rukovali prekidima, prije mnogo godina je dodao Linux : Mrežni API koji svi moderni drajveri koriste za poboljšanje performansi pri velikim brzinama. Pri malim brzinama kernel i dalje prima prekide od mrežne kartice na stari način. Kada stigne dovoljno paketa koji premašuju prag, kernel onemogućuje prekide i umjesto toga počinje prozivati mrežni adapter i skupljati pakete u komadima. Obrada se vrši u softirq-u, odnosno u nakon sistemskih poziva i hardverskih prekida, kada je kernel (za razliku od korisničkog prostora) već pokrenut.
Ovo je mnogo brže, ali uzrokuje drugačiji problem. Ako ima previše paketa, tada se svo vrijeme troši na obradu paketa sa mrežne kartice, a procesi korisničkog prostora nemaju vremena da zapravo isprazne ove redove (čitanje sa TCP veza, itd.). Na kraju se redovi popunjavaju i mi počinjemo ispuštati pakete. U pokušaju da pronađe balans, kernel postavlja budžet za maksimalan broj paketa obrađenih u softirq kontekstu. Kada se ovaj budžet premaši, budi se posebna nit ksoftirqd (videćete jednog od njih u ps po jezgri) koji obrađuje ove softirqe izvan normalnog syscall/prekidnog puta. Ova nit je zakazana pomoću standardnog planera procesa, koji pokušava pravedno alocirati resurse.
Proučavajući kako kernel obrađuje pakete, možete vidjeti da postoji određena vjerovatnoća zagušenja. Ako se softirq pozivi primaju rjeđe, paketi će morati čekati neko vrijeme da budu obrađeni u redu čekanja na prijemu na mrežnoj kartici. Ovo može biti zbog nekog zadatka koji blokira jezgru procesora ili nešto drugo sprječava jezgru da pokrene softirq.
Sužavanje obrade na jezgro ili metodu
Softirq kašnjenja su za sada samo nagađanje. Ali ima smisla i znamo da vidimo nešto vrlo slično. Dakle, sljedeći korak je potvrda ove teorije. A ako se potvrdi, onda pronađite razlog kašnjenja.
Vratimo se na naše spore pakete:
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
Kao što je ranije rečeno, ovi ICMP paketi se heširaju u jedan RX NIC red i obrađuju od strane jednog CPU jezgra. Ako želimo razumjeti kako Linux funkcionira, korisno je znati gdje (na kojoj jezgri CPU-a) i kako (softirq, ksoftirqd) se ovi paketi obrađuju da bismo pratili proces.
Sada je vrijeme da koristite alate koji vam omogućavaju da nadgledate Linux kernel u realnom vremenu. Ovdje smo koristili . Ovaj skup alata vam omogućava da pišete male C programe koji povezuju proizvoljne funkcije u kernelu i baferuju događaje u Python program u korisničkom prostoru koji ih može obraditi i vratiti vam rezultat. Povezivanje proizvoljnih funkcija u kernelu je nezgodan posao, ali uslužni program je dizajniran za maksimalnu sigurnost i dizajniran je da pronađe upravo one probleme u proizvodnji koji se ne mogu lako reproducirati u testnom ili razvojnom okruženju.
Plan je jednostavan: znamo da kernel obrađuje ove ICMP pingove, tako da ćemo staviti udicu na funkciju kernela , koji prihvaća dolazni paket ICMP eho zahtjeva i inicira slanje ICMP eho odgovora. Paket možemo identificirati povećanjem broja icmp_seq, koji pokazuje hping3 viši.
Kod izgleda komplikovano, ali nije tako strašno kao što se čini. Funkcija icmp_echo transferi struct sk_buff *skb: Ovo je paket sa "echo zahtjevom". Možemo to pratiti, izvući sekvencu echo.sequence (što se poredi sa icmp_seq by hping3 выше) i pošaljite ga u korisnički prostor. Takođe je zgodno uhvatiti trenutno ime/id procesa. Ispod su rezultati koje vidimo direktno dok kernel obrađuje pakete:
TGID PID NAZIV PROCESA ICMP_SEQ 0 0 swapper/11 770 0 swapper/0 11 771 swapper/0 0 11 swapper/772 0 0 swapper/11 773 0 prometej 0 11 774 swapper/20041 20086 775 swapper/0 0 11 swapper/776 0 0 izvještaji 11
Ovdje treba napomenuti da u kontekstu softirq procesi koji su izvršili sistemske pozive će se pojaviti kao "procesi" kada je u stvari kernel taj koji bezbedno obrađuje pakete u kontekstu kernela.
Pomoću ovog alata možemo povezati specifične procese sa određenim paketima koji pokazuju kašnjenje od hping3. Hajde da to učinimo jednostavnim grep na ovom hvatanju za određene vrijednosti icmp_seq. Paketi koji odgovaraju gornjim vrijednostima icmp_seq označeni su zajedno sa njihovim RTT-om koje smo primijetili gore (u zagradama su očekivane RTT vrijednosti za pakete koje smo filtrirali zbog RTT vrijednosti manjih od 50ms):
TGID PID NAZIV PROCESA 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)
Rezultati nam govore nekoliko stvari. Prvo, svi ovi paketi se obrađuju kontekstom ksoftirqd/11. To znači da su za ovaj određeni par mašina ICMP paketi heširani u jezgro 11 na kraju primaoca. Takođe vidimo da kad god dođe do zastoja, postoje paketi koji se obrađuju u kontekstu sistemskog poziva cadvisor... Onda ksoftirqd preuzima zadatak i obrađuje akumulirani red čekanja: tačno onoliko paketa koji se nakupio nakon toga cadvisor.
Činjenica da neposredno prije uvijek radi cadvisor, implicira njegovu uključenost u problem. Ironično, svrha - "analizirati korištenje resursa i karakteristike performansi pokrenutih kontejnera" umjesto da uzrokuje ovaj problem performansi.
Kao i kod drugih aspekata kontejnera, sve su to vrlo napredni alati i može se očekivati da će imati problema s performansama u nekim nepredviđenim okolnostima.
Šta cadvisor radi da usporava red paketa?
Sada imamo prilično dobro razumijevanje kako dolazi do pada, koji proces ga uzrokuje i na kojem CPU-u. Vidimo da zbog teškog blokiranja Linux kernel nema vremena za planiranje ksoftirqd. I vidimo da se paketi obrađuju u kontekstu cadvisor. Logično je to pretpostaviti cadvisor pokreće spor sistemski poziv, nakon čega se obrađuju svi paketi akumulirani u tom trenutku:
Ovo je teorija, ali kako je testirati? Ono što možemo učiniti je pratiti jezgro CPU-a kroz ovaj proces, pronaći tačku gdje broj paketa prelazi budžet i ksoftirqd se poziva, a zatim pogledamo još malo unazad da vidimo šta je tačno radilo na CPU jezgri neposredno prije te točke . To je kao rendgensko snimanje CPU-a svakih nekoliko milisekundi. To će izgledati otprilike ovako:
Zgodno, sve se to može uraditi sa postojećim alatima. Na primjer, provjerava dato CPU jezgro na određenoj frekvenciji i može generirati raspored poziva pokrenutom sistemu, uključujući i korisnički prostor i Linux kernel. Možete uzeti ovaj zapis i obraditi ga koristeći malu viljušku programa od Brendana Gregga, koji čuva redosled praćenja steka. Možemo sačuvati jednolinijske tragove steka svakih 1 ms, a zatim označiti i sačuvati uzorak 100 milisekundi prije nego što trag udari 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
Evo rezultata:
(сотни следов, которые выглядят похожими)
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
Ovdje ima puno stvari, ali glavna stvar je da pronađemo obrazac “cadvisor prije ksoftirqd” koji smo ranije vidjeli u ICMP tracer-u. Šta to znači?
Svaka linija je CPU trag u određenom trenutku. Svaki poziv niz stek na liniji odvojen je tačkom i zarezom. U sredini redova vidimo sistemski poziv koji se zove: read(): .... ;do_syscall_64;sys_read; .... Tako cadvisor troši dosta vremena na sistemski poziv read()vezano za funkcije mem_cgroup_* (vrh steka poziva/kraj linije).
Nezgodno je vidjeti u praćenju poziva šta se tačno čita, pa krenimo strace i hajde da vidimo šta radi cadvisor i pronađemo sistemske pozive duže od 100ms:
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>
Kao što možete očekivati, ovdje vidimo spore pozive read(). Iz sadržaja operacija čitanja i konteksta mem_cgroup jasno je da su ti izazovi read() pogledajte fajl memory.stat, koji prikazuje upotrebu memorije i ograničenja cgroup (Docker-ova tehnologija izolacije resursa). Alat cadvisor ispituje ovu datoteku da dobije informacije o korištenju resursa za kontejnere. Provjerimo da li kernel ili cadvisor radi nešto neočekivano:
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 ~ $
Sada možemo reproducirati grešku i shvatiti da se Linux kernel suočava s patologijom.
Zašto je operacija čitanja tako spora?
U ovoj fazi mnogo je lakše pronaći poruke drugih korisnika o sličnim problemima. Kako se ispostavilo, u cadvisor trackeru je ova greška prijavljena kao , samo što niko nije primijetio da se kašnjenje također nasumično odražava na mrežni stog. Zaista je uočeno da cadvisor troši više CPU vremena nego što se očekivalo, ali tome se nije pridavao veliki značaj, budući da naši serveri imaju mnogo CPU resursa, tako da problem nije pažljivo proučavan.
Problem je u tome što cgroups uzimaju u obzir upotrebu memorije unutar imenskog prostora (kontejnera). Kada svi procesi u ovoj cgroup izađu, Docker oslobađa memorijsku cgroup. Međutim, "memorija" nije samo memorija procesa. Iako se sama procesna memorija više ne koristi, čini se da kernel i dalje dodjeljuje keširani sadržaj, kao što su dentries i inode (metapodaci direktorija i datoteke), koji se keširaju u memorijskoj cgroup. Iz opisa problema:
zombie cgroups: cgrupe koje nemaju procese i koje su obrisane, ali i dalje imaju dodijeljenu memoriju (u mom slučaju, iz keš memorije dentry, ali se može dodijeliti i iz keša stranice ili tmpfs-a).
Provjera kernela svih stranica u kešu prilikom oslobađanja cgrupe može biti vrlo spora, pa je odabran lijeni proces: pričekajte da se ove stranice ponovo zatraže, a zatim konačno obrišite cgrupu kada je memorija zaista potrebna. Do ovog trenutka, cgroup se i dalje uzima u obzir prilikom prikupljanja statistike.
Sa stanovišta performansi, žrtvovali su memoriju radi performansi: ubrzali su početno čišćenje ostavljajući nešto keširane memorije iza sebe. Ovo je u redu. Kada kernel koristi posljednju keširanu memoriju, cgroup se na kraju briše, tako da se ne može nazvati "curenjem". Nažalost, specifična implementacija mehanizma pretraživanja memory.stat u ovoj verziji kernela (4.9), u kombinaciji sa ogromnom količinom memorije na našim serverima, znači da je potrebno mnogo više vremena za vraćanje najnovijih keširanih podataka i brisanje cgrupnih zombija.
Ispostavilo se da su neki od naših čvorova imali toliko cgroup zombija da su čitanje i latencija premašili sekundu.
Zaobilazno rešenje za problem sa cadvisorom je da se odmah oslobodi keš memorije dentries/inoda u celom sistemu, što odmah eliminiše kašnjenje čitanja kao i kašnjenje mreže na hostu, pošto brisanje keša uključuje keširane zombi stranice cgroup i one se takođe oslobađaju. Ovo nije rješenje, ali potvrđuje uzrok problema.
Ispostavilo se da su u novijim verzijama kernela (4.19+) performanse poziva poboljšane memory.stat, pa je prelazak na ovaj kernel riješio problem. U isto vrijeme, imali smo alate za otkrivanje problematičnih čvorova u Kubernetes klasterima, graciozno njihovo ispuštanje i ponovno pokretanje. Pročešljali smo sve klastere, pronašli čvorove sa dovoljno velikom latencijom i ponovo ih pokrenuli. Ovo nam je dalo vremena da ažuriramo OS na preostalim serverima.
Sumirati
Budući da je ova greška zaustavila obradu reda čekanja RX NIC-a na stotine milisekundi, istovremeno je uzrokovala i veliko kašnjenje na kratkim vezama i kašnjenje u sredini veze, kao što je između MySQL zahtjeva i paketa odgovora.
Razumevanje i održavanje performansi najosnovnijih sistema, kao što je Kubernetes, je ključno za pouzdanost i brzinu svih usluga zasnovanih na njima. Svaki sistem koji pokrenete ima koristi od poboljšanja performansi Kubernetesa.
izvor: www.habr.com