Hai un par de anos Kubernetes no blog oficial de GitHub. Desde entón, converteuse na tecnoloxía estándar para a implantación de servizos. Kubernetes xestiona agora unha parte importante dos servizos internos e públicos. A medida que os nosos clústeres crecían e os requisitos de rendemento se facían máis estritos, comezamos a notar que algúns servizos en Kubernetes experimentaban esporádicamente unha latencia que non se podía explicar pola carga da propia aplicación.
Esencialmente, as aplicacións experimentan unha latencia de rede aparentemente aleatoria de ata 100 ms ou máis, o que provoca tempo de espera ou reintentos. Espérase que os servizos puidesen responder ás solicitudes moito máis rápido que 100 ms. Pero isto é imposible se a conexión en si leva tanto tempo. Por separado, observamos consultas de MySQL moi rápidas que deberían tardar milisegundos, e MySQL completouse en milisegundos, pero desde a perspectiva da aplicación solicitante, a resposta tardou 100 ms ou máis.
Inmediatamente quedou claro que o problema só se producía ao conectarse a un nodo de Kubernetes, aínda que a chamada procedía de fóra de Kubernetes. A forma máis sinxela de reproducir o problema é nunha proba , que se executa desde calquera host interno, proba o servizo Kubernetes nun porto específico e rexistra esporádicamente unha alta latencia. Neste artigo, veremos como puidemos rastrexar a causa deste problema.
Eliminando a complexidade innecesaria na cadea que conduce ao fracaso
Ao reproducir o mesmo exemplo, queriamos reducir o foco do problema e eliminar capas de complexidade innecesarias. Inicialmente, había demasiados elementos no fluxo entre Vegeta e as vainas de Kubernetes. Para identificar un problema de rede máis profundo, cómpre descartar algúns deles.
O cliente (Vegeta) crea unha conexión TCP con calquera nodo do clúster. Kubernetes funciona como unha rede superposta (sobre a rede do centro de datos existente) que usa , é dicir, encapsula os paquetes IP da rede de superposición dentro dos paquetes IP do centro de datos. Ao conectarse ao primeiro nodo, realízase a tradución de enderezos de rede (NAT) con estado para traducir o enderezo IP e o porto do nodo Kubernetes ao enderezo IP e ao porto da rede de superposición (específicamente, o pod coa aplicación). Para os paquetes entrantes, realízase a secuencia inversa de accións. É un sistema complexo con moito estado e moitos elementos que se actualizan e cambian constantemente a medida que se despregan e se moven servizos.
Utilidade tcpdump na proba de Vegeta hai un atraso durante o apretón de mans TCP (entre SYN e SYN-ACK). Para eliminar esta complexidade innecesaria, pode usar hping3 para simples "pings" con paquetes SYN. Comprobamos se hai un atraso no paquete de resposta e despois restablecemos a conexión. Podemos filtrar os datos para incluír só paquetes de máis de 100 ms e obter unha forma máis sinxela de reproducir o problema que a proba completa da capa 7 de rede en Vegeta. Aquí están os "pings" do nodo de Kubernetes usando TCP SYN/SYN-ACK no "porto do nodo" do servizo (30927) a intervalos de 10 ms, filtrados polas respostas máis lentas:
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
Pode facer inmediatamente a primeira observación. A xulgar polos números de secuencia e os tempos, está claro que non se trata de conxestións puntuais. O atraso adoita acumularse e finalmente procédese.
A continuación, queremos descubrir que compoñentes poden estar implicados na aparición de conxestión. Quizais estas sexan algunhas das centos de regras de iptables en NAT? Ou hai algún problema co túnel IPIP na rede? Unha forma de probar isto é probar cada paso do sistema eliminándoo. Que pasa se eliminas a lóxica NAT e do firewall, deixando só a parte IPIP:
Afortunadamente, Linux facilita o acceso directo á capa de superposición IP se a máquina está na mesma rede:
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 xulgar polos resultados, o problema segue a ser! Isto exclúe iptables e NAT. Entón, o problema é TCP? Vexamos como vai 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
Os resultados mostran que o problema non desapareceu. Quizais este sexa un túnel IPIP? Simplificamos aínda máis a proba:
Envíanse todos os paquetes entre estes dous hosts?
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
Simplificamos a situación a dous nodos Kubernetes que se envían un ao outro calquera paquete, incluso un ping ICMP. Aínda ven a latencia se o servidor de destino é "malo" (uns peores que outros).
Agora a última pregunta: por que o atraso só ocorre nos servidores de nodo kube? E ocorre cando kube-node é o emisor ou o receptor? Afortunadamente, isto tamén é bastante fácil de descubrir enviando un paquete desde un host fóra de Kubernetes, pero co mesmo destinatario "malo coñecido". Como podes ver, o problema non desapareceu:
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
Despois executaremos as mesmas solicitudes desde o nodo kube de orixe anterior ao host externo (o que exclúe o host de orixe xa que o ping inclúe tanto un compoñente RX como 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
Ao examinar as capturas de paquetes de latencia, obtivemos algunha información adicional. En concreto, que o remitente (abaixo) ve este tempo de espera, pero o destinatario (arriba) non - ve a columna Delta (en segundos):
Ademais, se observas a diferenza na orde dos paquetes TCP e ICMP (por números de secuencia) no lado do destinatario, os paquetes ICMP sempre chegan na mesma secuencia na que foron enviados, pero con diferente tempo. Ao mesmo tempo, os paquetes TCP ás veces se entrelazan e algúns deles quedan atascados. En particular, se examinas os portos dos paquetes SYN, están en orde do lado do remitente, pero non do lado do receptor.
Hai unha diferenza sutil no como os servidores modernos (como os do noso centro de datos) procesan paquetes que conteñen TCP ou ICMP. Cando chega un paquete, o adaptador de rede "hashéao por conexión", é dicir, tenta dividir as conexións en filas e enviar cada fila a un núcleo de procesador separado. Para TCP, este hash inclúe o enderezo IP e o porto de orixe e destino. Noutras palabras, cada conexión ten un hash (potencialmente) diferente. Para ICMP, só os enderezos IP teñen un hash, xa que non hai portos.
Outra observación nova: durante este período vemos atrasos ICMP en todas as comunicacións entre dous hosts, pero TCP non. Isto indícanos que a causa probablemente está relacionada co hash da cola RX: a conxestión está case con toda seguridade no procesamento de paquetes RX, non no envío de respostas.
Isto elimina o envío de paquetes da lista de posibles causas. Agora sabemos que o problema de procesamento de paquetes está no lado de recepción nalgúns servidores kube-node.
Comprensión do procesamento de paquetes no núcleo Linux
Para entender por que se produce o problema no receptor nalgúns servidores de nodo kube, vexamos como procesa os paquetes o núcleo de Linux.
Volvendo á implementación tradicional máis sinxela, a tarxeta de rede recibe o paquete e envía o núcleo de Linux que hai un paquete que debe ser procesado. O núcleo detén outros traballos, cambia o contexto ao controlador de interrupcións, procesa o paquete e, a continuación, volve ás tarefas actuais.
Este cambio de contexto é lento: a latencia podería non ser perceptible nas tarxetas de rede de 10 Mbps nos anos 90, pero nas tarxetas 10G modernas cun rendemento máximo de 15 millóns de paquetes por segundo, cada núcleo dun pequeno servidor de oito núcleos pode interromperse millóns. de veces por segundo.
Para non xestionar interrupcións constantemente, hai moitos anos engadiuse Linux : API de rede que utilizan todos os controladores modernos para mellorar o rendemento a altas velocidades. A baixas velocidades, o núcleo aínda recibe interrupcións da tarxeta de rede na forma antiga. Unha vez que chegan paquetes suficientes que superan o limiar, o núcleo desactiva as interrupcións e, no seu lugar, comeza a sondear o adaptador de rede e recoller os paquetes en anacos. O procesamento realízase en softirq, é dicir, en despois de chamadas ao sistema e interrupcións de hardware, cando o núcleo (en oposición ao espazo do usuario) xa está en execución.
Isto é moito máis rápido, pero causa un problema diferente. Se hai demasiados paquetes, pásase todo o tempo procesando os paquetes da tarxeta de rede e os procesos de espazo de usuario non teñen tempo para baleirar estas filas (lendo desde conexións TCP, etc.). Finalmente as filas enchéronse e comezamos a soltar paquetes. Nun intento de atopar un equilibrio, o núcleo establece un orzamento para o número máximo de paquetes procesados no contexto softirq. Unha vez superado este orzamento, despertase un fío separado ksoftirqd (Verás un deles en ps por núcleo) que manexa estes softirq fóra da ruta normal de chamada/interrupción do sistema. Este fío está programado mediante o programador de procesos estándar, que tenta asignar os recursos de forma xusta.
Despois de estudar como o núcleo procesa os paquetes, podes ver que hai unha certa probabilidade de conxestión. Se as chamadas de softirq se reciben con menos frecuencia, os paquetes terán que esperar un tempo para ser procesados na cola RX da tarxeta de rede. Isto pode deberse a que algunha tarefa bloquea o núcleo do procesador ou a que outra cousa está a impedir que o núcleo funcione con softirq.
Reducir o procesamento ata o núcleo ou método
Os atrasos de Softirq son só unha suposición polo momento. Pero ten sentido, e sabemos que estamos a ver algo moi semellante. Polo que o seguinte paso é confirmar esta teoría. E se se confirma, entón busca o motivo dos atrasos.
Volvamos aos nosos paquetes lentos:
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
Como se comentou anteriormente, estes paquetes ICMP son agrupados nunha única fila de NIC RX e procesados por un único núcleo de CPU. Se queremos entender como funciona Linux, é útil saber onde (en que núcleo da CPU) e como (softirq, ksoftirqd) se procesan estes paquetes para seguir o proceso.
Agora toca utilizar ferramentas que che permitan supervisar o núcleo de Linux en tempo real. Aquí usamos . Este conxunto de ferramentas permítelle escribir pequenos programas C que enganchan funcións arbitrarias no núcleo e almacenan os eventos nun programa Python no espazo de usuario que pode procesalos e devolverlle o resultado. Conectar funcións arbitrarias no núcleo é un negocio complicado, pero a utilidade está deseñada para a máxima seguridade e está deseñada para rastrexar exactamente o tipo de problemas de produción que non se reproducen facilmente nun ambiente de proba ou desenvolvemento.
O plan aquí é sinxelo: sabemos que o núcleo procesa estes pings ICMP, polo que imos poñer un gancho na función do núcleo. , que acepta un paquete de solicitude de eco ICMP entrante e inicia o envío dunha resposta de eco ICMP. Podemos identificar un paquete aumentando o número icmp_seq, que se mostra hping3 superior.
Código parece complicado, pero non dá tanto medo como parece. Función icmp_echo transferencias struct sk_buff *skb: Este é un paquete cunha "solicitude de eco". Podemos rastrexalo, sacar a secuencia echo.sequence (que se compara con icmp_seq por hping3 выше), e envíao ao espazo do usuario. Tamén é conveniente capturar o nome/id do proceso actual. Abaixo amósanse os resultados que vemos directamente mentres o núcleo procesa paquetes:
NOME DO PROCESO PID TGID ICMP_SEQ 0 0 troca/11 770 0 troca/0 11 771 troca/0 0 11 troca/772 0 0 troca/11 773 0 Prometheus 0 11 774 troca/20041 20086 775 troca/0 0 11 troca/776 0 0 informes de radios 11
Cómpre sinalar aquí que no contexto softirq os procesos que realizaron chamadas ao sistema aparecerán como "procesos" cando en realidade é o núcleo o que procesa os paquetes con seguridade no contexto do núcleo.
Con esta ferramenta podemos asociar procesos específicos con paquetes específicos que mostren un atraso de hping3. Imos facelo sinxelo grep sobre esta captura para determinados valores icmp_seq. Os paquetes que coinciden cos valores icmp_seq anteriores foron marcados xunto co seu RTT que observamos anteriormente (entre parénteses están os valores RTT esperados para os paquetes que filtramos debido a valores RTT inferiores a 50 ms):
NOME DO PROCESO PID TGID ICMP_SEQ ** RTT -- 10137 10436 cadvisor 1951 10137 10436 cadvisor 1952 76 76 ksoftirqd/11 1953 ** 99 ms 76 76 ksoftirqd/11 1954 ** 89 ms 76 76 ksoftirqd/11 1955 ** 79ms 76 76 ksoftirqd/11 1956 ** 69 ms 76 76 ksoftirqd/11 1957 ** 59 ms 76 76 ksoftirqd/11 1958 ** (49 ms) 76 76 ksoftirqd/11 1959 ** (39 ms) 76 76 ksoftirqd/11 1960 ** (29 ms) 76 76 ksoftirqd/11 1961 ** (19 ms) 76 76 ksoftirqd/11 1962 ** (9 ms) -- 10137 10436 cadvisor 2068 10137 10436 cadvisor 2069 76 76 ksoftirqd/11 2070 ** 75 ms 76 76 ksoftirqd/11 2071 ** 65 ms 76 76 ksoftirqd/11 2072 ** 55 ms 76 76 ksoftirqd/11 2073 ** (45 ms) 76 76 ksoftirqd/11 2074 ** (35 ms) 76 76 ksoftirqd/11 2075 ** (25 ms) 76 76 ksoftirqd/11 2076 ** (15 ms) 76 76 ksoftirqd/11 2077 ** (5 ms)
Os resultados dinnos varias cousas. En primeiro lugar, todos estes paquetes son procesados polo contexto ksoftirqd/11. Isto significa que para este par de máquinas en particular, os paquetes ICMP foron enviados ao núcleo 11 no extremo receptor. Tamén vemos que sempre que hai un atasco, hai paquetes que se procesan no contexto da chamada do sistema cadvisor. Entón ksoftirqd asume a tarefa e procesa a cola acumulada: exactamente o número de paquetes acumulados despois cadvisor.
O feito de que inmediatamente antes sempre funciona cadvisor, implica a súa implicación no problema. Irónicamente, o propósito - "Analiza o uso de recursos e as características de rendemento dos contedores en execución" en lugar de causar este problema de rendemento.
Do mesmo xeito que con outros aspectos dos contedores, todas estas son ferramentas moi avanzadas e cabe esperar que experimenten problemas de rendemento nalgunhas circunstancias imprevistas.
Que fai cadvisor para ralentizar a cola de paquetes?
Agora temos unha boa comprensión de como ocorre o fallo, que proceso o está a provocar e en que CPU. Vemos que debido ao bloqueo duro, o núcleo de Linux non ten tempo para programar ksoftirqd. E vemos que os paquetes son procesados en contexto cadvisor. É lóxico supoñer que cadvisor inicia unha chamada de sistema lenta, despois de que se procesan todos os paquetes acumulados nese momento:
Esta é unha teoría, pero como probala? O que podemos facer é rastrexar o núcleo da CPU ao longo deste proceso, atopar o punto no que o número de paquetes supera o orzamento e chámase ksoftirqd e, a continuación, mirar un pouco máis atrás para ver que se estaba executando exactamente no núcleo da CPU xusto antes dese punto. . É como unha radiografía da CPU cada poucos milisegundos. Será algo así:
Convenientemente, todo isto pódese facer coas ferramentas existentes. Por exemplo, comproba un núcleo de CPU determinado cunha frecuencia especificada e pode xerar unha programación de chamadas ao sistema en execución, incluíndo tanto o espazo de usuario como o núcleo de Linux. Podes coller este rexistro e procesalo usando unha pequena bifurcación do programa de Brendan Gregg, que conserva a orde da traza da pila. Podemos gardar trazos de pila dunha soa liña cada 1 ms e, a continuación, resaltar e gardar unha mostra 100 milisegundos antes de que chegue a traza 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
Aquí están os resultados:
(сотни следов, которые выглядят похожими)
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
Hai moitas cousas aquí, pero o principal é que atopamos o patrón "cadvisor antes de ksoftirqd" que vimos anteriormente no rastreador ICMP. Qué significa?
Cada liña é un trazo da CPU nun momento específico. Cada chamada da pila nunha liña está separada por un punto e coma. No medio das liñas vemos a chamada syscall: read(): .... ;do_syscall_64;sys_read; .... Entón, cadvisor dedica moito tempo á chamada do sistema read()relacionadas coas funcións mem_cgroup_* (parte superior da pila de chamadas/fin da liña).
É inconveniente ver nun rastrexo de chamadas o que se está lendo exactamente, así que imos correr strace e vexamos o que fai cadvisor e atopemos chamadas ao sistema de máis 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>
Como podes esperar, aquí vemos chamadas lentas read(). A partir dos contidos das operacións de lectura e do contexto mem_cgroup está claro que estes retos read() consulte o ficheiro memory.stat, que mostra o uso da memoria e os límites de cgroup (tecnoloxía de illamento de recursos de Docker). A ferramenta cadvisor consulta este ficheiro para obter información sobre o uso dos recursos dos contedores. Comprobamos se é o núcleo ou o cadvisor facendo algo inesperado:
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 ~ $
Agora podemos reproducir o erro e entender que o kernel de Linux enfróntase a unha patoloxía.
Por que a operación de lectura é tan lenta?
Nesta fase, é moito máis doado atopar mensaxes doutros usuarios sobre problemas similares. Como se viu, no rastreador de cadvisor informouse deste erro como , é que ninguén se decatou de que a latencia tamén se reflicte aleatoriamente na pila de rede. De feito, observouse que cadvisor consumía máis tempo de CPU do esperado, pero non se lle deu moita importancia, xa que os nosos servidores teñen moitos recursos de CPU, polo que o problema non foi estudado detidamente.
O problema é que os cgroups teñen en conta o uso da memoria dentro do espazo de nomes (contedor). Cando todos os procesos deste cgroup saen, Docker libera o cgroup de memoria. Non obstante, "memoria" non é só memoria de proceso. Aínda que a propia memoria de proceso xa non se utiliza, parece que o núcleo aínda asigna contidos en caché, como dentries e inodos (metadatos de directorio e ficheiros), que se almacenan na memoria caché no cgroup de memoria. Da descrición do problema:
cgroups zombies: cgroups que non teñen procesos e foron eliminados, pero que aínda teñen memoria asignada (no meu caso, dende a caché dentry, pero tamén se pode asignar dende a caché da páxina ou tmpfs).
A comprobación do núcleo de todas as páxinas da caché ao liberar un cgroup pode ser moi lenta, polo que elíxese o proceso preguiceiro: agarda ata que se soliciten de novo estas páxinas e, finalmente, borra o cgroup cando a memoria sexa realmente necesaria. Ata este punto, cgroup aínda se ten en conta á hora de recoller estatísticas.
Desde o punto de vista do rendemento, sacrificaron a memoria polo rendemento: acelerando a limpeza inicial deixando algo de memoria caché atrás. Isto está ben. Cando o kernel usa o último da memoria caché, o cgroup é finalmente borrado, polo que non se pode chamar "fuga". Desafortunadamente, a implementación específica do mecanismo de busca memory.stat nesta versión do núcleo (4.9), combinada coa enorme cantidade de memoria dos nosos servidores, significa que leva moito máis tempo restaurar os últimos datos almacenados na caché e borrar os zombies do cgroup.
Resulta que algúns dos nosos nodos tiñan tantos cgroup zombies que a lectura e a latencia superaban un segundo.
A solución para o problema de cadvisor é liberar inmediatamente as cachés de dentries/inodos en todo o sistema, o que elimina inmediatamente a latencia de lectura e a latencia de rede no host, xa que ao limpar a caché se activan as páxinas zombies de cgroup caché e tamén se liberan. Esta non é unha solución, pero confirma a causa do problema.
Resultou que nas versións máis recentes do núcleo (4.19+) mellorouse o rendemento das chamadas memory.stat, polo que cambiar a este núcleo solucionou o problema. Ao mesmo tempo, tiñamos ferramentas para detectar nodos problemáticos nos clústeres de Kubernetes, drenalos con gracia e reinicialos. Peiteamos todos os clústeres, atopamos nós cunha latencia suficientemente alta e reiniciámolos. Isto deunos tempo para actualizar o SO nos servidores restantes.
Resumo
Debido a que este erro detivo o procesamento da cola RX NIC durante centos de milisegundos, provocou simultaneamente unha alta latencia en conexións curtas e unha latencia de conexión media, como entre as solicitudes de MySQL e os paquetes de resposta.
Comprender e manter o rendemento dos sistemas máis fundamentais, como Kubernetes, é fundamental para a fiabilidade e a velocidade de todos os servizos baseados neles. Todos os sistemas que executas benefician das melloras de rendemento de Kubernetes.
Fonte: www.habr.com