Un paio di anni fa, Kubernetes nel blog ufficiale di GitHub. Da allora è diventata la tecnologia standard per il deployment dei servizi. Oggi Kubernetes gestisce una parte significativa dei servizi interni ed esterni. Con l'aumento delle dimensioni dei nostri cluster e delle esigenze prestazionali, abbiamo notato che in alcuni servizi su Kubernetes si verificano sporadicamente ritardi che non possono essere giustificati dal carico dell'applicazione stessa.
Fondamentalmente, negli applicativi si verificano ritardi di rete casuali fino a 100 ms e oltre, causando timeout o tentativi di riconnessione. Ci si aspettava che i servizi rispondessero alle richieste molto più rapidamente di 100 ms. Tuttavia, questo non è possibile se la connessione stessa richiede così tanto tempo. Se osserviamo separatamente le richieste MySQL, che dovrebbero richiedere solo millisecondi, MySQL effettivamente le gestisce in millisecondi, ma dal punto di vista dell'applicazione che effettua la richiesta, la risposta richiede 100 ms o più.
È diventato subito chiaro che il problema si verifica solo durante la connessione a un nodo Kubernetes, anche se la chiamata proviene da fuori Kubernetes. La riproduzione del problema è più semplice in un test , che viene eseguito da qualsiasi host interno, testa il servizio Kubernetes su una porta specifica e registra sporadicamente grandi latenze. In questo articolo vedremo come siamo riusciti a tracciare la causa di questo problema.
Eliminiamo la complessità superflua nella catena di fallimento
Riproducendo lo stesso esempio, abbiamo voluto restringere il focus sul problema e rimuovere strati di complessità non necessari. Inizialmente, c'erano troppi elementi nel flusso tra Vegeta e i pod su Kubernetes. Per identificare un problema di rete più profondo, è necessario escludere alcuni di essi.
Il client (Vegeta) stabilisce una connessione TCP con qualsiasi nodo nel cluster. Kubernetes funziona come una rete overlay (sopra la rete esistente del datacenter), che utilizza , ovvero incapsula i pacchetti IP della rete overlay all'interno dei pacchetti IP del datacenter. Quando ci si connette al primo nodo, viene eseguita la traduzione degli indirizzi di rete (NAT) con tracciamento dello stato per tradurre l'indirizzo IP e la porta del nodo Kubernetes nell'indirizzo IP e nella porta nella rete overlay (in particolare, del pod con l'applicazione). I pacchetti in arrivo seguono un ordine inverso. Questo è un sistema complesso con molti stati e numerosi elementi che vengono costantemente aggiornati e modificati man mano che i servizi vengono distribuiti e spostati.
Utility tcpdump Il test di Vegeta mostra ritardi durante la fase di handshake TCP (tra SYN e SYN-ACK). Per rimuovere questa complessità superflua, è possibile utilizzare hping3 per semplici "ping" con pacchetti SYN. Controlliamo se ci sono ritardi nel pacchetto di risposta e poi reimpostiamo la connessione. Possiamo filtrare i dati, includendo solo i pacchetti con un ritardo superiore a 100 ms, ottenendo una versione di riproduzione più semplice del problema rispetto a un completo test di rete di livello 7 in Vegeta. Ecco i "ping" al nodo Kubernetes utilizzando TCP SYN/SYN-ACK sulla "porta del nodo" del servizio (30927) con un intervallo di 10 ms, filtrati per le risposte più lente:
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
Si può subito fare la prima osservazione. Dai numeri di sequenza e dai tempi, è evidente che non si tratta di congestioni sporadiche. I ritardi si accumulano frequentemente e vengono infine gestiti.
Successivamente, vogliamo capire quali componenti potrebbero essere coinvolti nella creazione della congestione. Potrebbero essere alcune delle centinaia di regole iptables nel NAT? O ci sono problemi con il tunneling IPIP nella rete? Un modo per verificare questo è esaminare ogni passaggio del sistema, escludendolo. Cosa succede se rimuoviamo il NAT e la logica del firewall, lasciando solo la parte IPIP:
Fortunatamente, Linux consente un facile accesso diretto allo strato overlay IP se la macchina è nella stessa rete:
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 giudicare dai risultati, il problema persiste! Questo esclude iptables e NAT. Quindi, il problema è nel TCP? Vediamo cosa succede con un normale 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
I risultati mostrano che il problema persiste. Potrebbe essere un tunnel IPIP? Semplifichiamo ulteriormente il test:
Tutti i pacchetti vengono inviati tra questi due host?
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
Abbiamo semplificato la situazione a due nodi Kubernetes che si inviano qualsiasi pacchetto, anche un ping ICMP. Continueranno a riscontrare ritardi se l'host di destinazione è "cattivo" (alcuni più di altri).
Ora l'ultima domanda: perché il ritardo si verifica solo sui server kube-node? Accade quando kube-node è il mittente o il destinatario? Fortunatamente, è piuttosto facile scoprirlo inviando un pacchetto da un host al di fuori di Kubernetes, ma con lo stesso "cattivo" destinatario noto. Come possiamo vedere, il problema persiste:
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
Eseguiremo le stesse richieste dal precedente kube-node sorgente all'host esterno (il che esclude l'host sorgente, poiché il ping coinvolge sia RX che 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 statistica di hping ---
22352 pacchetti trasmessi, 22350 pacchetti ricevuti, 1% di perdita di pacchetti
ritorno minimo/medio/massimo = 0.2/7.6/1010.6 ms
Analizzando i pacchetti catturati con ritardo, abbiamo ottenuto alcune informazioni aggiuntive. In particolare, il mittente (in basso) vede questo timeout, mentre il destinatario (in alto) non lo vede — vedi la colonna Delta (in secondi):
Inoltre, se osserviamo la differenza nell'ordine dei pacchetti TCP e ICMP (in base ai numeri di sequenza) dal lato del destinatario, i pacchetti ICMP arrivano sempre nell'ordine in cui sono stati inviati, ma con tempistiche diverse. Allo stesso tempo, i pacchetti TCP possono a volte alternarsi, e alcuni di essi si bloccano. In particolare, se esaminiamo le porte dei pacchetti SYN, dal lato del mittente sono in ordine, mentre dal lato del destinatario non lo sono.
C'è una sottile differenza in come dei server moderni (come nel nostro data center) gestiscono i pacchetti contenenti TCP o ICMP. Quando un pacchetto arriva, l'adattatore di rete "hash-down" per connessione, cioè cerca di suddividere le connessioni in code e inviare ogni coda a un core del processore separato. Per TCP, questo hash include l'indirizzo IP sorgente e di destinazione e la porta. In altre parole, ogni connessione è hashata (potenzialmente) in modo diverso. Per ICMP, vengono hashati solo gli indirizzi IP, poiché non ci sono porte.
Un'altra nuova osservazione: in questo periodo vediamo ritardi ICMP in tutte le comunicazioni tra i due host, mentre per TCP non ci sono. Ciò ci dice che la causa è probabilmente legata all'hashing delle code RX: è quasi certo che ci sia un collo di bottiglia nella gestione dei pacchetti RX, e non nell'invio delle risposte.
Questo esclude l'invio di pacchetti dalle possibili cause. Ora sappiamo che il problema nella gestione dei pacchetti si trova sul lato ricevente su alcuni server kube-node.
Esaminando la gestione dei pacchetti nel kernel Linux
Per capire perché il problema si verifica sul destinatario su alcuni server kube-node, vediamo come il kernel Linux gestisce i pacchetti.
Tornando all'implementazione tradizionale più semplice, la scheda di rete riceve un pacchetto e invia al kernel Linux, segnalando che c'è un pacchetto da elaborare. Il kernel interrompe altre operazioni, passa al gestore delle interruzioni, elabora il pacchetto e poi torna alle attività correnti.
Questo passaggio di contesto avviene lentamente: potrebbe non essere stato notato un ritardo con le schede di rete a 10 megabit negli anni '90, ma su schede moderne a 10G con una massima capacità di 15 milioni di pacchetti al secondo, ogni core piccolo di un server a otto core può essere interrotto milioni di volte al secondo.
Per evitare di dover gestire continuamente le interruzioni, molti anni fa in Linux è stata aggiunta : API di rete che viene utilizzato da tutti i moderni driver per migliorare le prestazioni ad alte velocità. A basse velocità, il kernel continua a ricevere interruzioni dalla scheda di rete nel modo tradizionale. Non appena arriva un numero sufficiente di pacchetti che supera una certa soglia, il kernel disattiva le interruzioni e inizia a interrogare l'adattatore di rete, recuperando i pacchetti a blocchi. L'elaborazione avviene in softirq, cioè in dopo le chiamate di sistema e le interruzioni hardware, quando il kernel (a differenza dello spazio utente) è già attivo.
Questo è molto più veloce, ma crea un altro problema. Se ci sono troppi pacchetti, tutto il tempo viene speso a elaborare i pacchetti dalla scheda di rete e i processi nello spazio utente non riescono effettivamente a svuotare queste code (lettura da connessioni TCP, ecc.). Alla fine, le code si riempiono e iniziamo a scartare pacchetti. Per tentare di trovare un equilibrio, il kernel stabilisce un budget per il numero massimo di pacchetti elaborati nel contesto di softirq. Non appena questo budget viene superato, viene attivato un thread separato ksoftirqd (ne vedrete uno in ps per ogni core), che elabora questi softirq al di fuori del normale percorso syscall/interrupt. Questo thread viene pianificato utilizzando il programma di pianificazione dei processi standard, che cerca di distribuire le risorse in modo equo.
Analizzando come il kernel elabora i pacchetti, si può notare che c'è una certa probabilità di congestione. Se le chiamate a softirq arrivano meno frequentemente, i pacchetti dovranno aspettare un po' nella coda RX sulla scheda di rete. Questo potrebbe essere causato da qualche attività che blocca il percorso del kernel o qualcos'altro che impedisce al kernel di avviare softirq.
Raffiniamo l'elaborazione nel kernel o nel metodo
Le latenze di softirq sono al momento solo un'ipotesi. Ma ha senso e sappiamo che stiamo osservando qualcosa di molto simile. Pertanto, il passo successivo è confermare questa teoria. E se viene confermata, trovare la causa dei ritardi.
Torniamo ai nostri pacchetti lenti:
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
Come discusso in precedenza, questi pacchetti ICMP vengono accodati in un'unica coda NIC RX ed elaborati da un solo core CPU. Se vogliamo capire come funziona Linux, è utile sapere dove (su quale core CPU) e come (softirq, ksoftirqd) vengono elaborati questi pacchetti, per tracciare il processo.
È ora di utilizzare strumenti che consentono di monitorare il comportamento del kernel Linux in tempo reale. Qui abbiamo utilizzato . Questo set di strumenti consente di scrivere piccoli programmi in C che interceptano funzioni arbitrarie nel kernel e bufferizzano gli eventi in un programma Python dello spazio utente, che può elaborarli e restituirti il risultato. Gli hook per funzioni arbitrarie nel kernel sono un compito complesso, ma l'utilità è progettata per la massima sicurezza ed è destinata a monitorare problemi di produzione come questo, che non sono facili da riprodurre in un ambiente di test o sviluppo.
Il piano è semplice: sappiamo che il kernel elabora questi ping ICMP, quindi installeremo un hook sulla funzione del kernel , che riceve il pacchetto ICMP "echo request" in arrivo e avvia l'invio della risposta ICMP "echo response". Possiamo identificare il pacchetto per l'incremento del numero icmp_seq, che mostra hping3 superiore.
Codice può sembrare complesso, ma non è così spaventoso come sembra. La funzione icmp_echo trasmette struct sk_buff *skb: è il pacchetto con la richiesta "echo request". Possiamo tracciarlo, estrarre la sequenza echo.sequence (che corrisponde a icmp_seq di hping3 in precedenza), e inviarla nello spazio utente. È anche utile catturare il nome del processo attuale/ID. Di seguito sono mostrati i risultati che vediamo durante l'elaborazione dei pacchetti da parte del kernel:
TGID PID NOME PROCESSO 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
È importante notare che nel contesto softirq i processi che hanno eseguito chiamate di sistema appariranno come "processi", anche se in realtà il kernel elabora i pacchetti in modo sicuro nel contesto del kernel.
Con questo strumento possiamo stabilire un collegamento specifico tra processi specifici e pacchetti specifici che mostrano ritardi in hping3. Facciamo un semplice grep in questa cattura per determinati valori icmp_seq. I pacchetti corrispondenti ai valori icmp_seq sopra citati sono stati contrassegnati insieme ai loro RTT, che abbiamo osservato sopra (tra parentesi sono indicati i valori RTT attesi per i pacchetti che abbiamo filtrato a causa di RTT inferiori a 50 ms):
TGID PID NOME PROCESSO 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)
I risultati ci dicono diverse cose. Innanzitutto, tutti questi pacchetti vengono gestiti dal contesto ksoftirqd/11. Ciò significa che per questa specifica coppia di macchine, i pacchetti ICMP venivano affidati al core 11 sul lato ricevente. Possiamo anche vedere che ad ogni congestione ci sono pacchetti gestiti nel contesto della chiamata di sistema cadvisor. Poi ksoftirqd prende in carico e gestisce la coda accumulata: esattamente il numero di pacchetti che si è accumulato dopo cadvisor.
Il fatto che subito prima di questo funzioni sempre cadvisor, implica la sua partecipazione al problema. Ironia della sorte, il suo scopo è — "analizzare l'uso delle risorse e le caratteristiche delle prestazioni dei container in esecuzione", e non causare questo problema di prestazioni.
Come per altri aspetti del funzionamento dei container, è tutto strumenti estremamente avanzati, da cui è del tutto ragionevole aspettarsi problemi di prestazioni in alcune circostanze impreviste.
Cosa fa cadvisor che rallenta la coda dei pacchetti?
Ora abbiamo una comprensione piuttosto buona di come si verifica il fallimento, quale processo lo causa e su quale CPU. Vediamo che a causa del bloqueo rigido, il kernel Linux non riesce a pianificare in tempo. ksoftirqdE vediamo che i pacchetti vengono gestiti nel contesto. cadvisorÈ logico supporre che cadvisor lanci un syscall lento, dopo il quale vengono gestiti tutti i pacchetti accumulati in quel momento:
Questa è una teoria, ma come possiamo testarla? Ciò che possiamo fare è tracciare l'attività del kernel della CPU durante tutto questo processo, trovare il punto in cui si supera il budget per il numero di pacchetti e viene chiamato ksoftirqd, e poi guardare poco prima — cosa stava lavorando sulla CPU proprio prima di quel momento. È come una radiografia della CPU ogni pochi millisecondi. Dovrebbe apparire più o meno così:
È comodo che tutto questo possa essere fatto con gli strumenti esistenti. Ad esempio, controlla un determinato core CPU a intervalli regolari e può generare un grafico delle chiamate del sistema in esecuzione, inclusi sia lo spazio utente che il kernel Linux. Possiamo prendere questo record e processarlo con un piccolo fork del programma di Brendan Gregg, che conserva l'ordine della traccia dello stack. Possiamo conservare singole tracce dello stack ogni 1 ms, e poi estrarre e salvare un campione per 100 millisecondi prima che entri nella traccia 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
Questi sono i risultati:
(centinaia di tracce che sembrano simili)
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
C'è molto da vedere, ma la cosa principale è che troviamo il modello "cadvisor prima di ksoftirqd", che abbiamo già osservato nel tracciatore ICMP. Cosa significa?
Ogni riga è un tracciamento della CPU in un dato momento. Ogni chiamata nel stack nella riga è separata da un punto e virgola. Nel mezzo delle righe vediamo la syscall invocata: read(): .... ;do_syscall_64;sys_read; .... Quindi, cadvisor spende molto tempo in una chiamata di sistema read(), relativa alle funzioni mem_cgroup_* (parte superiore dello stack delle chiamate/fine della riga).
Nel tracciamento delle chiamate è complicato vedere cosa venga effettivamente letto, quindi eseguiamo strace e vediamo cosa fa cadvisor, cercando le chiamate di sistema che durano più di 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
Come previsto, qui vediamo chiamate lente read(). Dall'output delle operazioni di lettura e dal contesto mem_cgroup si evince che queste chiamate read() si riferiscono al file memory.stat, che mostra l'utilizzo della memoria e i limiti del cgroup (tecnologia di isolamento delle risorse in Docker). Lo strumento cadvisor interroga questo file per ottenere informazioni sull'utilizzo delle risorse per i container. Controlliamo se è il kernel o se cadvisor sta facendo qualcosa di inaspettato:
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 ~ $
Ora possiamo riprodurre il bug e comprendere che il kernel Linux si trova di fronte a una patologia.
Cosa causa una lettura così lenta?
A questo punto, è molto più facile trovare messaggi da altri utenti riguardanti problemi simili. Si è scoperto che nel tracker di cadvisor questo bug era stato segnalato come , ma nessuno aveva notato che il ritardo si rifletteva casualmente anche nello stack di rete. In effetti, è stato osservato che cadvisor consumava più tempo della CPU del previsto, ma non si è dato particolare peso, poiché i nostri server hanno molte risorse di CPU e quindi non è stata esaminata in dettaglio.
Il problema è che i gruppi di controllo (cgroups) considerano l'utilizzo della memoria all'interno dello spazio dei nomi (container). Quando tutti i processi in questo cgroup terminano, Docker libera il gruppo di controllo della memoria. Tuttavia, "memoria" non è solo la memoria del processo. Anche se la memoria dei processi non è più utilizzata, si scopre che il kernel assegna ancora contenuti memorizzati nella cache, come dentries e inodes (metadati di directory e file), che vengono memorizzati nella memory cgroup. Dalla descrizione del problema:
cgroups-zombie: gruppi di controllo che non hanno processi e sono stati rimossi, ma per i quali è ancora allocata memoria (nel mio caso, dalla cache dentry, ma potrebbe anche provenire dalla cache delle pagine o tmpfs).
Il controllo da parte del kernel di tutte le pagine in cache durante la liberazione del cgroup può essere molto lento, quindi è stato scelto un processo pigro: aspettare che queste pagine vengano nuovamente richieste e solo allora, quando la memoria è realmente necessaria, finalmente ripulire il cgroup. Fino a quel momento, il cgroup continua ad essere considerato nella raccolta statistiche.
Dal punto di vista delle prestazioni, hanno sacrificato la memoria a favore della velocità: accelerando la pulizia iniziale grazie a una minima quantità di memoria cache residua. È accettabile. Quando il kernel utilizza l'ultima parte della memoria cache, la cgroup alla fine viene svuotata, quindi non può essere definita "perdita di memoria". Purtroppo, l'implementazione specifica del meccanismo di ricerca memory.stat in questa versione del kernel (4.9), combinata con l'enorme quantità di memoria sui nostri server, porta a un tempo di ripristino dei dati cache più lungo e alla pulizia degli zombie cgroup.
Si è scoperto che su alcuni dei nostri nodi c'era così tanti zombie cgroup che la lettura e la latenza superavano il secondo.
Un modo per aggirare il problema di cadvisor è rilasciare immediatamente le cache di dentries/inodes in tutto il sistema, il che elimina immediatamente la latenza di lettura e la latenza di rete sull'host, poiché la rimozione della cache include le pagine cache zombie cgroup, che vengono anch'esse liberate. Non è una soluzione, ma conferma la causa del problema.
Si è scoperto che nelle versioni più recenti del kernel (4.19+) sono stati migliorati i tempi di chiamata memory.stat, quindi l'aggiornamento a questo kernel ha risolto il problema. Nel frattempo, avevamo anche strumenti per rilevare i nodi problematici nei cluster Kubernetes, per il loro elegante scarico e riavvio. Abbiamo esaminato tutti i cluster, trovato nodi con latenza sufficientemente alta e riavviati. Questo ci ha dato tempo per aggiornare il sistema operativo sugli altri server.
In sintesi
Poiché questo bug bloccava l'elaborazione delle code NIC RX per centinaia di millisecondi, causava al contempo una grande latenza su connessioni brevi e latenza nel mezzo della connessione, ad esempio, tra richieste MySQL e pacchetti di risposta.
Comprendere e supportare le prestazioni dei sistemi più fondamentali, come Kubernetes, è fondamentale per l'affidabilità e la velocità di tutti i servizi basati su di essi. Tutti i sistemi avviati traggono vantaggio dai miglioramenti delle prestazioni di Kubernetes.
Fonte: habr.com
