Kilka lat temu Kubernetes na oficjalnym blogu GitHub. Od tego czasu stał się standardową technologią wdrażania usług. Teraz Kubernetes zarządza znaczną częścią wewnętrznych i publicznych usług. W miarę jak nasze klastry rosły, a wymagania dotyczące wydajności stały się bardziej rygorystyczne, zaczęliśmy zauważać, że w niektórych usługach w Kubernetes sporadycznie pojawiają się opóźnienia, których nie można wyjaśnić obciążeniem samej aplikacji.
W istocie w aplikacjach dochodzi do czegoś w rodzaju losowego opóźnienia sieciowego sięgającego 100 ms lub więcej, co prowadzi do przekroczeń czasu oczekiwania lub ponownych prób. Oczekiwano, że usługi będą w stanie odpowiadać na zapytania znacznie szybciej niż w ciągu 100 ms. Lecz to niemożliwe, jeśli samo połączenie zajmuje tyle czasu. Oddzielnie obserwowaliśmy bardzo szybkie zapytania MySQL, które powinny zajmować milisekundy, i MySQL naprawdę radziła sobie w milisekundach, ale z perspektywy aplikacji zapytującej odpowiedź zajmowała 100 ms lub więcej.
Od razu stało się jasne, że problem występuje tylko przy połączeniu z węzłem Kubernetes, nawet jeśli wywołanie pochodziło z zewnątrz Kubernetes. Najłatwiej było odtworzyć problem w teście , który jest uruchamiany z dowolnego wewnętrznego hosta, testuje usługę Kubernetes na określonym porcie i sporadycznie rejestruje duże opóźnienia. W tym artykule omówimy, jak udało nam się zidentyfikować przyczynę tego problemu.
Eliminowanie zbędnej złożoności w łańcuchu do awarii
Odtwarzając ten sam przykład, chcieliśmy zawęzić fokus problemu i usunąć zbędne warstwy złożoności. Początkowo w strumieniu między Vegeta a podami na Kubernetes było zbyt wiele elementów. Aby określić głębszy problem sieciowy, trzeba było wykluczyć niektóre z nich.
Klient (Vegeta) nawiązuje połączenie TCP z dowolnym węzłem w klastrze. Kubernetes działa jako sieć nakładkowa (na istniejącą sieć centrum danych), która wykorzystuje , co oznacza, że kapsułkuje pakiety IP sieci nakładkowej w pakietach IP centrum danych. Podczas łączenia z pierwszym węzłem następuje transformacja adresów sieciowych. (NAT) z monitorowaniem stanu do przekształcania adresu IP i portu węzła Kubernetes na adres IP i port w sieci nakładkowej (w szczególności pod z aplikacją). Dla przychodzących pakietów wykonywana jest odwrotna sekwencja działań. To skomplikowany system z dużą liczbą stanów i wieloma elementami, które są stale aktualizowane i zmieniają się w miarę rozwijania i przemieszczania usług.
Narzędzie tcpdump w teście Vegeta powoduje opóźnienie podczas handshake'u TCP (między SYN a SYN-ACK). Aby wyeliminować tę dodatkową złożoność, można użyć hping3 do prostych „pingów” pakietami SYN. Sprawdzamy, czy występuje opóźnienie w odpowiedzi, a następnie zrywamy połączenie. Możemy filtrować dane, włączając tylko pakiety z opóźnieniem powyżej 100 ms, uzyskując prostszy sposób na odtworzenie problemu niż pełny test na poziomie sieciowym 7 w Vegeta. Oto „pingi” węzła Kubernetes z użyciem TCP SYN/SYN-ACK na „porcie węzła” usługi (30927) z interwałem 10 ms, filtrowane według najwolniejszych odpowiedzi:
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
Można od razu zauważyć pierwszą obserwację. Po numerach sekwencyjnych i czasach widać, że to nie jednorazowe zatory. Opóźnienie często się kumuluje i w końcu jest przetwarzane.
Następnie chcemy ustalić, które komponenty mogą być odpowiedzialne za powstawanie zatoru. Może to być jedno z setek reguł iptables w NAT? A może jakieś problemy z tunelowaniem IPIP w sieci? Jednym ze sposobów, aby to sprawdzić, jest przetestowanie każdego kroku systemu, eliminując go. Co się stanie, jeśli usuniemy NAT i logikę zapory, pozostawiając tylko część IPIP:
Na szczęście Linux pozwala łatwo uzyskać dostęp do warstwy nakładkowej IP, jeśli maszyna należy do tej samej sieci:
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
Z wyników wynika, że problem nadal występuje! Wyklucza to iptables i NAT. Znaczy, że problem leży w TCP? Sprawdźmy, jak wygląda standardowy ping ICMP:
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
Wyniki pokazują, że problem nie zniknął. Może to tunel IPIP? Uprośćmy test:
Czy wszystkie pakiety są przesyłane między tymi dwoma hostami?
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
Uprościliśmy sytuację do dwóch węzłów Kubernetes, które wysyłają do siebie dowolne pakiety, nawet ping ICMP. Nadal zauważają opóźnienia, jeśli docelowy host jest «zły» (niektóre gorsze od innych).
Teraz ostatnie pytanie: dlaczego opóźnienie występuje tylko na serwerach kube-node? I występuje, gdy kube-node jest nadawcą lub odbiorcą? Na szczęście, można to łatwo ustalić, wysyłając pakiet z hosta poza Kubernetes, ale do tego samego «znanego złego» odbiorcy. Jak widać, problem nie zniknął:
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
Następnie wykonamy te same zapytania z poprzedniego hosta kube-node do zewnętrznego hosta (co wyklucza hosta źródłowego, ponieważ ping obejmuje komponent RX i TX):
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 statystyka hping ---
22352 pakiety wysłane, 22350 pakiety odebrane, 1% utraty pakietów
czas przejazdu min/średnia/maks = 0.2/7.6/1010.6 ms
Analizując opóźnienia pakietów, uzyskaliśmy dodatkowe informacje. W szczególności nadawca (na dole) dostrzega ten timeout, podczas gdy odbiorca (na górze) go nie widzi — zobacz kolumnę Delta (w sekundach):
Ponadto, patrząc na różnice w kolejności pakietów TCP i ICMP (według numerów kolejnych) po stronie odbiorcy, pakiety ICMP zawsze przychodzą w tej samej kolejności, w jakiej zostały wysłane, ale z różnym timingiem. Tymczasem pakiety TCP czasami się mieszają, a część z nich zatrzymuje się. W szczególności, jeśli zbadamy porty pakietów SYN, to po stronie nadawcy są one w porządku, a po stronie odbiorcy — nie.
Istnieje subtelna różnica w tym, jak nowoczesnych serwerów (jak w naszym centrum danych) przetwarzają pakiety zawierające TCP lub ICMP. Gdy pakiet dociera, adapter sieciowy „hashuje go według połączenia”, tzn. próbuje podzielić połączenia na kolejki i wysłać każdą kolejkę na oddzielne jądro procesora. Dla TCP ten hasz obejmuje zarówno adres IP źródłowy, jak i docelowy oraz port. Innymi słowy, każde połączenie jest haszowane (potencjalnie) inaczej. Dla ICMP haszowane są tylko adresy IP, ponieważ porty nie istnieją.
Kolejna nowa obserwacja: w tym okresie zauważamy opóźnienia ICMP w komunikacji między dwoma hostami, a w TCP ich nie ma. To mówi nam, że przyczyna prawdopodobnie ma związek z haszowaniem kolejek RX: z dużą pewnością zator powstaje w przetwarzaniu pakietów RX, a nie w wysyłaniu odpowiedzi.
To wyklucza z listy możliwych przyczyn wysyłania pakietów. Teraz wiemy, że problem z przetwarzaniem pakietów występuje po stronie odbiorczej na niektórych serwerach kube-node.
Zajmujemy się przetwarzaniem pakietów w jądrze Linux
Aby zrozumieć, dlaczego problem występuje u odbiorcy na niektórych serwerach kube-node, przyjrzyjmy się, jak jądro Linux przetwarza pakiety.
Wracając do najprostszej tradycyjnej realizacji, karta sieciowa otrzymuje pakiet i wysyła do jądra Linux, że jest pakiet, który należy przetworzyć. Jądro zatrzymuje inne prace, przełącza kontekst na obsługę przerwania, przetwarza pakiet, a następnie wraca do obecnych zadań.
Przełączanie kontekstu odbywa się powoli: być może opóźnienie było niezauważalne na 10-megabitowych kartach sieciowych w latach 90., ale na nowoczesnych kartach 10G o maksymalnej przepustowości 15 milionów pakietów na sekundę, każde małe ośmiordzeniowe serwerowe rdzenie mogą być przerywane miliony razy na sekundę.
Aby nie zajmować się ciągłym przetwarzaniem przerwań, wiele lat temu dodano do Linuxa : interfejs sieciowy, który jest używany przez wszystkie nowoczesne sterowniki w celu zwiększenia wydajności przy dużych prędkościach. Przy niskich prędkościach rdzeń nadal odbiera przerwania z karty sieciowej w stary sposób. Gdy przychodzi wystarczająca liczba pakietów, która przekracza próg, rdzeń wyłącza przerwania i zamiast tego zaczyna pytania do adaptera sieciowego i zbiera pakiety w porcjach. Przetwarzanie odbywa się w softirq, czyli w po wywołaniach systemowych i przerwaniach sprzętowych, gdy rdzeń (w przeciwieństwie do przestrzeni użytkownika) jest już uruchomiony.
To jest znacznie szybsze, ale powoduje inny problem. Jeśli jest zbyt wiele pakietów, cały czas idzie na przetwarzanie pakietów z karty sieciowej, a procesy przestrzeni użytkownika nie mają czasu na faktyczne opróżnianie tych kolejek (odczytywanie z połączeń TCP itp.). W końcu kolejki zapychają się i zaczynamy odrzucać pakiety. Starając się znaleźć równowagę, rdzeń ustawia budżet na maksymalną liczbę pakietów przetwarzanych w kontekście softirq. Gdy ten budżet zostanie przekroczony, budzi się oddzielny wątek ksoftirqd (zobaczysz jeden z nich w ps dla każdego rdzenia), który przetwarza te softirq poza normalną ścieżką syscall/przerwanie. Ten wątek jest planowany za pomocą standardowego planisty procesów, który stara się sprawiedliwie rozdzielać zasoby.
Analizując, jak rdzeń przetwarza pakiety, można zauważyć, że istnieje pewne prawdopodobieństwo wystąpienia zatorów. Jeśli wywołania softirq przychodzą rzadziej, pakiety będą musiały trochę poczekać na przetworzenie w kolejce RX na karcie sieciowej. Może to wynikać z jakiegoś zadania blokującego rdzeń procesora lub cokolwiek innego, co przeszkadza rdzeniowi w uruchomieniu softirq.
Ograniczamy przetwarzanie do rdzenia lub metody
Opóźnienia softirq są na razie tylko hipotezą. Jednak ma to sens i wiemy, że obserwujemy coś bardzo podobnego. Dlatego następnym krokiem jest potwierdzenie tej teorii. A jeśli się potwierdzi, należy znaleźć przyczynę opóźnień.
Wracając do naszych powolnych pakietów:
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
Jak wcześniej omawiano, te pakiety ICMP są hashowane do jednej kolejki NIC RX i przetwarzane przez jeden rdzeń CPU. Jeśli chcemy zrozumieć działanie Linuksa, warto wiedzieć, gdzie (na którym rdzeniu CPU) i jak (softirq, ksoftirqd) te pakiety są przetwarzane, aby śledzić proces.
Teraz nadszedł czas, aby użyć narzędzi, które pozwalają na monitorowanie działania jądra Linuksa w czasie rzeczywistym. Użyliśmy tutaj . Ten zestaw narzędzi pozwala pisać małe programy w C, które przechwytują dowolne funkcje w jądrze i buforują zdarzenia w programie użytkownika w Pythonie, który może je przetwarzać i zwracać Ci wyniki. Hooki do dowolnych funkcji w jądrze są skomplikowane, ale narzędzie jest zaprojektowane z myślą o maksymalnym bezpieczeństwie i ma na celu monitorowanie właśnie takich problemów produkcyjnych, które trudno jest odtworzyć w środowisku testowym lub deweloperskim.
Plan jest prosty: wiemy, że jądro przetwarza te pingi ICMP, więc postawimy hook na funkcji jądra , która przyjmuje przychodzący pakiet ICMP „echo request” i inicjuje wysyłanie odpowiedzi ICMP „echo response”. Możemy zidentyfikować pakiet, zwracając uwagę na zwiększający się numer icmp_seq, który pokazuje hping3 wyżej.
Kod wygląda skomplikowane, ale nie jest tak straszne, jak się wydaje. Funkcja icmp_echo przekazuje struct sk_buff *skb: to pakiet z żądaniem „echo request”. Możemy go śledzić, wydobywając sekwencję echo.sequence (która odpowiada icmp_seq z hping3 powyżej), a następnie wysłać ją do przestrzeni użytkownika. Warto także uchwycić aktualną nazwę procesu/id. Poniżej przedstawione są wyniki, które widzimy bezpośrednio podczas przetwarzania pakietów przez jądro:
TGID PID NAZWA PROCESU 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
Należy zauważyć, że w kontekście softirq procesy, które wykonały wywołania systemowe, będą wyświetlane jako „procesy”, mimo że w rzeczywistości jądro bezpiecznie przetwarza pakiety w kontekście jądra.
Dzięki temu narzędziu możemy powiązać konkretne procesy z konkretnymi pakietami, które wykazują opóźnienia hping3. Wykonajmy prostą grep na tym zrzucie dla określonych wartości icmp_seq. Pakiety odpowiadające powyższym wartościom icmp_seq zostały oznaczone wraz z ich RTT, które obserwowaliśmy powyżej (w nawiasach podano oczekiwane wartości RTT pakietów, które odfiltrowaliśmy z powodu wartości RTT mniejszych niż 50 ms):
TGID PID NAZWA PROCESU 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)
Wyniki mówią nam o kilku rzeczach. Po pierwsze, wszystkie te pakiety przetwarzane są przez kontekst ksoftirqd/11. Oznacza to, że dla tej konkretnej pary maszyn pakiety ICMP były haszowane do jądra 11 po stronie odbierającej. Widocznie każde opóźnienie towarzyszy obecności pakietów wykorzystywanych w kontekście wywołania systemowego cadvisor. Następnie ksoftirqd bierze na siebie zadanie i przetwarza skumulowaną kolejkę: dokładnie tę ilość pakietów, która zgromadziła się po cadvisor.
Fakt, że tuż przed tym zawsze działa cadvisor, sugeruje jego udział w problemie. Ironią jest, że przeznaczenie — „analizować wykorzystanie zasobów i charakterystyki wydajności uruchomionych kontenerów”, a nie powodować tego problemu z wydajnością.
Jak w przypadku innych aspektów działania kontenerów, jest to niezwykle zaawansowane narzędzie, od którego można oczekiwać problemów z wydajnością w pewnych nieprzewidzianych okolicznościach.
Co takiego robi cadvisor, że spowalnia kolejkę pakietów?
Teraz mamy całkiem dobre zrozumienie, jak dochodzi do awarii, jaki proces ją wywołuje i na którym CPU. Widocznie z powodu poważnej blokady jądro Linuxa nie jest w stanie na czas zaplanować ksoftirqd. A widzimy, że pakiety są przetwarzane w kontekście cadvisor. Słusznie można przypuszczać, że cadvisor uruchamia powolne wywołanie syscall, po którym przetwarzane są wszystkie nagromadzone w tym czasie pakiety:
To jest teoria, ale jak ją zweryfikować? Co możemy zrobić, to śledzić pracę jądra CPU przez cały ten proces, znaleźć moment, w którym następuje przekroczenie budżetu liczby pakietów i wywoływane jest ksoftirqd, a następnie przyjrzeć się wcześniejszym działaniom — co dokładnie pracowało na jądrze CPU bezpośrednio przed tym momentem. To jak rentgen CPU co kilka milisekund. Wyglądałby mniej więcej tak:
Na szczęście wszystko to można zrobić istniejącymi narzędziami. Na przykład, w określonym interwale sprawdza wyznaczone jądro CPU i może generować wykres wywołań działającego systemu, w tym zarówno przestrzeni użytkownika, jak i jądra Linux. Można wziąć ten zapis i przetworzyć go za pomocą małego forka programu od Brandona Gregga, który zachowuje porządek śledzenia stosu. Możemy zachowywać jednowierszowe śledzenia stosu co 1 ms, a następnie wyodrębnić i zapisać próbkę 100 milisekund przed tym, jak w śledzenie wchodzi 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
Oto wyniki:
(setki śladów, które wyglądają podobnie)
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
Jest tu wiele informacji, ale najważniejsze jest to, że znajdujemy wzorzec „cadvisor przed ksoftirqd”, który widzieliśmy wcześniej w śladach ICMP. Co to oznacza?
Każdy wiersz to ślad CPU w danym momencie. Każde wywołanie w dół stosu w wierszu jest oddzielone średnikiem. W środku wierszy widzimy wywoływany syscall: read(): .... ;do_syscall_64;sys_read; .... W ten sposób cadvisor spędza dużo czasu na wywołaniu systemowym read(), dotyczącym funkcji mem_cgroup_* (górna część stosu wywołań/koniec wiersza).
W śladzie wywołań trudno zobaczyć, co dokładnie jest odczytywane, więc uruchomimy strace i zobaczymy, co robi cadvisor, i znajdziemy wywołania systemowe trwające dłużej niż 100 ms:
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
Jak można się było spodziewać, tutaj widzimy wolne wywołania read(). Z treści operacji odczytu i kontekstu mem_cgroup widać, że te wywołania read() odnoszą się do pliku memory.stat, który pokazuje użycie pamięci i ograniczenia cgroup (technologia izolacji zasobów w Dockerze). Narzędzie cadvisor odpytywało ten plik, aby uzyskać informacje o użyciu zasobów dla kontenerów. Sprawdźmy, czy to jądro, czy cadvisor robi coś niespodziewanego:
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 ~ $
Teraz możemy odtworzyć błąd i rozumiemy, że jądro Linux napotyka patologię.
Dlaczego operacja odczytu jest tak wolna?
Na tym etapie znacznie łatwiej znaleźć raporty innych użytkowników na temat podobnych problemów. Jak się okazało, w trackerze cadvisor zgłoszono ten błąd jako , po prostu nikt nie zauważył, że opóźnienie również losowo odzwierciedla się w stosie sieciowym. Naprawdę zauważono, że cadvisor zużywa więcej czasu procesora, niż oczekiwano, ale nie przywiązywano do tego szczególnej wagi, ponieważ nasze serwery mają dużo zasobów procesora, więc problem nie był dokładnie badany.
Problem polega na tym, że grupy kontrolne (cgroups) uwzględniają użycie pamięci w przestrzeni nazw (kontenerze). Kiedy wszystkie procesy w tej cgroup kończą działanie, Docker zwalnia grupę kontrolną pamięci. Jednak "pamięć" to nie tylko pamięć procesu. Choć sama pamięć procesów nie jest już używana, okazuje się, że jądro przydziela jeszcze zawartość w pamięci podręcznej, taką jak dentries i inodes (metadane katalogów i plików), które są buforowane w memory cgroup. Z opisu problemu:
cgroups-zombie: grupy kontrolne, w których nie ma procesów i których nie usunięto, ale dla których wciąż przydzielona jest pamięć (w moim przypadku, z pamięci podręcznej dentry, ale może być również przydzielana z pamięci podręcznej stron lub tmpfs).
Sprawdzanie przez jądro wszystkich stron w pamięci podręcznej przy zwalnianiu cgroup może być bardzo wolne, dlatego wybrano opóźniony proces: poczekać, aż te strony zostaną ponownie zażądane, a dopiero wtedy, gdy pamięć będzie rzeczywiście potrzebna, ostatecznie wyczyścić cgroup. Do tego momentu cgroup nadal uwzględnia się przy zbieraniu statystyk.
Z punktu widzenia wydajności poświęcono pamięć na rzecz wydajności: przyspieszenie początkowego czyszczenia poprzez pozostawienie nieco pamięci podręcznej. To w porządku. Kiedy jądro korzysta z ostatniej części pamięci podręcznej, cgroup ostatecznie się czyści, więc nie można tego nazwać „wyciekaniem”. Niestety, konkretna implementacja mechanizmu wyszukiwania memory.stat w tej wersji jądra (4.9), w połączeniu z ogromną ilością pamięci na naszych serwerach, prowadzi do tego, że odzyskanie ostatnich danych z pamięci podręcznej i oczyszczenie cgroup zombie zajmuje znacznie więcej czasu.
Okazało się, że na niektórych naszych węzłach było tak dużo cgroup zombie, że odczyty i opóźnienia przekraczały sekundę.
Sposób obejścia problemu cadvisor polega na natychmiastowym zwolnieniu pamięci podręcznych dentries/inodes w całym systemie, co od razu eliminuje opóźnienie odczytu, a także opóźnienie sieciowe na hoście, ponieważ usunięcie pamięci podręcznej obejmuje zcache'owane strony cgroup zombie, które również są zwalniane. To nie jest rozwiązanie, ale potwierdza przyczynę problemu.
Okazało się, że w nowszych wersjach jądra (4.19+) poprawiono wydajność wywołania memory.stat, co sprawia, że przejście na to jądro eliminuje problem. Jednocześnie mieliśmy narzędzia do wykrywania problematycznych węzłów w klastrach Kubernetes, ich eleganckiego wyłączania i ponownego uruchamiania. Przeszukaliśmy wszystkie klastry, znaleźliśmy węzły z wystarczająco wysokim opóźnieniem i je zrestartowaliśmy. Dało nam to czas na aktualizację systemu operacyjnego na pozostałych serwerach.
Podsumowując
Ponieważ ten błąd zatrzymywał przetwarzanie kolejek NIC RX na setki milisekund, jednocześnie powodował zarówno duże opóźnienie na krótkich połączeniach, jak i opóźnienia w środku połączenia, na przykład między zapytaniami MySQL a pakietami odpowiedzi.
Zrozumienie i wsparcie wydajności najbardziej fundamentalnych systemów, takich jak Kubernetes, jest kluczowe dla niezawodności i szybkości wszystkich usług na ich podstawie. Wszelkie poprawy wydajności Kubernetes przynoszą korzyści wszystkim uruchamianym systemom.
Źródło: habr.com
