Pred nekaj leti Kubernetes na uradnem blogu GitHub. Od takrat je postala standardna tehnologija za uvajanje storitev. Kubernetes zdaj upravlja pomemben del notranjih in javnih storitev. Ko so naši grozdi rasli in so zahteve glede zmogljivosti postale strožje, smo začeli opažati, da so nekatere storitve na Kubernetesu občasno imele zakasnitev, ki je ni bilo mogoče razložiti z obremenitvijo same aplikacije.
V bistvu se aplikacije soočajo z navidezno naključno omrežno zakasnitvijo do 100 ms ali več, kar povzroči časovne omejitve ali ponovne poskuse. Pričakuje se, da se bodo storitve lahko odzvale na zahteve veliko hitreje kot 100 ms. A to je nemogoče, če sama povezava traja toliko časa. Ločeno smo opazili zelo hitre poizvedbe MySQL, ki bi morale trajati nekaj milisekund, MySQL pa se je dokončal v milisekundah, vendar je z vidika aplikacije, ki je zahtevala, odgovor trajal 100 ms ali več.
Takoj je postalo jasno, da se je težava pojavila samo pri povezovanju z vozliščem Kubernetes, tudi če je klic prišel izven Kubernetesa. Najlažji način za reprodukcijo težave je v testu , ki se izvaja s katerega koli notranjega gostitelja, preizkuša storitev Kubernetes na določenih vratih in občasno registrira visoko zakasnitev. V tem članku si bomo ogledali, kako nam je uspelo izslediti vzrok te težave.
Odprava nepotrebne zapletenosti v verigi, ki vodi do neuspeha
S reprodukcijo istega primera smo želeli zožiti fokus problema in odstraniti nepotrebne plasti kompleksnosti. Sprva je bilo v toku med Vegeto in Kubernetesovimi stroki preveč elementov. Če želite prepoznati globljo težavo z omrežjem, morate nekatere izmed njih izključiti.
Odjemalec (Vegeta) ustvari TCP povezavo s poljubnim vozliščem v gruči. Kubernetes deluje kot prekrivno omrežje (na vrhu obstoječega omrežja podatkovnega centra), ki uporablja , to pomeni, da enkapsulira pakete IP prekrivnega omrežja znotraj paketov IP podatkovnega centra. Pri povezovanju s prvim vozliščem se izvede prevod omrežnega naslova (NAT) s stanjem za prevajanje naslova IP in vrat vozlišča Kubernetes v naslov IP in vrata v prekrivnem omrežju (natančneje, pod z aplikacijo). Za dohodne pakete se izvede obratno zaporedje dejanj. To je zapleten sistem z veliko stanja in številnimi elementi, ki se nenehno posodabljajo in spreminjajo, ko se storitve uvajajo in premikajo.
Uporabnost tcpdump pri Vegeta testu pride do zamika med rokovanjem TCP (med SYN in SYN-ACK). Če želite odstraniti to nepotrebno zapletenost, lahko uporabite hping3 za preproste "pinge" s paketi SYN. Preverimo, ali je prišlo do zakasnitve v odzivnem paketu, in nato ponastavimo povezavo. Podatke lahko filtriramo tako, da vključujejo samo pakete, večje od 100 ms, in dobimo lažji način za reprodukcijo težave kot celoten test omrežne plasti 7 v Vegeti. Tukaj so »pingi« vozlišča Kubernetes z uporabo TCP SYN/SYN-ACK na storitvi »vrata vozlišča« (30927) v intervalih 10 ms, filtrirani po najpočasnejših odzivih:
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
Takoj lahko naredi prvo opazko. Glede na zaporedne številke in časovne razporeditve je jasno, da ne gre za enkratne zastoje. Zamuda se pogosto kopiči in se na koncu obdela.
Nato želimo ugotoviti, katere komponente so lahko vpletene v pojav zastojev. Mogoče so to nekatera od stotin pravil iptables v NAT? Ali pa obstajajo težave s tuneliranjem IPIP v omrežju? Eden od načinov, da to preizkusite, je, da preizkusite vsak korak sistema tako, da ga izločite. Kaj se zgodi, če odstranite NAT in logiko požarnega zidu ter pustite samo del IPIP:
Na srečo Linux olajša neposreden dostop do prekrivne plasti IP, če je naprava v istem omrežju:
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
Po rezultatih sodeč problem še vedno ostaja! To izključuje iptables in NAT. Torej je problem TCP? Poglejmo, kako poteka običajni ping ICMP:
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 kažejo, da težava ni izginila. Mogoče je to tunel IPIP? Poenostavimo test še:
Ali so vsi paketi poslani med tema dvema gostiteljema?
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
Situacijo smo poenostavili na dve vozlišči Kubernetes, ki drug drugemu pošiljata poljuben paket, tudi ICMP ping. Še vedno vidijo zakasnitev, če je ciljni gostitelj "slab" (nekateri slabši od drugih).
Zdaj pa zadnje vprašanje: zakaj se zakasnitev pojavi samo na strežnikih kube-node? In ali se to zgodi, ko je kube-node pošiljatelj ali prejemnik? Na srečo je to tudi zelo enostavno ugotoviti s pošiljanjem paketa z gostitelja zunaj Kubernetesa, vendar z istim "znano slabim" prejemnikom. Kot lahko vidite, težava ni izginila:
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
Nato bomo zagnali iste zahteve iz prejšnjega izvornega vozlišča kube do zunanjega gostitelja (ki izključuje izvornega gostitelja, saj ping vključuje komponento RX in 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
S pregledom zajemanja paketov z zakasnitvijo smo pridobili nekaj dodatnih informacij. Natančneje, da pošiljatelj (spodaj) vidi to časovno omejitev, prejemnik (zgoraj) pa ne – glejte stolpec Delta (v sekundah):
Poleg tega, če pogledate razliko v vrstnem redu paketov TCP in ICMP (po zaporednih številkah) na strani prejemnika, paketi ICMP vedno prispejo v istem zaporedju, v katerem so bili poslani, vendar z različnim časom. Hkrati se paketi TCP včasih prepletajo in nekateri od njih se zataknejo. Še posebej, če pregledate vrata paketov SYN, so na strani pošiljatelja v redu, na strani prejemnika pa ne.
Obstaja subtilna razlika v tem, kako sodobni strežniki (kot tisti v našem podatkovnem centru) obdelujejo pakete, ki vsebujejo TCP ali ICMP. Ko prispe paket, ga omrežna kartica "razprši na povezavo", kar pomeni, da poskuša povezave razbiti v čakalne vrste in vsako čakalno vrsto poslati v ločeno procesorsko jedro. Za TCP ta zgoščena vrednost vključuje izvorni in ciljni naslov IP in vrata. Z drugimi besedami, vsaka povezava je zgoščena (potencialno) drugače. Za ICMP so zgoščeni samo naslovi IP, ker ni vrat.
Še ena nova ugotovitev: v tem obdobju opazimo zamude ICMP pri vseh komunikacijah med dvema gostiteljema, TCP pa ne. To nam pove, da je vzrok verjetno povezan z zgoščevanjem čakalne vrste RX: zastoji so skoraj zagotovo v obdelavi paketov RX, ne v pošiljanju odgovorov.
To izloči pošiljanje paketov s seznama možnih vzrokov. Zdaj vemo, da je težava pri obdelavi paketov na strani sprejema na nekaterih strežnikih kube-node.
Razumevanje obdelave paketov v jedru Linuxa
Da bi razumeli, zakaj se težava pojavi pri sprejemniku na nekaterih strežnikih kube-node, si poglejmo, kako jedro Linuxa obdeluje pakete.
Če se vrnemo k najpreprostejši tradicionalni izvedbi, omrežna kartica sprejme paket in ga pošlje jedro Linuxa, da obstaja paket, ki ga je treba obdelati. Jedro ustavi drugo delo, preklopi kontekst na obravnavo prekinitev, obdela paket in se nato vrne k trenutnim nalogam.
To preklapljanje konteksta je počasno: zakasnitev morda ni bila opazna na 10Mbps omrežnih karticah v 90-ih, toda na sodobnih 10G karticah z največjo prepustnostjo 15 milijonov paketov na sekundo lahko vsako jedro majhnega osemjedrnega strežnika prekine milijone krat na sekundo.
Da ne bi nenehno obravnavali prekinitev, je pred mnogimi leti dodal Linux : Omrežni API, ki ga uporabljajo vsi sodobni gonilniki za izboljšanje delovanja pri visokih hitrostih. Pri nizkih hitrostih jedro še vedno prejema prekinitve iz omrežne kartice na star način. Ko prispe dovolj paketov, ki presežejo prag, jedro onemogoči prekinitve in namesto tega začne preverjati omrežno kartico in pobirati pakete v kosih. Obdelava se izvaja v softirq, to je v po sistemskih klicih in prekinitvah strojne opreme, ko se jedro (v nasprotju z uporabniškim prostorom) že izvaja.
To je veliko hitreje, vendar povzroča drugačno težavo. Če je paketov preveč, se ves čas porabi za obdelavo paketov iz omrežne kartice in procesi uporabniškega prostora nimajo časa, da bi dejansko izpraznili te čakalne vrste (branje iz povezav TCP itd.). Sčasoma se čakalne vrste napolnijo in začnemo spuščati pakete. V poskusu, da najde ravnotežje, jedro nastavi proračun za največje število paketov, obdelanih v kontekstu softirq. Ko je ta proračun presežen, se prebudi ločena nit ksoftirqd (enega od njih boste videli v ps na jedro), ki te softirq-e obravnava zunaj običajne poti sistemskega klica/prekinitve. Ta nit je načrtovana s standardnim načrtovalcem procesov, ki poskuša pravično dodeliti sredstva.
Ko ste preučili, kako jedro obdeluje pakete, lahko vidite, da obstaja določena verjetnost zastojev. Če so klici softirq prejeti manj pogosto, bodo morali paketi nekaj časa čakati na obdelavo v čakalni vrsti RX na omrežni kartici. To je lahko posledica neke naloge, ki blokira jedro procesorja, ali pa kaj drugega jedru preprečuje izvajanje softirq.
Zožitev obdelave na jedro ali metodo
Zamude Softirq so za zdaj le ugibanja. Vendar je smiselno in vemo, da vidimo nekaj zelo podobnega. Naslednji korak je torej potrditev te teorije. In če je potrjeno, poiščite razlog za zamude.
Vrnimo se k našim počasnim 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
Kot smo že omenili, so ti paketi ICMP zgoščeni v eno čakalno vrsto RX NIC in obdelani z enim jedrom CPE. Če želimo razumeti, kako deluje Linux, je koristno vedeti, kje (na katerem jedru procesorja) in kako (softirq, ksoftirqd) se ti paketi obdelujejo, da lahko sledimo procesu.
Zdaj je čas za uporabo orodij, ki vam omogočajo spremljanje jedra Linuxa v realnem času. Tukaj smo uporabili . Ta nabor orodij vam omogoča pisanje majhnih programov C, ki zaskočijo poljubne funkcije v jedru in medpomnijo dogodke v program Python v uporabniškem prostoru, ki jih lahko obdela in vam vrne rezultat. Pripenjanje poljubnih funkcij v jedru je zapleten posel, vendar je pripomoček zasnovan za največjo varnost in je zasnovan tako, da izsledi natanko tiste vrste proizvodnih težav, ki jih ni enostavno reproducirati v testnem ali razvojnem okolju.
Načrt tukaj je preprost: vemo, da jedro obdeluje te pinge ICMP, zato bomo zataknili funkcijo jedra , ki sprejme dohodni paket odmeva ICMP in sproži pošiljanje odziva ICMP. Paket lahko identificiramo tako, da povečamo številko icmp_seq, ki se prikaže hping3 višje.
Koda: izgleda zapleteno, vendar ni tako strašljivo, kot se zdi. funkcija icmp_echo posreduje struct sk_buff *skb: To je paket z "echo zahtevo". Lahko mu sledimo, izvlečemo zaporedje echo.sequence (ki se primerja z icmp_seq od hping3 выше), in ga pošljite v uporabniški prostor. Prav tako je priročno zajeti trenutno ime/id procesa. Spodaj so rezultati, ki jih vidimo neposredno, medtem ko jedro obdeluje pakete:
TGID PID IME PROCESA ICMP_SEQ 0 0 zamenjava/11 770 0 zamenjava/0 11 771 zamenjava/0 0 11 zamenjava/772 0 0 zamenjava/11 773 0 prometej 0 11 774 zamenjava/20041 20086 775 zamenjava/0 0 11 zamenjava/776 0 0 spokes-report-s 11
Tukaj je treba opozoriti, da v kontekstu softirq procesi, ki so opravili sistemske klice, bodo prikazani kot "procesi", čeprav je v resnici jedro tisto, ki varno obdeluje pakete v kontekstu jedra.
S tem orodjem lahko povežemo določene procese z določenimi paketi, ki kažejo zamudo hping3. Poenostavimo grep na tem zajemu za določene vrednosti icmp_seq. Paketi, ki se ujemajo z zgornjimi vrednostmi icmp_seq, so bili označeni skupaj z njihovim RTT, ki smo ga opazili zgoraj (v oklepajih so pričakovane vrednosti RTT za pakete, ki smo jih filtrirali zaradi vrednosti RTT, krajših od 50 ms):
TGID PID IME PROCESA ICMP_SEQ ** RTT -- 10137 10436 cadvisor 1951 10137 10436 cadvisor 1952 76 76 ksoftirqd/11 1953 ** 99 ms 76 76 ksoftirqd/11 1954 ** 89ms 76 76 ksoftirqd/11 1955 ** 79ms 76 76 ksoftirqd/11 1956 ** 69ms 76 76 ksoftirqd/11 1957 ** 59 ms 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 ** 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 ** (5ms)
Rezultati nam povedo več stvari. Prvič, vse te pakete obdela kontekst ksoftirqd/11. To pomeni, da so bili za ta določen par strojev paketi ICMP zgoščeni v jedro 11 na prejemnem koncu. Vidimo tudi, da kadar koli pride do zastoja, obstajajo paketi, ki se obdelajo v kontekstu sistemskega klica cadvisor. Potem ksoftirqd prevzame nalogo in obdela nakopičeno čakalno vrsto: točno toliko paketov, ki se je nabralo po tem cadvisor.
Dejstvo, da tik pred vedno deluje cadvisor, implicira njegovo vpletenost v problem. Ironično, namen - "analizirajte porabo virov in karakteristike delovanja delujočih vsebnikov", namesto da povzročite to težavo z zmogljivostjo.
Tako kot pri drugih vidikih vsebnikov so to vsa zelo napredna orodja in lahko pričakujemo, da bodo v nekaterih nepredvidenih okoliščinah imeli težave z zmogljivostjo.
Kaj naredi cadvisor, da upočasni čakalno vrsto paketov?
Zdaj precej dobro razumemo, kako pride do zrušitve, kateri proces jo povzroča in na katerem procesorju. Vidimo, da zaradi trdega blokiranja jedro Linuxa nima časa za načrtovanje ksoftirqd. In vidimo, da se paketi obdelujejo v kontekstu cadvisor. Logično je domnevati, da cadvisor zažene počasen sistemski klic, po katerem se obdelajo vsi paketi, zbrani v tem času:
To je teorija, a kako jo preizkusiti? Kar lahko naredimo je, da sledimo jedru CPU skozi ta proces, najdemo točko, kjer število paketov preseže proračun in se kliče ksoftirqd, nato pa pogledamo malo dlje nazaj, da vidimo, kaj točno se je izvajalo v jedru CPE tik pred to točko . To je kot rentgensko slikanje procesorja vsakih nekaj milisekund. Videti bo nekako takole:
Priročno je, da je vse to mogoče narediti z obstoječimi orodji. na primer preverja dano jedro procesorja pri določeni frekvenci in lahko ustvari urnik klicev delujočega sistema, vključno z uporabniškim prostorom in jedrom Linuxa. Ta zapis lahko vzamete in obdelate z uporabo majhne vilice programa od Brendana Gregga, ki ohranja vrstni red sledi sklada. Vsako 1 ms lahko shranimo enovrstične sledi sklada, nato pa označimo in shranimo vzorec 100 milisekund, preden sled zadene 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
Tukaj so rezultati:
(сотни следов, которые выглядят похожими)
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
Tukaj je veliko stvari, a glavna stvar je, da najdemo vzorec "cadvisor pred ksoftirqd", ki smo ga videli prej v sledilniku ICMP. Kaj to pomeni?
Vsaka vrstica je sled procesorja v določenem trenutku. Vsak klic navzdol po skladu v vrstici je ločen s podpičjem. Na sredini vrstic vidimo klicani sistemski klic: read(): .... ;do_syscall_64;sys_read; .... Tako Cadvisor porabi veliko časa za sistemski klic read()povezanih s funkcijami mem_cgroup_* (vrh klicnega sklada/konec vrstice).
V sledenju klica je neprijetno videti, kaj točno se bere, zato poženimo strace in poglejmo, kaj počne cadvisor in najdemo sistemske klice, daljše od 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>
Kot lahko pričakujete, tukaj vidimo počasne klice read(). Iz vsebine operacij branja in konteksta mem_cgroup jasno je, da ti izzivi read() glej datoteko memory.stat, ki prikazuje uporabo pomnilnika in omejitve cgroup (Dockerjeva tehnologija izolacije virov). Orodje cadvisor poizveduje po tej datoteki, da pridobi informacije o uporabi virov za vsebnike. Preverimo, ali je jedro ali cadvisor naredil nekaj nepričakovanega:
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 ~ $
Zdaj lahko reproduciramo napako in razumemo, da se jedro Linuxa sooča s patologijo.
Zakaj je postopek branja tako počasen?
Na tej stopnji je veliko lažje najti sporočila drugih uporabnikov o podobnih težavah. Kot se je izkazalo, je bil v sledilniku cadvisor ta hrošč sporočen kot , samo nihče ni opazil, da se zakasnitev naključno odraža tudi v omrežnem skladu. Res je bilo opaziti, da cadvisor porabi več procesorskega časa, kot je bilo pričakovano, vendar temu ni bilo pripisanega velikega pomena, saj imajo naši strežniki veliko procesorskih virov, zato težava ni bila natančno preučena.
Težava je v tem, da cgroups upoštevajo uporabo pomnilnika znotraj imenskega prostora (vsebnika). Ko vsi procesi v tej cgroup zapustijo, Docker sprosti pomnilniško cgroup. Vendar "pomnilnik" ni le procesni pomnilnik. Čeprav se sam procesni pomnilnik ne uporablja več, se zdi, da jedro še vedno dodeljuje predpomnjeno vsebino, kot so dentries in inode (imenik in metapodatki datoteke), ki so predpomnjeni v pomnilniški cgroup. Iz opisa težave:
zombie cgroups: cgroups, ki nimajo procesov in so bile izbrisane, vendar imajo še vedno dodeljen pomnilnik (v mojem primeru iz predpomnilnika dentry, lahko pa ga dodelite tudi iz predpomnilnika strani ali tmpfs).
Preverjanje jedra vseh strani v predpomnilniku pri sproščanju cgroup je lahko zelo počasno, zato je izbran leni postopek: počakajte, da se te strani ponovno zahtevajo, nato pa končno počistite cgroup, ko je pomnilnik dejansko potreben. Do te točke se cgroup še vedno upošteva pri zbiranju statistike.
Z vidika zmogljivosti so žrtvovali pomnilnik za zmogljivost: pospešili so začetno čiščenje tako, da so za seboj pustili nekaj predpomnjenega pomnilnika. To je v redu. Ko jedro uporabi zadnji del predpomnjenega pomnilnika, se cgroup sčasoma počisti, zato tega ne moremo imenovati "puščanje". Na žalost posebna izvedba iskalnega mehanizma memory.stat v tej različici jedra (4.9) v kombinaciji z ogromno količino pomnilnika na naših strežnikih pomeni, da traja veliko dlje, da obnovimo najnovejše predpomnjene podatke in očistimo zombije cgroup.
Izkazalo se je, da so nekatera naša vozlišča imela toliko zombijev cgroup, da sta branje in zakasnitev presegla sekundo.
Rešitev za težavo s programom cadvisor je takojšnja sprostitev predpomnilnikov dentries/inodes v celotnem sistemu, kar takoj odpravi zakasnitev branja in zakasnitev omrežja na gostitelju, saj čiščenje predpomnilnika vklopi predpomnjene zombi strani cgroup in jih tudi sprosti. To ni rešitev, vendar potrjuje vzrok težave.
Izkazalo se je, da je bila v novejših različicah jedra (4.19+) zmogljivost klicev izboljšana memory.stat, tako da je preklop na to jedro odpravil težavo. Hkrati smo imeli orodja za odkrivanje problematičnih vozlišč v gručah Kubernetes, njihovo elegantno izpraznitev in ponovni zagon. Prečesali smo vse gruče, našli vozlišča z dovolj visoko latenco in jih ponovno zagnali. To nam je dalo čas za posodobitev operacijskega sistema na preostalih strežnikih.
Če povzamemo:
Ker je ta napaka zaustavila obdelavo čakalne vrste RX NIC za stotine milisekund, je hkrati povzročila tako visoko zakasnitev pri kratkih povezavah kot zakasnitev srednje povezave, na primer med zahtevami MySQL in odzivnimi paketi.
Razumevanje in vzdrževanje delovanja najbolj temeljnih sistemov, kot je Kubernetes, je ključnega pomena za zanesljivost in hitrost vseh storitev, ki temeljijo na njih. Vsak sistem, ki ga uporabljate, ima koristi od izboljšav zmogljivosti Kubernetes.
Vir: www.habr.com