Kilka lat temu Kubernetes в официальном блоге GitHub. С тех пор он стал стандартной технологией для развёртывания сервисов. Теперь Kubernetes управляет значительной частью внутренних и публичных служб. Поскольку наши кластеры выросли, а требования к производительности стали более жёсткими, мы стали замечать, что в некоторых службах на Kubernetes спорадически появляются задержки, которые нельзя объяснить нагрузкой самого приложения.
По сути, в приложениях происходит будто случайная сетевая задержка до 100 мс и более, что приводит к тайм-аутам или повторным попыткам. Ожидалось, что службы смогут отвечать на запросы гораздо быстрее 100 мс. Но это невозможно, если само соединение отнимает столько времени. Отдельно мы наблюдали очень быстрые запросы MySQL, которые должны были занимать миллисекунды, и MySQL действительно справлялась за миллисекунды, но с точки зрения запрашивающего приложения ответ занимал 100 мс или больше.
Сразу стало понятно, что проблема возникает только при соединении с узлом Kubernetes, даже если вызов приходил извне Kubernetes. Проще всего воспроизвести проблему в тесте , который запускается с любого внутреннего хоста, тестирует службу Kubernetes на определённом порту, и спорадически регистрирует большую задержку. В этой статье рассмотрим, как нам удалось отследить причину этой проблемы.
Eliminacja niepotrzebnej złożoności w łańcuchu prowadzącej do awarii
Odtwarzając ten sam przykład, chcieliśmy zawęzić zakres problemu i usunąć niepotrzebne warstwy złożoności. Początkowo w przepływie między Vegetą a zasobnikami Kubernetesa było zbyt wiele elementów. Aby zidentyfikować głębszy problem z siecią, należy wykluczyć niektóre z nich.
Klient (Vgeta) tworzy 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 oznacza to, że hermetyzuje pakiety IP sieci nakładkowej wewnątrz pakietów IP centrum danych. Podczas łączenia się z pierwszym węzłem wykonywana jest translacja adresów sieciowych (NAT) stanowy w celu translacji adresu IP i portu węzła Kubernetes na adres IP i port w sieci nakładkowej (a konkretnie pod z aplikacją). W przypadku pakietów przychodzących wykonywana jest odwrotna sekwencja działań. Jest to złożony system z wieloma stanami i wieloma elementami, które są stale aktualizowane i zmieniane w miarę wdrażania i przenoszenia usług.
Użyteczność tcpdump w teście Vegety występuje opóźnienie podczas uzgadniania TCP (między SYN i SYN-ACK). Aby usunąć tę niepotrzebną złożoność, możesz użyć hping3 dla prostych „pingów” z pakietami SYN. Sprawdzamy, czy nie ma opóźnienia w pakiecie odpowiedzi, a następnie resetujemy połączenie. Możemy filtrować dane tak, aby zawierały tylko pakiety dłuższe niż 100 ms i uzyskać łatwiejszy sposób odtworzenia problemu niż pełny test warstwy 7 sieci Vegety. Oto „pingi” węzła Kubernetes przy użyciu protokołu TCP SYN/SYN-ACK na „porcie węzła” usługi (30927) w odstępach 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
Potrafi od razu dokonać pierwszej obserwacji. Sądząc po numerach porządkowych i czasach, jasne jest, że nie są to jednorazowe zatory. Opóźnienie często się kumuluje i ostatecznie jest przetwarzane.
Następnie chcemy dowiedzieć się, które elementy mogą brać udział w powstawaniu zatorów. Może to niektóre z setek reguł iptables w NAT? A może są jakieś problemy z tunelowaniem IPIP w sieci? Jednym ze sposobów sprawdzenia tego jest przetestowanie każdego kroku systemu poprzez jego wyeliminowanie. Co się stanie, jeśli usuniesz logikę NAT i firewall, pozostawiając tylko część IPIP:
Na szczęście Linux ułatwia bezpośredni dostęp do warstwy nakładki IP, jeśli komputer znajduje się w 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
Sądząc po wynikach, problem nadal pozostaje! Nie obejmuje to iptables i NAT. Więc problemem jest TCP? Zobaczmy, jak przebiega zwykły 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
Результаты показывают, что проблема не исчезла. Возможно, это туннель IPIP? Давайте ещё упростим тест:
Czy wszystkie pakiety są przesyłane pomię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 wysyłających sobie nawzajem dowolny pakiet, nawet ping ICMP. Nadal widzą opóźnienia, jeśli host docelowy jest „zły” (niektóre gorsze niż inne).
Teraz ostatnie pytanie: dlaczego opóźnienie występuje tylko na serwerach kube-node? A czy tak się dzieje, gdy kube-node jest nadawcą czy odbiorcą? Na szczęście można to łatwo ustalić, wysyłając pakiet z hosta spoza Kubernetes, ale z tym samym „znanym złym” odbiorcą. 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 uruchomimy te same żądania z poprzedniego źródłowego węzła kube do hosta zewnętrznego (co wyklucza host źródłowy, ponieważ polecenie ping zawiera zarówno komponent RX, jak 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 hping statistic ---
22352 packets transmitted, 22350 packets received, 1% packet loss
round-trip min/avg/max = 0.2/7.6/1010.6 ms
Badając przechwytywanie pakietów z opóźnieniem, uzyskaliśmy dodatkowe informacje. W szczególności nadawca (na dole) widzi ten limit czasu, ale odbiorca (na górze) nie - zobacz kolumnę Delta (w sekundach):
Ponadto, jeśli spojrzysz na różnicę w kolejności pakietów TCP i ICMP (według numerów sekwencyjnych) po stronie odbiorcy, pakiety ICMP zawsze docierają w tej samej kolejności, w jakiej zostały wysłane, ale z innym czasem. Jednocześnie pakiety TCP czasami się przeplatają i niektóre z nich utkną. W szczególności, jeśli sprawdzisz porty pakietów SYN, są one w porządku po stronie nadawcy, ale nie po stronie odbiorcy.
Istnieje subtelna różnica w sposobie nowoczesne serwery (takie jak te w naszym centrum danych) przetwarzają pakiety zawierające TCP lub ICMP. Po nadejściu pakietu karta sieciowa „haszykuje go dla każdego połączenia”, to znaczy próbuje podzielić połączenia na kolejki i wysłać każdą kolejkę do osobnego rdzenia procesora. W przypadku protokołu TCP ten skrót zawiera zarówno źródłowy, jak i docelowy adres IP oraz port. Innymi słowy, każde połączenie jest hashowane (potencjalnie) inaczej. W przypadku protokołu ICMP szyfrowane są tylko adresy IP, ponieważ nie ma portów.
Kolejna nowa obserwacja: w tym okresie obserwujemy opóźnienia ICMP we całej komunikacji między dwoma hostami, ale w protokole TCP nie. To mówi nam, że przyczyna jest prawdopodobnie związana z mieszaniem kolejki RX: przeciążenie prawie na pewno występuje w przetwarzaniu pakietów RX, a nie w wysyłaniu odpowiedzi.
Eliminuje to wysyłanie pakietów z listy możliwych przyczyn. Wiemy teraz, że na niektórych serwerach kube-node problem z przetwarzaniem pakietów występuje po stronie odbioru.
Разбираемся с обработкой пакетов в ядре Linux
Чтобы понять, почему проблема возникает у получателя на некоторых серверах kube-node, давайте посмотрим, как ядро Linux обрабатывает пакеты.
Wracając do najprostszej tradycyjnej realizacji, karta sieciowa odbiera pakiet i wysyła ядру Linux, что есть пакет, который нужно обработать. Ядро останавливает другую работу, переключает контекст на обработчик прерываний, обрабатывает пакет, а затем возвращается к текущим задачам.
To przełączanie kontekstu jest powolne: opóźnienia mogły nie być zauważalne na kartach sieciowych 10 Mb/s w latach 90., ale na nowoczesnych kartach 10G o maksymalnej przepustowości 15 milionów pakietów na sekundę każdy rdzeń małego ośmiordzeniowego serwera może zostać przerwany w milionach razy na sekundę.
Aby nie musieć stale obsługiwać przerwań, wiele lat temu dodano Linuksa : Interfejs API sieci, którego używają wszystkie nowoczesne sterowniki w celu poprawy wydajności przy dużych prędkościach. Przy niskich prędkościach jądro nadal odbiera przerwania z karty sieciowej w stary sposób. Gdy dotrze wystarczająca liczba pakietów przekraczających próg, jądro wyłącza przerwania i zamiast tego rozpoczyna odpytywanie karty sieciowej i zbieranie pakietów partiami. Przetwarzanie odbywa się w softirq, czyli w po wywołaniach systemowych i przerwaniach sprzętowych, gdy jądro (w przeciwieństwie do przestrzeni użytkownika) jest już uruchomione.
Jest to znacznie szybsze, ale powoduje inny problem. Jeśli pakietów jest za dużo, to cały czas poświęcany jest na przetwarzanie pakietów z karty sieciowej, a procesy przestrzeni użytkownika nie mają czasu na faktyczne opróżnienie tych kolejek (odczyt z połączeń TCP itp.). W końcu kolejki się zapełniają i zaczynamy odrzucać pakiety. Próbując znaleźć równowagę, jądro ustala budżet na maksymalną liczbę pakietów przetwarzanych w kontekście softirq. Po przekroczeniu tego budżetu budzi się odrębny wątek ksoftirqd (zobaczysz jeden z nich w ps na rdzeń), który obsługuje te softirq poza normalną ścieżką wywołań systemowych/przerwań. Ten wątek jest planowany przy użyciu standardowego harmonogramu procesów, który stara się sprawiedliwie przydzielać zasoby.
Po przestudiowaniu, w jaki sposób jądro przetwarza pakiety, widać, że istnieje pewne prawdopodobieństwo przeciążenia. Jeśli wywołania softirq są odbierane rzadziej, pakiety będą musiały poczekać jakiś czas na przetworzenie w kolejce RX na karcie sieciowej. Może to być spowodowane jakimś zadaniem blokującym rdzeń procesora lub czymś innym uniemożliwiającym uruchomienie softirq przez rdzeń.
Zawężenie przetwarzania do rdzenia lub metody
Opóźnienia Softirq to na razie tylko przypuszczenie. Ale ma to sens i wiemy, że widzimy coś bardzo podobnego. Zatem kolejnym krokiem będzie potwierdzenie tej teorii. A jeśli zostanie to potwierdzone, znajdź przyczynę opóźnień.
Wróćmy do naszych wolnych 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 wspomniano wcześniej, te pakiety ICMP są mieszane w pojedynczą kolejkę RX NIC i przetwarzane przez pojedynczy rdzeń procesora. Jeśli chcemy zrozumieć, jak działa Linux, warto wiedzieć, gdzie (na którym rdzeniu procesora) i jak (softirq, ksoftirqd) te pakiety są przetwarzane, aby śledzić proces.
Teraz przyszedł czas na wykorzystanie narzędzi pozwalających na monitorowanie jądra Linuksa w czasie rzeczywistym. Tutaj użyliśmy . Ten zestaw narzędzi umożliwia pisanie małych programów w języku C, które przechwytują dowolne funkcje w jądrze i buforują zdarzenia w programie w języku Python w przestrzeni użytkownika, który może je przetworzyć i zwrócić wynik. Podłączanie dowolnych funkcji do jądra jest sprawą złożoną, ale narzędzie zostało zaprojektowane z myślą o maksymalnym bezpieczeństwie i ma na celu śledzenie dokładnie tego rodzaju problemów produkcyjnych, które nie są łatwo odtworzone w środowisku testowym lub programistycznym.
Plan jest prosty: wiemy, że jądro przetwarza pingi ICMP, więc zahaczymy o funkcję jądra , który akceptuje przychodzący pakiet żądania echa ICMP i inicjuje wysyłanie odpowiedzi echa ICMP. Możemy zidentyfikować pakiet, zwiększając numer icmp_seq, co pokazuje hping3 powyżej
kod wygląda na skomplikowane, ale nie jest tak straszne, jak się wydaje. Funkcjonować icmp_echo transmituje struct sk_buff *skb: To jest pakiet z „żądaniem echa”. Możemy to wyśledzić i wyciągnąć sekwencję echo.sequence (co porównuje z icmp_seq przez hping3 выше) i wyślij go do przestrzeni użytkownika. Wygodne jest także przechwycenie bieżącej nazwy/identyfikatora procesu. Poniżej znajdują się 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 11 zmiennik/778 4512 4542 779 raport-szprychy XNUMX
Warto tutaj zaznaczyć, że w kontekście softirq procesy, które wykonały wywołania systemowe, będą widoczne jako „procesy”, podczas gdy w rzeczywistości to jądro bezpiecznie przetwarza pakiety w kontekście jądra.
Za pomocą tego narzędzia możemy powiązać określone procesy z konkretnymi pakietami, które wykazują opóźnienie wynoszące hping3. Uprośćmy to grep na tym przechwytywaniu dla pewnych wartości icmp_seq. Zanotowano pakiety pasujące do powyższych wartości icmp_seq wraz z ich RTT, które zaobserwowaliśmy powyżej (w nawiasach podano oczekiwane wartości RTT dla pakietów, które odfiltrowaliśmy ze względu na wartości RTT mniejsze 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 k softir 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 ksoft irqd/ 11 1961 ** (19 ms) 76 76 ksoftirqd/11 1962 ** (9 ms) -- 10137 10436 cadvisor 2068 10137 10436 cadvisor 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 ** (15ms ) 76 76 ksoftirqd/11 2077 ** (5ms)
Wyniki mówią nam kilka rzeczy. Po pierwsze, wszystkie te pakiety są przetwarzane przez kontekst ksoftirqd/11. Oznacza to, że dla tej konkretnej pary maszyn pakiety ICMP zostały zaszyfrowane do rdzenia 11 po stronie odbiorczej. Widzimy również, że zawsze, gdy występuje zacięcie, istnieją pakiety przetwarzane w kontekście wywołania systemowego cadvisor. Potem ksoftirqd przejmuje zadanie i przetwarza zgromadzoną kolejkę: dokładnie taką liczbę pakietów, jaka została zgromadzona później cadvisor.
Fakt, że bezpośrednio przed tym zawsze działa cadvisor, oznacza jego zaangażowanie w problem. Jak na ironię, cel - „analizuj wykorzystanie zasobów i charakterystykę wydajności działających kontenerów”, zamiast powodować ten problem z wydajnością.
Podobnie jak w przypadku innych aspektów kontenerów, wszystkie te narzędzia są bardzo zaawansowane i w pewnych nieprzewidzianych okolicznościach mogą wystąpić problemy z wydajnością.
Co robi cadvisor, że spowalnia kolejkę pakietów?
Teraz całkiem dobrze rozumiemy, jak dochodzi do awarii, jaki proces ją powoduje i na którym procesorze. Widzimy, że z powodu twardego blokowania jądro Linuksa nie ma czasu na planowanie ksoftirqd. Widzimy, że pakiety są przetwarzane w kontekście cadvisor. Logiczne jest założenie tego cadvisor uruchamia powolne wywołanie systemowe, po którym przetwarzane są wszystkie zgromadzone w tym czasie pakiety:
To teoria, ale jak ją sprawdzić? Jedyne, co możemy zrobić, to prześledzić rdzeń procesora podczas całego procesu, znaleźć moment, w którym liczba pakietów przekracza budżet i zostaje wywołane polecenie ksoftirqd, a następnie spojrzeć nieco dalej, aby zobaczyć, co dokładnie działo się w rdzeniu procesora tuż przed tym punktem . To jakby prześwietlać procesor co kilka milisekund. Będzie to wyglądać mniej więcej tak:
Dogodnie, wszystko to można zrobić za pomocą istniejących narzędzi. Na przykład, sprawdza dany rdzeń procesora z określoną częstotliwością i może wygenerować harmonogram wywołań działającego systemu, uwzględniający zarówno przestrzeń użytkownika, jak i jądro Linuksa. Możesz wziąć ten zapis i przetworzyć go za pomocą małego forka programu od Brendana Gregga, który zachowuje kolejność śledzenia stosu. Możemy zapisywać jednoliniowe ślady stosu co 1 ms, a następnie podświetlać i zapisywać próbkę 100 milisekund przed trafieniem śladu 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:
(сотни следов, которые выглядят похожими)
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 rzeczy, ale najważniejsze jest to, że znajdujemy wzorzec „cadvisor przed ksoftirqd”, który widzieliśmy wcześniej w znaczniku ICMP. Co to znaczy?
Każda linia to ślad procesora w określonym momencie. Każde wywołanie w dół stosu w linii jest oddzielone średnikiem. W środku linii widzimy wywołanie syscall: read(): .... ;do_syscall_64;sys_read; .... Dlatego cadvisor spędza dużo czasu na wywołaniach systemowych read()związane z funkcjami mem_cgroup_* (góra stosu wywołań/koniec linii).
Niewygodne jest sprawdzanie w śledzeniu wywołania, co dokładnie jest czytane, więc uciekajmy strace i zobaczmy, co robi cadvisor i znajdź wywołania systemowe dłuższe niż 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>
Jak można się spodziewać, widzimy tutaj powolne połączenia read(). Z zawartości operacji odczytu i kontekstu mem_cgroup jasne jest, że są to wyzwania read() zapoznaj się z plikiem memory.stat, który pokazuje użycie pamięci i limity cgroup (technologia izolacji zasobów Dockera). Narzędzie cadvisor wysyła zapytanie do tego pliku, aby uzyskać informacje o wykorzystaniu zasobów dla kontenerów. Sprawdźmy, czy to jądro lub cadvisor robią coś nieoczekiwanego:
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 zrozumieć, że jądro Linuksa stoi w obliczu patologii.
Dlaczego operacja odczytu jest tak powolna?
Na tym etapie znacznie łatwiej jest znaleźć wiadomości od innych użytkowników dotyczące podobnych problemów. Jak się okazało, w trackerze cadvisor błąd ten został zgłoszony jako , po prostu nikt nie zauważył, że opóźnienie jest również losowo odzwierciedlane w stosie sieciowym. Rzeczywiście zauważono, że cadvisor zużywał więcej czasu procesora, niż oczekiwano, ale nie przywiązano do tego dużej wagi, ponieważ nasze serwery mają dużo zasobów procesora, więc problem nie został dokładnie zbadany.
Problem polega na tym, że cgroups uwzględniają użycie pamięci w przestrzeni nazw (kontenerze). Kiedy wszystkie procesy w tej grupie cgroup zostaną zakończone, Docker zwalnia grupę pamięci. Jednak „pamięć” to nie tylko pamięć procesowa. Chociaż sama pamięć procesowa nie jest już używana, wydaje się, że jądro nadal przypisuje zawartość buforowaną, taką jak dentry i i-węzły (metadane katalogów i plików), które są buforowane w grupie pamięci. Z opisu problemu:
cgroups zombie: cgroups, które nie mają procesów i zostały usunięte, ale nadal mają przydzieloną pamięć (w moim przypadku z pamięci podręcznej Dentry, ale można ją również przydzielić z pamięci podręcznej strony lub tmpfs).
Sprawdzanie przez jądro wszystkich stron w pamięci podręcznej podczas zwalniania grupy c może być bardzo powolne, dlatego wybierany jest leniwy proces: poczekaj, aż te strony zostaną ponownie zażądane, a następnie w końcu wyczyść grupę c, gdy pamięć będzie rzeczywiście potrzebna. Do tego momentu cgroup jest nadal brana pod uwagę przy zbieraniu statystyk.
Z punktu widzenia wydajności poświęcili pamięć na rzecz wydajności: przyspieszając wstępne czyszczenie, pozostawiając część pamięci podręcznej. Jest okej. Kiedy jądro wykorzystuje ostatnią część pamięci podręcznej, grupa cgroup zostaje ostatecznie wyczyszczona, więc nie można tego nazwać „wyciekiem”. Niestety specyficzna implementacja mechanizmu wyszukiwania memory.stat w tej wersji jądra (4.9), w połączeniu z ogromną ilością pamięci na naszych serwerach, oznacza, że przywrócenie najnowszych danych z pamięci podręcznej i usunięcie zombie z grupy cgroup zajmuje znacznie więcej czasu.
Okazuje się, że w niektórych naszych węzłach było tak wiele zombie z grupy cgroup, że odczyt i opóźnienie przekraczały sekundę.
Rozwiązaniem problemu cadvisora jest natychmiastowe zwolnienie pamięci podręcznej Dentry/i-węzłów w całym systemie, co natychmiast eliminuje opóźnienia w odczycie, a także opóźnienia sieci na hoście, ponieważ wyczyszczenie pamięci podręcznej włącza buforowane strony cgroup zombie i je również uwalnia. Nie jest to rozwiązanie, ale potwierdza przyczynę problemu.
Okazało się, że w nowszych wersjach jądra (4.19+) poprawiono wydajność wywołań memory.stat, więc przejście na to jądro rozwiązało problem. Jednocześnie dysponowaliśmy narzędziami do wykrywania problematycznych węzłów w klastrach Kubernetes, płynnego ich opróżniania i ponownego uruchamiania. Przeszukaliśmy wszystkie klastry, znaleźliśmy węzły o wystarczająco dużym opóźnieniu i zrestartowaliśmy je. Dało nam to czas na aktualizację systemu operacyjnego na pozostałych serwerach.
Reasumując
Ponieważ błąd ten zatrzymywał przetwarzanie kolejki karty sieciowej RX na setki milisekund, powodował jednocześnie zarówno duże opóźnienia w przypadku krótkich połączeń, jak i opóźnienia w połowie połączeń, na przykład między żądaniami MySQL a pakietami odpowiedzi.
Понимание и поддержка производительности самых фундаментальных систем, таких как Kubernetes, имеет решающее значение для надёжности и скорости всех сервисов на их основе. От улучшений производительности Kubernetes выигрывают все запускаемые системы.
Źródło: www.habr.com