Alcuni anni fa, Kubernetes nel blog ufficiale di GitHub. Da allora è diventata la tecnologia standard per il deployment dei servizi. Ora Kubernetes gestisce una parte significativa dei servizi interni ed esterni. Poiché i nostri cluster sono cresciuti e le richieste di prestazioni sono diventate più rigorose, abbiamo iniziato a notare che in alcuni servizi su Kubernetes si verificano sporadicamente ritardi che non possono essere spiegati dal carico stesso dell'applicazione.
In sostanza, nelle applicazioni si verifica una sorta di ritardo di rete casuale fino a 100 ms o più, il che porta a timeout o tentativi ripetuti. Ci si aspettava che i servizi potessero rispondere alle richieste molto più rapidamente di 100 ms. Ma questo è impossibile se la connessione stessa richiede tanto tempo. Separatamente, abbiamo osservato richieste MySQL molto veloci, che avrebbero dovuto richiedere millisecondi, e MySQL effettivamente rispondeva in millisecondi, ma dal punto di vista dell'applicazione richiedente la risposta richiedeva 100 ms o più.
È diventato subito chiaro che il problema si verifica solo quando ci si connette a un nodo Kubernetes, anche se la richiesta proveniva dall'esterno di Kubernetes. È più semplice riprodurre il problema in un test , che viene eseguito da qualsiasi host interno, testa un servizio Kubernetes su una porta specifica e registra sporadicamente un ritardo elevato. In questo articolo esamineremo come siamo riusciti a identificare la causa di questo problema.
Eliminiamo la complessità superflua nella catena che porta al guasto
Riproducendo lo stesso esempio, volevamo restringere il focus del problema ed eliminare strati di complessità non necessari. Inizialmente, c'erano troppi elementi nel flusso tra Vegeta e i pod in Kubernetes. Per determinare un problema di rete più profondo, era 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 la conversione dell'indirizzo IP e della porta del nodo Kubernetes in un indirizzo IP e una porta nella rete overlay (in particolare, del pod con l'applicazione). Per i pacchetti in arrivo, viene eseguita la sequenza inversa. Si tratta di un sistema complesso con un gran numero di stati e molteplici elementi che vengono costantemente aggiornati e modificati mentre i servizi vengono distribuiti e spostati.
Utilità tcpdump nel test di Vegeta produce latenza durante il handshake TCP (tra SYN e SYN-ACK). Per eliminare questa complessità eccessiva, è possibile utilizzare hping3 per semplici "ping" con pacchetti SYN. Controlliamo se c'è latenza nel pacchetto di risposta e quindi chiudiamo la connessione. Possiamo filtrare i dati includendo solo pacchetti oltre 100 ms e ottenere una versione più semplice della riproduzione del problema rispetto al test completo del livello 7 in Vegeta. Ecco i "ping" del 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 occasionali. La latenza spesso si accumula e infine viene elaborata.
Successivamente vogliamo capire quali componenti possano essere coinvolti nella congestione. Potrebbe essere uno dei centinaia di regole di iptables nel NAT? O ci sono problemi con il tunneling IPIP nella rete? Uno dei modi per verificarlo è controllare ogni passaggio del sistema, escludendolo. Cosa succede se rimuoviamo il NAT e la logica del firewall, lasciando solo la parte IPIP:
Per fortuna, Linux consente di accedere facilmente direttamente allo strato overlay IP, se la macchina fa parte della 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 è ancora presente! Questo esclude iptables e NAT. Quindi, il problema è nel TCP? Vediamo come va il ping ICMP normale:
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 non è scomparso. Forse è un tunnel IPIP? Facciamo un test semplificato:
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 pacchetti tra loro, incluso il ping ICMP. Vedono comunque una latenza, se l'host di destinazione è "cattivo" (alcuni sono peggiori di altri).
Ora l'ultima domanda: perché la latenza si verifica solo sui server kube-node? E avviene quando kube-node è il mittente o il destinatario? Fortunatamente, è anche piuttosto facile scoprirlo, inviando un pacchetto da un host esterno a Kubernetes, ma con lo stesso "male noto" destinatario. Come possiamo vedere, il problema non è scomparso:
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
Eseguiamo quindi le stesse richieste dal precedente kube-node di origine verso l'host esterno (escludendo l'host di origine, poiché il ping include 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 hping ---
22352 pacchetti trasmessi, 22350 pacchetti ricevuti, 1% di perdita di pacchetti
round-trip min/avg/max = 0.2/7.6/1010.6 ms
Esaminando le catture dei pacchetti 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 colonna Delta (in secondi):
Inoltre, se si guarda alla differenza nell'ordine dei pacchetti TCP e ICMP (per numero 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 a volte si alternano e alcuni di essi si bloccano. In particolare, se si esamina i porti dei pacchetti SYN, dal lato del mittente sono in ordine, mentre dal lato del destinatario no.
C'è una sottile differenza in come dei server moderni (come nel nostro data center) gestiscono i pacchetti contenenti TCP o ICMP. Quando arriva un pacchetto, l'adattatore di rete "esegue un hash per connessione", cioè cerca di suddividere le connessioni in code e inviare ciascuna coda a un nucleo di processore separato. Per TCP, questo hash include sia l'indirizzo IP sorgente che quello di destinazione e le porte. In altre parole, ogni connessione è (potenzialmente) hashata in modo diverso. Per ICMP, vengono hashati solo gli indirizzi IP, poiché non ci sono porte.
Un'altra nuova osservazione: durante questo periodo vediamo ritardi ICMP in tutte le comunicazioni tra due host, mentre per TCP non ci sono. Questo ci dice che la causa è probabilmente legata all'hashing delle code RX: è quasi certo che il collo di bottiglia si verifichi nel trattamento dei pacchetti RX, e non nell'invio delle risposte.
Questo esclude dalla lista delle possibili cause l'invio dei pacchetti. Ora sappiamo che il problema con il trattamento dei pacchetti si trova sul lato di ricezione su alcuni server kube-node.
Analizzando il trattamento 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 alla più semplice implementazione tradizionale, la scheda di rete riceve un pacchetto e invia al kernel Linux, segnalando che c'è un pacchetto da elaborare. Il kernel interrompe il lavoro corrente, passa al gestore delle interruzioni, elabora il pacchetto e poi torna ai compiti attuali.
Questo passaggio di contesto avviene lentamente: forse, il ritardo era invisibile con le schede di rete da 10 megabit negli anni '90, ma sulle moderne schede 10G con una larghezza di banda massima di 15 milioni di pacchetti al secondo, ogni core di un piccolo server a otto nuclei può essere interrotto milioni di volte al secondo.
Per evitare di dover continuamente gestire le interruzioni, molti anni fa in Linux è stato aggiunto : un'API di rete utilizzata 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. Quando arriva un numero sufficiente di pacchetti, che supera una soglia, il kernel disabilita le interruzioni e inizia invece a sondare l'adattatore di rete e a prelevare i pacchetti a pacchetti. L'elaborazione avviene in softirq, cioè nel dopo le chiamate di sistema e le interruzioni hardware, quando il kernel (a differenza dello spazio utente) è già in esecuzione.
Questo è molto più veloce, ma crea un altro problema. Se ci sono troppi pacchetti, tutto il tempo viene speso per elaborare i pacchetti dalla scheda di rete, mentre i processi dello spazio utente non riescono effettivamente a svuotare queste code (lettura dalle connessioni TCP, ecc.). Alla fine, le code si riempiono e iniziamo a scartare pacchetti. Cercando 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 svegliato un thread separato ksoftirqd (ne vedrete uno in ps per ogni core), che gestisce questi softirq al di fuori del normale percorso syscall/interrupt. Questo thread viene pianificato utilizzando il pianificatore di processi standard, che cerca di distribuire equamente le risorse.
Studiare come il kernel gestisce i pacchetti rivela che esiste una certa probabilità di congestione. Se le chiamate di softirq arrivano meno frequentemente, i pacchetti dovranno attendere del tempo per essere elaborati nella coda RX della scheda di rete. Questo può accadere a causa di qualche attività che blocca il kernel della CPU, o qualcos'altro impedisce al kernel di avviare softirq.
Riscalando l'elaborazione al kernel o metodo
Le latenze softirq sono ancora solo un'ipotesi. Ma ha senso, e sappiamo che stiamo osservando qualcosa di molto simile. Pertanto, il passo successivo è confermare questa teoria. E se si confermerà, trovare la causa delle latenze.
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 una singola coda NIC RX e elaborati da un singolo core CPU. Se vogliamo comprendere il funzionamento di Linux, è utile sapere dove (su quale core CPU) e come (softirq, ksoftirqd) vengono elaborati questi pacchetti, per rintracciare il processo.
Ora è il momento di utilizzare strumenti che consentono di monitorare in tempo reale il funzionamento del kernel Linux. Qui abbiamo utilizzato . Questo set di strumenti consente di scrivere piccoli programmi in C che intercettano funzioni arbitrarie nel kernel e memorizzano eventi in un programma Python nello spazio utente, che può elaborarli e restituire i risultati. Gli hook per funzioni arbitrarie nel kernel sono una questione complessa, ma l'utilità è progettata per massima sicurezza ed è destinata a monitorare esattamente tali problemi di produzione che sono difficili da riprodurre in un ambiente di test o sviluppo.
Il piano qui è semplice: sappiamo che il kernel elabora questi ping ICMP, quindi imposteremo un hook sulla funzione del kernel , che riceve un pacchetto ICMP in entrata «echo request» e avvia l'invio di una risposta ICMP «echo response». Possiamo identificare il pacchetto tramite l'aumento del numero icmp_seq, che mostra hping3 sopra.
Codice sembra complesso, ma non è così spaventoso come sembra. La funzione icmp_echo trasmette struct sk_buff *skb: è il pacchetto con una richiesta «echo request». Possiamo tracciarlo, estrarre la sequenza echo.sequence (che si mappa con icmp_seq di hping3 sopra), e inviarla nello spazio utente. È anche utile catturare il nome attuale del processo/id. Di seguito sono mostrati i risultati che vediamo direttamente 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
Qui va notato che nel contesto softirq i processi che hanno effettuato chiamate di sistema verranno visualizzati come «processi», anche se in realtà il kernel gestisce in modo sicuro i pacchetti nel contesto del kernel.
Con questo strumento possiamo stabilire un collegamento tra processi specifici e pacchetti specifici, che mostrano un ritardo in hping3. Facciamo una semplice grep su questo cattura per valori specifici icmp_seq. I pacchetti corrispondenti ai valori icmp_seq sopra menzionati sono stati segnalati insieme al loro RTT, che abbiamo osservato sopra (tra parentesi sono indicati i valori RTT attesi per i pacchetti che abbiamo filtrato a causa di valori 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. Prima di tutto, tutti questi pacchetti sono gestiti nel contesto ksoftirqd/11. Questo significa che per questa specifica coppia di macchine i pacchetti ICMP sono stati hashati sul nucleo 11 sulla parte ricevente. Vediamo anche che ad ogni congestione sono presenti pacchetti che vengono gestiti nel contesto della chiamata di sistema cadvisor. Poi ksoftirqd prende il compito su di sé e gestisce la coda accumulata: il numero esatto di pacchetti che si sono accumulati dopo cadvisor.
Il fatto che subito prima di questo funzioni sempre cadvisor, implica la sua partecipazione al problema. Ironia della sorte, la funzione di è «analizzare l'utilizzo delle risorse e le caratteristiche delle prestazioni dei contenitori in esecuzione», non causare questo problema di prestazioni.
Come per altri aspetti del lavoro con i container, si tratta di uno strumento estremamente avanzato, da cui ci si può aspettare problemi di performance in alcune circostanze impreviste.
Cosa fa esattamente cadvisor che rallenta la coda dei pacchetti?
Ora abbiamo una comprensione piuttosto buona di come si verifica il fallimento, quale processo lo provoca e su quale CPU. Vediamo che a causa del blocco rigido, il kernel Linux non riesce a pianificare in tempo. ksoftirqdE vediamo che i pacchetti vengono elaborati nel contesto cadvisor. È logico supporre che cadvisor stia eseguendo una syscall lenta, dopo la quale vengono elaborati tutti i pacchetti accumulatisi nel frattempo:
Questa è una teoria, ma come possiamo verificare? Ciò che possiamo fare è monitorare l'attività del CPU kernel durante tutto questo processo, trovare il punto in cui si supera il budget per il numero di pacchetti e si attiva ksoftirqd, e poi guardare poco prima - cosa stava lavorando sul kernel CPU proprio prima di questo momento. È come una radiografia del CPU ogni pochi millisecondi. Apparirà più o meno così:
È comodo che tutto questo possa essere fatto con strumenti esistenti. Per esempio, controlla periodicamente il kernel CPU specificato e può generare un grafico delle chiamate del sistema in esecuzione, comprese sia lo spazio utente che il kernel Linux. Possiamo prendere questa registrazione e trattarla con un piccolo fork del programma di Brendan Gregg, che conserva l'ordine della traccia dello stack. Possiamo salvare le tracce dello stack a una sola riga ogni 1 ms, e poi evidenziare e conservare un campione per 100 millisecondi prima che la traccia venga coinvolta. 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
Ecco i risultati:
(centinaia di tracce che sembrano simili)
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
Qui c'è molto, ma la cosa principale è che troviamo il modello «cadvisor prima di ksoftirqd», che avevamo già visto nel tracciatore ICMP. Cosa significa?
Ogni riga è una traccia CPU in un determinato momento. Ogni chiamata verso il basso nella pila nella riga è separata da un punto e virgola. Nel mezzo delle righe vediamo la syscall chiamata: read(): .... ;do_syscall_64;sys_read; .... Quindi, cadvisor trascorre molto tempo nella chiamata di sistema read(), relativa alle funzioni mem_cgroup_* (parte superiore della pila di chiamate/fine riga).
Nella traccia delle chiamate è scomodo vedere cosa viene effettivamente letto, quindi avviamo strace e vediamo cosa fa cadvisor, e troviamo 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 ci si poteva aspettare, qui vediamo chiamate lente read(). Dal contenuto delle operazioni di lettura e del contesto mem_cgroup è chiaro che queste chiamate read() riguardano il file memory.stat, che mostra l'uso della memoria e i limiti del cgroup (tecnologia di isolamento delle risorse in Docker). Lo strumento cadvisor interroga questo file per ottenere informazioni sull'uso delle risorse per i contenitori. Controlliamo se è il kernel o cadvisor a fare 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 comprendiamo che il kernel Linux sta affrontando una patologia.
Cosa rende così lenta l'operazione di lettura?
A questo punto è molto più facile trovare messaggi da altri utenti su problemi simili. Come si è scoperto, nel tracker di cadvisor questo bug è stato segnalato come una , e semplicemente nessuno aveva notato che il ritardo si rifletteva anche casualmente nello stack di rete. È stato effettivamente notato che cadvisor richiede più tempo della CPU di quanto previsto, ma a questo non si è dato particolare peso, dato che i nostri server hanno molte risorse di CPU, quindi il problema non è stato approfondito.
Il problema è che i gruppi di controllo (cgroups) considerano l'uso della memoria all'interno dello spazio dei nomi (contenitore). Quando tutti i processi in questo cgroup terminano, Docker libera il gruppo di controllo della memoria. Tuttavia, "memoria" non è solo memoria del processo. Anche se la memoria dei processi non viene più utilizzata, il kernel continua a gestire contenuti ancora memorizzati nella cache, come dentries e inodes (metadati di directory e file), che vengono memorizzati nella cache nel cgroup della memoria. Dalla descrizione del problema:
cgroups-zombi: gruppi di controllo senza processi e rimossi, ma per i quali è ancora allocata memoria (nel mio caso, dalla cache di dentry, ma può anche essere allocata dalla cache delle pagine o da 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: attendere fino a quando queste pagine vengono nuovamente richieste e solo allora, quando la memoria è veramente necessaria, finalmente liberare il cgroup. Fino a quel momento, il cgroup continua a essere considerato nella raccolta delle statistiche.
Dal punto di vista delle prestazioni, hanno sacrificato la memoria a favore delle prestazioni: l'accelerazione della pulizia iniziale grazie al fatto che rimane un po' di memoria cache. Va bene. Quando il kernel utilizza l'ultima parte della memoria cache, il cgroup alla fine viene ripulito, quindi non si può parlare di "perdita". Sfortunatamente, l'implementazione specifica del meccanismo di ricerca memory.stat in questa versione del kernel (4.9), insieme all'enorme quantità di memoria sui nostri server, porta a richiedere molto più tempo per recuperare gli ultimi dati memorizzati nella cache e pulire i cgroup zombie.
Si è scoperto che su alcuni dei nostri nodi c'erano così tanti cgroup zombie che la lettura e il ritardo superavano il secondo.
Il modo per aggirare il problema di cadvisor è liberare immediatamente le cache di dentries/inodes in tutto il sistema, il che elimina immediatamente il ritardo nella lettura e il ritardo di rete sull'host, poiché l'eliminazione della cache include anche le pagine memorizzate nella cache dei cgroup zombie, 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+) le prestazioni dell'invocazione sono migliorate memory.stat, quindi passare a questo kernel risolveva il problema. Nel frattempo, avevamo strumenti per rilevare i nodi problematici nei cluster Kubernetes, per scaricarli elegantemente e riavviarli. Abbiamo perlustrato tutti i cluster, trovando nodi con un ritardo sufficientemente alto e li abbiamo riavviati. Questo ci ha dato il tempo di aggiornare il sistema operativo sugli altri server.
In sintesi
Poiché questo bug bloccava l'elaborazione delle code NIC RX per centinaia di millisecondi, simultaneamente causava un grande ritardo nelle connessioni brevi e un ritardo a metà connessione, ad esempio, tra le richieste MySQL e i pacchetti di risposta.
Comprendere e sostenere le prestazioni dei sistemi più fondamentali, come Kubernetes, è cruciale per l'affidabilità e la velocità di tutti i servizi basati su di essi. Tutti i sistemi in esecuzione beneficiano dei miglioramenti delle prestazioni di Kubernetes.
Fonte: habr.com
