For et par år siden Kubernetes på den officielle GitHub-blog. Siden da er det blevet standardteknologien til implementering af tjenester. Kubernetes administrerer nu en betydelig del af interne og offentlige tjenester. Efterhånden som vores klynger voksede, og ydeevnekravene blev strengere, begyndte vi at bemærke, at nogle tjenester på Kubernetes sporadisk oplevede latenstid, som ikke kunne forklares af selve applikationens belastning.
I det væsentlige oplever applikationer tilsyneladende tilfældig netværksforsinkelse på op til 100 ms eller mere, hvilket resulterer i timeouts eller genforsøg. Tjenester forventedes at kunne reagere på anmodninger meget hurtigere end 100 ms. Men dette er umuligt, hvis selve forbindelsen tager så lang tid. Separat observerede vi meget hurtige MySQL-forespørgsler, der burde have taget millisekunder, og MySQL blev gennemført på millisekunder, men fra den anmodende applikations perspektiv tog svaret 100ms eller mere.
Det blev straks klart, at problemet kun opstod ved forbindelse til en Kubernetes-knude, selvom opkaldet kom udefra Kubernetes. Den nemmeste måde at genskabe problemet er i en test , som kører fra enhver intern vært, tester Kubernetes-tjenesten på en specifik port og registrerer sporadisk høj latenstid. I denne artikel vil vi se på, hvordan vi var i stand til at spore årsagen til dette problem.
Eliminering af unødvendig kompleksitet i kæden, der fører til fiasko
Ved at gengive det samme eksempel ønskede vi at indsnævre problemets fokus og fjerne unødvendige lag af kompleksitet. I starten var der for mange elementer i flowet mellem Vegeta og Kubernetes-bælgene. For at identificere et dybere netværksproblem skal du udelukke nogle af dem.
Klienten (Vegeta) opretter en TCP-forbindelse med en hvilken som helst node i klyngen. Kubernetes fungerer som et overlejringsnetværk (oven på det eksisterende datacenternetværk), der bruger , det vil sige, at det indkapsler IP-pakkerne i overlejringsnetværket inde i IP-pakkerne i datacentret. Når der oprettes forbindelse til den første node, udføres netværksadresseoversættelse (NAT) stateful til at oversætte IP-adressen og porten på Kubernetes-noden til IP-adressen og porten i overlejringsnetværket (specifikt poden med applikationen). For indgående pakker udføres den omvendte rækkefølge af handlinger. Det er et komplekst system med en masse tilstand og mange elementer, der konstant opdateres og ændres, efterhånden som tjenesterne implementeres og flyttes.
Hjælpeprogram tcpdump i Vegeta-testen er der en forsinkelse under TCP-håndtrykket (mellem SYN og SYN-ACK). For at fjerne denne unødvendige kompleksitet, kan du bruge hping3 for simple "pings" med SYN-pakker. Vi tjekker, om der er en forsinkelse i svarpakken, og nulstiller derefter forbindelsen. Vi kan filtrere dataene til kun at inkludere pakker større end 100ms og få en nemmere måde at reproducere problemet på end den fulde netværkslag 7-test i Vegeta. Her er Kubernetes node "pinger" ved hjælp af TCP SYN/SYN-ACK på tjenesten "node port" (30927) med 10 ms intervaller, filtreret efter langsomste svar:
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
Kan straks foretage den første observation. At dømme efter sekvensnumrene og timingen er det klart, at der ikke er tale om engangsoverbelastninger. Forsinkelsen akkumuleres ofte og behandles til sidst.
Dernæst ønsker vi at finde ud af, hvilke komponenter der kan være involveret i forekomsten af overbelastning. Måske er dette nogle af de hundredvis af iptables-regler i NAT? Eller er der problemer med IPIP-tunneling på netværket? En måde at teste dette på er at teste hvert trin i systemet ved at eliminere det. Hvad sker der, hvis du fjerner NAT og firewalllogik, og kun efterlader IPIP-delen:
Heldigvis gør Linux det nemt at få direkte adgang til IP-overlejringslaget, hvis maskinen er på det samme netværk:
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
At dømme efter resultaterne er problemet stadig tilbage! Dette udelukker iptables og NAT. Så problemet er TCP? Lad os se, hvordan en almindelig ICMP-ping går:
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
Resultaterne viser, at problemet ikke er forsvundet. Måske er dette en IPIP-tunnel? Lad os forenkle testen yderligere:
Sendes alle pakker mellem disse to værter?
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
Vi har forenklet situationen til to Kubernetes-noder, der sender en hvilken som helst pakke til hinanden, endda et ICMP-ping. De ser stadig latens, hvis målværten er "dårlig" (nogle værre end andre).
Nu det sidste spørgsmål: hvorfor opstår forsinkelsen kun på kube-node-servere? Og sker det, når kube-node er afsender eller modtager? Det er heldigvis også ret nemt at finde ud af ved at sende en pakke fra en vært uden for Kubernetes, men med den samme "kendte dårlige" modtager. Som du kan se, er problemet ikke forsvundet:
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
Vi kører derefter de samme anmodninger fra den tidligere kilde-kube-node til den eksterne vært (hvilket udelukker kildeværten, da pinget inkluderer både en RX- og TX-komponent):
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
Ved at undersøge latenspakkefangster fik vi nogle yderligere oplysninger. Specifikt, at afsenderen (nederst) ser denne timeout, men modtageren (øverst) ikke gør det - se kolonnen Delta (i sekunder):
Hvis man derudover ser på forskellen i rækkefølgen af TCP- og ICMP-pakker (efter sekvensnumre) på modtagersiden, ankommer ICMP-pakker altid i samme rækkefølge, som de blev sendt i, men med forskellig timing. Samtidig interlever TCP-pakker nogle gange, og nogle af dem sætter sig fast. Især hvis du undersøger portene på SYN-pakker, er de i orden på afsenderens side, men ikke på modtagerens side.
Der er en subtil forskel på hvordan moderne servere (som dem i vores datacenter) behandler pakker, der indeholder TCP eller ICMP. Når en pakke ankommer, "hasher" netværksadapteren den pr. forbindelse, det vil sige, at den forsøger at bryde forbindelserne i køer og sende hver kø til en separat processorkerne. For TCP inkluderer denne hash både kilde- og destinations-IP-adressen og -porten. Med andre ord er hver forbindelse hash (potentielt) forskelligt. For ICMP er det kun IP-adresser, der hashes, da der ikke er nogen porte.
En anden ny observation: i denne periode ser vi ICMP-forsinkelser på al kommunikation mellem to værter, men det gør TCP ikke. Dette fortæller os, at årsagen sandsynligvis er relateret til RX-køhashing: Overbelastningen er næsten helt sikkert i behandlingen af RX-pakker, ikke i afsendelsen af svar.
Dette eliminerer afsendelse af pakker fra listen over mulige årsager. Vi ved nu, at pakkebehandlingsproblemet er på modtagesiden på nogle kube-node-servere.
Forståelse af pakkebehandling i Linux-kernen
For at forstå, hvorfor problemet opstår ved modtageren på nogle kube-node-servere, lad os se på, hvordan Linux-kernen behandler pakker.
For at vende tilbage til den enkleste traditionelle implementering, modtager netværkskortet pakken og sender Linux-kernen, at der er en pakke, der skal behandles. Kernen stopper andet arbejde, skifter kontekst til interrupt-handleren, behandler pakken og vender derefter tilbage til de aktuelle opgaver.
Denne kontekstskiftning er langsom: ventetid var måske ikke mærkbar på 10 Mbps netværkskort i 90'erne, men på moderne 10G-kort med en maksimal gennemstrømning på 15 millioner pakker pr. gange i sekundet.
For ikke konstant at håndtere afbrydelser, tilføjede Linux for mange år siden : Netværks-API, som alle moderne drivere bruger til at forbedre ydeevnen ved høje hastigheder. Ved lave hastigheder modtager kernen stadig afbrydelser fra netværkskortet på den gamle måde. Når der ankommer nok pakker, der overstiger tærsklen, deaktiverer kernen interrupts og begynder i stedet at polle netværksadapteren og samle pakker op i bidder. Behandling udføres i softirq, det vil sige i efter systemkald og hardwareafbrydelser, når kernen (i modsætning til brugerplads) allerede kører.
Dette er meget hurtigere, men forårsager et andet problem. Hvis der er for mange pakker, så går al tiden med at behandle pakker fra netværkskortet, og brugerrumsprocesser har ikke tid til rent faktisk at tømme disse køer (læsning fra TCP-forbindelser osv.). Til sidst fyldes køerne op, og vi begynder at droppe pakker. I et forsøg på at finde en balance, sætter kernen et budget for det maksimale antal pakker, der behandles i softirq-konteksten. Når dette budget er overskredet, vækkes en separat tråd ksoftirqd (du vil se en af dem i ps per kerne), der håndterer disse softirqs uden for den normale syscall/afbrydelsessti. Denne tråd er planlagt ved hjælp af standardprocesplanlæggeren, som forsøger at allokere ressourcer retfærdigt.
Efter at have studeret, hvordan kernen behandler pakker, kan du se, at der er en vis sandsynlighed for overbelastning. Hvis softirq-opkald modtages sjældnere, skal pakker vente i nogen tid på at blive behandlet i RX-køen på netværkskortet. Dette kan skyldes, at en opgave blokerer processorkernen, eller noget andet forhindrer kernen i at køre softirq.
Indsnævring af behandlingen til kernen eller metoden
Softirq-forsinkelser er kun et gæt for nu. Men det giver mening, og vi ved, at vi ser noget meget lignende. Så det næste skridt er at bekræfte denne teori. Og hvis det bliver bekræftet, så find årsagen til forsinkelserne.
Lad os vende tilbage til vores langsomme pakker:
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
Som diskuteret tidligere, hashes disse ICMP-pakker til en enkelt RX NIC-kø og behandles af en enkelt CPU-kerne. Hvis vi ønsker at forstå, hvordan Linux fungerer, er det nyttigt at vide, hvor (på hvilken CPU-kerne) og hvordan (softirq, ksoftirqd) disse pakker behandles for at spore processen.
Nu er det tid til at bruge værktøjer, der giver dig mulighed for at overvåge Linux-kernen i realtid. Her brugte vi . Dette sæt værktøjer giver dig mulighed for at skrive små C-programmer, der tilslutter vilkårlige funktioner i kernen og buffer begivenhederne ind i et Python-program i brugerrummet, som kan behandle dem og returnere resultatet til dig. Tilslutning af vilkårlige funktioner i kernen er en vanskelig forretning, men værktøjet er designet til maksimal sikkerhed og er designet til at spore præcis den slags produktionsproblemer, som ikke let kan reproduceres i et test- eller udviklingsmiljø.
Planen her er enkel: vi ved, at kernen behandler disse ICMP-pings, så vi sætter en krog på kernefunktionen , som accepterer en indgående ICMP ekko-anmodningspakke og starter afsendelse af et ICMP ekkosvar. Vi kan identificere en pakke ved at øge icmp_seq-nummeret, som viser hping3 ovenfor.
Kode ser kompliceret ud, men det er ikke så skræmmende, som det ser ud til. Fungere icmp_echo sender struct sk_buff *skb: Dette er en pakke med en "ekko-anmodning". Vi kan spore det, trække rækkefølgen ud echo.sequence (som sammenlignes med icmp_seq af hping3 выше), og send det til brugerområdet. Det er også praktisk at fange det aktuelle procesnavn/id. Nedenfor er resultaterne, som vi ser direkte, mens kernen behandler pakker:
TGID PID PROCESS NAVN ICMP_SEQ 0 0 bytte/11 770 0 bytte/0 11 771 bytte/0 0 11 bytte/772 0 0 bytte/11 773 0 prometheus 0 11 774 bytte/20041 20086 775 bytte/0 0 11 bytte/776 0 0 eger-rapport-s 11
Det skal her bemærkes, at i sammenhængen softirq processer, der foretog systemkald, vil fremstå som "processer", når det faktisk er kernen, der sikkert behandler pakker i kernens kontekst.
Med dette værktøj kan vi knytte specifikke processer til specifikke pakker, der viser en forsinkelse på hping3. Lad os gøre det enkelt grep på denne optagelse for visse værdier icmp_seq. Pakker, der matcher ovenstående icmp_seq-værdier, blev markeret sammen med deres RTT, vi observerede ovenfor (i parentes er de forventede RTT-værdier for pakker, vi filtrerede fra på grund af RTT-værdier mindre end 50ms):
TGID PID PROCESS NAVN 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 ** (5ms)
Resultaterne fortæller os flere ting. For det første behandles alle disse pakker af konteksten ksoftirqd/11. Dette betyder, at ICMP-pakker for dette særlige par af maskiner blev hashed til kerne 11 i den modtagende ende. Vi ser også, at når der er en jam, er der pakker, der behandles i forbindelse med systemkaldet cadvisor. Derefter ksoftirqd overtager opgaven og behandler den akkumulerede kø: præcis det antal pakker, der er akkumuleret efter cadvisor.
Det faktum, at umiddelbart før det altid virker cadvisor, indebærer hans involvering i problemet. Ironisk nok formålet - "analysere ressourceforbrug og ydeevnekarakteristika for kørende containere" i stedet for at forårsage dette ydeevneproblem.
Som med andre aspekter af containere er disse alle meget avancerede værktøjer og kan forventes at opleve ydeevneproblemer under nogle uforudsete omstændigheder.
Hvad gør cadvisor, der bremser pakkekøen?
Vi har nu en ret god forståelse af, hvordan nedbruddet opstår, hvilken proces der forårsager det, og på hvilken CPU. Vi ser, at Linux-kernen på grund af hård blokering ikke har tid til at planlægge ksoftirqd. Og vi ser, at pakker behandles i kontekst cadvisor. Det er logisk at antage det cadvisor starter et langsomt syscall, hvorefter alle pakker, der er akkumuleret på det tidspunkt, behandles:
Dette er en teori, men hvordan tester man den? Det, vi kan gøre, er at spore CPU-kernen gennem hele denne proces, finde det punkt, hvor antallet af pakker overskrider budgettet, og ksoftirqd kaldes, og så se lidt længere tilbage for at se, hvad der præcist kørte på CPU-kernen lige før det tidspunkt. . Det er som at røntgenfotografere CPU'en hvert par millisekunder. Det kommer til at se sådan ud:
Alt dette kan bekvemt gøres med eksisterende værktøjer. For eksempel, kontrollerer en given CPU-kerne ved en specificeret frekvens og kan generere en tidsplan for opkald til det kørende system, inklusive både brugerplads og Linux-kernen. Du kan tage denne post og behandle den ved hjælp af en lille forgrening af programmet fra Brendan Gregg, som bevarer rækkefølgen af staksporet. Vi kan gemme enkeltlinjes stakspor hver 1 ms og derefter fremhæve og gemme en prøve 100 millisekunder før sporet rammer 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
Her er resultaterne:
(сотни следов, которые выглядят похожими)
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
Der er mange ting her, men det vigtigste er, at vi finder "cadvisor before ksoftirqd"-mønsteret, som vi så tidligere i ICMP-sporingen. Hvad betyder det?
Hver linje er et CPU-spor på et bestemt tidspunkt. Hvert opkald ned i stakken på en linje er adskilt af et semikolon. I midten af linjerne ser vi syscallen kaldes: read(): .... ;do_syscall_64;sys_read; .... Så cadvisor bruger meget tid på systemkaldet read()relateret til funktioner mem_cgroup_* (øverst på opkaldsstakken/slut på linjen).
Det er ubelejligt at se i et opkaldsspor, hvad der præcist bliver læst, så lad os løbe strace og lad os se, hvad cadvisor gør og finde systemkald, der er længere end 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>
Som du måske forventer, ser vi langsomme opkald her read(). Fra indholdet af læseoperationer og kontekst mem_cgroup det er klart, at disse udfordringer read() henvise til filen memory.stat, som viser hukommelsesforbrug og cgroup-grænser (Dockers ressourceisoleringsteknologi). Cadvisor-værktøjet forespørger denne fil for at få oplysninger om ressourceforbrug for containere. Lad os tjekke, om det er kernen eller cadvisor, der gør noget uventet:
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 ~ $
Nu kan vi reproducere fejlen og forstå, at Linux-kernen står over for en patologi.
Hvorfor er læseoperationen så langsom?
På dette stadium er det meget nemmere at finde beskeder fra andre brugere om lignende problemer. Som det viste sig, blev denne fejl rapporteret som i cadvisor-trackeren , det er bare, at ingen har bemærket, at latensen også afspejles tilfældigt i netværksstakken. Det blev ganske vist bemærket, at cadvisor brugte mere CPU-tid end forventet, men dette blev ikke tillagt stor betydning, da vores servere har mange CPU-ressourcer, så problemet blev ikke nøje undersøgt.
Problemet er, at cgroups tager højde for hukommelsesbrug i navnerummet (containeren). Når alle processer i denne cgroup afsluttes, frigiver Docker hukommelsen cgroup. Men "hukommelse" er ikke kun proceshukommelse. Selvom selve proceshukommelsen ikke længere bruges, ser det ud til, at kernen stadig tildeler cachelagret indhold, såsom dentries og inoder (mappe- og filmetadata), som er cachelagret i hukommelsens cgroup. Fra problembeskrivelsen:
zombie cgroups: cgroups, der ikke har nogen processer og er blevet slettet, men som stadig har tildelt hukommelse (i mit tilfælde fra dentry-cachen, men det kan også allokeres fra sidecachen eller tmpfs).
Kernens kontrol af alle siderne i cachen, når en cgroup frigøres, kan være meget langsom, så den dovne proces er valgt: vent til disse sider bliver anmodet om igen, og ryd til sidst cgroup, når hukommelsen faktisk er nødvendig. Indtil dette tidspunkt er cgroup stadig taget i betragtning ved indsamling af statistik.
Fra et præstationssynspunkt ofrede de hukommelse for ydeevne: fremskynde den indledende oprydning ved at efterlade noget cachelagret hukommelse. Det er fint. Når kernen bruger den sidste af den cachelagrede hukommelse, bliver cgroup til sidst ryddet, så den kan ikke kaldes en "lækage". Desværre, den specifikke implementering af søgemekanismen memory.stat i denne kerneversion (4.9), kombineret med den enorme mængde hukommelse på vores servere, betyder det, at det tager meget længere tid at gendanne de seneste cachelagrede data og rydde cgroup-zombier.
Det viser sig, at nogle af vores noder havde så mange cgroup-zombier, at læsningen og latensen oversteg et sekund.
Løsningen for cadvisor-problemet er øjeblikkeligt at frigøre dentries/inodes-caches i hele systemet, hvilket øjeblikkeligt eliminerer læselatens samt netværkslatens på værten, da rydning af cachen slår de cachelagrede cgroup-zombiesider til, og de frigives også. Dette er ikke en løsning, men det bekræfter årsagen til problemet.
Det viste sig, at i nyere kerneversioner (4.19+) var opkaldsydelsen forbedret memory.stat, så skift til denne kerne løste problemet. Samtidig havde vi værktøjer til at opdage problematiske noder i Kubernetes-klynger, tømme dem elegant og genstarte dem. Vi finkæmmede alle klyngerne, fandt noder med høj nok latency og genstartede dem. Dette gav os tid til at opdatere OS på de resterende servere.
Opsummering
Fordi denne fejl stoppede RX NIC-købehandlingen i hundredvis af millisekunder, forårsagede den samtidig både høj latens på korte forbindelser og mid-connection latency, såsom mellem MySQL-anmodninger og svarpakker.
Forståelse og vedligeholdelse af ydeevnen af de mest fundamentale systemer, såsom Kubernetes, er afgørende for pålideligheden og hastigheden af alle tjenester baseret på dem. Hvert system, du kører, drager fordel af Kubernetes ydeevneforbedringer.
Kilde: www.habr.com