Un paio di anni fa Kubernetes sul blog ufficiale di GitHub. Da allora, è diventata la tecnologia standard per la distribuzione dei servizi. Kubernetes ora gestisce una parte significativa dei servizi interni e pubblici. Man mano che i nostri cluster crescevano e i requisiti prestazionali diventavano più rigorosi, abbiamo iniziato a notare che alcuni servizi su Kubernetes sperimentavano sporadicamente una latenza che non poteva essere spiegata dal carico dell'applicazione stessa.
In sostanza, le applicazioni sperimentano una latenza di rete casuale fino a 100 ms o più, con conseguenti timeout o nuovi tentativi. Ci si aspettava che i servizi fossero in grado di rispondere alle richieste molto più velocemente di 100 ms. Ma questo è impossibile se la connessione stessa richiede così tanto tempo. Separatamente, abbiamo osservato query MySQL molto veloci che dovrebbero richiedere millisecondi e MySQL è stata completata in millisecondi, ma dal punto di vista dell'applicazione richiedente la risposta ha richiesto 100 ms o più.
È stato subito chiaro che il problema si verificava solo durante la connessione a un nodo Kubernetes, anche se la chiamata proveniva dall'esterno di Kubernetes. Il modo più semplice per riprodurre il problema è eseguire un test , che viene eseguito da qualsiasi host interno, testa il servizio Kubernetes su una porta specifica e registra sporadicamente un'elevata latenza. In questo articolo vedremo come siamo riusciti a rintracciare la causa di questo problema.
Eliminare la complessità non necessaria nella catena che porta al fallimento
Riproducendo lo stesso esempio, volevamo restringere il focus del problema e rimuovere inutili livelli di complessità. Inizialmente c'erano troppi elementi nel flusso tra Vegeta e i pod Kubernetes. Per identificare un problema di rete più profondo, è necessario escluderne alcuni.
Il client (Vegeta) crea una connessione TCP con qualsiasi nodo del cluster. Kubernetes funziona come una rete sovrapposta (sopra la rete del data center esistente) che utilizza , ovvero incapsula i pacchetti IP della rete overlay all'interno dei pacchetti IP del data center. Quando ci si connette al primo nodo, viene eseguita la traduzione dell'indirizzo di rete (NAT) con stato per tradurre l'indirizzo IP e la porta del nodo Kubernetes nell'indirizzo IP e nella porta nella rete overlay (nello specifico, il pod con l'applicazione). Per i pacchetti in entrata viene eseguita la sequenza inversa di azioni. È un sistema complesso con molti stati e molti elementi che vengono costantemente aggiornati e modificati man mano che i servizi vengono distribuiti e spostati.
Utilità tcpdump nel test Vegeta si nota un ritardo durante l'handshake TCP (tra SYN e SYN-ACK). Per rimuovere questa complessità non necessaria, è possibile utilizzare hping3 per semplici “ping” con pacchetti SYN. Controlliamo se c'è un ritardo nel pacchetto di risposta, quindi ripristiniamo la connessione. Possiamo filtrare i dati per includere solo i pacchetti superiori a 100 ms e ottenere un modo più semplice per riprodurre il problema rispetto al test completo del livello 7 della rete di Vegeta. Ecco i "ping" del nodo Kubernetes che utilizzano TCP SYN/SYN-ACK sulla "porta del nodo" del servizio (30927) a intervalli di 10 ms, filtrati in base alle 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
Può immediatamente fare la prima osservazione. A giudicare dai numeri di sequenza e dai tempi, è chiaro che non si tratta di congestioni una tantum. Il ritardo spesso si accumula e alla fine viene elaborato.
Successivamente, vogliamo scoprire quali componenti potrebbero essere coinvolti nel verificarsi della congestione. Forse queste sono alcune delle centinaia di regole iptables in NAT? Oppure ci sono problemi con il tunneling IPIP sulla rete? Un modo per verificarlo è testare ogni passaggio del sistema eliminandolo. Cosa succede se rimuovi NAT e logica firewall, lasciando solo la parte IPIP:
Fortunatamente, Linux semplifica l'accesso diretto al livello di overlay IP se la macchina si trova sulla 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 rimane ancora! Ciò esclude iptables e NAT. Quindi il problema è TCP? Vediamo come va 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 non è scomparso. Forse questo è 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 in modo che due nodi Kubernetes si inviino reciprocamente qualsiasi pacchetto, anche un ping ICMP. Vedono ancora la latenza se l'host di destinazione è "cattivo" (alcuni peggiori di altri).
Ora l'ultima domanda: perché il ritardo si verifica solo sui server kube-node? E succede quando kube-node è il mittente o il destinatario? Fortunatamente, anche questo è abbastanza semplice da capire inviando un pacchetto da un host esterno a Kubernetes, ma con lo stesso destinatario “noto come cattivo”. Come puoi 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
Eseguiremo quindi le stesse richieste dal nodo kube di origine precedente all'host esterno (che esclude l'host di origine poiché il ping include sia un componente 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 hping statistic ---
22352 packets transmitted, 22350 packets received, 1% packet loss
round-trip min/avg/max = 0.2/7.6/1010.6 ms
Esaminando le acquisizioni dei pacchetti di latenza, abbiamo ottenuto alcune informazioni aggiuntive. Nello specifico, il mittente (in basso) vede questo timeout, ma il destinatario (in alto) no: vedi la colonna Delta (in secondi):
Inoltre, se si osserva la differenza nell'ordine dei pacchetti TCP e ICMP (per numero di sequenza) sul lato destinatario, i pacchetti ICMP arrivano sempre nella stessa sequenza in cui sono stati inviati, ma con tempi diversi. Allo stesso tempo, i pacchetti TCP a volte si intercalano e alcuni di essi rimangono bloccati. In particolare, se si esaminano le porte dei pacchetti SYN, queste sono in ordine dal lato del mittente, ma non dal lato del destinatario.
C'è una sottile differenza nel come i server moderni (come quelli del nostro data center) elaborano pacchetti contenenti TCP o ICMP. Quando arriva un pacchetto, l'adattatore di rete "lo esegue l'hashing per connessione", ovvero tenta di suddividere le connessioni in code e di inviare ciascuna coda a un core del processore separato. Per TCP, questo hash include sia l'indirizzo IP di origine che quello di destinazione e la porta. In altre parole, ogni connessione viene sottoposta ad hashing (potenzialmente) in modo diverso. Per ICMP, viene eseguito l'hashing solo degli indirizzi IP, poiché non sono presenti porte.
Un'altra nuova osservazione: durante questo periodo vediamo ritardi ICMP su tutte le comunicazioni tra due host, ma TCP no. Questo ci dice che probabilmente la causa è legata all’hashing della coda RX: la congestione è quasi sicuramente nell’elaborazione dei pacchetti RX, non nell’invio delle risposte.
Ciò elimina l'invio di pacchetti dall'elenco delle possibili cause. Ora sappiamo che il problema dell'elaborazione dei pacchetti è sul lato di ricezione su alcuni server kube-node.
Comprendere l'elaborazione dei pacchetti nel kernel Linux
Per capire perché il problema si verifica nel ricevitore su alcuni server kube-node, diamo un'occhiata a come il kernel Linux elabora i pacchetti.
Ritornando all'implementazione tradizionale più semplice, la scheda di rete riceve il pacchetto e lo invia il kernel Linux che c'è un pacchetto che deve essere elaborato. Il kernel interrompe il resto del lavoro, cambia il contesto al gestore delle interruzioni, elabora il pacchetto e quindi ritorna alle attività correnti.
Questo cambio di contesto è lento: la latenza potrebbe non essere stata evidente sulle schede di rete da 10 Mbps negli anni '90, ma sulle moderne schede 10G con un throughput massimo di 15 milioni di pacchetti al secondo, ciascun core di un piccolo server a otto core può essere interrotto a milioni di volte al secondo.
Per non dover gestire costantemente le interruzioni, molti anni fa è stato aggiunto Linux : API di rete utilizzata da tutti i conducenti moderni per migliorare le prestazioni alle alte velocità. A basse velocità il kernel riceve ancora gli interrupt dalla scheda di rete nel vecchio modo. Una volta arrivati abbastanza pacchetti che superano la soglia, il kernel disabilita gli interrupt e inizia invece a interrogare l'adattatore di rete e a raccogliere i pacchetti in blocchi. L'elaborazione viene eseguita in softirq, cioè in dopo le chiamate di sistema e le interruzioni hardware, quando il kernel (al contrario dello spazio utente) è già in esecuzione.
Questo è molto più veloce, ma causa un problema diverso. Se ci sono troppi pacchetti, tutto il tempo viene dedicato all'elaborazione dei pacchetti dalla scheda di rete e i processi dello spazio utente non hanno il tempo di svuotare effettivamente queste code (lettura dalle connessioni TCP, ecc.). Alla fine le code si riempiono e iniziamo a scaricare i pacchetti. Nel tentativo di trovare un equilibrio, il kernel imposta un budget per il numero massimo di pacchetti elaborati nel contesto softirq. Una volta superato questo budget, si risveglia un thread separato ksoftirqd (ne vedrai uno in ps per core) che gestisce questi softirq al di fuori del normale percorso syscall/interrupt. Questo thread viene pianificato utilizzando lo scheduler del processo standard, che tenta di allocare le risorse in modo equo.
Dopo aver studiato come il kernel elabora i pacchetti, puoi vedere che esiste una certa probabilità di congestione. Se le chiamate softirq vengono ricevute meno frequentemente, i pacchetti dovranno attendere un po' di tempo per essere elaborati nella coda RX sulla scheda di rete. Ciò potrebbe essere dovuto ad alcune attività che bloccano il core del processore o a qualcos'altro che impedisce al core di eseguire softirq.
Restringere l'elaborazione al nucleo o al metodo
I ritardi di Softirq sono solo una supposizione per ora. Ma ha senso e sappiamo che stiamo vedendo qualcosa di molto simile. Quindi il prossimo passo sarà confermare questa teoria. E se è confermato, trova il motivo 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 sottoposti ad hashing in una singola coda NIC RX ed elaborati da un singolo core della CPU. Se vogliamo capire come funziona Linux, è utile sapere dove (su quale core della CPU) e come (softirq, ksoftirqd) vengono elaborati questi pacchetti per poter tracciare il processo.
Adesso è il momento di utilizzare strumenti che permettano di monitorare il kernel Linux in tempo reale. Qui abbiamo usato . Questo insieme di strumenti ti consente di scrivere piccoli programmi C che agganciano funzioni arbitrarie nel kernel e memorizzano gli eventi in un programma Python nello spazio utente che può elaborarli e restituirti il risultato. Agganciare funzioni arbitrarie nel kernel è una questione complessa, ma l'utilità è progettata per la massima sicurezza ed è progettata per rintracciare esattamente il tipo di problemi di produzione che non sono facilmente riproducibili in un ambiente di test o di sviluppo.
Il piano qui è semplice: sappiamo che il kernel elabora questi ping ICMP, quindi inseriremo un hook nella funzione kernel , che accetta un pacchetto di richiesta echo ICMP in entrata e avvia l'invio di una risposta echo ICMP. Possiamo identificare un pacchetto aumentando il numero icmp_seq, che mostra hping3 sopra.
codice sembra complicato, ma non è così spaventoso come sembra. Funzione icmp_echo trasferimenti struct sk_buff *skb: Questo è un pacchetto con una "richiesta echo". Possiamo rintracciarlo ed estrarre la sequenza echo.sequence (che confronta con icmp_seq da hping3 выше) e inviarlo allo spazio utente. È anche conveniente acquisire il nome/id del processo corrente. Di seguito sono riportati i risultati che vediamo direttamente mentre il kernel elabora i pacchetti:
TGID NOME PROCESSO PID 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 rapporti-raggi-s XNUMX
Va notato qui che nel contesto softirq i processi che hanno effettuato chiamate di sistema appariranno come "processi" quando in realtà è il kernel che elabora in modo sicuro i pacchetti nel contesto del kernel.
Con questo strumento possiamo associare processi specifici a pacchetti specifici che mostrano un ritardo di hping3. Rendiamolo semplice grep su questa acquisizione per determinati valori icmp_seq. I pacchetti che corrispondono ai valori icmp_seq di cui sopra sono stati annotati insieme al loro RTT osservato sopra (tra parentesi ci sono i valori RTT attesi per i pacchetti che abbiamo filtrato a causa di valori RTT inferiori a 50 ms):
TGID NOME PROCESSO PID 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 ** 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 ksoft irqd/ 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 elaborati dal contesto ksoftirqd/11. Ciò significa che per questa particolare coppia di macchine, i pacchetti ICMP sono stati sottoposti ad hashing sul core 11 del destinatario. Vediamo anche che ogni volta che si verifica un inceppamento, ci sono pacchetti che vengono elaborati nel contesto della chiamata di sistema cadvisor. poi ksoftirqd assume il compito ed elabora la coda accumulata: esattamente il numero di pacchetti che si è accumulato successivamente cadvisor.
Il fatto che immediatamente prima funzioni sempre cadvisor, implica il suo coinvolgimento nel problema. Ironicamente, lo scopo - "analizzare l'utilizzo delle risorse e le caratteristiche prestazionali dei contenitori in esecuzione" anziché causare questo problema di prestazioni.
Come per altri aspetti dei contenitori, questi sono tutti strumenti altamente avanzati e possono verificarsi problemi di prestazioni in alcune circostanze impreviste.
Cosa fa Cadvisor per rallentare la coda dei pacchetti?
Ora abbiamo una comprensione abbastanza buona di come si verifica l'arresto anomalo, quale processo lo causa e su quale CPU. Vediamo che a causa del blocco rigido, il kernel Linux non ha tempo per la pianificazione ksoftirqd. E vediamo che i pacchetti vengono elaborati nel contesto cadvisor. È logico presumerlo cadvisor lancia una chiamata di sistema lenta, dopo la quale vengono elaborati tutti i pacchetti accumulati in quel momento:
Questa è una teoria, ma come verificarla? Ciò che possiamo fare è tracciare il core della CPU durante questo processo, trovare il punto in cui il numero di pacchetti supera il budget e viene chiamato ksoftirqd, quindi guardare un po' più indietro per vedere cosa stava esattamente funzionando sul core della CPU poco prima di quel punto . È come sottoporre a raggi X la CPU ogni pochi millisecondi. Apparirà qualcosa del genere:
Convenientemente, tutto questo può essere fatto con gli strumenti esistenti. Per esempio, controlla un dato core della CPU a una frequenza specifica e può generare un programma di chiamate al sistema in esecuzione, incluso sia lo spazio utente che il kernel Linux. Puoi prendere questo record ed elaborarlo utilizzando un piccolo fork del programma da Brendan Gregg, che preserva l'ordine dell'analisi dello stack. Possiamo salvare tracce di stack a riga singola ogni 1 ms, quindi evidenziare e salvare un campione 100 millisecondi prima che la traccia raggiunga 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:
(сотни следов, которые выглядят похожими)
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
Ci sono molte cose qui, ma la cosa principale è che troviamo il modello "cadvisor prima di ksoftirqd" che abbiamo visto in precedenza nel tracciante ICMP. Cosa significa?
Ogni riga è una traccia della CPU in un determinato momento. Ogni chiamata nello stack su una riga è separata da un punto e virgola. Nel mezzo delle righe vediamo la chiamata di sistema chiamata: read(): .... ;do_syscall_64;sys_read; .... Quindi Cadvisor dedica molto tempo alla chiamata di sistema read()legati alle funzioni mem_cgroup_* (inizio dello stack di chiamate/fine della riga).
È scomodo vedere nel tracciamento di una chiamata cosa viene letto esattamente, quindi corriamo strace e vediamo cosa fa Cadvisor e troviamo le chiamate di sistema più lunghe di 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>
Come ci si potrebbe aspettare, qui vediamo chiamate lente read(). Dal contenuto delle operazioni di lettura e dal contesto mem_cgroup è chiaro che queste sfide read() fare riferimento al fascicolo memory.stat, che mostra l'utilizzo della memoria e i limiti di cgroup (tecnologia di isolamento delle risorse di Docker). Lo strumento Cadvisor interroga questo file per ottenere informazioni sull'utilizzo 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 capire che il kernel Linux è affetto da una patologia.
Perché l'operazione di lettura è così lenta?
In questa fase è molto più semplice trovare messaggi di altri utenti su problemi simili. Come si è scoperto, nel tracker Cadvisor questo bug è stato segnalato come , è solo che nessuno ha notato che la latenza si riflette casualmente anche nello stack di rete. Si è infatti notato che Cadvisor consumava più tempo CPU del previsto, ma a questo non è stata data molta importanza, poiché i nostri server hanno molte risorse CPU, quindi il problema non è stato studiato attentamente.
Il problema è che i cgroup tengono conto dell'utilizzo della memoria all'interno dello spazio dei nomi (contenitore). Quando tutti i processi in questo cgroup escono, Docker rilascia il cgroup di memoria. Tuttavia, la "memoria" non è solo la memoria del processo. Sebbene la memoria del processo in sé non venga più utilizzata, sembra che il kernel assegni ancora i contenuti memorizzati nella cache, come dentry e inode (metadati di directory e file), che sono memorizzati nella cache nel cgroup di memoria. Dalla descrizione del problema:
cgroup zombie: cgroup che non hanno processi e sono stati cancellati, ma hanno ancora memoria allocata (nel mio caso, dalla dentry cache, ma può anche essere allocata dalla page cache o tmpfs).
Il controllo da parte del kernel di tutte le pagine nella cache quando si libera un cgroup può essere molto lento, quindi viene scelto il processo pigro: attendere finché queste pagine non vengono richieste nuovamente, quindi cancellare finalmente il cgroup quando la memoria è effettivamente necessaria. Fino a questo momento, cgroup viene ancora preso in considerazione nella raccolta delle statistiche.
Dal punto di vista delle prestazioni, hanno sacrificato la memoria a favore delle prestazioni: accelerando la pulizia iniziale lasciando dietro di sé un po' di memoria nella cache. Questo va bene. Quando il kernel utilizza l'ultima memoria cache, il cgroup viene eventualmente cancellato, quindi non può essere definito un "leak". Sfortunatamente, 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, significa che ci vuole molto più tempo per ripristinare gli ultimi dati memorizzati nella cache e cancellare gli zombie di cgroup.
Si scopre che alcuni dei nostri nodi avevano così tanti cgroup zombie che la lettura e la latenza superavano un secondo.
La soluzione alternativa al problema di Cadvisor è liberare immediatamente le cache di dentry/inode in tutto il sistema, eliminando immediatamente la latenza di lettura e di rete sull'host, poiché svuotare la cache attiva le pagine cgroup zombie memorizzate nella cache e libera anche quelle. Questa non è una soluzione, ma conferma la causa del problema.
Si è scoperto che nelle versioni del kernel più recenti (4.19+) le prestazioni delle chiamate erano migliorate memory.stat, quindi il passaggio a questo kernel ha risolto il problema. Allo stesso tempo, disponevamo di strumenti per rilevare i nodi problematici nei cluster Kubernetes, svuotarli con garbo e riavviarli. Abbiamo setacciato tutti i cluster, trovato nodi con una latenza sufficientemente elevata e li abbiamo riavviati. Questo ci ha dato il tempo di aggiornare il sistema operativo sui server rimanenti.
Riassumendo
Poiché questo bug ha interrotto l'elaborazione della coda della scheda NIC RX per centinaia di millisecondi, ha causato contemporaneamente sia un'elevata latenza su connessioni brevi che una latenza a metà connessione, ad esempio tra richieste MySQL e pacchetti di risposta.
Comprendere e mantenere le prestazioni dei sistemi più fondamentali, come Kubernetes, è fondamentale per l'affidabilità e la velocità di tutti i servizi basati su di essi. Ogni sistema che esegui beneficia dei miglioramenti delle prestazioni di Kubernetes.
Fonte: habr.com