Il y a quelques années, Kubernetes sur le blog officiel GitHub. Depuis, elle est devenue la technologie standard pour déployer des services. Kubernetes gère désormais une part importante des services internes et publics. À mesure que nos clusters se développaient et que les exigences de performances devenaient plus strictes, nous avons commencé à remarquer que certains services sur Kubernetes connaissaient sporadiquement une latence qui ne pouvait pas être expliquée par la charge de l'application elle-même.
Essentiellement, les applications subissent une latence réseau aléatoire pouvant atteindre 100 ms ou plus, ce qui entraîne des délais d'attente ou des tentatives. Les services devaient être capables de répondre aux demandes bien plus rapidement que 100 ms. Mais cela est impossible si la connexion elle-même prend autant de temps. Par ailleurs, nous avons observé des requêtes MySQL très rapides qui devraient prendre quelques millisecondes, et MySQL s'est terminé en millisecondes, mais du point de vue de l'application requérante, la réponse a pris 100 ms ou plus.
Il est immédiatement devenu évident que le problème ne survenait que lors de la connexion à un nœud Kubernetes, même si l'appel provenait de l'extérieur de Kubernetes. Le moyen le plus simple de reproduire le problème est de réaliser un test , qui s'exécute à partir de n'importe quel hôte interne, teste le service Kubernetes sur un port spécifique et enregistre sporadiquement une latence élevée. Dans cet article, nous verrons comment nous avons pu localiser la cause de ce problème.
Éliminer la complexité inutile dans la chaîne menant à l'échec
En reproduisant le même exemple, nous voulions affiner le problème et supprimer les niveaux de complexité inutiles. Au départ, il y avait trop d’éléments dans le flux entre Vegeta et les pods Kubernetes. Pour identifier un problème de réseau plus profond, vous devez en exclure certains.
Le client (Vegeta) crée une connexion TCP avec n'importe quel nœud du cluster. Kubernetes fonctionne comme un réseau superposé (au-dessus du réseau de centre de données existant) qui utilise , c'est-à-dire qu'il encapsule les paquets IP du réseau superposé à l'intérieur des paquets IP du centre de données. Lors de la connexion au premier nœud, la traduction d'adresse réseau est effectuée (NAT) avec état pour traduire l'adresse IP et le port du nœud Kubernetes en adresse IP et en port dans le réseau superposé (en particulier, le pod avec l'application). Pour les paquets entrants, la séquence d'actions inverse est effectuée. Il s'agit d'un système complexe avec de nombreux états et de nombreux éléments qui sont constamment mis à jour et modifiés à mesure que les services sont déployés et déplacés.
Utilitaire tcpdump dans le test Vegeta, il y a un délai lors de la prise de contact TCP (entre SYN et SYN-ACK). Pour supprimer cette complexité inutile, vous pouvez utiliser hping3 pour de simples « pings » avec des paquets SYN. Nous vérifions s'il y a un retard dans le paquet de réponse, puis réinitialisons la connexion. Nous pouvons filtrer les données pour inclure uniquement les paquets supérieurs à 100 ms et obtenir un moyen plus simple de reproduire le problème que le test complet de la couche réseau 7 de Vegeta. Voici les « pings » du nœud Kubernetes utilisant TCP SYN/SYN-ACK sur le « port du nœud » du service (30927) à des intervalles de 10 ms, filtrés par les réponses les plus lentes :
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
Peut immédiatement faire la première observation. À en juger par les numéros de séquence et les horaires, il est clair qu’il ne s’agit pas de congestions ponctuelles. Le retard s’accumule souvent et finit par être traité.
Nous souhaitons ensuite découvrir quels composants peuvent être impliqués dans l’apparition d’une congestion. Peut-être s'agit-il de quelques-unes des centaines de règles iptables dans NAT ? Ou y a-t-il des problèmes avec le tunneling IPIP sur le réseau ? Une façon de vérifier cela consiste à tester chaque étape du système en l’éliminant. Que se passe-t-il si vous supprimez la logique NAT et pare-feu, ne laissant que la partie IPIP :
Heureusement, Linux facilite l'accès direct à la couche de superposition IP si la machine est sur le même réseau :
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
A en juger par les résultats, le problème demeure ! Cela exclut iptables et NAT. Alors le problème vient de TCP ? Voyons comment se déroule un ping ICMP régulier :
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
Les résultats montrent que le problème n’a pas disparu. Peut-être s'agit-il d'un tunnel IPIP ? Simplifions encore le test :
Tous les paquets sont-ils envoyés entre ces deux hôtes ?
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
Nous avons simplifié la situation : deux nœuds Kubernetes s'envoient n'importe quel paquet, même un ping ICMP. Ils voient toujours la latence si l'hôte cible est « mauvais » (certains pires que d'autres).
Maintenant, la dernière question : pourquoi le retard ne se produit-il que sur les serveurs kube-node ? Et cela se produit-il lorsque kube-node est l'expéditeur ou le destinataire ? Heureusement, cela est également assez facile à comprendre en envoyant un paquet depuis un hôte extérieur à Kubernetes, mais avec le même destinataire « incorrect connu ». Comme vous pouvez le constater, le problème n'a pas disparu :
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
Nous exécuterons ensuite les mêmes requêtes du nœud Kube source précédent vers l'hôte externe (ce qui exclut l'hôte source puisque le ping inclut à la fois un composant RX et 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
En examinant les captures de paquets de latence, nous avons obtenu des informations supplémentaires. Plus précisément, l'expéditeur (en bas) voit ce délai d'attente, mais pas le destinataire (en haut) - voir la colonne Delta (en secondes) :
De plus, si vous regardez la différence dans l'ordre des paquets TCP et ICMP (par numéros de séquence) du côté destinataire, les paquets ICMP arrivent toujours dans le même ordre dans lequel ils ont été envoyés, mais avec un timing différent. Dans le même temps, les paquets TCP s'entrelacent parfois et certains d'entre eux restent bloqués. En particulier, si vous examinez les ports des paquets SYN, ils sont en ordre du côté de l'expéditeur, mais pas du côté du destinataire.
Il y a une différence subtile dans la façon dont les serveurs modernes (comme ceux de notre centre de données) traitent les paquets contenant TCP ou ICMP. Lorsqu'un paquet arrive, la carte réseau « le hache par connexion », c'est-à-dire qu'elle essaie de diviser les connexions en files d'attente et d'envoyer chaque file d'attente à un cœur de processeur distinct. Pour TCP, ce hachage inclut à la fois l’adresse IP et le port source et destination. En d’autres termes, chaque connexion est hachée (potentiellement) différemment. Pour ICMP, seules les adresses IP sont hachées, puisqu'il n'y a pas de ports.
Autre observation nouvelle : pendant cette période, nous constatons des retards ICMP sur toutes les communications entre deux hôtes, mais pas TCP. Cela nous indique que la cause est probablement liée au hachage de la file d'attente RX : la congestion concerne presque certainement le traitement des paquets RX, et non l'envoi des réponses.
Cela élimine l'envoi de paquets de la liste des causes possibles. Nous savons maintenant que le problème de traitement des paquets se situe du côté de la réception sur certains serveurs Kube-Node.
Comprendre le traitement des paquets dans le noyau Linux
Pour comprendre pourquoi le problème se produit au niveau du récepteur sur certains serveurs Kube-Node, regardons comment le noyau Linux traite les paquets.
Revenant à la mise en œuvre traditionnelle la plus simple, la carte réseau reçoit le paquet et envoie le noyau Linux qu'il existe un paquet qui doit être traité. Le noyau arrête tout autre travail, bascule le contexte vers le gestionnaire d'interruption, traite le paquet, puis revient aux tâches en cours.
Ce changement de contexte est lent : la latence n'était peut-être pas perceptible sur les cartes réseau 10 Mbps dans les années 90, mais sur les cartes 10G modernes avec un débit maximum de 15 millions de paquets par seconde, chaque cœur d'un petit serveur à huit cœurs peut être interrompu par des millions. de fois par seconde.
Afin de ne pas gérer constamment les interruptions, Linux a ajouté il y a de nombreuses années : API réseau que tous les pilotes modernes utilisent pour améliorer les performances à grande vitesse. À basse vitesse, le noyau reçoit toujours les interruptions de la carte réseau selon l'ancienne méthode. Une fois que suffisamment de paquets arrivent dépassant le seuil, le noyau désactive les interruptions et commence à interroger la carte réseau et à récupérer les paquets par morceaux. Le traitement est effectué dans softirq, c'est-à-dire dans après les appels système et les interruptions matérielles, lorsque le noyau (contrairement à l'espace utilisateur) est déjà en cours d'exécution.
C'est beaucoup plus rapide, mais cela pose un problème différent. S'il y a trop de paquets, alors tout le temps est consacré au traitement des paquets de la carte réseau et les processus de l'espace utilisateur n'ont pas le temps de vider réellement ces files d'attente (lecture des connexions TCP, etc.). Finalement, les files d'attente se remplissent et nous commençons à supprimer des paquets. Pour tenter de trouver un équilibre, le noyau définit un budget pour le nombre maximum de paquets traités dans le contexte softirq. Une fois ce budget dépassé, un fil de discussion distinct est réveillé ksoftirqd (vous en verrez un dans ps par cœur) qui gère ces softirqs en dehors du chemin normal d'appel système/d'interruption. Ce thread est planifié à l'aide du planificateur de processus standard, qui tente d'allouer équitablement les ressources.
Après avoir étudié la manière dont le noyau traite les paquets, vous pouvez constater qu'il existe une certaine probabilité de congestion. Si les appels softirq sont reçus moins fréquemment, les paquets devront attendre un certain temps pour être traités dans la file d'attente RX sur la carte réseau. Cela peut être dû à une tâche bloquant le cœur du processeur ou à quelque chose d'autre qui empêche le cœur d'exécuter softirq.
Réduire le traitement au cœur ou à la méthode
Les retards de Softirq ne sont qu'une supposition pour l'instant. Mais c’est logique, et nous savons que nous assistons à quelque chose de très similaire. La prochaine étape consiste donc à confirmer cette théorie. Et si cela se confirme, trouvez la raison des retards.
Revenons à nos paquets lents :
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
Comme indiqué précédemment, ces paquets ICMP sont hachés dans une seule file d'attente de carte réseau RX et traités par un seul cœur de processeur. Si l'on veut comprendre le fonctionnement de Linux, il est utile de savoir où (sur quel cœur de CPU) et comment (softirq, ksoftirqd) ces packages sont traités afin de suivre le processus.
Il est maintenant temps d'utiliser des outils qui vous permettent de surveiller le noyau Linux en temps réel. Ici, nous avons utilisé . Cet ensemble d'outils vous permet d'écrire de petits programmes C qui accrochent des fonctions arbitraires dans le noyau et mettent les événements en mémoire tampon dans un programme Python en espace utilisateur qui peut les traiter et vous renvoyer le résultat. L'intégration de fonctions arbitraires dans le noyau est une question complexe, mais l'utilitaire est conçu pour une sécurité maximale et pour détecter exactement le type de problèmes de production qui ne sont pas facilement reproduits dans un environnement de test ou de développement.
Le plan ici est simple : nous savons que le noyau traite ces pings ICMP, nous allons donc mettre un hook sur la fonction du noyau. , qui accepte un paquet de demande d'écho ICMP entrant et lance l'envoi d'une réponse d'écho ICMP. Nous pouvons identifier un paquet en augmentant le numéro icmp_seq, qui affiche hping3 ci-dessus.
Code ça a l'air compliqué, mais ce n'est pas aussi effrayant qu'il y paraît. Fonction icmp_echo transmet struct sk_buff *skb: Il s'agit d'un paquet avec une "demande d'écho". Nous pouvons le suivre, extraire la séquence echo.sequence (ce qui se compare à icmp_seq par hping3 выше), et envoyez-le à l’espace utilisateur. Il est également pratique de capturer le nom/identifiant du processus actuel. Vous trouverez ci-dessous les résultats que nous voyons directement pendant que le noyau traite les paquets :
TGID PID NOM DU PROCESSUS 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 swapper/778 4512 4542 779 rayons-rapport-s XNUMX
Il convient de noter ici que dans le contexte softirq les processus qui ont effectué des appels système apparaîtront comme des « processus » alors qu'en fait c'est le noyau qui traite les paquets en toute sécurité dans le contexte du noyau.
Avec cet outil, nous pouvons associer des processus spécifiques à des packages spécifiques qui présentent un retard de hping3. Faisons simple grep sur cette capture pour certaines valeurs icmp_seq. Les paquets correspondant aux valeurs icmp_seq ci-dessus ont été notés avec leur RTT que nous avons observé ci-dessus (entre parenthèses se trouvent les valeurs RTT attendues pour les paquets que nous avons filtrés en raison de valeurs RTT inférieures à 50 ms) :
TGID PID NOM DU PROCESSUS 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 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 j/2071 65 ** 76ms 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 ** (XNUMX ms)
Les résultats nous disent plusieurs choses. Premièrement, tous ces packages sont traités par le contexte ksoftirqd/11. Cela signifie que pour cette paire de machines particulière, les paquets ICMP ont été hachés vers le cœur 11 à la réception. Nous voyons également que chaque fois qu'il y a un bourrage, certains paquets sont traités dans le cadre de l'appel système. cadvisor. Alors ksoftirqd prend en charge la tâche et traite la file d'attente accumulée : exactement le nombre de paquets accumulés après cadvisor.
Le fait qu'immédiatement avant cela fonctionne toujours cadvisor, implique son implication dans le problème. Ironiquement, le but - "analyser l'utilisation des ressources et les caractéristiques de performances des conteneurs en cours d'exécution" plutôt que de provoquer ce problème de performances.
Comme pour d’autres aspects des conteneurs, ce sont tous des outils très avancés et on peut s’attendre à ce qu’ils rencontrent des problèmes de performances dans certaines circonstances imprévues.
Que fait Cadvisor pour ralentir la file d'attente des paquets ?
Nous comprenons maintenant assez bien comment le crash se produit, quel processus en est la cause et sur quel processeur. On voit qu'en raison d'un blocage dur, le noyau Linux n'a pas le temps de planifier ksoftirqd. Et on voit que les paquets sont traités en contexte cadvisor. Il est logique de supposer que cadvisor lance un appel système lent, après quoi tous les paquets accumulés à ce moment-là sont traités :
C'est une théorie, mais comment la tester ? Ce que nous pouvons faire, c'est retracer le cœur du processeur tout au long de ce processus, trouver le point où le nombre de paquets dépasse le budget et où ksoftirqd est appelé, puis regarder un peu plus en arrière pour voir ce qui fonctionnait exactement sur le cœur du processeur juste avant ce point. . C'est comme radiographier le processeur toutes les quelques millisecondes. Cela ressemblera à ceci :
Idéalement, tout cela peut être fait avec les outils existants. Par exemple, vérifie un cœur de processeur donné à une fréquence spécifiée et peut générer un calendrier d'appels au système en cours d'exécution, incluant à la fois l'espace utilisateur et le noyau Linux. Vous pouvez prendre cet enregistrement et le traiter à l'aide d'un petit fork du programme de Brendan Gregg, qui préserve l'ordre de la trace de la pile. Nous pouvons enregistrer les traces de pile sur une seule ligne toutes les 1 ms, puis mettre en évidence et enregistrer un échantillon 100 millisecondes avant que la trace n'arrive. 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
Voici les résultats:
(сотни следов, которые выглядят похожими)
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
Il y a beaucoup de choses ici, mais l'essentiel est que l'on retrouve le modèle « cadvisor avant ksoftirqd » que nous avons vu plus tôt dans le traceur ICMP. Qu'est-ce que ça veut dire?
Chaque ligne est une trace du processeur à un moment donné. Chaque appel de la pile sur une ligne est séparé par un point-virgule. Au milieu des lignes, nous voyons l'appel système appelé : read(): .... ;do_syscall_64;sys_read; .... Cadvisor passe donc beaucoup de temps sur l'appel système read()liés aux fonctions mem_cgroup_* (haut de la pile d'appels/fin de ligne).
Il n'est pas pratique de voir dans une trace d'appel ce qui est exactement lu, alors allons-y strace et voyons ce que fait Cadvisor et trouvons les appels système de plus de 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>
Comme vous vous en doutez, nous voyons ici des appels lents read(). À partir du contenu des opérations de lecture et du contexte mem_cgroup il est clair que ces défis read() se référer au dossier memory.stat, qui affiche l'utilisation de la mémoire et les limites du groupe de contrôle (la technologie d'isolation des ressources de Docker). L'outil Cadvisor interroge ce fichier pour obtenir des informations sur l'utilisation des ressources pour les conteneurs. Vérifions si c'est le noyau ou Cadvisor qui fait quelque chose d'inattendu :
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 ~ $
On peut désormais reproduire le bug et comprendre que le noyau Linux est confronté à une pathologie.
Pourquoi l'opération de lecture est-elle si lente ?
À ce stade, il est beaucoup plus facile de trouver des messages d'autres utilisateurs concernant des problèmes similaires. Il s'est avéré que dans le tracker Cadvisor, ce bug a été signalé comme , c'est juste que personne n'a remarqué que la latence se reflète également de manière aléatoire dans la pile réseau. Il a en effet été remarqué que cadvisor consommait plus de temps CPU que prévu, mais cela n'a pas été accordé beaucoup d'importance, car nos serveurs disposent de beaucoup de ressources CPU, le problème n'a donc pas été soigneusement étudié.
Le problème est que les groupes de contrôle prennent en compte l'utilisation de la mémoire dans l'espace de noms (conteneur). Lorsque tous les processus de ce groupe de contrôle se terminent, Docker libère le groupe de contrôle mémoire. Cependant, la « mémoire » ne se limite pas à la mémoire des processus. Bien que la mémoire du processus elle-même ne soit plus utilisée, il semble que le noyau attribue toujours des contenus mis en cache, tels que des dentries et des inodes (métadonnées de répertoire et de fichier), qui sont mis en cache dans le groupe de contrôle de mémoire. D'après la description du problème :
groupes de contrôle zombie : groupes de contrôle qui n'ont aucun processus et qui ont été supprimés, mais qui ont toujours de la mémoire allouée (dans mon cas, à partir du cache dentry, mais elle peut également être allouée à partir du cache de pages ou de tmpfs).
La vérification par le noyau de toutes les pages du cache lors de la libération d'un groupe de contrôle peut être très lente, c'est pourquoi le processus paresseux est choisi : attendre que ces pages soient à nouveau demandées, puis enfin effacer le groupe de contrôle lorsque la mémoire est réellement nécessaire. Jusqu’à présent, cgroup est toujours pris en compte lors de la collecte des statistiques.
Du point de vue des performances, ils ont sacrifié la mémoire au profit des performances : ils ont accéléré le nettoyage initial en laissant de la mémoire cache derrière eux. C'est bon. Lorsque le noyau utilise la dernière mémoire mise en cache, le groupe de contrôle est finalement effacé, il ne peut donc pas être qualifié de « fuite ». Malheureusement, la mise en œuvre spécifique du mécanisme de recherche memory.stat dans cette version du noyau (4.9), combiné à l'énorme quantité de mémoire sur nos serveurs, cela signifie qu'il faut beaucoup plus de temps pour restaurer les dernières données mises en cache et éliminer les zombies du groupe de contrôle.
Il s'avère que certains de nos nœuds avaient tellement de zombies de groupe de contrôle que la lecture et la latence dépassaient la seconde.
La solution de contournement au problème de Cadvisor consiste à libérer immédiatement les caches dentries/inodes dans tout le système, ce qui élimine immédiatement la latence de lecture ainsi que la latence du réseau sur l'hôte, car la suppression du cache active les pages du groupe de contrôle zombie mises en cache et les libère également. Ce n'est pas une solution, mais cela confirme la cause du problème.
Il s'est avéré que dans les versions plus récentes du noyau (4.19+), les performances des appels ont été améliorées. memory.stat, donc le passage à ce noyau a résolu le problème. Dans le même temps, nous disposions d'outils pour détecter les nœuds problématiques dans les clusters Kubernetes, les drainer en douceur et les redémarrer. Nous avons passé au peigne fin tous les clusters, trouvé des nœuds avec une latence suffisamment élevée et les avons redémarrés. Cela nous a donné le temps de mettre à jour le système d'exploitation sur les serveurs restants.
Résumant
Étant donné que ce bug a arrêté le traitement de la file d'attente de la carte réseau RX pendant des centaines de millisecondes, il a simultanément provoqué une latence élevée sur les connexions courtes et une latence à mi-connexion, comme entre les requêtes MySQL et les paquets de réponse.
Comprendre et maintenir les performances des systèmes les plus fondamentaux, tels que Kubernetes, est essentiel à la fiabilité et à la rapidité de tous les services qui en dépendent. Chaque système que vous exécutez bénéficie des améliorations de performances de Kubernetes.
Source: habr.com