Acum câțiva ani Kubernetes pe blogul oficial GitHub. De atunci, a devenit tehnologia standard pentru implementarea serviciilor. Kubernetes gestionează acum o parte semnificativă a serviciilor interne și publice. Pe măsură ce clusterele noastre au crescut și cerințele de performanță au devenit mai stricte, am început să observăm că unele servicii de pe Kubernetes se confruntau sporadic cu o latență care nu putea fi explicată prin încărcarea aplicației în sine.
În esență, aplicațiile se confruntă cu o latență a rețelei aparent aleatorie de până la 100 ms sau mai mult, ceea ce duce la expirări sau reîncercări. Se aștepta ca serviciile să poată răspunde solicitărilor mult mai repede de 100 ms. Dar acest lucru este imposibil dacă conexiunea în sine durează atât de mult timp. Separat, am observat interogări MySQL foarte rapide care ar fi trebuit să dureze milisecunde, iar MySQL s-a finalizat în milisecunde, dar din perspectiva aplicației solicitante, răspunsul a durat 100 ms sau mai mult.
Imediat a devenit clar că problema a apărut doar la conectarea la un nod Kubernetes, chiar dacă apelul a venit din afara Kubernetes. Cel mai simplu mod de a reproduce problema este într-un test , care rulează de pe orice gazdă internă, testează serviciul Kubernetes pe un anumit port și înregistrează sporadic o latență ridicată. În acest articol, ne vom uita la modul în care am reușit să găsim cauza acestei probleme.
Eliminarea complexității inutile în lanțul care duce la eșec
Prin reproducerea aceluiași exemplu, am dorit să restrângem focalizarea problemei și să eliminăm straturile inutile de complexitate. Inițial, au existat prea multe elemente în fluxul dintre Vegeta și podurile Kubernetes. Pentru a identifica o problemă de rețea mai profundă, trebuie să excludeți unele dintre ele.
Clientul (Vegeta) creează o conexiune TCP cu orice nod din cluster. Kubernetes funcționează ca o rețea suprapusă (pe deasupra rețelei existente de centre de date) care utilizează , adică încapsulează pachetele IP ale rețelei de suprapunere în interiorul pachetelor IP ale centrului de date. La conectarea la primul nod, se realizează traducerea adresei de rețea (NAT) cu stare pentru a traduce adresa IP și portul nodului Kubernetes în adresa IP și portul din rețeaua de suprapunere (în special, podul cu aplicația). Pentru pachetele primite, se efectuează secvența inversă a acțiunilor. Este un sistem complex cu multă stare și multe elemente care sunt actualizate și modificate în mod constant pe măsură ce serviciile sunt implementate și mutate.
Utilitate tcpdump în testul Vegeta există o întârziere în timpul strângerii de mână TCP (între SYN și SYN-ACK). Pentru a elimina această complexitate inutilă, puteți utiliza hping3 pentru „ping-uri” simple cu pachete SYN. Verificăm dacă există o întârziere în pachetul de răspuns și apoi resetăm conexiunea. Putem filtra datele pentru a include numai pachete mai mari de 100 ms și putem obține o modalitate mai ușoară de a reproduce problema decât testul complet de nivel 7 al rețelei din Vegeta. Iată „pingurile” nodului Kubernetes folosind TCP SYN/SYN-ACK pe „portul nodului” al serviciului (30927) la intervale de 10 ms, filtrate după răspunsurile cele mai lente:
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
Poate face imediat prima observație. Judecând după numerele de secvență și timpii, este clar că acestea nu sunt congestii unice. Întârzierea se acumulează adesea și în cele din urmă este procesată.
În continuare, dorim să aflăm ce componente pot fi implicate în apariția congestiei. Poate acestea sunt câteva dintre sutele de reguli iptables din NAT? Sau există probleme cu tunelul IPIP în rețea? O modalitate de a testa acest lucru este de a testa fiecare pas al sistemului prin eliminarea acestuia. Ce se întâmplă dacă eliminați NAT și logica firewall, lăsând doar partea IPIP:
Din fericire, Linux facilitează accesul direct la stratul de suprapunere IP dacă mașina se află în aceeași rețea:
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
Judecând după rezultate, problema rămâne! Aceasta exclude iptables și NAT. Deci problema este TCP? Să vedem cum merge un ping ICMP obișnuit:
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
Rezultatele arată că problema nu a dispărut. Poate că acesta este un tunel IPIP? Să simplificăm mai mult testul:
Sunt toate pachetele trimise între aceste două gazde?
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
Am simplificat situația la două noduri Kubernetes care își trimit reciproc orice pachet, chiar și un ping ICMP. Ei încă văd latență dacă gazda țintă este „rea” (unele mai proaste decât altele).
Acum ultima întrebare: de ce întârzierea apare doar pe serverele kube-node? Și se întâmplă atunci când kube-node este emițătorul sau receptorul? Din fericire, acest lucru este, de asemenea, destul de ușor de înțeles prin trimiterea unui pachet de la o gazdă din afara Kubernetes, dar cu același destinatar „cunoscut rău”. După cum puteți vedea, problema nu a dispărut:
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
Vom rula apoi aceleași solicitări de la nodul kube-sursă anterior către gazda externă (care exclude gazda sursă, deoarece ping-ul include atât o componentă RX, cât și 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
Examinând capturile de pachete de latență, am obținut câteva informații suplimentare. Mai exact, că expeditorul (jos) vede acest timeout, dar destinatarul (sus) nu - vede coloana Delta (în secunde):
În plus, dacă te uiți la diferența în ordinea pachetelor TCP și ICMP (după numere de secvență) pe partea destinatarului, pachetele ICMP ajung întotdeauna în aceeași secvență în care au fost trimise, dar cu un timp diferit. În același timp, pachetele TCP se întrepătrund uneori, iar unele dintre ele se blochează. În special, dacă examinați porturile pachetelor SYN, acestea sunt în ordine pe partea expeditorului, dar nu pe partea receptorului.
Există o diferență subtilă în modul în care serverele moderne (cum ar fi cele din centrul nostru de date) procesează pachete care conțin TCP sau ICMP. Când sosește un pachet, adaptorul de rețea îl „hash pe conexiune”, adică încearcă să rupă conexiunile în cozi și să trimită fiecare coadă la un nucleu separat de procesor. Pentru TCP, acest hash include atât adresa IP și portul sursă, cât și destinație. Cu alte cuvinte, fiecare conexiune este hashing (potențial) diferit. Pentru ICMP, numai adresele IP sunt hashing, deoarece nu există porturi.
O altă observație nouă: în această perioadă vedem întârzieri ICMP la toate comunicațiile dintre două gazde, dar TCP nu. Acest lucru ne spune că cauza este probabil legată de hashingul cozii RX: congestia este aproape sigur în procesarea pachetelor RX, nu în trimiterea răspunsurilor.
Acest lucru elimină trimiterea de pachete din lista cauzelor posibile. Acum știm că problema procesării pachetelor este de partea recepției pe unele servere kube-node.
Înțelegerea procesării pachetelor în nucleul Linux
Pentru a înțelege de ce apare problema la receptor pe unele servere kube-node, să ne uităm la modul în care nucleul Linux procesează pachetele.
Revenind la cea mai simplă implementare tradițională, placa de rețea primește pachetul și trimite nucleul Linux că există un pachet care trebuie procesat. Nucleul oprește alte lucrări, comută contextul la handlerul de întrerupere, procesează pachetul și apoi revine la sarcinile curente.
Această schimbare a contextului este lentă: latența poate să nu fi fost vizibilă pe plăcile de rețea de 10 Mbps în anii '90, dar pe cardurile moderne 10G cu un debit maxim de 15 milioane de pachete pe secundă, fiecare nucleu al unui server mic cu opt nuclee poate fi întrerupt milioane de euro. de ori pe secundă.
Pentru a nu gestiona în mod constant întreruperile, acum mulți ani a adăugat Linux : API de rețea pe care toți șoferii moderni îl folosesc pentru a îmbunătăți performanța la viteze mari. La viteze mici, nucleul încă primește întreruperi de la placa de rețea în modul vechi. Odată ce sosesc suficiente pachete care depășesc pragul, nucleul dezactivează întreruperile și, în schimb, începe să interogheze adaptorul de rețea și să preia pachetele în bucăți. Prelucrarea se realizează în softirq, adică în după apelurile de sistem și întreruperile hardware, când nucleul (spre deosebire de spațiul utilizatorului) rulează deja.
Acest lucru este mult mai rapid, dar provoacă o altă problemă. Dacă există prea multe pachete, atunci tot timpul este petrecut procesând pachetele de pe placa de rețea, iar procesele din spațiul utilizatorului nu au timp să golească efectiv aceste cozi (citirea din conexiunile TCP etc.). În cele din urmă, cozile se umplu și începem să aruncăm pachete. În încercarea de a găsi un echilibru, nucleul stabilește un buget pentru numărul maxim de pachete procesate în contextul softirq. Odată ce acest buget este depășit, se trezește un fir separat ksoftirqd (vei vedea pe unul dintre ei în ps per nucleu) care gestionează aceste softirq-uri în afara căii normale de apel/întrerupere a sistemului. Acest thread este programat folosind planificatorul de proces standard, care încearcă să aloce resurse în mod corect.
După ce ați studiat modul în care nucleul procesează pachetele, puteți vedea că există o anumită probabilitate de congestie. Dacă apelurile softirq sunt primite mai rar, pachetele vor trebui să aștepte ceva timp pentru a fi procesate în coada RX de pe placa de rețea. Acest lucru se poate datora unei sarcini care blochează nucleul procesorului sau altceva împiedică nucleul să ruleze softirq.
Restrângerea procesării la miez sau metodă
Întârzierile Softirq sunt doar o presupunere pentru moment. Dar are sens și știm că vedem ceva foarte asemănător. Deci următorul pas este confirmarea acestei teorii. Și dacă este confirmat, atunci găsiți motivul întârzierilor.
Să revenim la pachetele noastre lente:
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
După cum sa discutat mai devreme, aceste pachete ICMP sunt hashing într-o singură coadă RX NIC și procesate de un singur nucleu CPU. Dacă vrem să înțelegem cum funcționează Linux, este util să știm unde (pe ce nucleu CPU) și cum (softirq, ksoftirqd) sunt procesate aceste pachete pentru a urmări procesul.
Acum este timpul să folosiți instrumente care vă permit să monitorizați kernel-ul Linux în timp real. Aici am folosit . Acest set de instrumente vă permite să scrieți mici programe C care atașează funcții arbitrare în nucleu și să memoreze evenimentele într-un program Python în spațiul utilizatorului care le poate procesa și vă poate returna rezultatul. Conectarea funcțiilor arbitrare în nucleu este o afacere dificilă, dar utilitarul este conceput pentru securitate maximă și este conceput pentru a urmări exact tipul de probleme de producție care nu sunt ușor de reprodus într-un mediu de testare sau dezvoltare.
Planul aici este simplu: știm că nucleul procesează aceste ping-uri ICMP, așa că vom pune un cârlig pe funcția kernelului , care acceptă un pachet de solicitare de ecou ICMP de intrare și inițiază trimiterea unui răspuns de ecou ICMP. Putem identifica un pachet prin creșterea numărului icmp_seq, care se arată hping3 de mai sus.
Cod pare complicat, dar nu este atât de înfricoșător pe cât pare. Funcţie icmp_echo transmite struct sk_buff *skb: Acesta este un pachet cu o „cerere ecou”. Îl putem urmări, scoatem secvența echo.sequence (care se compară cu icmp_seq de hping3 выше) și trimiteți-l în spațiul utilizatorului. De asemenea, este convenabil să capturați numele/id-ul procesului curent. Mai jos sunt rezultatele pe care le vedem direct în timp ce nucleul procesează pachete:
NUME PROCES PID TGID ICMP_SEQ 0 0 swapper/11 770 0 swapper/0 11 771 swapper/0 0 11 swapper/772 0 0 swapper/11 773 0 prometheus 0 11 774 swapper/20041 20086 775 swapper/0 0 11 swapper/776 0 0 spițe-raport-s 11
Trebuie remarcat aici că în context softirq procesele care au efectuat apeluri de sistem vor apărea ca „procese” când, de fapt, nucleul este cel care procesează în siguranță pachetele în contextul nucleului.
Cu acest instrument putem asocia procese specifice cu pachete specifice care prezintă o întârziere de hping3. Să facem totul simplu grep asupra acestei capturi pentru anumite valori icmp_seq. Pachetele care se potrivesc cu valorile icmp_seq de mai sus au fost semnalate împreună cu RTT-ul lor pe care l-am observat mai sus (în paranteze sunt valorile RTT așteptate pentru pachetele pe care le-am filtrat din cauza valorilor RTT mai mici de 50 ms):
TGID PID NUME PROCES 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 ** (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 ** 75ms 76 76 ksoftirqd/11 2071 ** 65ms 76 76 ksoftirqd/11 2072 ** 55ms 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)
Rezultatele ne spun mai multe lucruri. În primul rând, toate aceste pachete sunt procesate de context ksoftirqd/11. Aceasta înseamnă că pentru această pereche specială de mașini, pachetele ICMP au fost trimise prin hashing la miezul 11 la capătul de recepție. De asemenea, vedem că ori de câte ori există un blocaj, există pachete care sunt procesate în contextul apelului de sistem. cadvisor. atunci ksoftirqd preia sarcina și procesează coada acumulată: exact numărul de pachete care s-a acumulat după cadvisor.
Faptul că imediat înainte funcționează întotdeauna cadvisor, implică implicarea lui în problemă. În mod ironic, scopul - „analizați utilizarea resurselor și caracteristicile de performanță ale containerelor care rulează”, mai degrabă decât să cauzeze această problemă de performanță.
Ca și în cazul altor aspecte ale containerelor, toate acestea sunt instrumente foarte avansate și se poate aștepta să se confrunte cu probleme de performanță în anumite circumstanțe neprevăzute.
Ce face cadvisor care încetinește coada de pachete?
Acum avem o înțelegere destul de bună a modului în care are loc blocarea, ce proces o cauzează și pe ce procesor. Vedem că din cauza blocării grele, nucleul Linux nu are timp să se programeze ksoftirqd. Și vedem că pachetele sunt procesate în context cadvisor. Este logic să presupunem că cadvisor lansează un apel sistem lent, după care sunt procesate toate pachetele acumulate la acel moment:
Aceasta este o teorie, dar cum să o testăm? Ceea ce putem face este să urmărim nucleul procesorului de-a lungul acestui proces, să găsim punctul în care numărul de pachete depășește bugetul și este apelat ksoftirqd și apoi să privim puțin mai departe pentru a vedea ce rula exact pe nucleul procesorului chiar înainte de acel moment. . Este ca și cum ar fi radiografiat procesorul la fiecare câteva milisecunde. Va arata cam asa:
În mod convenabil, toate acestea se pot face cu instrumentele existente. De exemplu, verifică un anumit nucleu CPU la o frecvență specificată și poate genera un program de apeluri către sistemul care rulează, incluzând atât spațiul utilizatorului, cât și nucleul Linux. Puteți lua această înregistrare și o puteți procesa folosind un mic furk al programului de la Brendan Gregg, care păstrează ordinea urmei stivei. Putem salva urmele stivei cu o singură linie la fiecare 1 ms, apoi evidențiam și salvam un eșantion cu 100 de milisecunde înainte ca urmă să ajungă 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
Iată rezultatele:
(сотни следов, которые выглядят похожими)
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
Există o mulțime de lucruri aici, dar principalul lucru este că găsim modelul „cadvisor before ksoftirqd” pe care l-am văzut mai devreme în urmăritorul ICMP. Ce înseamnă?
Fiecare linie este o urmă CPU la un anumit moment în timp. Fiecare apel din stiva de pe o linie este separat prin punct și virgulă. În mijlocul liniilor vedem apelul de sistem numit: read(): .... ;do_syscall_64;sys_read; .... Deci cadvisor petrece mult timp apelului de sistem read()legate de funcții mem_cgroup_* (partea de sus a stivei de apeluri/sfârșitul liniei).
Este incomod să vezi într-o urmărire a apelurilor ce se citește exact, așa că haideți să alergăm strace și să vedem ce face cadvisor și să găsim apeluri de sistem mai lungi de 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>
După cum vă puteți aștepta, vedem apeluri lente aici read(). Din conținutul operațiilor de citire și context mem_cgroup este clar că aceste provocări read() consultați fișierul memory.stat, care arată utilizarea memoriei și limitele cgroup (tehnologia de izolare a resurselor Docker). Instrumentul cadvisor interogează acest fișier pentru a obține informații despre utilizarea resurselor pentru containere. Să verificăm dacă nucleul sau cadvisorul face ceva neașteptat:
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 ~ $
Acum putem reproduce eroarea și înțelegem că kernel-ul Linux se confruntă cu o patologie.
De ce operația de citire este atât de lentă?
În această etapă, este mult mai ușor să găsiți mesaje de la alți utilizatori despre probleme similare. După cum sa dovedit, în cadvisor tracker această eroare a fost raportată ca , doar că nimeni nu a observat că latența se reflectă și în mod aleatoriu în stiva de rețea. S-a observat într-adevăr că cadvisor consuma mai mult timp CPU decât se aștepta, dar nu i s-a acordat prea multă importanță, deoarece serverele noastre au multe resurse CPU, așa că problema nu a fost studiată cu atenție.
Problema este că cgroups iau în considerare utilizarea memoriei în spațiul de nume (container). Când toate procesele din acest cgroup ies, Docker eliberează cgroup-ul de memorie. Cu toate acestea, „memoria” nu este doar memorie de proces. Deși memoria de proces în sine nu mai este utilizată, se pare că nucleul încă alocă conținuturi în cache, cum ar fi dentiri și inode (metadate de director și fișier), care sunt stocate în memoria cache în cgroup-ul de memorie. Din descrierea problemei:
zombie cgroups: cgroups care nu au procese și au fost șterse, dar au încă memorie alocată (în cazul meu, din cache-ul dentry, dar poate fi alocat și din cache-ul paginii sau tmpfs).
Verificarea de către nucleu a tuturor paginilor din cache la eliberarea unui cgroup poate fi foarte lentă, așa că se alege procesul leneș: așteptați până când aceste pagini sunt solicitate din nou și apoi ștergeți cgroup-ul când memoria este de fapt necesară. Până în acest moment, cgroup este încă luat în considerare la colectarea statisticilor.
Din punct de vedere al performanței, au sacrificat memoria pentru performanță: accelerând curățarea inițială, lăsând în urmă o memorie cache. Este în regulă. Când nucleul folosește ultima memorie cache, cgroup-ul este în cele din urmă șters, deci nu poate fi numit „scurgere”. Din păcate, implementarea specifică a mecanismului de căutare memory.stat în această versiune de kernel (4.9), combinată cu cantitatea uriașă de memorie de pe serverele noastre, înseamnă că este nevoie de mult mai mult pentru a restaura cele mai recente date stocate în cache și pentru a șterge zombii cgroup.
Se pare că unele dintre nodurile noastre aveau atât de mulți zombi cgroup încât citirea și latența au depășit o secundă.
Soluția pentru problema cadvisor este eliberarea imediată a cache-urilor dentries/inode în întregul sistem, ceea ce elimină imediat latența de citire, precum și latența rețelei pe gazdă, deoarece ștergerea cache-ului activează paginile zombie cgroup din cache și sunt, de asemenea, eliberate. Aceasta nu este o soluție, dar confirmă cauza problemei.
S-a dovedit că în versiunile mai noi de kernel (4.19+) performanța apelurilor a fost îmbunătățită memory.stat, deci trecerea la acest nucleu a rezolvat problema. În același timp, am avut instrumente pentru a detecta nodurile problematice din clusterele Kubernetes, a le drena cu grație și a le reporni. Am pieptănat toate clusterele, am găsit noduri cu o latență suficient de mare și le-am repornit. Acest lucru ne-a dat timp să actualizăm sistemul de operare pe serverele rămase.
Rezumând
Deoarece această eroare a oprit procesarea cozii RX NIC pentru sute de milisecunde, a provocat simultan atât o latență ridicată pe conexiunile scurte, cât și o latență medie a conexiunii, cum ar fi între cererile MySQL și pachetele de răspuns.
Înțelegerea și menținerea performanței celor mai fundamentale sisteme, cum ar fi Kubernetes, este esențială pentru fiabilitatea și viteza tuturor serviciilor bazate pe acestea. Fiecare sistem pe care îl rulați beneficiază de îmbunătățirile performanței Kubernetes.
Sursa: www.habr.com