Een paar jaar geleden Kubernetes op de officiële GitHub-blog. Sindsdien is het de standaardtechnologie geworden voor het inzetten van diensten. Kubernetes beheert nu een aanzienlijk deel van de interne en publieke diensten. Naarmate onze clusters groeiden en de prestatie-eisen strenger werden, merkten we dat sommige services op Kubernetes sporadisch last hadden van latentie die niet kon worden verklaard door de belasting van de applicatie zelf.
In wezen ervaren applicaties een schijnbaar willekeurige netwerklatentie van maximaal 100 ms of meer, wat resulteert in time-outs of nieuwe pogingen. Van services werd verwacht dat ze veel sneller dan 100 ms op verzoeken konden reageren. Maar dit is onmogelijk als de verbinding zelf zoveel tijd kost. Daarnaast hebben we zeer snelle MySQL-query's waargenomen die milliseconden hadden moeten duren, en MySQL werd in milliseconden voltooid, maar vanuit het perspectief van de aanvragende applicatie duurde het antwoord 100 ms of meer.
Het werd meteen duidelijk dat het probleem alleen optrad bij het verbinden met een Kubernetes-node, zelfs als de oproep van buiten Kubernetes kwam. De eenvoudigste manier om het probleem te reproduceren is door middel van een test , dat vanaf elke interne host draait, de Kubernetes-service op een specifieke poort test en sporadisch een hoge latentie registreert. In dit artikel bekijken we hoe we de oorzaak van dit probleem hebben kunnen achterhalen.
Het elimineren van onnodige complexiteit in de keten die tot falen leidt
Door hetzelfde voorbeeld te reproduceren, wilden we de focus van het probleem verkleinen en onnodige lagen van complexiteit verwijderen. Aanvankelijk waren er te veel elementen in de stroom tussen Vegeta en de Kubernetes-pods. Om een dieper liggend netwerkprobleem te identificeren, moet u enkele daarvan uitsluiten.
De client (Vegeta) maakt een TCP-verbinding met elk knooppunt in het cluster. Kubernetes functioneert als een overlay-netwerk (bovenop het bestaande datacenternetwerk) dat gebruik maakt van , dat wil zeggen dat het de IP-pakketten van het overlay-netwerk inkapselt in de IP-pakketten van het datacenter. Bij verbinding met het eerste knooppunt wordt netwerkadresvertaling uitgevoerd (NAT) stateful om het IP-adres en de poort van het Kubernetes-knooppunt te vertalen naar het IP-adres en de poort in het overlay-netwerk (met name de pod met de applicatie). Voor binnenkomende pakketten wordt de omgekeerde volgorde van acties uitgevoerd. Het is een complex systeem met veel status en veel elementen die voortdurend worden bijgewerkt en gewijzigd naarmate services worden ingezet en verplaatst.
Nut tcpdump in de Vegeta-test is er een vertraging tijdens de TCP-handshake (tussen SYN en SYN-ACK). Om deze onnodige complexiteit te verwijderen, kunt u gebruiken hping3 voor eenvoudige “pings” met SYN-pakketten. We controleren of er vertraging is in het antwoordpakket en resetten vervolgens de verbinding. We kunnen de gegevens filteren om alleen pakketten op te nemen die groter zijn dan 100 ms en zo een gemakkelijkere manier krijgen om het probleem te reproduceren dan de volledige netwerklaag 7-test in Vegeta. Hier zijn de "pings" van het Kubernetes-knooppunt met behulp van TCP SYN/SYN-ACK op de service "node port" (30927) met intervallen van 10 ms, gefilterd op de langzaamste reacties:
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 meteen de eerste observatie maken. Afgaande op de volgnummers en tijdstippen is het duidelijk dat dit geen eenmalige opstoppingen zijn. De vertraging stapelt zich vaak op en wordt uiteindelijk verwerkt.
Vervolgens willen we achterhalen welke componenten mogelijk betrokken zijn bij het ontstaan van congestie. Misschien zijn dit enkele van de honderden iptables-regels in NAT? Of zijn er problemen met IPIP-tunneling op het netwerk? Eén manier om dit te testen is door elke stap van het systeem te testen door deze te elimineren. Wat gebeurt er als u NAT- en firewalllogica verwijdert en alleen het IPIP-gedeelte overblijft:
Gelukkig maakt Linux het gemakkelijk om rechtstreeks toegang te krijgen tot de IP-overlaylaag als de machine zich op hetzelfde netwerk bevindt:
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
Afgaande op de resultaten blijft het probleem nog steeds bestaan! Dit is exclusief iptables en NAT. Dus het probleem is TCP? Laten we eens kijken hoe een normale ICMP-ping verloopt:
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
Uit de resultaten blijkt dat het probleem niet is verdwenen. Misschien is dit een IPIP-tunnel? Laten we de test verder vereenvoudigen:
Worden alle pakketten tussen deze twee hosts verzonden?
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
We hebben de situatie vereenvoudigd tot twee Kubernetes-knooppunten die elkaar elk pakket sturen, zelfs een ICMP-ping. Ze zien nog steeds latentie als de doelhost "slecht" is (sommige slechter dan andere).
Nu de laatste vraag: waarom treedt de vertraging alleen op op kube-node-servers? En gebeurt het wanneer kube-node de afzender of de ontvanger is? Gelukkig is dit ook vrij eenvoudig te achterhalen door een pakket te verzenden vanaf een host buiten Kubernetes, maar met dezelfde “bekende slechte” ontvanger. Zoals u kunt zien, is het probleem niet verdwenen:
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
Vervolgens voeren we dezelfde verzoeken uit van het vorige bronkube-knooppunt naar de externe host (waarbij de bronhost wordt uitgesloten omdat de ping zowel een RX- als een TX-component bevat):
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
Door de latentiepakketopnamen te onderzoeken, hebben we wat aanvullende informatie verkregen. In het bijzonder dat de afzender (onder) deze time-out ziet, maar de ontvanger (boven) niet - zie de Delta-kolom (in seconden):
Als je bovendien kijkt naar het verschil in de volgorde van TCP- en ICMP-pakketten (volgens volgnummers) aan de ontvangerskant, komen ICMP-pakketten altijd aan in dezelfde volgorde waarin ze zijn verzonden, maar met een verschillende timing. Tegelijkertijd interleaven TCP-pakketten soms, waardoor sommige vastlopen. Als je vooral de poorten van SYN-pakketten onderzoekt, zijn ze aan de kant van de afzender in orde, maar niet aan de kant van de ontvanger.
Er is een subtiel verschil in hoe moderne servers (zoals die in ons datacenter) verwerken pakketten die TCP of ICMP bevatten. Wanneer een pakket arriveert, "hasht de netwerkadapter het per verbinding", dat wil zeggen dat hij probeert de verbindingen in wachtrijen op te splitsen en elke wachtrij naar een afzonderlijke processorkern te sturen. Voor TCP omvat deze hash zowel het bron- als het bestemmings-IP-adres en de poort. Met andere woorden, elke verbinding wordt (potentieel) anders gehasht. Voor ICMP worden alleen IP-adressen gehasht, omdat er geen poorten zijn.
Nog een nieuwe observatie: gedurende deze periode zien we ICMP-vertragingen op alle communicatie tussen twee hosts, maar TCP niet. Dit vertelt ons dat de oorzaak waarschijnlijk verband houdt met het hashen van de RX-wachtrij: de congestie zit vrijwel zeker in de verwerking van RX-pakketten, niet in het verzenden van antwoorden.
Dit elimineert het verzenden van pakketten uit de lijst met mogelijke oorzaken. We weten nu dat het pakketverwerkingsprobleem zich op sommige kube-node-servers aan de ontvangstzijde bevindt.
Pakketverwerking in de Linux-kernel begrijpen
Om te begrijpen waarom het probleem zich voordoet bij de ontvanger op sommige kube-node-servers, gaan we kijken hoe de Linux-kernel pakketten verwerkt.
Terugkerend naar de eenvoudigste traditionele implementatie: de netwerkkaart ontvangt het pakket en verzendt het de Linux-kernel dat er een pakket is dat moet worden verwerkt. De kernel stopt ander werk, schakelt de context over naar de interrupthandler, verwerkt het pakket en keert vervolgens terug naar de huidige taken.
Deze contextwisseling is traag: de latentie was in de jaren '10 misschien niet merkbaar op 90Mbps-netwerkkaarten, maar op moderne 10G-kaarten met een maximale doorvoer van 15 miljoen pakketten per seconde kan elke kern van een kleine acht-core server miljoenen worden onderbroken. keer per seconde.
Om niet voortdurend met interrupts om te gaan, heeft Linux daar vele jaren geleden aan toegevoegd : Netwerk-API die alle moderne stuurprogramma's gebruiken om de prestaties bij hoge snelheden te verbeteren. Bij lage snelheden ontvangt de kernel nog steeds op de oude manier interrupts van de netwerkkaart. Zodra er voldoende pakketten arriveren die de drempel overschrijden, schakelt de kernel interrupts uit en begint in plaats daarvan de netwerkadapter te pollen en pakketten in stukjes op te pikken. De verwerking wordt uitgevoerd in softirq, dat wil zeggen in na systeemaanroepen en hardware-onderbrekingen, wanneer de kernel (in tegenstelling tot de gebruikersruimte) al actief is.
Dit is veel sneller, maar veroorzaakt een ander probleem. Als er te veel pakketten zijn, wordt de hele tijd besteed aan het verwerken van pakketten van de netwerkkaart, en hebben gebruikersruimteprocessen geen tijd om deze wachtrijen daadwerkelijk leeg te maken (lezen van TCP-verbindingen, enz.). Uiteindelijk raken de wachtrijen vol en beginnen we pakketten te droppen. In een poging een evenwicht te vinden stelt de kernel een budget in voor het maximale aantal pakketten dat in de softirq-context wordt verwerkt. Zodra dit budget wordt overschreden, ontstaat er een aparte draad ksoftirqd (je ziet er eentje binnen ps per core) die deze softirqs buiten het normale syscall/interrupt-pad afhandelt. Deze thread wordt gepland met behulp van de standaard procesplanner, die probeert bronnen eerlijk toe te wijzen.
Nadat je hebt bestudeerd hoe de kernel pakketten verwerkt, kun je zien dat er een zekere kans op congestie bestaat. Als softirq-oproepen minder vaak worden ontvangen, zullen pakketten enige tijd moeten wachten voordat ze worden verwerkt in de RX-wachtrij op de netwerkkaart. Dit kan te wijten zijn aan het feit dat een taak de processorkern blokkeert, of dat iets anders verhindert dat de kern softirq uitvoert.
Het beperken van de verwerking tot de kern of werkwijze
Vertragingen bij Softirq zijn voorlopig slechts een gok. Maar het is logisch en we weten dat we iets soortgelijks zien. De volgende stap is dus het bevestigen van deze theorie. En als het wordt bevestigd, zoek dan de reden voor de vertragingen.
Laten we terugkeren naar onze langzame pakketten:
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
Zoals eerder besproken worden deze ICMP-pakketten gehasht in een enkele RX NIC-wachtrij en verwerkt door een enkele CPU-kern. Als we willen begrijpen hoe Linux werkt, is het handig om te weten waar (op welke CPU-kern) en hoe (softirq, ksoftirqd) deze pakketten worden verwerkt om het proces te kunnen volgen.
Nu is het tijd om tools te gebruiken waarmee je de Linux-kernel in realtime kunt monitoren. Hier gebruikten we . Met deze set tools kun je kleine C-programma's schrijven die willekeurige functies in de kernel koppelen en de gebeurtenissen bufferen in een Python-programma in de gebruikersruimte dat ze kan verwerken en het resultaat aan je kan retourneren. Het aansluiten van willekeurige functies in de kernel is een lastige zaak, maar het hulpprogramma is ontworpen voor maximale veiligheid en is ontworpen om precies het soort productieproblemen op te sporen die niet gemakkelijk kunnen worden gereproduceerd in een test- of ontwikkelomgeving.
Het plan hier is eenvoudig: we weten dat de kernel deze ICMP-pings verwerkt, dus we zullen een hook aan de kernelfunctie plaatsen , dat een binnenkomend ICMP-echoverzoekpakket accepteert en het verzenden van een ICMP-echoantwoord initieert. We kunnen een pakket identificeren door het icmp_seq-nummer te verhogen, wat wordt weergegeven hping3 hoger.
code ziet er ingewikkeld uit, maar het is niet zo eng als het lijkt. Functie icmp_echo ередаёт struct sk_buff *skb: Dit is een pakket met een "echoverzoek". We kunnen het volgen en de reeks eruit halen echo.sequence (wat te vergelijken is met icmp_seq door hping3 выше), en stuur het naar de gebruikersruimte. Het is ook handig om de huidige procesnaam/-ID vast te leggen. Hieronder staan de resultaten die we direct zien terwijl de kernel pakketten verwerkt:
TGID PID PROCESNAAM ICMP_SEQ 0 0 wisselaar/11 770 0 wisselaar/0 11 771 wisselaar/0 0 11 wisselaar/772 0 0 wisselaar/11 773 0 prometheus 0 11 774 wisselaar/20041 20086 775 wisselaar/0 0 11 wisselaar/776 0 0 spaakrapport-s 11
Hierbij moet worden opgemerkt dat in de context softirq processen die systeemaanroepen hebben gedaan, zullen verschijnen als "processen", terwijl het in feite de kernel is die pakketten veilig verwerkt in de context van de kernel.
Met deze tool kunnen we specifieke processen koppelen aan specifieke pakketten die een vertraging vertonen van hping3. Laten we het eenvoudig maken grep op deze opname voor bepaalde waarden icmp_seq. Pakketten die overeenkomen met de bovenstaande icmp_seq-waarden werden gemarkeerd samen met hun RTT die we hierboven hebben waargenomen (tussen haakjes staan de verwachte RTT-waarden voor pakketten die we hebben uitgefilterd vanwege RTT-waarden van minder dan 50 ms):
TGID PID PROCESNAAM ICMP_SEQ ** RTT -- 10137 10436 kadaver 1951 10137 10436 kadaver 1952 76 76 ksoftirqd/11 1953 ** 99 ms 76 76 ksoftirqd/11 1954 ** 89 ms 76 76 ksoftirqd/11 1955 ** 79 ms 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 ** (39ms) 76 76 ksoftirqd/11 1960 ** (29 ms) 76 76 ksoftirqd/11 1961 ** (19 ms) 76 76 ksoftirqd/11 1962 ** (9ms) -- 10137 10436 kadaver 2068 10137 10436 kadaver 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)
De resultaten vertellen ons verschillende dingen. Ten eerste worden al deze pakketten verwerkt door de context ksoftirqd/11. Dit betekent dat voor dit specifieke paar machines ICMP-pakketten werden gehasht naar kern 11 aan de ontvangende kant. We zien ook dat wanneer er een storing is, er pakketten zijn die worden verwerkt in de context van de systeemaanroep cadvisor. Dan ksoftirqd neemt de taak over en verwerkt de verzamelde wachtrij: precies het aantal pakketten dat zich daarna heeft verzameld cadvisor.
Het feit dat het onmiddellijk ervoor altijd werkt cadvisor, impliceert zijn betrokkenheid bij het probleem. Ironisch genoeg het doel - "analyseer het gebruik van bronnen en prestatiekenmerken van actieve containers" in plaats van dit prestatieprobleem te veroorzaken.
Net als bij andere aspecten van containers zijn dit allemaal zeer geavanceerde tools en kunnen er onder bepaalde onvoorziene omstandigheden prestatieproblemen optreden.
Wat doet Cadvisor dat de pakketwachtrij vertraagt?
We hebben nu een redelijk goed inzicht in hoe de crash plaatsvindt, welk proces deze veroorzaakt en op welke CPU. We zien dat de Linux-kernel door harde blokkering geen tijd heeft om te plannen ksoftirqd. En we zien dat pakketten in context worden verwerkt cadvisor. Het is logisch om dat aan te nemen cadvisor lanceert een langzame syscall, waarna alle op dat moment verzamelde pakketten worden verwerkt:
Dit is een theorie, maar hoe test je die? Wat we kunnen doen is de CPU-kern gedurende dit proces traceren, het punt vinden waarop het aantal pakketten het budget overschrijdt en ksoftirqd wordt aangeroepen, en dan iets verder terugkijken om te zien wat er vlak voor dat punt precies op de CPU-kern draaide. . Het is alsof je elke paar milliseconden een röntgenfoto van de CPU maakt. Het zal er ongeveer zo uitzien:
Handig genoeg kan dit allemaal worden gedaan met bestaande tools. Bijvoorbeeld, controleert een gegeven CPU-kern op een gespecificeerde frequentie en kan een schema van oproepen naar het draaiende systeem genereren, inclusief zowel gebruikersruimte als de Linux-kernel. U kunt deze record nemen en verwerken met behulp van een kleine vork van het programma van Brendan Gregg, die de volgorde van de stapeltracering behoudt. We kunnen elke 1 ms stacktraces van één regel opslaan en vervolgens een sample markeren en opslaan 100 milliseconden voordat de trace arriveert 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
Hier zijn de 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
Er zijn hier veel dingen, maar het belangrijkste is dat we het patroon “cadvisor before ksoftirqd” vinden dat we eerder in de ICMP-tracer zagen. Wat betekent het?
Elke regel is een CPU-trace op een specifiek tijdstip. Elke oproep op de stapel op een lijn wordt gescheiden door een puntkomma. In het midden van de regels zien we dat de syscall wordt aangeroepen: read(): .... ;do_syscall_64;sys_read; .... Cadvisor besteedt dus veel tijd aan de systeemoproep read()gerelateerd aan functies mem_cgroup_* (bovenaan de call-stack/einde van de regel).
Het is lastig om in een oproeptracering te zien wat er precies wordt gelezen, dus laten we rennen strace en laten we eens kijken wat cadvisor doet en systeemoproepen vinden die langer duren dan 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>
Zoals je zou verwachten, zien we hier trage oproepen read(). Van de inhoud van leesbewerkingen en context mem_cgroup het is duidelijk dat deze uitdagingen read() raadpleeg het bestand memory.stat, die het geheugengebruik en de cgroup-limieten toont (de resource-isolatietechnologie van Docker). De Cadvisor-tool vraagt dit bestand op om informatie over het resourcegebruik voor containers te verkrijgen. Laten we eens kijken of het de kernel of cadvisor is die iets onverwachts doet:
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 kunnen we de bug reproduceren en begrijpen dat de Linux-kernel met een pathologie wordt geconfronteerd.
Waarom is de leesbewerking zo traag?
In dit stadium is het veel gemakkelijker om berichten van andere gebruikers over soortgelijke problemen te vinden. Het bleek dat deze bug in de cadvisor-tracker werd gerapporteerd als , het is alleen zo dat niemand heeft gemerkt dat de latentie ook willekeurig wordt weerspiegeld in de netwerkstack. Het viel ons inderdaad op dat Cadvisor meer CPU-tijd in beslag nam dan verwacht, maar hieraan werd niet veel belang gehecht, aangezien onze servers over veel CPU-bronnen beschikken, dus het probleem werd niet zorgvuldig bestudeerd.
Het probleem is dat cgroups rekening houden met geheugengebruik binnen de naamruimte (container). Wanneer alle processen in deze cgroup afsluiten, geeft Docker de geheugen-cgroup vrij. 'Geheugen' is echter niet alleen maar procesgeheugen. Hoewel het procesgeheugen zelf niet langer wordt gebruikt, lijkt het erop dat de kernel nog steeds inhoud in de cache toewijst, zoals dentries en inodes (metagegevens van mappen en bestanden), die in de cache in de geheugen-cgroup zijn opgeslagen. Uit de probleembeschrijving:
zombie cgroups: cgroups die geen processen hebben en zijn verwijderd, maar waaraan nog steeds geheugen is toegewezen (in mijn geval vanuit de dentry cache, maar het kan ook worden toegewezen vanuit de paginacache of tmpfs).
De controle door de kernel van alle pagina's in de cache bij het vrijmaken van een cgroup kan erg traag zijn, dus wordt gekozen voor het luie proces: wachten tot deze pagina's opnieuw worden opgevraagd, en dan uiteindelijk de cgroup leegmaken wanneer het geheugen daadwerkelijk nodig is. Tot nu toe wordt er nog steeds rekening gehouden met cgroup bij het verzamelen van statistieken.
Vanuit prestatieoogpunt hebben ze geheugen opgeofferd voor prestaties: het versnellen van de initiële opschoning door wat cachegeheugen achter te laten. Dit is goed. Wanneer de kernel het laatste geheugen in de cache gebruikt, wordt de cgroup uiteindelijk gewist, zodat er geen sprake kan zijn van een "lek". Helaas is de specifieke implementatie van het zoekmechanisme memory.stat in deze kernelversie (4.9), gecombineerd met de enorme hoeveelheid geheugen op onze servers, betekent dat het veel langer duurt om de nieuwste gegevens in de cache te herstellen en cgroup-zombies te wissen.
Het blijkt dat sommige van onze knooppunten zoveel cgroup-zombies hadden dat de lees- en latentie meer dan een seconde bedroegen.
De oplossing voor het cadvisor-probleem is om dentries/inodes-caches onmiddellijk door het hele systeem vrij te maken, waardoor zowel de leeslatentie als de netwerklatentie op de host onmiddellijk worden geëlimineerd, aangezien het wissen van de cache de in de cache opgeslagen cgroup-zombiepagina's inschakelt en deze ook vrijmaakt. Dit is geen oplossing, maar bevestigt de oorzaak van het probleem.
Het bleek dat in nieuwere kernelversies (4.19+) de aanroepprestaties verbeterd waren memory.stat, dus het overschakelen naar deze kernel loste het probleem op. Tegelijkertijd beschikten we over tools om problematische knooppunten in Kubernetes-clusters te detecteren, deze op een elegante manier leeg te maken en opnieuw op te starten. We hebben alle clusters uitgekamd, knooppunten gevonden met voldoende latentie en deze opnieuw opgestart. Dit gaf ons de tijd om het besturingssysteem op de resterende servers bij te werken.
Samengevat
Omdat deze bug de verwerking van de RX NIC-wachtrij gedurende honderden milliseconden stopte, veroorzaakte dit tegelijkertijd zowel een hoge latentie bij korte verbindingen als een latentie in het midden van de verbinding, zoals tussen MySQL-verzoeken en antwoordpakketten.
Het begrijpen en onderhouden van de prestaties van de meest fundamentele systemen, zoals Kubernetes, is van cruciaal belang voor de betrouwbaarheid en snelheid van alle daarop gebaseerde services. Elk systeem dat u gebruikt, profiteert van prestatieverbeteringen van Kubernetes.
Bron: www.habr.com