Fa un parell d'anys Kubernetes al bloc oficial de GitHub. Des de llavors, s'ha convertit en la tecnologia estàndard per desplegar serveis. Kubernetes gestiona ara una part important dels serveis interns i públics. A mesura que els nostres clústers van créixer i els requisits de rendiment es van fer més estrictes, vam començar a notar que alguns serveis de Kubernetes experimentaven esporàdicament una latència que no es podia explicar per la càrrega de l'aplicació mateixa.
Essencialment, les aplicacions experimenten una latència de xarxa aleatòria de fins a 100 ms o més, cosa que provoca temps d'espera o reintents. S'esperava que els serveis poguessin respondre a les sol·licituds molt més ràpidament que 100 ms. Però això és impossible si la connexió en si porta tant de temps. Per separat, vam observar consultes MySQL molt ràpides que haurien de trigar mil·lisegons, i MySQL es va completar en mil·lisegons, però des de la perspectiva de l'aplicació sol·licitant, la resposta va trigar 100 ms o més.
Immediatament es va fer evident que el problema només es va produir quan es connectava a un node de Kubernetes, fins i tot si la trucada venia de fora de Kubernetes. La manera més senzilla de reproduir el problema és en una prova , que s'executa des de qualsevol host intern, prova el servei Kubernetes en un port específic i registra esporàdicament una alta latència. En aquest article, veurem com hem pogut localitzar la causa d'aquest problema.
Eliminació de la complexitat innecessària de la cadena que condueix al fracàs
En reproduir el mateix exemple, hem volgut reduir el focus del problema i eliminar capes de complexitat innecessàries. Inicialment, hi havia massa elements en el flux entre Vegeta i les beines de Kubernetes. Per identificar un problema de xarxa més profund, cal descartar-ne alguns.
El client (Vegeta) crea una connexió TCP amb qualsevol node del clúster. Kubernetes funciona com una xarxa superposada (a sobre de la xarxa del centre de dades existent) que utilitza , és a dir, encapsula els paquets IP de la xarxa de superposició dins dels paquets IP del centre de dades. Quan es connecta al primer node, es realitza la traducció d'adreces de xarxa (NAT) amb estat per traduir l'adreça IP i el port del node Kubernetes a l'adreça IP i el port de la xarxa de superposició (concretament, el pod amb l'aplicació). Per als paquets entrants, es realitza la seqüència inversa d'accions. És un sistema complex amb molt d'estat i molts elements que s'actualitzen i canvien constantment a mesura que es despleguen i es mouen serveis.
Utilitat tcpdump a la prova de Vegeta hi ha un retard durant la connexió de mans TCP (entre SYN i SYN-ACK). Per eliminar aquesta complexitat innecessària, podeu utilitzar hping3 per a "pings" senzills amb paquets SYN. Comprovem si hi ha un retard en el paquet de resposta i després restablirem la connexió. Podem filtrar les dades per incloure només paquets de més de 100 ms i obtenir una manera més fàcil de reproduir el problema que la prova completa de la capa 7 de xarxa de Vegeta. Aquí hi ha "pings" del node de Kubernetes que utilitzen TCP SYN/SYN-ACK al "port del node" del servei (30927) a intervals de 10 ms, filtrats per les respostes més 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
Pot fer immediatament la primera observació. A jutjar pels números de seqüència i els temps, és evident que no es tracta de congestions puntuals. El retard sovint s'acumula i finalment es processa.
A continuació, volem esbrinar quins components poden estar implicats en l'aparició de congestió. Potser aquestes són algunes dels centenars de regles d'iptables a NAT? O hi ha problemes amb el túnel IPIP a la xarxa? Una manera de comprovar-ho és provar cada pas del sistema eliminant-lo. Què passa si elimineu NAT i la lògica del tallafoc, deixant només la part IPIP:
Afortunadament, Linux facilita l'accés a la capa de superposició IP directament si la màquina es troba a la mateixa xarxa:
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 jutjar pels resultats, el problema segueix sent! Això exclou iptables i NAT. Així que el problema és TCP? Vegem com funciona un ping ICMP normal:
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
Els resultats mostren que el problema no ha desaparegut. Potser això és un túnel IPIP? Simplificam encara més la prova:
S'envien tots els paquets entre aquests dos amfitrions?
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
Hem simplificat la situació a dos nodes Kubernetes que s'envien mútuament qualsevol paquet, fins i tot un ping ICMP. Encara veuen latència si l'amfitrió objectiu és "dolent" (alguns pitjors que altres).
Ara l'última pregunta: per què el retard només es produeix als servidors kube-node? I passa quan kube-node és l'emissor o el receptor? Afortunadament, això també és bastant fàcil d'esbrinar enviant un paquet des d'un amfitrió fora de Kubernetes, però amb el mateix destinatari "dolent conegut". Com podeu veure, el problema no ha desaparegut:
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
A continuació, executarem les mateixes sol·licituds des del node kube d'origen anterior a l'amfitrió extern (que exclou l'amfitrió d'origen ja que el ping inclou un component 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 hping statistic ---
22352 packets transmitted, 22350 packets received, 1% packet loss
round-trip min/avg/max = 0.2/7.6/1010.6 ms
En examinar les captures de paquets de latència, vam obtenir informació addicional. Concretament, que el remitent (a baix) veu aquest temps d'espera, però el destinatari (a dalt) no, veu la columna Delta (en segons):
A més, si observeu la diferència en l'ordre dels paquets TCP i ICMP (per números de seqüència) al costat del destinatari, els paquets ICMP sempre arriben en la mateixa seqüència en què es van enviar, però amb un temps diferent. Al mateix temps, els paquets TCP de vegades s'entrellacen i alguns d'ells s'enganxen. En particular, si examineu els ports dels paquets SYN, estan en ordre pel costat de l'emissor, però no pel costat del receptor.
Hi ha una diferència subtil en com els servidors moderns (com els del nostre centre de dades) processen paquets que contenen TCP o ICMP. Quan arriba un paquet, l'adaptador de xarxa el "hash per connexió", és a dir, intenta trencar les connexions en cues i enviar cada cua a un nucli de processador independent. Per a TCP, aquest hash inclou tant l'adreça IP i el port d'origen com de destinació. En altres paraules, cada connexió té un hash (potencialment) diferent. Per a ICMP, només les adreces IP tenen hash, ja que no hi ha ports.
Una altra observació nova: durant aquest període veiem retards ICMP en totes les comunicacions entre dos amfitrions, però TCP no. Això ens diu que la causa probablement està relacionada amb el hashing de la cua RX: la congestió és gairebé segura en el processament dels paquets RX, no en l'enviament de respostes.
Això elimina l'enviament de paquets de la llista de possibles causes. Ara sabem que el problema de processament de paquets es troba al costat de la recepció en alguns servidors de nodes kube.
Comprensió del processament de paquets al nucli Linux
Per entendre per què es produeix el problema al receptor d'alguns servidors de nodes kube, mirem com processa els paquets el nucli de Linux.
Tornant a la implementació tradicional més senzilla, la targeta de xarxa rep el paquet i envia el nucli de Linux que hi ha un paquet que s'ha de processar. El nucli atura altres treballs, canvia el context al controlador d'interrupcions, processa el paquet i després torna a les tasques actuals.
Aquest canvi de context és lent: la latència potser no es notava a les targetes de xarxa de 10 Mbps als anys 90, però a les targetes de 10G modernes amb un rendiment màxim de 15 milions de paquets per segon, cada nucli d'un petit servidor de vuit nuclis es pot interrompre milions. de vegades per segon.
Per no gestionar constantment les interrupcions, fa molts anys que va afegir Linux : API de xarxa que utilitzen tots els controladors moderns per millorar el rendiment a altes velocitats. A velocitats baixes, el nucli encara rep interrupcions de la targeta de xarxa de la manera antiga. Un cop arriben prou paquets que superen el llindar, el nucli desactiva les interrupcions i, en canvi, comença a sondejar l'adaptador de xarxa i recollir paquets en trossos. El processament es realitza en softirq, és a dir, en després de les trucades al sistema i les interrupcions de maquinari, quan el nucli (a diferència de l'espai d'usuari) ja s'està executant.
Això és molt més ràpid, però provoca un problema diferent. Si hi ha massa paquets, tot el temps es dedica a processar paquets des de la targeta de xarxa i els processos d'espai d'usuari no tenen temps per buidar aquestes cues (llegir des de connexions TCP, etc.). Finalment les cues s'omplen i comencem a deixar caure paquets. En un intent de trobar un equilibri, el nucli estableix un pressupost per al nombre màxim de paquets processats en el context softirq. Un cop superat aquest pressupost, es desperta un fil a part ksoftirqd (veureu un d'ells a ps per nucli) que gestiona aquests softirqs fora de la ruta normal de syscall/interrupt. Aquest fil es programa mitjançant el planificador de processos estàndard, que intenta assignar els recursos de manera justa.
Després d'haver estudiat com el nucli processa els paquets, podeu veure que hi ha una certa probabilitat de congestió. Si les trucades softirq es reben amb menys freqüència, els paquets hauran d'esperar un temps per processar-se a la cua RX de la targeta de xarxa. Això pot ser degut a que alguna tasca bloqueja el nucli del processador, o alguna altra cosa impedeix que el nucli executi softirq.
Reduint el processament al nucli o mètode
Els retards de Softirq són només una suposició de moment. Però té sentit, i sabem que estem veient alguna cosa molt semblant. Per tant, el següent pas és confirmar aquesta teoria. I si es confirma, cerqueu el motiu dels retards.
Tornem als nostres 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
Com s'ha comentat anteriorment, aquests paquets ICMP s'hagin en una única cua de NIC RX i processats per un únic nucli de CPU. Si volem entendre com funciona Linux, és útil saber on (en quin nucli de CPU) i com (softirq, ksoftirqd) es processen aquests paquets per fer un seguiment del procés.
Ara és el moment d'utilitzar eines que us permetin supervisar el nucli de Linux en temps real. Aquí hem utilitzat . Aquest conjunt d'eines us permet escriure petits programes C que connecten funcions arbitràries al nucli i emmagatzemen els esdeveniments en un programa Python d'espai d'usuari que els pot processar i tornar-vos el resultat. Enganxar funcions arbitràries al nucli és una qüestió complexa, però la utilitat està dissenyada per a la màxima seguretat i està dissenyada per rastrejar exactament el tipus de problemes de producció que no es reprodueixen fàcilment en un entorn de prova o desenvolupament.
El pla aquí és senzill: sabem que el nucli processa aquests pings ICMP, així que posarem un ganxo a la funció del nucli , que accepta un paquet de sol·licitud d'eco ICMP entrant i inicia l'enviament d'una resposta d'eco ICMP. Podem identificar un paquet augmentant el número icmp_seq, que es mostra hping3 a sobre.
Codi sembla complicat, però no fa tanta por com sembla. Funció icmp_echo transmet struct sk_buff *skb: Aquest és un paquet amb una "sol·licitud d'eco". Podem seguir-lo, treure la seqüència echo.sequence (que es compara amb icmp_seq per hping3 выше) i enviar-lo a l'espai d'usuari. També és convenient capturar el nom/identificador del procés actual. A continuació es mostren els resultats que veiem directament mentre el nucli processa paquets:
TGID PID NOM DEL PROCÉS 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 775 swapper/0 0 11 776 swapper/0 0 11 777 swapper/0 0 11 778 4512 4542 swapper/779 XNUMX XNUMX XNUMX ràdios-informe-s XNUMX
Cal assenyalar aquí que en el context softirq els processos que van fer trucades al sistema apareixeran com a "processos" quan de fet és el nucli el que processa els paquets de manera segura en el context del nucli.
Amb aquesta eina podem associar processos específics amb paquets específics que mostren un retard de hping3. Fem-ho senzill grep sobre aquesta captura per a determinats valors icmp_seq. Els paquets que coincideixen amb els valors icmp_seq anteriors es van anotar juntament amb el seu RTT que hem observat anteriorment (entre parèntesis hi ha els valors RTT esperats per als paquets que vam filtrar a causa de valors RTT inferiors a 50 ms):
TGID PID NOM DEL PROCÉS ICMP_SEQ ** RTT -- 10137 10436 cadvisor 1951 10137 10436 cadvisor 1952 76 76 ksoftirqd/11 1953 ** 99ms 76 76 11 1954 ksoftirqd/89 ir qd/76 76 ** 11ms 1955 79 ksoftirqd/ 76 76 ** 11ms 1956 69 ksoftirqd/76 76 ** 11ms 1957 59 ksoftirqd/76 76 ** (11ms) 1958 49 ksoftirqd/76 76 ** (11ms 1959 39 ksoftirqd/76 76) 11 1960 ksoft irqd/ 29 76 ** (76 ms) 11 1961 ksoftirqd/19 76 ** (76 ms) -- 11 1962 cadvisor 9 10137 10436 cadvisor 2068 10137 10436 ksoftir 2069 76 ksoftir 76 11 ksoftir irqd/2070 75 ** 76 ms 76 11 ksoftirqd/ 2071 65 ** 76 ms 76 11 ksoftirqd/2072 55 ** (76 ms) 76 11 ksoftirqd/2073 45 ** (76 ms) 76 11 ksoftirqd/2074 35 76 76 ksoftirqd/11 2075 **25 76 ksoftirqd/76 11 ** (2076 ms) ** (15 ms ) 76 76 ksoftirqd/11 2077 ** (5 ms)
Els resultats ens diuen diverses coses. En primer lloc, tots aquests paquets es processen pel context ksoftirqd/11. Això vol dir que per a aquest parell de màquines en particular, els paquets ICMP es van utilitzar com a hash al nucli 11 a l'extrem receptor. També veiem que sempre que hi ha un embús, hi ha paquets que es processen en el context de la trucada del sistema cadvisor. Aleshores ksoftirqd es fa càrrec de la tasca i processa la cua acumulada: exactament el nombre de paquets que s'han acumulat després cadvisor.
El fet que immediatament abans sempre funciona cadvisor, implica la seva implicació en el problema. Irònicament, el propòsit - "Analitzar l'ús dels recursos i les característiques de rendiment dels contenidors en execució" en lloc de causar aquest problema de rendiment.
Com passa amb altres aspectes dels contenidors, totes aquestes són eines molt avançades i es pot esperar que experimentin problemes de rendiment en algunes circumstàncies imprevistes.
Què fa cadvisor que frena la cua de paquets?
Ara tenim una bona comprensió de com es produeix l'error, quin procés l'està causant i en quina CPU. Veiem que a causa del bloqueig dur, el nucli de Linux no té temps per programar-se ksoftirqd. I veiem que els paquets es processen en context cadvisor. És lògic suposar-ho cadvisor llança una crida al sistema lenta, després de la qual es processen tots els paquets acumulats en aquell moment:
Aquesta és una teoria, però com provar-la? El que podem fer és rastrejar el nucli de la CPU al llarg d'aquest procés, trobar el punt on el nombre de paquets supera el pressupost i es diu ksoftirqd, i després mirar una mica més enrere per veure què s'executava exactament al nucli de la CPU just abans d'aquest punt. . És com fer una radiografia de la CPU cada pocs mil·lisegons. Es veurà com això:
Convenientment, tot això es pot fer amb les eines existents. Per exemple, verifica un nucli de CPU determinat a una freqüència especificada i pot generar una programació de trucades al sistema en execució, incloent-hi l'espai d'usuari i el nucli de Linux. Podeu agafar aquest registre i processar-lo mitjançant una petita bifurcació del programa de Brendan Gregg, que conserva l'ordre de la traça de la pila. Podem desar traces de pila d'una sola línia cada 1 ms, i després ressaltar i desar una mostra 100 mil·lisegons abans que arribi la traça 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
Aquests són els resultats:
(сотни следов, которые выглядят похожими)
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
Hi ha moltes coses aquí, però el més important és que trobem el patró "cadvisor abans de ksoftirqd" que vam veure anteriorment al traçador ICMP. Què vol dir?
Cada línia és una traça de la CPU en un moment determinat. Cada trucada de la pila d'una línia està separada per un punt i coma. Al mig de les línies veiem que el syscall es diu: read(): .... ;do_syscall_64;sys_read; .... Per tant, cadvisor dedica molt de temps a la trucada del sistema read()relacionades amb les funcions mem_cgroup_* (parte superior de la pila de trucades/final de la línia).
És inconvenient veure en un rastre de trucades què s'està llegint exactament, així que anem a córrer strace i anem a veure què fa cadvisor i trobar trucades al sistema de més 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>
Com és d'esperar, aquí veiem trucades lentes read(). A partir dels continguts de les operacions de lectura i del context mem_cgroup és evident que aquests reptes read() consulteu l'arxiu memory.stat, que mostra l'ús de la memòria i els límits de cgroup (tecnologia d'aïllament de recursos de Docker). L'eina cadvisor consulta aquest fitxer per obtenir informació sobre l'ús dels recursos per als contenidors. Comprovem si el nucli o el cadvisor fa alguna cosa inesperada:
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 ~ $
Ara podem reproduir l'error i entendre que el nucli de Linux s'enfronta a una patologia.
Per què l'operació de lectura és tan lenta?
En aquesta etapa, és molt més fàcil trobar missatges d'altres usuaris sobre problemes similars. Com va resultar, al rastrejador de cadvisor es va informar d'aquest error com , és que ningú es va adonar que la latència també es reflecteix aleatòriament a la pila de xarxa. De fet, es va notar que cadvisor consumia més temps de CPU del que s'esperava, però no se li va donar molta importància, ja que els nostres servidors tenen molts recursos de CPU, de manera que el problema no es va estudiar amb atenció.
El problema és que els cgroups tenen en compte l'ús de memòria dins de l'espai de noms (contenidor). Quan tots els processos d'aquest grup c surten, Docker allibera el grup c de memòria. Tanmateix, "memòria" no és només memòria de procés. Tot i que la memòria de procés ja no s'utilitza, sembla que el nucli encara assigna continguts en memòria cau, com ara dentries i inodes (metadades de directori i fitxer), que s'emmagatzemen a la memòria cau al grup c. A partir de la descripció del problema:
cgroups zombis: cgroups que no tenen processos i s'han suprimit, però encara tenen memòria assignada (en el meu cas, des de la memòria cau dentry, però també es pot assignar des de la memòria cau de la pàgina o tmpfs).
La comprovació del nucli de totes les pàgines de la memòria cau quan s'allibera un grup c pot ser molt lenta, de manera que s'escull el procés mandros: espereu fins que aquestes pàgines es tornin a sol·licitar i, finalment, esborrar el grup c quan la memòria sigui realment necessària. Fins a aquest punt, cgroup encara es té en compte a l'hora de recopilar estadístiques.
Des del punt de vista del rendiment, van sacrificar la memòria pel rendiment: accelerar la neteja inicial deixant enrere una mica de memòria cau. Això està bé. Quan el nucli utilitza l'última memòria de la memòria cau, finalment s'esborra el cgroup, de manera que no es pot anomenar "fuga". Malauradament, la implementació específica del mecanisme de cerca memory.stat en aquesta versió del nucli (4.9), combinada amb l'enorme quantitat de memòria dels nostres servidors, significa que es triga molt més temps a restaurar les últimes dades emmagatzemades a la memòria cau i esborrar els zombis cgroup.
Resulta que alguns dels nostres nodes tenien tants zombis cgroup que la lectura i la latència van superar un segon.
La solució al problema del cadvisor és alliberar immediatament les memòries cau de dentries/inodes a tot el sistema, la qual cosa elimina immediatament la latència de lectura i la latència de xarxa a l'amfitrió, ja que esborrar la memòria cau activa les pàgines del grup de zombies a la memòria cau i també les allibera. Això no és una solució, però confirma la causa del problema.
Va resultar que en les versions més noves del nucli (4.19+) es va millorar el rendiment de les trucades memory.stat, així que canviar a aquest nucli es va solucionar el problema. Al mateix temps, teníem eines per detectar nodes problemàtics als clústers de Kubernetes, drenar-los amb gràcia i reiniciar-los. Vam pentinar tots els clústers, vam trobar nodes amb una latència prou alta i els vam reiniciar. Això ens va donar temps per actualitzar el sistema operatiu als servidors restants.
En resum
Com que aquest error va aturar el processament de la cua RX NIC durant centenars de mil·lisegons, va provocar simultàniament una alta latència en connexions curtes i una latència de connexió mitjana, com ara entre les sol·licituds de MySQL i els paquets de resposta.
Entendre i mantenir el rendiment dels sistemes més fonamentals, com ara Kubernetes, és fonamental per a la fiabilitat i la velocitat de tots els serveis basats en ells. Cada sistema que executeu es beneficia de les millores de rendiment de Kubernetes.
Font: www.habr.com