Vor ein paar Jahren Kubernetes auf dem offiziellen GitHub-Blog. Seitdem ist es zur Standardtechnologie für die Bereitstellung von Diensten geworden. Kubernetes verwaltet mittlerweile einen erheblichen Teil der internen und öffentlichen Dienste. Als unsere Cluster wuchsen und die Leistungsanforderungen strenger wurden, bemerkten wir, dass es bei einigen Diensten auf Kubernetes sporadisch zu Latenzen kam, die nicht durch die Auslastung der Anwendung selbst erklärt werden konnten.
Im Wesentlichen kommt es bei Anwendungen zu zufälligen Netzwerklatenzen von bis zu 100 ms oder mehr, was zu Zeitüberschreitungen oder Wiederholungsversuchen führt. Von den Diensten wurde erwartet, dass sie viel schneller als 100 ms auf Anfragen reagieren können. Dies ist jedoch unmöglich, wenn die Verbindung selbst so viel Zeit in Anspruch nimmt. Unabhängig davon haben wir sehr schnelle MySQL-Abfragen beobachtet, die Millisekunden dauern sollten, und MySQL wurde in Millisekunden abgeschlossen, aber aus Sicht der anfordernden Anwendung dauerte die Antwort 100 ms oder mehr.
Es war sofort klar, dass das Problem nur bei der Verbindung zu einem Kubernetes-Knoten auftrat, auch wenn der Aufruf von außerhalb von Kubernetes kam. Der einfachste Weg, das Problem zu reproduzieren, ist ein Test , das von jedem internen Host aus ausgeführt wird, testet den Kubernetes-Dienst auf einem bestimmten Port und registriert sporadisch hohe Latenzzeiten. In diesem Artikel schauen wir uns an, wie wir der Ursache dieses Problems auf die Spur kommen konnten.
Eliminierung unnötiger Komplexität in der Kette, die zum Scheitern führt
Durch die Reproduktion desselben Beispiels wollten wir den Fokus des Problems eingrenzen und unnötige Komplexitätsebenen entfernen. Anfangs gab es zu viele Elemente im Fluss zwischen Vegeta und den Kubernetes-Pods. Um ein tiefer liegendes Netzwerkproblem zu identifizieren, müssen Sie einige davon ausschließen.
Der Client (Vegeta) stellt eine TCP-Verbindung mit jedem Knoten im Cluster her. Kubernetes fungiert als Overlay-Netzwerk (auf dem vorhandenen Rechenzentrumsnetzwerk), das verwendet , das heißt, es kapselt die IP-Pakete des Overlay-Netzwerks in die IP-Pakete des Rechenzentrums. Beim Herstellen einer Verbindung zum ersten Knoten wird eine Netzwerkadressübersetzung durchgeführt (NAT) zustandsbehaftet, um die IP-Adresse und den Port des Kubernetes-Knotens in die IP-Adresse und den Port im Overlay-Netzwerk (insbesondere dem Pod mit der Anwendung) zu übersetzen. Bei eingehenden Paketen wird die umgekehrte Reihenfolge der Aktionen ausgeführt. Es handelt sich um ein komplexes System mit vielen Zuständen und vielen Elementen, die ständig aktualisiert und geändert werden, wenn Dienste bereitgestellt und verschoben werden.
Dienstprogramm tcpdump Im Vegeta-Test kommt es zu einer Verzögerung beim TCP-Handshake (zwischen SYN und SYN-ACK). Um diese unnötige Komplexität zu beseitigen, können Sie verwenden hping3 für einfache „Pings“ mit SYN-Paketen. Wir prüfen, ob es eine Verzögerung im Antwortpaket gibt, und setzen dann die Verbindung zurück. Wir können die Daten so filtern, dass sie nur Pakete enthalten, die länger als 100 ms sind, und erhalten so eine einfachere Möglichkeit, das Problem zu reproduzieren als Vegetas vollständigen Netzwerk-Layer-7-Test. Hier sind Kubernetes-Knoten-„Pings“ mit TCP SYN/SYN-ACK auf dem „Knoten-Port“ des Dienstes (30927) in 10-ms-Intervallen, gefiltert nach den langsamsten Antworten:
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
Kann sofort die erste Beobachtung machen. Anhand der Sequenznummern und Zeitpunkte ist klar, dass es sich hierbei nicht um einmalige Überlastungen handelt. Die Verzögerung summiert sich häufig und wird schließlich verarbeitet.
Als nächstes wollen wir herausfinden, welche Komponenten an der Entstehung von Staus beteiligt sein können. Vielleicht sind dies einige der Hunderten von iptables-Regeln in NAT? Oder gibt es Probleme mit dem IPIP-Tunneling im Netzwerk? Eine Möglichkeit, dies zu überprüfen, besteht darin, jeden Schritt des Systems zu testen, indem man ihn eliminiert. Was passiert, wenn Sie NAT und Firewall-Logik entfernen und nur den IPIP-Teil übrig lassen:
Glücklicherweise erleichtert Linux den direkten Zugriff auf die IP-Overlay-Schicht, wenn sich die Maschine im selben Netzwerk befindet:
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
Den Ergebnissen nach zu urteilen, besteht das Problem immer noch! Davon ausgenommen sind iptables und NAT. Das Problem ist also TCP? Sehen wir uns an, wie ein normaler ICMP-Ping abläuft:
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
Die Ergebnisse zeigen, dass das Problem nicht verschwunden ist. Vielleicht ist das ein IPIP-Tunnel? Vereinfachen wir den Test noch weiter:
Werden alle Pakete zwischen diesen beiden Hosts gesendet?
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
Wir haben die Situation so vereinfacht, dass zwei Kubernetes-Knoten sich gegenseitig beliebige Pakete senden, sogar einen ICMP-Ping. Sie sehen immer noch Latenz, wenn der Zielhost „schlecht“ ist (einige schlimmer als andere).
Nun die letzte Frage: Warum tritt die Verzögerung nur auf Kube-Node-Servern auf? Und passiert es, wenn kube-node der Sender oder der Empfänger ist? Glücklicherweise lässt sich dies auch ganz einfach herausfinden, indem man ein Paket von einem Host außerhalb von Kubernetes sendet, aber an denselben „bekanntermaßen schlechten“ Empfänger. Wie Sie sehen, ist das Problem nicht verschwunden:
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
Anschließend führen wir dieselben Anforderungen vom vorherigen Quell-Kube-Knoten an den externen Host aus (wobei der Quellhost ausgeschlossen ist, da der Ping sowohl eine RX- als auch eine TX-Komponente enthält):
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
Durch die Untersuchung der Latenz-Paketerfassung haben wir einige zusätzliche Informationen erhalten. Konkret, dass der Absender (unten) diese Zeitüberschreitung sieht, der Empfänger (oben) jedoch nicht – siehe Spalte Delta (in Sekunden):
Wenn man sich außerdem den Unterschied in der Reihenfolge von TCP- und ICMP-Paketen (nach Sequenznummern) auf der Empfängerseite ansieht, kommen ICMP-Pakete immer in der gleichen Reihenfolge an, in der sie gesendet wurden, jedoch mit unterschiedlichem Timing. Gleichzeitig verschachteln sich TCP-Pakete manchmal und einige von ihnen bleiben hängen. Wenn Sie insbesondere die Ports von SYN-Paketen untersuchen, sind diese auf der Seite des Senders in Ordnung, auf der Seite des Empfängers jedoch nicht.
Es gibt einen subtilen Unterschied darin, wie Moderne Server (wie die in unserem Rechenzentrum) verarbeiten Pakete, die TCP oder ICMP enthalten. Wenn ein Paket ankommt, „hasht“ der Netzwerkadapter es pro Verbindung, d. h. er versucht, die Verbindungen in Warteschlangen aufzuteilen und jede Warteschlange an einen separaten Prozessorkern zu senden. Bei TCP umfasst dieser Hash sowohl die Quell- als auch die Ziel-IP-Adresse und den Port. Mit anderen Worten: Jede Verbindung wird (möglicherweise) unterschiedlich gehasht. Bei ICMP werden nur IP-Adressen gehasht, da keine Ports vorhanden sind.
Eine weitere neue Beobachtung: Während dieser Zeit kommt es zu ICMP-Verzögerungen bei der gesamten Kommunikation zwischen zwei Hosts, bei TCP jedoch nicht. Dies zeigt uns, dass die Ursache wahrscheinlich mit dem Hashing der RX-Warteschlange zusammenhängt: Die Überlastung liegt mit ziemlicher Sicherheit in der Verarbeitung von RX-Paketen und nicht im Senden von Antworten.
Dadurch wird das Versenden von Paketen aus der Liste möglicher Ursachen gestrichen. Wir wissen jetzt, dass das Paketverarbeitungsproblem auf einigen Kube-Node-Servern auf der Empfangsseite liegt.
Paketverarbeitung im Linux-Kernel verstehen
Um zu verstehen, warum das Problem beim Empfänger auf einigen Kube-Node-Servern auftritt, schauen wir uns an, wie der Linux-Kernel Pakete verarbeitet.
Zurück zur einfachsten herkömmlichen Implementierung: Die Netzwerkkarte empfängt das Paket und sendet es dem Linux-Kernel, dass es ein Paket gibt, das verarbeitet werden muss. Der Kernel stoppt andere Arbeiten, wechselt den Kontext zum Interrupt-Handler, verarbeitet das Paket und kehrt dann zu den aktuellen Aufgaben zurück.
Dieser Kontextwechsel ist langsam: Auf 10-Mbit/s-Netzwerkkarten in den 90er-Jahren war die Latenz möglicherweise nicht spürbar, aber auf modernen 10G-Karten mit einem maximalen Durchsatz von 15 Millionen Paketen pro Sekunde kann jeder Kern eines kleinen Servers mit acht Kernen millionenfach unterbrochen werden von Malen pro Sekunde.
Um nicht ständig mit Interrupts umgehen zu müssen, wurde Linux vor vielen Jahren hinzugefügt : Netzwerk-API, die alle modernen Treiber verwenden, um die Leistung bei hohen Geschwindigkeiten zu verbessern. Bei niedrigen Geschwindigkeiten empfängt der Kernel immer noch auf die alte Art und Weise Interrupts von der Netzwerkkarte. Sobald genügend Pakete eintreffen, die den Schwellenwert überschreiten, deaktiviert der Kernel Interrupts und beginnt stattdessen, den Netzwerkadapter abzufragen und Pakete in Blöcken aufzunehmen. Die Verarbeitung erfolgt in Softirq, also in nach Systemaufrufen und Hardware-Interrupts, wenn der Kernel (im Gegensatz zum Userspace) bereits läuft.
Das ist viel schneller, verursacht aber ein anderes Problem. Wenn zu viele Pakete vorhanden sind, wird die gesamte Zeit mit der Verarbeitung von Paketen von der Netzwerkkarte verbracht, und Benutzerraumprozesse haben keine Zeit, diese Warteschlangen tatsächlich zu leeren (Lesen von TCP-Verbindungen usw.). Irgendwann füllen sich die Warteschlangen und wir beginnen, Pakete zu verwerfen. Um ein Gleichgewicht zu finden, legt der Kernel ein Budget für die maximale Anzahl von Paketen fest, die im Softirq-Kontext verarbeitet werden. Sobald dieses Budget überschritten wird, wird ein separater Thread aktiviert ksoftirqd (Sie werden einen davon sehen ps pro Kern), der diese Softirqs außerhalb des normalen Systemaufruf-/Interruptpfads verarbeitet. Dieser Thread wird mithilfe des Standardprozessplaners geplant, der versucht, die Ressourcen fair zuzuteilen.
Nachdem Sie untersucht haben, wie der Kernel Pakete verarbeitet, können Sie erkennen, dass eine gewisse Wahrscheinlichkeit einer Überlastung besteht. Wenn Softirq-Aufrufe seltener eingehen, müssen Pakete einige Zeit auf die Verarbeitung in der RX-Warteschlange auf der Netzwerkkarte warten. Dies kann daran liegen, dass eine Aufgabe den Prozessorkern blockiert, oder etwas anderes verhindert, dass der Kern Softirq ausführt.
Eingrenzung der Verarbeitung auf den Kern oder die Methode
Softirq-Verzögerungen sind vorerst nur eine Vermutung. Aber es macht Sinn und wir wissen, dass wir etwas sehr Ähnliches sehen. Der nächste Schritt besteht also darin, diese Theorie zu bestätigen. Und wenn es sich bestätigt, finden Sie den Grund für die Verzögerungen.
Kehren wir zu unseren langsamen Paketen zurück:
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
Wie bereits erwähnt, werden diese ICMP-Pakete in eine einzelne RX-NIC-Warteschlange gehasht und von einem einzelnen CPU-Kern verarbeitet. Wenn wir verstehen wollen, wie Linux funktioniert, ist es hilfreich zu wissen, wo (auf welchem CPU-Kern) und wie (softirq, ksoftirqd) diese Pakete verarbeitet werden, um den Prozess verfolgen zu können.
Jetzt ist es an der Zeit, Tools zu verwenden, mit denen Sie den Linux-Kernel in Echtzeit überwachen können. Hier haben wir verwendet . Mit diesem Werkzeugsatz können Sie kleine C-Programme schreiben, die beliebige Funktionen in den Kernel einbinden und die Ereignisse in einem Python-Programm im Benutzerbereich puffern, das sie verarbeiten und das Ergebnis an Sie zurückgeben kann. Das Einbinden beliebiger Funktionen in den Kernel ist eine komplexe Angelegenheit, aber das Dienstprogramm ist auf maximale Sicherheit ausgelegt und darauf ausgelegt, genau die Art von Produktionsproblemen aufzuspüren, die sich in einer Test- oder Entwicklungsumgebung nicht einfach reproduzieren lassen.
Der Plan hier ist einfach: Wir wissen, dass der Kernel diese ICMP-Pings verarbeitet, also setzen wir einen Haken in die Kernel-Funktion , das ein eingehendes ICMP-Echo-Anfragepaket akzeptiert und das Senden einer ICMP-Echo-Antwort initiiert. Wir können ein Paket identifizieren, indem wir die icmp_seq-Nummer erhöhen, was angezeigt wird hping3 oben.
Code sieht kompliziert aus, ist aber nicht so beängstigend, wie es scheint. Funktion icmp_echo überträgt struct sk_buff *skb: Dies ist ein Paket mit einer „Echo-Anfrage“. Wir können es verfolgen und die Sequenz ermitteln echo.sequence (was im Vergleich zu icmp_seq von hping3 выше) und senden Sie es an den Benutzerbereich. Es ist auch praktisch, den aktuellen Prozessnamen/die aktuelle Prozess-ID zu erfassen. Unten sind die Ergebnisse, die wir direkt sehen, während der Kernel Pakete verarbeitet:
TGID PID PROZESSNAME 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 Tauscher/11 777 0 0 11 swapper/778 4512 4542 779 spokes-report-s XNUMX
Das ist hier im Kontext zu beachten softirq Prozesse, die Systemaufrufe getätigt haben, werden als „Prozesse“ angezeigt, obwohl es tatsächlich der Kernel ist, der Pakete im Kontext des Kernels sicher verarbeitet.
Mit diesem Tool können wir bestimmte Prozesse mit bestimmten Paketen verknüpfen, die eine Verzögerung von aufweisen hping3. Machen wir es einfach grep auf dieser Erfassung für bestimmte Werte icmp_seq. Pakete, die mit den oben genannten icmp_seq-Werten übereinstimmen, wurden zusammen mit ihrer oben beobachteten RTT notiert (in Klammern sind die erwarteten RTT-Werte für Pakete angegeben, die wir aufgrund von RTT-Werten von weniger als 50 ms herausgefiltert haben):
TGID PID PROZESSNAME ICMP_SEQ ** RTT -- 10137 10436 cadvisor 1951 10137 10436 cadvisor 1952 76 76 ksoftirqd/11 1953 ** 99 ms 76 76 ksoftirqd/11 1954 ** 89 ms 76 76 ksoftir 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 76 ksoftirqd/11 1960 ** (29 ms) 76 76 11 ksoft irqd/ 1961 19 ** (76 ms) 76 11 ksoftirqd/1962 9 ** (10137 ms) -- 10436 2068 cadvisor 10137 10436 2069 cadvisor 76 76 11 ksoftirqd/2070 75 ** 76 ms 76 11 ksoftirq d/2071 65 ** 76 ms 76 11 ksoftirqd/ 2072 55 ** 76 ms 76 11 ksoftirqd/2073 45 ** (76 ms) 76 11 ksoftirqd/2074 35 ** (76 ms) 76 11 ksoftirqd/2075 25 ** (76 ms) 76 11 ksoftirqd/2076 15 ** (76 m s ) 76 11 ksoftirqd/2077 5 ** (XNUMXms)
Die Ergebnisse sagen uns mehrere Dinge. Zunächst werden alle diese Pakete vom Kontext verarbeitet ksoftirqd/11. Das bedeutet, dass für dieses bestimmte Maschinenpaar ICMP-Pakete an den Kern 11 auf der Empfängerseite gehasht wurden. Wir sehen auch, dass es immer dann, wenn es zu einem Stau kommt, Pakete gibt, die im Kontext des Systemaufrufs verarbeitet werden cadvisor. Dann, ksoftirqd übernimmt die Aufgabe und verarbeitet die angesammelte Warteschlange: genau die Anzahl an Paketen, die sich danach angesammelt hat cadvisor.
Die Tatsache, dass unmittelbar davor immer funktioniert cadvisor, impliziert seine Beteiligung an dem Problem. Ironischerweise der Zweck - „Ressourcennutzung und Leistungsmerkmale laufender Container analysieren“, anstatt dieses Leistungsproblem zu verursachen.
Wie bei anderen Aspekten von Containern handelt es sich hierbei allesamt um hochentwickelte Tools, bei denen unter unvorhergesehenen Umständen mit Leistungsproblemen zu rechnen ist.
Was macht Cadvisor, um die Paketwarteschlange zu verlangsamen?
Wir haben jetzt ein ziemlich gutes Verständnis dafür, wie der Absturz auftritt, welcher Prozess ihn verursacht und auf welcher CPU. Wir sehen, dass der Linux-Kernel aufgrund der harten Blockierung keine Zeit zum Planen hat ksoftirqd. Und wir sehen, dass Pakete im Kontext verarbeitet werden cadvisor. Es ist logisch, das anzunehmen cadvisor startet einen langsamen Systemaufruf, nach dem alle zu diesem Zeitpunkt gesammelten Pakete verarbeitet werden:
Das ist eine Theorie, aber wie kann man sie testen? Was wir tun können, ist, den CPU-Kern während dieses Prozesses zu verfolgen, den Punkt zu finden, an dem die Anzahl der Pakete das Budget überschreitet und ksoftirqd aufgerufen wird, und dann etwas weiter zurück zu schauen, um zu sehen, was genau kurz vor diesem Punkt auf dem CPU-Kern lief . Es ist, als würde man die CPU alle paar Millisekunden röntgen. Es wird ungefähr so aussehen:
Praktischerweise kann dies alles mit vorhandenen Tools durchgeführt werden. Zum Beispiel, überprüft einen bestimmten CPU-Kern mit einer bestimmten Häufigkeit und kann einen Zeitplan für Aufrufe an das laufende System erstellen, einschließlich Benutzerbereich und Linux-Kernel. Sie können diesen Datensatz nehmen und ihn mit einem kleinen Zweig des Programms verarbeiten von Brendan Gregg, der die Reihenfolge des Stack-Trace beibehält. Wir können einzeilige Stack-Traces alle 1 ms speichern und dann 100 Millisekunden vor dem Eintreffen des Trace ein Beispiel hervorheben und speichern 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 sind die Ergebnisse:
(сотни следов, которые выглядят похожими)
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
Hier gibt es eine Menge Dinge, aber die Hauptsache ist, dass wir das Muster „cadvisor before ksoftirqd“ finden, das wir zuvor im ICMP-Tracer gesehen haben. Was bedeutet das?
Jede Zeile ist ein CPU-Trace zu einem bestimmten Zeitpunkt. Jeder Aufruf einer Zeile im Stapel wird durch ein Semikolon getrennt. In der Mitte der Zeilen sehen wir, wie der Systemaufruf aufgerufen wird: read(): .... ;do_syscall_64;sys_read; .... Daher verbringt Cadvisor viel Zeit mit dem Systemaufruf read()im Zusammenhang mit Funktionen mem_cgroup_* (oben im Aufrufstapel/Ende der Zeile).
Es ist unpraktisch, in einer Anrufverfolgung zu sehen, was genau gelesen wird, also lassen Sie uns ausführen strace Und schauen wir uns an, was Cadvisor macht und wie wir Systemaufrufe finden, die länger als 100 ms sind:
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>
Wie zu erwarten ist, sehen wir hier langsame Anrufe read(). Aus dem Inhalt von Lesevorgängen und Kontext mem_cgroup Es ist klar, dass diese Herausforderungen read() siehe Datei memory.stat, das die Speichernutzung und Cgroup-Grenzwerte anzeigt (Dockers Ressourcenisolationstechnologie). Das Cadvisor-Tool fragt diese Datei ab, um Informationen zur Ressourcennutzung für Container zu erhalten. Lassen Sie uns prüfen, ob der Kernel oder Cadvisor etwas Unerwartetes tut:
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 ~ $
Jetzt können wir den Fehler reproduzieren und verstehen, dass der Linux-Kernel mit einer Pathologie konfrontiert ist.
Warum ist der Lesevorgang so langsam?
In dieser Phase ist es viel einfacher, Nachrichten anderer Benutzer zu ähnlichen Problemen zu finden. Wie sich herausstellte, wurde dieser Fehler im Cadvisor-Tracker als gemeldet Es ist nur niemandem aufgefallen, dass sich die Latenz auch zufällig im Netzwerkstapel widerspiegelt. Es wurde zwar festgestellt, dass Cadvisor mehr CPU-Zeit verbrauchte als erwartet, aber dem wurde keine große Bedeutung beigemessen, da unsere Server über viele CPU-Ressourcen verfügen und das Problem daher nicht sorgfältig untersucht wurde.
Das Problem besteht darin, dass Kontrollgruppen die Speichernutzung innerhalb des Namespace (Containers) berücksichtigen. Wenn alle Prozesse in dieser Kontrollgruppe beendet werden, gibt Docker die Speicherkontrollgruppe frei. Allerdings ist „Speicher“ nicht nur Prozessspeicher. Obwohl der Prozessspeicher selbst nicht mehr verwendet wird, scheint es, dass der Kernel weiterhin zwischengespeicherte Inhalte wie Dentries und Inodes (Verzeichnis- und Dateimetadaten) zuweist, die in der Speicher-Cgroup zwischengespeichert werden. Aus der Problembeschreibung:
Zombie-Cgroups: Cgroups, die keine Prozesse haben und gelöscht wurden, denen aber immer noch Speicher zugewiesen ist (in meinem Fall aus dem Dentry-Cache, aber er kann auch aus dem Seiten-Cache oder tmpfs zugewiesen werden).
Die Überprüfung aller Seiten im Cache durch den Kernel beim Freigeben einer Kontrollgruppe kann sehr langsam sein, daher wird der Lazy-Prozess gewählt: Warten Sie, bis diese Seiten erneut angefordert werden, und löschen Sie dann schließlich die Kontrollgruppe, wenn der Speicher tatsächlich benötigt wird. Bis zu diesem Zeitpunkt wird cgroup bei der Statistikerhebung noch berücksichtigt.
Unter Leistungsgesichtspunkten haben sie Speicher zugunsten der Leistung geopfert: Sie haben die anfängliche Bereinigung beschleunigt, indem sie etwas zwischengespeicherten Speicher zurückgelassen haben. Es ist in Ordnung. Wenn der Kernel den letzten Teil des zwischengespeicherten Speichers nutzt, wird die cgroup schließlich gelöscht, sodass es nicht von einem „Leck“ gesprochen werden kann. Leider ist die spezifische Implementierung des Suchmechanismus memory.stat In dieser Kernel-Version (4.9) dauert es in Kombination mit der riesigen Speichermenge auf unseren Servern viel länger, die neuesten zwischengespeicherten Daten wiederherzustellen und Cgroup-Zombies zu löschen.
Es stellte sich heraus, dass einige unserer Knoten so viele Cgroup-Zombies hatten, dass die Lese- und Latenzzeit eine Sekunde überschritt.
Die Problemumgehung für das Cadvisor-Problem besteht darin, Dentries/Inodes-Caches im gesamten System sofort freizugeben, wodurch die Leselatenz sowie die Netzwerklatenz auf dem Host sofort beseitigt werden, da durch das Leeren des Caches die zwischengespeicherten Zombie-Cgroup-Seiten aktiviert und auch freigegeben werden. Dies ist keine Lösung, bestätigt aber die Ursache des Problems.
Es stellte sich heraus, dass in neueren Kernel-Versionen (4.19+) die Aufrufleistung verbessert wurde memory.stat, daher wurde das Problem durch den Wechsel zu diesem Kernel behoben. Gleichzeitig verfügten wir über Tools, um problematische Knoten in Kubernetes-Clustern zu erkennen, sie ordnungsgemäß zu entleeren und neu zu starten. Wir haben alle Cluster durchkämmt, Knoten mit ausreichend hoher Latenz gefunden und sie neu gestartet. Dies gab uns Zeit, das Betriebssystem auf den verbleibenden Servern zu aktualisieren.
Zusammenfassend
Da dieser Fehler die Verarbeitung der RX-NIC-Warteschlange für Hunderte von Millisekunden stoppte, verursachte er gleichzeitig eine hohe Latenz bei kurzen Verbindungen und eine Latenz in der Mitte der Verbindung, beispielsweise zwischen MySQL-Anfragen und Antwortpaketen.
Das Verständnis und die Aufrechterhaltung der Leistung der grundlegendsten Systeme wie Kubernetes ist entscheidend für die Zuverlässigkeit und Geschwindigkeit aller darauf basierenden Dienste. Jedes von Ihnen ausgeführte System profitiert von den Leistungsverbesserungen von Kubernetes.
Source: habr.com