Vor ein paar Jahren wurde Kubernetes im offiziellen Blog von GitHub. Seitdem ist es zur Standardtechnologie für die Bereitstellung von Diensten geworden. Jetzt verwaltet Kubernetes einen wesentlichen Teil der internen und öffentlichen Dienste. Da unsere Cluster gewachsen sind und die Leistungsanforderungen strenger geworden sind, haben wir bemerkt, dass in einigen Diensten auf Kubernetes sporadisch Verzögerungen auftreten, die nicht durch die Last der Anwendung erklärt werden können.
Im Grunde genommen treten in den Anwendungen zufällige Netzwerkverzögerungen von bis zu 100 ms oder mehr auf, was zu Zeitüberschreitungen oder Wiederholungsversuchen führt. Es wurde erwartet, dass die Dienste viel schneller als 100 ms auf Anfragen reagieren können. Aber das ist unmöglich, wenn die Verbindung selbst so viel Zeit in Anspruch nimmt. Separat haben wir sehr schnelle MySQL-Anfragen beobachtet, die Millisekunden in Anspruch nehmen sollten, und MySQL hat auch tatsächlich in Millisekunden reagiert, aber aus der Sicht der anfragenden Anwendung dauerte die Antwort 100 ms oder länger.
Es wurde sofort klar, dass das Problem nur bei der Verbindung zu einem Kubernetes-Knoten auftritt, selbst wenn der Aufruf von außerhalb von Kubernetes kam. Am einfachsten lässt sich das Problem im Test , der von jedem internen Host aus gestartet wird, reproduzieren. Er testet den Kubernetes-Dienst an einem bestimmten Port und registriert sporadisch eine hohe Verzögerung. In diesem Artikel werden wir erörtern, wie es uns gelungen ist, die Ursache dieses Problems zu verfolgen.
Wir beseitigen überflüssige Komplexität in der Fehlersuche
Indem wir dasselbe Beispiel reproduzierten, wollten wir den Fokus auf das Problem eingrenzen und überflüssige Komplexitätsschichten entfernen. Zunächst gab es zu viele Elemente im Datenstrom zwischen Vegeta und den Pods auf Kubernetes. Um ein tieferes Netzwerkproblem zu identifizieren, müssen wir einige davon ausschließen.
Der Client (Vegeta) stellt eine TCP-Verbindung zu einem beliebigen Knoten im Cluster her. Kubernetes funktioniert als Overlay-Netzwerk (über das bestehende Datacenter-Netzwerk), das verwendet, d.h. es kapselt IP-Pakete des Overlay-Netzwerks in IP-Pakete des Datencenters ein. Beim Anschluss an den ersten Knoten wird eine Adressumwandlung durchgeführt. (NAT) mit Statusverfolgung zur Umwandlung der IP-Adresse und des Ports des Kubernetes-Knotens in die IP-Adresse und den Port im Overlay-Netzwerk (insbesondere des Pods mit der Anwendung). Für die empfangenen Pakete wird die umgekehrte Abfolge ausgeführt. Dies ist ein komplexes System mit vielen Zuständen und zahlreichen Elementen, die sich ständig aktualisieren und ändern, während Dienste bereitgestellt und verschoben werden.
Das Tool tcpdump im Vegeta-Test verursacht eine Verzögerung während des TCP-Handshakes (zwischen SYN und SYN-ACK). Um diese übermäßige Komplexität zu beseitigen, kann man verwenden hping3 für einfache „Pings“ mit SYN-Paketen. Wir überprüfen, ob es eine Verzögerung im Antwortpaket gibt und setzen dann die Verbindung zurück. Wir können die Daten filtern, indem wir nur Pakete mit mehr als 100 ms einbeziehen, und erhalten eine einfachere Möglichkeit zur Reproduktion des Problems als einen vollständigen Test der Netzwerkschicht 7 in Vegeta. Hier sind die „Pings“ des Kubernetes-Knotens unter Verwendung von TCP SYN/SYN-ACK am „Knotensport“ des Dienstes (30927) mit einem Intervall von 10 ms, 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
Man kann sofort die erste Beobachtung machen. Anhand der Sequenznummern und Zeitangaben ist zu erkennen, dass dies keine einmaligen Staus sind. Die Verzögerung sammelt sich häufig an und wird letztendlich verarbeitet.
Als Nächstes möchten wir herausfinden, welche Komponenten möglicherweise für die Entstehung des Staus verantwortlich sein könnten. Sind es vielleicht einige der Hunderten von iptables-Regeln im NAT? Oder gibt es Probleme mit der IPIP-Tunnelerstellung im Netzwerk? Eine Möglichkeit, dies zu überprüfen, besteht darin, jeden Schritt des Systems zu testen, indem man ihn ausschließt. Was passiert, wenn man NAT und die Logik der Firewall entfernt und nur den Teil des IPIP lässt:
Glücklicherweise erlaubt Linux den direkten Zugriff auf die Overlay-Schicht von IP, wenn die Maschine im selben Netzwerk ist:
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
Laut den Ergebnissen besteht das Problem weiterhin! Das schließt iptables und NAT aus. Also liegt das Problem im TCP? Schauen wir uns an, wie der normale ICMP-Ping verlä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. Könnte es sich um ein IPIP-Tunnel handeln? Lassen Sie uns den Test weiter vereinfachen:
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 auf zwei Kubernetes-Knoten vereinfacht, die sich gegenseitig Pakete senden, selbst einen ICMP-Ping. Sie sehen dennoch Verzögerungen, wenn der Zielhost „schlecht“ ist (einige schlechter als andere).
Jetzt die letzte Frage: Warum tritt die Verzögerung nur auf den kube-node-Servern auf? Und geschieht sie, wenn kube-node der Sender oder der Empfänger ist? Glücklicherweise ist es auch recht einfach herauszufinden, indem man ein Paket von einem Host außerhalb von Kubernetes mit demselben „bekannten schlechten“ Empfänger sendet. Wie wir 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
Dann führen wir die gleichen Anfragen vom vorherigen Quell-kube-node an einen externen Host aus (was den ursprünglichen Host ausschließt, da ein Ping sowohl RX- als auch TX-Komponenten beinhaltet):
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 Statistik ---
22352 Pakete gesendet, 22350 Pakete empfangen, 1% Paketverlust
Hin- und Rückfahrt min/Ø/max = 0.2/7.6/1010.6 ms
Nachdem wir die Verzögerung von Paketaufzeichnungen untersucht haben, haben wir einige zusätzliche Informationen erhalten. Insbesondere dass der Sender (unten) dieses Timeout sieht, der Empfänger (oben) es jedoch nicht sieht — siehe die Delta-Spalte (in Sekunden):
Darüber hinaus, wenn man den Unterschied in der Reihenfolge der TCP- und ICMP-Pakete (nach Sequenznummern) auf der Empfängerseite betrachtet, kommen die ICMP-Pakete immer in derselben Reihenfolge an, in der sie gesendet wurden, jedoch mit unterschiedlichem Timing. Währenddessen wechseln die TCP-Pakete manchmal und ein Teil bleibt stecken. Insbesondere wenn man die SYN-Pakete betrachtet, gehen sie auf der Senderseite in der richtigen Reihenfolge ein, aber auf der Empfängerseite nicht.
Es gibt einen feinen Unterschied in der Weise, wie moderner Server (wie in unserem Rechenzentrum) Pakete verarbeiten, die TCP oder ICMP enthalten. Wenn ein Paket ankommt, „hasht“ der Netzwerkadapter es nach Verbindung, das heißt, er versucht, Verbindungen in Warteschlangen aufzuteilen und jede Warteschlange auf ein separates Prozessorkern zu senden. Für TCP umfasst dieses Hashing sowohl die Quell- als auch die Ziel-IP-Adresse und den Port. Mit anderen Worten, jede Verbindung wird (potenziell) unterschiedlich gehasht. Für ICMP werden nur die IP-Adressen gehasht, da es keine Ports gibt.
Eine weitere neue Beobachtung: In diesem Zeitraum sehen wir ICMP-Verzögerungen bei allen Kommunikationen zwischen zwei Hosts, jedoch nicht bei TCP. Das sagt uns, dass der Grund wahrscheinlich mit dem Hashing der RX-Warteschlangen zusammenhängt: Sehr wahrscheinlich entsteht der Engpass in der Verarbeitung von RX-Paketen, nicht beim Versenden von Antworten.
Das schließt das Senden von Paketen als mögliche Ursache aus. Jetzt wissen wir, dass das Problem mit der Paketverarbeitung auf der Empfangsseite auf einigen kube-node-Servern liegt.
Wir klären die Paketverarbeitung im Linux-Kernel
Um zu verstehen, warum das Problem auf der Empfängerseite bei einigen kube-node-Servern auftritt, schauen wir uns an, wie der Linux-Kernel Pakete verarbeitet.
Zurück zur einfachsten traditionellen Implementierung empfängt die Netzwerkkarte ein Paket und sendet an den Linux-Kernel, dass ein Paket 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 erfolgt langsam: Möglicherweise war die Verzögerung bei 10-Mbit-Netzwerkkarten in den 90er Jahren unbemerkt, aber bei modernen 10G-Karten mit einer maximalen Durchsatzrate von 15 Millionen Paketen pro Sekunde kann jedes Core eines kleinen achtkernigen Servers Millionen Male pro Sekunde unterbrochen werden.
Um nicht ständig die Unterbrechungen verarbeiten zu müssen, wurde vor vielen Jahren in Linux : eine Netzwerk-API, die alle modernen Treiber für eine bessere Leistung bei hohen Geschwindigkeiten nutzen. Bei niedrigen Geschwindigkeiten nimmt der Kernel weiterhin Interrupts von der Netzwerkkarte auf die alte Weise entgegen. Sobald eine ausreichende Anzahl von Paketen ankommt, die einen Schwellenwert überschreitet, deaktiviert der Kernel die Unterbrechungen und beginnt stattdessen, den Netzwerkadapter abzufragen und Pakete in Portionen abzuholen. Die Verarbeitung erfolgt im softirq, also im nach Systemaufrufen und Hardware-Interrupts, wenn der Kernel (im Gegensatz zum Benutzerspeicher) bereits gestartet ist.
Das ist viel schneller, bringt aber ein anderes Problem mit sich. Wenn zu viele Pakete ankommen, wird die gesamte Zeit für die Verarbeitung der Pakete von der Netzwerkkarte aufgewendet, und die Prozesse im Benutzerspeicher können diese Warteschlangen (z. B. das Lesen von TCP-Verbindungen) nicht rechtzeitig leeren. Schließlich füllen sich die Warteschlangen, und wir beginnen, Pakete abzulehnen. Um ein Gleichgewicht zu finden, legt der Kernel ein Budget für die maximale Anzahl von Paketen fest, die im Kontext des softirq verarbeitet werden. Sobald dieses Budget überschritten wird, wird ein separater Thread ksoftirqd aufgeweckt (Sie werden einen von ihnen in ps für jeden Kern sehen), der diese softirq außerhalb des normalen Syscall-/Interrupt-Weges verarbeitet. Dieser Thread wird mit dem Standard-Prozessscheduler geplant, der versucht, die Ressourcen gerecht zu verteilen.
Wenn man beobachtet, wie der Kernel Pakete verarbeitet, fällt auf, dass hier eine gewisse Wahrscheinlichkeit für Staus besteht. Wenn die Aufrufe von softirq seltener erfolgen, müssen die Pakete eine gewisse Zeit auf die Verarbeitung in der RX-Warteschlange an der Netzwerkkarte warten. Möglicherweise geschieht dies durch eine Aufgabe, die den Kernel des Prozessors blockiert, oder etwas anderes hindert den Kernel daran, den softirq zu starten.
Wir konzentrieren uns auf die Verarbeitung im Kernel oder die Methode
Die Verzögerungen bei softirq sind bisher nur eine Vermutung. Aber sie macht Sinn, und wir wissen, dass etwas sehr Ähnliches beobachtet wird. Daher ist der nächste Schritt, diese Theorie zu bestätigen. Und wenn sie sich bestätigt, dann den Grund für die Verzögerungen zu finden.
Kommen 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 Warteschlange für NIC RX gehasht und von einem CPU-Kern verarbeitet. Wenn wir das Verhalten von Linux verstehen wollen, ist es hilfreich zu wissen, wo (auf welchem CPU-Kern) und wie (softirq, ksoftirqd) diese Pakete verarbeitet werden, um den Prozess nachzuvollziehen.
Jetzt ist es an der Zeit, Werkzeuge zu verwenden, die es ermöglichen, die Funktionsweise des Linux-Kernels in Echtzeit zu überwachen. Hier haben wir verwendet . Dieses Toolset ermöglicht es, kleine Programme in C zu schreiben, die beliebige Funktionen im Kernel abfangen und Ereignisse in ein Benutzerraum-Python-Programm puffern, das sie verarbeiten und das Ergebnis zurückgeben kann. Hooks für beliebige Funktionen im Kernel sind komplex, aber das Werkzeug wurde für maximale Sicherheit entwickelt und soll spezifisch solche Produktionsprobleme nachverfolgen, die sich schwer in einer Test- oder Entwicklungsumgebung reproduzieren lassen.
Der Plan hier ist einfach: Wir wissen, dass der Kernel diese ICMP-Pings verarbeitet, also setzen wir einen Hook auf die Kernel-Funktion , die ein eingehendes ICMP-Paket "echo request" akzeptiert und den Versand der ICMP-Antwort "echo response" initiiert. Wir können das Paket anhand der Erhöhung der Nummer icmp_seq identifizieren, die zeigt hping3 höher sein.
Code sieht kompliziert aus, aber es ist nicht so furchterregend, wie es scheint. Die Funktion icmp_echo übergibt struct sk_buff *skb: das Paket mit der Anforderung "echo request". Wir können es nachverfolgen, die Sequenz herausziehen echo.sequence die mit icmp_seq von hping3 über), und sie in den Benutzerraum senden. Es ist auch praktisch, den aktuellen Prozessnamen/Identifikator einzufangen. Unten sind die Ergebnisse aufgeführt, die wir während der Verarbeitung der Pakete durch den Kernel direkt sehen:
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 swapper/11 777 0 0 swapper/11 778 4512 4542 spokes-report-s 779
Hier sollte angemerkt werden, dass im Kontext Softirq Prozesse, die Systemaufrufe getätigt haben, erscheinen als „Prozesse“, obwohl es sich dabei tatsächlich um das Kernelsystem handelt, das Pakete im Kernel kontext sicher verarbeitet.
Mit diesem Tool können wir eine Verbindung zwischen bestimmten Prozessen und konkreten Paketen herstellen, die eine Verzögerung in hping3zeigen. Wir führen einen einfachen grep auf diesem Capture für bestimmte Werte durch icmp_seq. Die Pakete, die den oben genannten Werten icmp_seq entsprechen, wurden zusammen mit ihrem RTT markiert, den wir oben beobachtet haben (in Klammern sind die erwarteten RTT-Werte für die 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 ** 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 ** (49ms) 76 76 ksoftirqd/11 1959 ** (39ms) 76 76 ksoftirqd/11 1960 ** (29ms) 76 76 ksoftirqd/11 1961 ** (19ms) 76 76 ksoftirqd/11 1962 ** (9ms) -- 10137 10436 cadvisor 2068 10137 10436 cadvisor 2069 76 76 ksoftirqd/11 2070 ** 75ms 76 76 ksoftirqd/11 2071 ** 65ms 76 76 ksoftirqd/11 2072 ** 55ms 76 76 ksoftirqd/11 2073 ** (45ms) 76 76 ksoftirqd/11 2074 ** (35ms) 76 76 ksoftirqd/11 2075 ** (25ms) 76 76 ksoftirqd/11 2076 ** (15ms) 76 76 ksoftirqd/11 2077 ** (5ms)
Die Ergebnisse geben uns mehrere Hinweise. Erstens werden all diese Pakete im Kontext Verarbeitung ksoftirqd/11. Das bedeutet, dass für dieses spezielle Paar von Maschinen die ICMP-Pakete auf Kernel 11 auf der empfangenden Seite gehasht wurden. Wir sehen auch, dass bei jedem Stau Pakete vorhanden sind, die im Kontext eines Systemaufrufs verarbeitet werden cadvisor. Dann ksoftirqd übernimmt die Aufgabe und bearbeitet die angehäufte Warteschlange: genau die Anzahl der Pakete, die sich nach cadvisor.
Anhand der Tatsache, dass immer direkt davor cadvisorläuft, lässt auf seine Beteiligung an dem Problem schließen. Ironischerweise ist die Bestimmung – „Analyse der Ressourcennutzung und Leistungsmerkmale der laufenden Container“, und nicht die Auslösung dieses Leistungsproblems.
Wie bei anderen Aspekten der Containerarbeit ist dies ein äußerst fortschrittliches Werkzeug, von dem man in einigen unerwarteten Situationen durchaus Leistungseinbußen erwarten kann.
Was bewirkt cadvisor, das die Paketwarteschlange verlangsamt?
Jetzt haben wir ein ziemlich gutes Verständnis dafür, wie der Fehler auftritt, welcher Prozess ihn verursacht und auf welchem CPU. Wir sehen, dass aufgrund von strengen Sperren der Linux-Kernel nicht rechtzeitig planen kann. ksoftirqdUnd wir sehen, dass die Pakete im Kontext verarbeitet werden. cadvisorEs ist logisch anzunehmen, dass cadvisor einen langsamen syscall ausführt, nach dem alle in der Zwischenzeit angesammelten Pakete bearbeitet werden:
Das ist die Theorie, aber wie können wir sie überprüfen? Was wir tun können, ist, die Arbeit des CPU-Kerns während dieses gesamten Prozesses zu verfolgen, den Punkt zu finden, an dem das Paketbudget überschritten wird und ksoftirqd aufgerufen wird, und dann etwas früher zu sehen – was genau auf dem CPU-Kern direkt vor diesem Moment lief. Das ist wie ein Röntgenbild des CPUs alle paar Millisekunden. Es wird ungefähr so aussehen:
Es ist praktisch, dass dies alles mit bestehenden Tools gemacht werden kann. Zum Beispiel überprüft in einem bestimmten Intervall den angegebenen CPU-Kern und kann ein Aufrufdiagramm des laufenden Systems erstellen, einschließlich Benutzerbereich und Linux-Kernel. Man kann diese Aufzeichnung nehmen und sie mit einem kleinen Fork des Programms von Brendan Gregg verarbeiten, der die Reihenfolge der Stack-Traces beibehält. Wir können einmalige Stack-Traces alle 1 ms speichern und dann eine Probe für 100 Millisekunden speichern, bevor sie in den Trace aufgenommen wird. 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:
(Hunderte von Spuren, die ähnlich aussehen)
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 viel, aber das Wichtigste ist, dass wir das Muster „cadvisor vor ksoftirqd“ sehen, das wir zuvor im ICMP-Tracer gesehen haben. Was bedeutet das?
Jede Zeile ist eine CPU-Trace zu einem bestimmten Zeitpunkt. Jeder Aufruf nach unten im Stack wird durch ein Semikolon getrennt. In der Mitte der Zeilen sehen wir den aufgerufenen Syscall: read(): .... ;do_syscall_64;sys_read; .... So verbringt cadvisor viel Zeit mit dem Systemaufruf read(), der sich auf die Funktionen mem_cgroup_* (oberer Teil des Aufrufstacks/Ende der Zeile).
Es ist unpraktisch, in der Aufrufverfolgung zu sehen, was genau gelesen wird, also lassen Sie uns strace und schauen, was cadvisor macht, und finden wir Systemaufrufe, die länger als 100 ms dauern:
theojulienne@kube-node-bad ~ $ sudo strace -p 10137 -T -ff 2>&1 | egrep '<0.[1-9]'
[pid 10436] ) = 0
[pid 10432] ) = 0
[pid 10137] ) = 0
[pid 10384] ) = 0
[pid 10436] "cache 154234880nrss 507904nrss_h"..., 4096) = 658
[pid 10384] ) = 0
[pid 10436] ) = 0
[pid 10436] "cache 0nrss 0nrss_huge 0nmapped_"..., 4096) = 577
[pid 10427] "cache 0nrss 0nrss_huge 0nmapped_"..., 4096) = 577
[pid 10411] ) = 0
[pid 10382] ) = 0 (Timeout)
[pid 10436] "cache 154234880nrss 507904nrss_h"..., 4096) = 660
[pid 10417] ) = 0
[pid 10436] ) = 0
[pid 10417] ) = 0
[pid 10417] "cache 0nrss 0nrss_huge 0nmapped_"..., 4096) = 576
Wie zu erwarten war, sehen wir hier langsame Aufrufe read(). Aus dem Inhalt von Leseoperationen und Kontext mem_cgroup ist ersichtlich, dass diese Aufrufe read() sich auf die Datei memory.stat, die die Speichernutzung und Limits der cgroup (Technologie zur Ressourcenisolierung in Docker) anzeigt. Das Tool cadvisor befragt diese Datei, um Informationen über die Ressourcennutzung der Container zu sammeln. Lass uns überprü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 Bug reproduzieren und verstehen, dass der Linux-Kernel auf eine Pathologie stößt.
Warum ist die Leseoperation so langsam?
Es ist jetzt viel einfacher, Nachrichten anderer Benutzer über ähnliche Probleme zu finden. Wie sich herausstellte, wurde in der cadvisor-Tracker über diesen Bug als , einfach hat niemand bemerkt, dass die Verzögerung auch zufällig im Netzwerk-Stack reflektiert wird. Tatsächlich wurde festgestellt, dass cadvisor mehr CPU-Zeit verbraucht, als erwartet, aber dem wurde nicht viel Beachtung geschenkt, da unsere Server über viele CPU-Ressourcen verfügen, sodass das Problem nicht eingehend untersucht wurde.
Das Problem liegt darin, dass die Kontrollgruppen (cgroups) den Speicherverbrauch innerhalb des Namensraums (Containers) berücksichtigen. Wenn alle Prozesse in dieser cgroup beendet sind, gibt Docker die Speichergruppe frei. Allerdings ist „Speicher“ nicht einfach der Speicher eines Prozesses. Auch wenn der Speicher der Prozesse nicht mehr verwendet wird, stellt sich heraus, dass der Kernel weiterhin zwischengespeicherte Inhalte wie dentries und inodes (Metadaten von Verzeichnissen und Dateien) zuweist, die in der memory cgroup zwischengespeichert werden. Aus der Problembeschreibung:
cgroups-Zombies: Kontrollgruppen, in denen keine Prozesse mehr vorhanden sind und die gelöscht wurden, für die jedoch weiterhin Speicher zugewiesen ist (in meinem Fall aus dem dentry-Cache, kann aber auch aus dem Seiten-Cache oder tmpfs zugewiesen werden).
Die Überprüfung aller Seiten im Cache durch den Kernel beim Freigeben der cgroup kann sehr langsam sein, daher wurde ein träger Prozess gewählt: warten, bis diese Seiten erneut angefordert werden, und erst dann, wenn der Speicher tatsächlich benötigt wird, die cgroup schließlich zu bereinigen. Bis zu diesem Zeitpunkt wird die cgroup weiterhin bei der Statistikberechnung berücksichtigt.
Aus leistungsseitiger Sicht opferten sie Speicher für die Leistung: die Beschleunigung der anfänglichen Bereinigung durch das verbleibende wenig gecachte Speicher. Das ist in Ordnung. Wenn der Kernel den letzten Teil des gecachten Speichers nutzt, wird die cgroup schließlich bereinigt, sodass man dies nicht als "Leck" bezeichnen kann. Leider führt die spezifische Implementierung des Suchmechanismus memory.stat in dieser Kernversion (4.9), zusammen mit der enormen Menge an Speicher auf unseren Servern, dazu, dass es viel länger dauert, die letztgekachten Daten wiederherzustellen und die cgroup-Zombies zu bereinigen.
Es stellte sich heraus, dass es auf einigen unserer Knoten so viele cgroup-Zombies gab, dass das Lesen und die Verzögerung über eine Sekunde betrugen.
Ein Weg, das Problem mit cadvisor zu umgehen, besteht darin, die Caches von dentries/inodes im gesamten System sofort freizugeben, was die Leseverzögerung sofort beseitigt und auch die Netzwerkverzögerung auf dem Host, da das Entfernen des Caches auch die gecachten Seiten der cgroup-Zombies umfasst, die ebenfalls freigegeben werden. Das ist keine Lösung, bestätigt aber die Ursache des Problems.
Es stellte sich heraus, dass in neueren Kernversionen (4.19+) die Leistung des Aufrufs memory.statverbessert wurde, sodass der Wechsel zu diesem Kernel das Problem behob. Gleichzeitig hatten wir ein Werkzeug zur Identifizierung problematischer Knoten in Kubernetes-Clustern, deren eleganten Ausschluss und Neustart. Wir durchsuchten alle Cluster, identifizierten Knoten mit ausreichend hoher Verzögerung und starteten diese neu. Das gab uns Zeit, das Betriebssystem auf den anderen Servern zu aktualisieren.
Zusammenfassend
Da dieser Bug die Verarbeitung von RX-NIC-Warteschlangen um Hunderte von Millisekunden stoppte, verursachte er gleichzeitig sowohl große Verzögerungen in kurzen Verbindungen als auch Verzögerungen in der Mitte der Verbindung, zum Beispiel zwischen MySQL-Anfragen und den Antwortpaketen.
Das Verständnis und die Unterstützung der Leistung der grundlegendsten Systeme wie Kubernetes ist entscheidend für die Zuverlässigkeit und Geschwindigkeit aller Dienste, die auf ihnen basieren. Alle ausgeführten Systeme profitieren von den Leistungsverbesserungen in Kubernetes.
Quelle: habr.com
