För ett par år sedan Kubernetes på den officiella GitHub-bloggen. Sedan dess har det blivit standardtekniken för att distribuera tjänster. Kubernetes hanterar nu en betydande del av interna och offentliga tjänster. När våra kluster växte och prestandakraven blev strängare började vi märka att vissa tjänster på Kubernetes sporadiskt upplevde latens som inte kunde förklaras av själva applikationens belastning.
I huvudsak upplever applikationer en slumpmässig nätverkslatens på upp till 100 ms eller mer, vilket resulterar i timeouts eller omförsök. Tjänsterna förväntades kunna svara på förfrågningar mycket snabbare än 100 ms. Men detta är omöjligt om själva anslutningen tar så lång tid. Separat observerade vi mycket snabba MySQL-frågor som borde ta millisekunder, och MySQL slutfördes på millisekunder, men från den begärande applikationens perspektiv tog svaret 100 ms eller mer.
Det blev direkt klart att problemet bara uppstod vid anslutning till en Kubernetes-nod, även om samtalet kom utifrån Kubernetes. Det enklaste sättet att reproducera problemet är i ett test , som körs från vilken intern värd som helst, testar Kubernetes-tjänsten på en specifik port och registrerar sporadiskt hög latens. I den här artikeln kommer vi att titta på hur vi kunde spåra orsaken till detta problem.
Eliminera onödig komplexitet i kedjan som leder till misslyckande
Genom att återge samma exempel ville vi begränsa problemets fokus och ta bort onödiga lager av komplexitet. Inledningsvis var det för många element i flödet mellan Vegeta och Kubernetes baljor. För att identifiera ett djupare nätverksproblem måste du utesluta några av dem.
Klienten (Vegeta) skapar en TCP-anslutning med valfri nod i klustret. Kubernetes fungerar som ett överläggsnätverk (utöver det befintliga datacenternätverket) som använder , det vill säga den kapslar in IP-paketen för överlagringsnätverket inuti datacentrets IP-paket. Vid anslutning till den första noden utförs nätverksadressöversättning (NAT) stateful för att översätta IP-adressen och porten för Kubernetes-noden till IP-adressen och porten i överlagringsnätverket (särskilt podden med applikationen). För inkommande paket utförs den omvända sekvensen av åtgärder. Det är ett komplext system med mycket tillstånd och många element som ständigt uppdateras och ändras när tjänster distribueras och flyttas.
Verktyg tcpdump i Vegeta-testet finns en fördröjning under TCP-handskakningen (mellan SYN och SYN-ACK). För att ta bort denna onödiga komplexitet kan du använda hping3 för enkla "pings" med SYN-paket. Vi kontrollerar om det är en fördröjning i svarspaketet och återställer sedan anslutningen. Vi kan filtrera data till att bara inkludera paket som är större än 100ms och få ett enklare sätt att reproducera problemet än Vegetas fullständiga nätverkslag 7-test. Här är Kubernetes nod "pings" med TCP SYN/SYN-ACK på tjänsten "node port" (30927) med 10 ms intervall, filtrerade av långsammaste 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 genast göra den första observationen. Att döma av sekvensnumren och tidpunkterna är det tydligt att det inte är fråga om engångsstockningar. Förseningen ackumuleras ofta och bearbetas så småningom.
Därefter vill vi ta reda på vilka komponenter som kan vara inblandade i uppkomsten av överbelastning. Kanske är detta några av de hundratals iptables-reglerna i NAT? Eller finns det några problem med IPIP-tunnling i nätverket? Ett sätt att kontrollera detta är att testa varje steg i systemet genom att eliminera det. Vad händer om du tar bort NAT och brandväggslogik och bara lämnar IPIP-delen:
Lyckligtvis gör Linux det enkelt att komma åt IP-överlagringsskiktet direkt om maskinen är på samma nätverk:
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
Att döma av resultaten kvarstår problemet fortfarande! Detta exkluderar iptables och NAT. Så problemet är TCP? Låt oss se hur en vanlig 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
Resultaten visar att problemet inte har försvunnit. Kanske är detta en IPIP-tunnel? Låt oss förenkla testet ytterligare:
Skickas alla paket mellan dessa två värdar?
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 förenklat situationen till att två Kubernetes-noder skickar vilket paket som helst till varandra, till och med en ICMP-ping. De ser fortfarande latens om målvärden är "dålig" (vissa värre än andra).
Nu den sista frågan: varför uppstår fördröjningen bara på kube-node-servrar? Och händer det när kube-node är avsändaren eller mottagaren? Lyckligtvis är detta också ganska lätt att ta reda på genom att skicka ett paket från en värd utanför Kubernetes, men med samma "kända dåliga" mottagare. Som du kan se har problemet inte försvunnit:
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 kommer sedan att köra samma förfrågningar från den tidigare källan kube-noden till den externa värden (vilket utesluter källvärden eftersom pingen inkluderar både en RX- och 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
Genom att undersöka latenspaketfångst fick vi lite ytterligare information. Specifikt att avsändaren (nederst) ser denna timeout, men mottagaren (överst) inte - se kolumnen Delta (i sekunder):
Dessutom, om man tittar på skillnaden i ordningsföljden för TCP- och ICMP-paket (efter sekvensnummer) på mottagarsidan, kommer ICMP-paket alltid i samma sekvens som de skickades i, men med olika timing. Samtidigt interfolierar TCP-paket ibland, och några av dem fastnar. I synnerhet om du undersöker portarna för SYN-paket är de i ordning på avsändarens sida, men inte på mottagarens sida.
Det är en subtil skillnad i hur moderna servrar (som de i vårt datacenter) bearbetar paket som innehåller TCP eller ICMP. När ett paket anländer "hashasar nätverksadaptern det per anslutning", det vill säga den försöker bryta upp anslutningarna i köer och skicka varje kö till en separat processorkärna. För TCP inkluderar denna hash både käll- och destinations-IP-adress och port. Med andra ord, varje anslutning hashas (potentiellt) olika. För ICMP hashas endast IP-adresser, eftersom det inte finns några portar.
En annan ny observation: under denna period ser vi ICMP-förseningar på all kommunikation mellan två värdar, men TCP gör det inte. Detta talar om för oss att orsaken sannolikt är relaterad till RX-köhashing: överbelastningen är nästan säkert i bearbetningen av RX-paket, inte i sändningen av svar.
Detta eliminerar sändning av paket från listan över möjliga orsaker. Vi vet nu att paketbearbetningsproblemet är på mottagningssidan på vissa kube-nodservrar.
Förstå paketbearbetning i Linux-kärnan
För att förstå varför problemet uppstår vid mottagaren på vissa kube-node-servrar, låt oss titta på hur Linux-kärnan bearbetar paket.
För att återgå till den enklaste traditionella implementeringen tar nätverkskortet emot paketet och skickar Linux-kärnan att det finns ett paket som måste bearbetas. Kärnan stoppar annat arbete, byter kontext till avbrottshanteraren, bearbetar paketet och återgår sedan till de aktuella uppgifterna.
Denna kontextväxling är långsam: latens kanske inte har märkts på 10 Mbps nätverkskort på 90-talet, men på moderna 10G-kort med en maximal genomströmning på 15 miljoner paket per sekund kan varje kärna i en liten åttakärnig server avbrytas för miljoner gånger per sekund.
För att inte ständigt hantera avbrott lades Linux till för många år sedan : Nätverks-API som alla moderna drivrutiner använder för att förbättra prestanda vid höga hastigheter. Vid låga hastigheter får kärnan fortfarande avbrott från nätverkskortet på det gamla sättet. När tillräckligt många paket anländer som överskrider tröskeln, inaktiverar kärnan avbrott och börjar istället polla nätverksadaptern och plocka upp paket i bitar. Bearbetning utförs i softirq, det vill säga i efter systemanrop och hårdvaruavbrott, när kärnan (i motsats till användarutrymme) redan körs.
Detta är mycket snabbare, men orsakar ett annat problem. Om det finns för många paket går all tid åt till att bearbeta paket från nätverkskortet, och användarutrymmesprocesser hinner inte faktiskt tömma dessa köer (läser från TCP-anslutningar, etc.). Så småningom fylls köerna och vi börjar släppa paket. I ett försök att hitta en balans sätter kärnan en budget för det maximala antalet paket som behandlas i softirq-kontexten. När denna budget väl har överskridits väcks en separat tråd ksoftirqd (du kommer att se en av dem i ps per kärna) som hanterar dessa softirqs utanför den normala syscall/avbrottsvägen. Den här tråden är schemalagd med hjälp av standardprocessplaneraren, som försöker allokera resurser rättvist.
Efter att ha studerat hur kärnan bearbetar paket kan du se att det finns en viss sannolikhet för överbelastning. Om softirq-samtal tas emot mer sällan kommer paketen att behöva vänta en tid för att behandlas i RX-kön på nätverkskortet. Detta kan bero på att någon uppgift blockerar processorkärnan, eller att något annat hindrar kärnan från att köra softirq.
Begränsa bearbetningen till kärnan eller metoden
Softirq-förseningar är bara en gissning för tillfället. Men det är vettigt, och vi vet att vi ser något mycket liknande. Så nästa steg är att bekräfta denna teori. Och om det bekräftas, hitta orsaken till förseningarna.
Låt oss återgå till våra långsamma paket:
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 diskuterats tidigare hashas dessa ICMP-paket till en enda RX NIC-kö och bearbetas av en enda CPU-kärna. Om vi vill förstå hur Linux fungerar är det användbart att veta var (på vilken CPU-kärna) och hur (softirq, ksoftirqd) dessa paket bearbetas för att spåra processen.
Nu är det dags att använda verktyg som låter dig övervaka Linux-kärnan i realtid. Här använde vi . Denna uppsättning verktyg låter dig skriva små C-program som kopplar godtyckliga funktioner i kärnan och buffrar händelserna till ett Python-program i användarutrymme som kan bearbeta dem och returnera resultatet till dig. Krokar för godtyckliga funktioner i kärnan är en komplex fråga, men verktyget är designat för maximal säkerhet och är designat för att spåra exakt den typ av produktionsproblem som inte lätt kan återskapas i en test- eller utvecklingsmiljö.
Planen här är enkel: vi vet att kärnan bearbetar dessa ICMP-pingar, så vi sätter en krok på kärnfunktionen , som accepterar ett inkommande ICMP-ekobegäranpaket och initierar sändning av ett ICMP-ekosvar. Vi kan identifiera ett paket genom att öka icmp_seq-numret, vilket visas hping3 ovan.
Kod ser komplicerat ut, men det är inte så läskigt som det verkar. Fungera icmp_echo sänder struct sk_buff *skb: Detta är ett paket med en "ekobegäran". Vi kan spåra det, dra ut sekvensen echo.sequence (vilket kan jämföras med icmp_seq av hping3 выше), och skicka den till användarutrymmet. Det är också bekvämt att fånga det aktuella processens namn/id. Nedan är resultaten som vi ser direkt medan kärnan bearbetar paket:
TGID PID Processnamn ICMP_SEQ 0 0 Swapper/11 770 0 0 Swapper/11 771 0 0 Swapper/11 772 0 0 Swapper/11 773 0 0 Swapper/11 774 20041 20086 Prometheus 775 0 0 Swapper/11 776 0 0 Swapper/11 777 0 0 11 778 swapper/4512 4542 779 XNUMX ekrar-rapporter XNUMX
Det bör här noteras att i sammanhanget softirq processer som gjorde systemanrop kommer att visas som "processer" när det i själva verket är kärnan som säkert bearbetar paket i kärnans sammanhang.
Med detta verktyg kan vi associera specifika processer med specifika paket som visar en fördröjning av hping3. Låt oss göra det enkelt grep på denna fångst för vissa värden icmp_seq. Paket som matchar ovanstående icmp_seq-värden noterades tillsammans med deras RTT som vi observerade ovan (inom parentes är de förväntade RTT-värdena för paket som vi filtrerade bort på grund av RTT-värden mindre än 50 ms):
TGID PID PROCESSNAMN ICMP_SEQ ** RTT -- 10137 10436 cadvisor 1951 10137 10436 cadvisor 1952 76 76 ksoftirqd/11 1953 ** 99ms 76 76 ksoftir 11d 1954 ksoftir 89d 76 ksoftir 76d qd/11 1955 ** 79ms 76 76 ksoftirqd/ 11 1956 ** 69 ms 76 76 ksoftirqd/11 1957 ** 59 ms 76 76 ksoftirqd/11 1958 ** (49 ms) 76 76 ksoftirqd/11 1959 ** (39 ms) 76 q 76 ms ** 11 1960/29 ms 76 ksoft irqd/ 76 11 ** (1961 ms) 19 76 ksoftirqd/76 11 ** (1962 ms) -- 9 10137 cadvisor 10436 2068 10137 cadvisor 10436 2069 76 ksoftir 76/11 ** 2070 ms qd/75 76 ** 76ms 11 2071 ksoftirqd/ 65 76 ** 76 ms 11 2072 ksoftirqd/55 76 ** (76 ms) 11 2073 ksoftirqd/45 76 ** (76 ms) 11 2074 ksoftirqd/35 76 ** 76q 11 ** (2075 ms) ** (25 ms) ms ) 76 76 ksoftirqd/11 2076 ** (15ms)
Resultaten säger oss flera saker. För det första bearbetas alla dessa paket av sammanhanget ksoftirqd/11. Detta betyder att för just detta par av maskiner hashades ICMP-paket till kärna 11 i den mottagande änden. Vi ser också att närhelst det finns ett jam finns det paket som bearbetas i samband med systemanropet cadvisor. sedan ksoftirqd tar över uppgiften och bearbetar den ackumulerade kön: exakt det antal paket som har ackumulerats efter cadvisor.
Det faktum att omedelbart innan det alltid fungerar cadvisor, antyder hans inblandning i problemet. Ironiskt nog, syftet - "analysera resursanvändning och prestanda för körande behållare" snarare än att orsaka detta prestandaproblem.
Precis som med andra aspekter av containrar är dessa alla mycket avancerade verktyg och kan förväntas uppleva prestandaproblem under vissa oförutsedda omständigheter.
Vad gör cadvisor som saktar ner paketkön?
Vi har nu en ganska bra förståelse för hur kraschen inträffar, vilken process som orsakar den och på vilken CPU. Vi ser att på grund av hård blockering har inte Linux-kärnan tid att schemalägga ksoftirqd. Och vi ser att paket bearbetas i sammanhang cadvisor. Det är logiskt att anta det cadvisor startar ett långsamt syscall, varefter alla paket som ackumulerats vid den tiden bearbetas:
Detta är en teori, men hur testar man den? Vad vi kan göra är att spåra CPU-kärnan under hela denna process, hitta punkten där antalet paket överskrider budgeten och ksoftirqd anropas, och sedan titta lite längre tillbaka för att se exakt vad som kördes på CPU-kärnan precis innan den punkten . Det är som att röntga processorn med några millisekunder. Det kommer att se ut ungefär så här:
Bekvämt kan allt detta göras med befintliga verktyg. Till exempel, kontrollerar en given CPU-kärna vid en specificerad frekvens och kan generera ett schema för anrop till det körande systemet, inklusive både användarutrymme och Linux-kärnan. Du kan ta denna post och bearbeta den med en liten gaffel av programmet från Brendan Gregg, som bevarar ordningen på stackspåret. Vi kan spara enradiga stackspår var 1 ms och sedan markera och spara ett prov 100 millisekunder innan spåret träffar 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
Här är resultaten:
(сотни следов, которые выглядят похожими)
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
Det finns många saker här, men huvudsaken är att vi hittar mönstret "cadvisor before ksoftirqd" som vi såg tidigare i ICMP-spåraren. Vad betyder det?
Varje rad är ett CPU-spår vid en viss tidpunkt. Varje anrop nerför stacken på en linje separeras med ett semikolon. I mitten av raderna ser vi syscallen kallas: read(): .... ;do_syscall_64;sys_read; .... Så cadvisor lägger mycket tid på systemanropet read()relaterade till funktioner mem_cgroup_* (överst på samtalsstapeln/slutet på linjen).
Det är obekvämt att se i ett samtalsspåra exakt vad som läses, så låt oss springa strace och låt oss se vad cadvisor gör och hitta systemanrop längre än 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 kan förvänta dig ser vi långsamma samtal här read(). Från innehållet i läsoperationer och sammanhang mem_cgroup det är tydligt att dessa utmaningar read() hänvisa till filen memory.stat, som visar minnesanvändning och cgroup-gränser (Dockers resursisoleringsteknik). Cadvisor-verktyget frågar efter den här filen för att få information om resursanvändning för behållare. Låt oss kolla om det är kärnan eller cadvisor som gör något oväntat:
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 reproducera buggen och förstå att Linux-kärnan står inför en patologi.
Varför är läsoperationen så långsam?
I det här skedet är det mycket lättare att hitta meddelanden från andra användare om liknande problem. Som det visade sig, i cadvisor tracker rapporterades detta fel som , det är bara det att ingen märkte att latensen också återspeglas slumpmässigt i nätverksstacken. Det märktes verkligen att cadvisor förbrukade mer CPU-tid än förväntat, men detta gavs inte så stor vikt, eftersom våra servrar har mycket CPU-resurser, så problemet studerades inte noggrant.
Problemet är att cgroups tar hänsyn till minnesanvändning inom namnutrymmet (behållaren). När alla processer i denna cgroup avslutas släpper Docker minnescgroupen. Men "minne" är inte bara processminne. Även om själva processminnet inte längre används, verkar det som om kärnan fortfarande tilldelar cachat innehåll, såsom dentries och inoder (katalog- och filmetadata), som cachelagras i minnets cgroup. Från problembeskrivningen:
zombie cgroups: cgroups som inte har några processer och som har tagits bort, men som fortfarande har allokerat minne (i mitt fall från dentry-cachen, men det kan också allokeras från sidcachen eller tmpfs).
Kärnans kontroll av alla sidor i cachen när en cgroup frigörs kan vara mycket långsam, så den lata processen väljs: vänta tills dessa sidor efterfrågas igen, och rensa sedan cgroup när minnet faktiskt behövs. Fram till denna punkt beaktas fortfarande cgroup vid insamling av statistik.
Ur prestandasynpunkt offrade de minne för prestanda: påskyndade den första rensningen genom att lämna lite cachat minne bakom sig. Det här är okej. När kärnan använder det sista av det cachade minnet, rensas cgroup så småningom, så det kan inte kallas en "läcka". Tyvärr, det specifika genomförandet av sökmekanismen memory.stat i denna kärnversion (4.9), i kombination med den enorma mängden minne på våra servrar, innebär det att det tar mycket längre tid att återställa den senaste cachade datan och rensa cgroup-zombies.
Det visar sig att några av våra noder hade så många cgroup-zombies att läsningen och latensen översteg en sekund.
Lösningen för cadvisor-problemet är att omedelbart frigöra dentries/inodes-cacher i hela systemet, vilket omedelbart eliminerar läslatens såväl som nätverkslatens på värden, eftersom rensning av cachen aktiverar de cachade zombie-cgroup-sidorna och frigör dem också. Detta är ingen lösning, men det bekräftar orsaken till problemet.
Det visade sig att i nyare kärnversioner (4.19+) förbättrades samtalsprestanda memory.stat, så att byta till den här kärnan löste problemet. Samtidigt hade vi verktyg för att upptäcka problematiska noder i Kubernetes-kluster, graciöst dränera dem och starta om dem. Vi kammade alla kluster, hittade noder med tillräckligt hög latens och startade om dem. Detta gav oss tid att uppdatera OS på de återstående servrarna.
Sammanfattningsvis
Eftersom denna bugg stoppade RX NIC-köbearbetningen i hundratals millisekunder, orsakade den samtidigt både hög latens på korta anslutningar och mid-connection latens, som mellan MySQL-förfrågningar och svarspaket.
Att förstå och bibehålla prestandan hos de mest grundläggande systemen, såsom Kubernetes, är avgörande för tillförlitligheten och hastigheten för alla tjänster baserade på dem. Varje system du kör drar nytta av Kubernetes prestandaförbättringar.
Källa: will.com