Hace un par de años Kubernetes en el blog oficial de GitHub. Desde entonces, se ha convertido en la tecnología estándar para implementar servicios. Kubernetes ahora gestiona una parte importante de los servicios públicos e internos. A medida que nuestros clústeres crecieron y los requisitos de rendimiento se volvieron más estrictos, comenzamos a notar que algunos servicios en Kubernetes experimentaban esporádicamente una latencia que no podía explicarse por la carga de la aplicación en sí.
Básicamente, las aplicaciones experimentan una latencia de red aparentemente aleatoria de hasta 100 ms o más, lo que provoca tiempos de espera o reintentos. Se esperaba que los servicios pudieran responder a las solicitudes mucho más rápido que 100 ms. Pero esto es imposible si la conexión lleva tanto tiempo. Por otra parte, observamos consultas MySQL muy rápidas que deberían haber tomado milisegundos, y MySQL se completó en milisegundos, pero desde la perspectiva de la aplicación solicitante, la respuesta tomó 100 ms o más.
Inmediatamente quedó claro que el problema solo ocurría al conectarse a un nodo de Kubernetes, incluso si la llamada procedía de fuera de Kubernetes. La forma más sencilla de reproducir el problema es mediante una prueba. , que se ejecuta desde cualquier host interno, prueba el servicio Kubernetes en un puerto específico y esporádicamente registra una latencia alta. En este artículo, veremos cómo pudimos rastrear la causa de este problema.
Eliminar la complejidad innecesaria en la cadena que conduce al fracaso.
Al reproducir el mismo ejemplo, queríamos limitar el foco del problema y eliminar capas innecesarias de complejidad. Inicialmente, había demasiados elementos en el flujo entre Vegeta y las cápsulas de Kubernetes. Para identificar un problema de red más profundo, es necesario descartar algunos de ellos.
El cliente (Vegeta) crea una conexión TCP con cualquier nodo del clúster. Kubernetes opera como una red superpuesta (sobre la red del centro de datos existente) que utiliza , es decir, encapsula los paquetes IP de la red superpuesta dentro de los paquetes IP del centro de datos. Al conectarse al primer nodo, se realiza la traducción de la dirección de red. (NAT) con estado para traducir la dirección IP y el puerto del nodo de Kubernetes a la dirección IP y el puerto en la red superpuesta (específicamente, el pod con la aplicación). Para los paquetes entrantes, se realiza la secuencia inversa de acciones. Es un sistema complejo con mucho estado y muchos elementos que se actualizan y cambian constantemente a medida que se implementan y mueven los servicios.
Utilidad tcpdump en la prueba de Vegeta hay un retraso durante el protocolo de enlace TCP (entre SYN y SYN-ACK). Para eliminar esta complejidad innecesaria, puede utilizar hping3 para “pings” simples con paquetes SYN. Verificamos si hay un retraso en el paquete de respuesta y luego restablecemos la conexión. Podemos filtrar los datos para incluir solo paquetes de más de 100 ms y obtener una manera más fácil de reproducir el problema que la prueba de capa 7 de red completa en Vegeta. Aquí están los "pings" del nodo de Kubernetes usando TCP SYN/SYN-ACK en el "puerto de nodo" del servicio (30927) a intervalos de 10 ms, filtrados por las respuestas más 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
Puedo hacer inmediatamente la primera observación. A juzgar por los números de secuencia y los tiempos, está claro que no se trata de congestiones puntuales. El retraso a menudo se acumula y finalmente se procesa.
A continuación, queremos saber qué componentes pueden estar implicados en la aparición de la congestión. ¿Quizás estas sean algunas de los cientos de reglas de iptables en NAT? ¿O hay algún problema con el túnel IPIP en la red? Una forma de probar esto es probar cada paso del sistema eliminándolo. ¿Qué sucede si elimina la lógica NAT y del firewall, dejando solo la parte IPIP?
Afortunadamente, Linux facilita el acceso directo a la capa de superposición de IP si la máquina está en la misma red:
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 juzgar por los resultados, ¡el problema persiste! Esto excluye iptables y NAT. ¿Entonces el problema es TCP? Veamos cómo va 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
Los resultados muestran que el problema no ha desaparecido. ¿Quizás este sea un túnel IPIP? Simplifiquemos aún más la prueba:
¿Se envían todos los paquetes entre estos dos 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
Hemos simplificado la situación para que dos nodos de Kubernetes se envíen entre sí cualquier paquete, incluso un ping ICMP. Todavía ven latencia si el host de destino es "malo" (algunos peores que otros).
Ahora la última pregunta: ¿por qué el retraso solo ocurre en los servidores de nodo kube? ¿Y sucede cuando kube-node es el remitente o el receptor? Afortunadamente, esto también es bastante fácil de resolver enviando un paquete desde un host fuera de Kubernetes, pero con el mismo destinatario "malo conocido". Como puedes ver, el problema no ha desaparecido:
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
Luego ejecutaremos las mismas solicitudes desde el nodo kube de origen anterior al host externo (lo que excluye el host de origen ya que el ping incluye un componente RX y 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
Al examinar las capturas de paquetes de latencia, obtuvimos información adicional. Específicamente, el remitente (abajo) ve este tiempo de espera, pero el destinatario (arriba) no; consulte la columna Delta (en segundos):
Además, si observa la diferencia en el orden de los paquetes TCP e ICMP (por números de secuencia) en el lado del destinatario, los paquetes ICMP siempre llegan en la misma secuencia en la que fueron enviados, pero con tiempos diferentes. Al mismo tiempo, los paquetes TCP a veces se entrelazan y algunos de ellos se atascan. En particular, si examina los puertos de los paquetes SYN, están en orden en el lado del remitente, pero no en el lado del receptor.
Hay una sutil diferencia en cómo Los servidores modernos (como los de nuestro centro de datos) procesan paquetes que contienen TCP o ICMP. Cuando llega un paquete, el adaptador de red lo "hashea por conexión", es decir, intenta dividir las conexiones en colas y enviar cada cola a un núcleo de procesador separado. Para TCP, este hash incluye la dirección IP y el puerto de origen y de destino. En otras palabras, cada conexión tiene un hash (potencialmente) diferente. Para ICMP, solo se aplican hash a las direcciones IP, ya que no hay puertos.
Otra nueva observación: durante este período vemos retrasos ICMP en todas las comunicaciones entre dos hosts, pero TCP no. Esto nos dice que la causa probablemente esté relacionada con el hash de la cola RX: es casi seguro que la congestión se produce en el procesamiento de paquetes RX, no en el envío de respuestas.
Esto elimina el envío de paquetes de la lista de posibles causas. Ahora sabemos que el problema de procesamiento de paquetes está en el lado de recepción en algunos servidores de nodo kube.
Comprender el procesamiento de paquetes en el kernel de Linux
Para comprender por qué ocurre el problema en el receptor en algunos servidores de nodo kube, veamos cómo el kernel de Linux procesa los paquetes.
Volviendo a la implementación tradicional más simple, la tarjeta de red recibe el paquete y envía el kernel de Linux que hay un paquete que necesita ser procesado. El kernel detiene otros trabajos, cambia el contexto al controlador de interrupciones, procesa el paquete y luego regresa a las tareas actuales.
Este cambio de contexto es lento: la latencia puede no haber sido perceptible en las tarjetas de red de 10 Mbps en los años 90, pero en las tarjetas 10G modernas con un rendimiento máximo de 15 millones de paquetes por segundo, cada núcleo de un pequeño servidor de ocho núcleos puede verse interrumpido por millones. de veces por segundo.
Para no tener que lidiar constantemente con interrupciones, hace muchos años Linux agregó : API de red que utilizan todos los controladores modernos para mejorar el rendimiento a altas velocidades. A bajas velocidades, el kernel todavía recibe interrupciones de la tarjeta de red como antes. Una vez que llegan suficientes paquetes que superan el umbral, el kernel desactiva las interrupciones y, en su lugar, comienza a sondear el adaptador de red y a recoger paquetes en trozos. El procesamiento se realiza en softirq, es decir, en después de llamadas al sistema e interrupciones de hardware, cuando el kernel (a diferencia del espacio de usuario) ya se está ejecutando.
Esto es mucho más rápido, pero causa un problema diferente. Si hay demasiados paquetes, entonces se dedica todo el tiempo a procesar paquetes desde la tarjeta de red y los procesos del espacio de usuario no tienen tiempo para vaciar realmente estas colas (lectura de conexiones TCP, etc.). Al final las colas se llenan y empezamos a dejar paquetes. En un intento por encontrar un equilibrio, el kernel establece un presupuesto para la cantidad máxima de paquetes procesados en el contexto softirq. Una vez superado este presupuesto se despierta un hilo aparte ksoftirqd (verás uno de ellos en ps por núcleo) que maneja estos softirqs fuera de la ruta normal de llamada al sistema/interrupción. Este hilo se programa utilizando el programador de procesos estándar, que intenta asignar recursos de manera justa.
Habiendo estudiado cómo el kernel procesa los paquetes, puede ver que existe una cierta probabilidad de congestión. Si las llamadas de softirq se reciben con menos frecuencia, los paquetes tendrán que esperar algún tiempo para ser procesados en la cola RX de la tarjeta de red. Esto puede deberse a que alguna tarea bloquea el núcleo del procesador o a algo más que impide que el núcleo ejecute softirq.
Restringir el procesamiento al núcleo o método.
Los retrasos de Softirq son sólo una suposición por ahora. Pero tiene sentido y sabemos que estamos viendo algo muy similar. Entonces el siguiente paso es confirmar esta teoría. Y si se confirma, busque el motivo de los retrasos.
Volvamos a nuestros 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 analizó anteriormente, estos paquetes ICMP se agrupan en una única cola RX NIC y se procesan mediante un único núcleo de CPU. Si queremos entender cómo funciona Linux, es útil saber dónde (en qué núcleo de CPU) y cómo (softirq, ksoftirqd) se procesan estos paquetes para poder seguir el proceso.
Ahora es el momento de utilizar herramientas que le permitan monitorear el kernel de Linux en tiempo real. Aquí usamos . Este conjunto de herramientas le permite escribir pequeños programas en C que enlazan funciones arbitrarias en el kernel y almacenan en buffer los eventos en un programa Python en el espacio de usuario que puede procesarlos y devolverle el resultado. Conectar funciones arbitrarias en el kernel es una tarea complicada, pero la utilidad está diseñada para brindar máxima seguridad y está diseñada para rastrear exactamente el tipo de problemas de producción que no se reproducen fácilmente en un entorno de prueba o desarrollo.
El plan aquí es simple: sabemos que el kernel procesa estos pings ICMP, así que conectaremos la función del kernel. , que acepta un paquete de solicitud de eco ICMP entrante e inicia el envío de una respuesta de eco ICMP. Podemos identificar un paquete aumentando el número icmp_seq, que muestra hping3 anteriormente.
código Parece complicado, pero no da tanto miedo como parece. Función icmp_echo transmite struct sk_buff *skb: Este es un paquete con una "solicitud de eco". Podemos rastrearlo, sacar la secuencia. echo.sequence (que se compara con icmp_seq por hping3 выше) y enviarlo al espacio del usuario. También es conveniente capturar el nombre/id del proceso actual. A continuación se muestran los resultados que vemos directamente mientras el kernel procesa paquetes:
TGID PID NOMBRE DEL PROCESO ICMP_SEQ 0 0 intercambiador/11 770 0 intercambiador/0 11 771 intercambiador/0 0 11 intercambiador/772 0 0 intercambiador/11 773 0 prometeo 0 11 774 intercambiador/20041 20086 775 intercambiador/0 0 11 intercambiador/776 0 0 radios-informe-s 11
Cabe señalar aquí que en el contexto softirq Los procesos que realizaron llamadas al sistema aparecerán como "procesos" cuando en realidad es el núcleo el que procesa paquetes de forma segura en el contexto del núcleo.
Con esta herramienta podemos asociar procesos específicos con paquetes específicos que muestran un retraso de hping3. Hagámoslo simple grep en esta captura para ciertos valores icmp_seq. Los paquetes que coinciden con los valores icmp_seq anteriores se marcaron junto con su RTT que observamos anteriormente (entre paréntesis están los valores RTT esperados para los paquetes que filtramos debido a valores RTT inferiores a 50 ms):
TGID PID NOMBRE DEL PROCESO 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 ** 75 ms 76 76 ksoftirqd/11 2071 ** 65ms 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 ** (5ms)
Los resultados nos dicen varias cosas. En primer lugar, todos estos paquetes son procesados por el contexto. ksoftirqd/11. Esto significa que para este par de máquinas en particular, los paquetes ICMP se enviaron al núcleo 11 en el extremo receptor. También vemos que siempre que hay un atasco, hay paquetes que se procesan en el contexto de la llamada al sistema. cadvisor. Entonces ksoftirqd se hace cargo de la tarea y procesa la cola acumulada: exactamente el número de paquetes que se han acumulado después cadvisor.
El hecho de que inmediatamente antes siempre funcione. cadvisor, implica su implicación en el problema. Irónicamente, el propósito - "analizar el uso de recursos y las características de rendimiento de los contenedores en ejecución" en lugar de causar este problema de rendimiento.
Al igual que con otros aspectos de los contenedores, todas estas son herramientas muy avanzadas y se puede esperar que experimenten problemas de rendimiento en algunas circunstancias imprevistas.
¿Qué hace cadvisor que ralentiza la cola de paquetes?
Ahora entendemos bastante bien cómo ocurre el bloqueo, qué proceso lo está causando y en qué CPU. Vemos que debido al bloqueo duro, el kernel de Linux no tiene tiempo para programar ksoftirqd. Y vemos que los paquetes se procesan en contexto. cadvisor. Es lógico suponer que cadvisor lanza una llamada al sistema lenta, después de la cual se procesan todos los paquetes acumulados en ese momento:
Esta es una teoría, pero ¿cómo probarla? Lo que podemos hacer es rastrear el núcleo de la CPU a lo largo de este proceso, encontrar el punto donde la cantidad de paquetes supera el presupuesto y se llama a ksoftirqd, y luego mirar un poco más atrás para ver qué se estaba ejecutando exactamente en el núcleo de la CPU justo antes de ese punto. . Es como radiografiar la CPU cada pocos milisegundos. Se verá algo como esto:
Convenientemente, todo esto se puede hacer con las herramientas existentes. Por ejemplo, comprueba un núcleo de CPU determinado con una frecuencia específica y puede generar una programación de llamadas al sistema en ejecución, incluido tanto el espacio de usuario como el kernel de Linux. Puedes tomar este registro y procesarlo usando una pequeña bifurcación del programa. de Brendan Gregg, que conserva el orden del seguimiento de la pila. Podemos guardar seguimientos de pila de una sola línea cada 1 ms y luego resaltar y guardar una muestra 100 milisegundos antes de que llegue el seguimiento. 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 los 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
Hay muchas cosas aquí, pero lo principal es que encontramos el patrón "cadvisor antes de ksoftirqd" que vimos anteriormente en el rastreador ICMP. ¿Qué significa?
Cada línea es un seguimiento de la CPU en un momento específico. Cada llamada de la pila en una línea está separada por un punto y coma. En medio de las líneas vemos que se llama a la llamada al sistema: read(): .... ;do_syscall_64;sys_read; .... Entonces cadvisor dedica mucho tiempo a la llamada al sistema. read()relacionado con funciones mem_cgroup_* (parte superior de la pila de llamadas/fin de línea).
Es inconveniente ver en un seguimiento de llamadas qué se está leyendo exactamente, así que ejecutemos strace y veamos qué hace cadvisor y encontremos llamadas al sistema de más de 100 ms:
theojulienne@kube-node-bad ~ $ sudo strace -p 10137 -T -ff 2>&1 | egrep '<0.[1-9]'
[pid 10436] <... futex resumed> ) = 0 <0.156784>
[pid 10432] <... futex resumed> ) = 0 <0.258285>
[pid 10137] <... futex resumed> ) = 0 <0.678382>
[pid 10384] <... futex resumed> ) = 0 <0.762328>
[pid 10436] <... read resumed> "cache 154234880nrss 507904nrss_h"..., 4096) = 658 <0.179438>
[pid 10384] <... futex resumed> ) = 0 <0.104614>
[pid 10436] <... futex resumed> ) = 0 <0.175936>
[pid 10436] <... read resumed> "cache 0nrss 0nrss_huge 0nmapped_"..., 4096) = 577 <0.228091>
[pid 10427] <... read resumed> "cache 0nrss 0nrss_huge 0nmapped_"..., 4096) = 577 <0.207334>
[pid 10411] <... epoll_ctl resumed> ) = 0 <0.118113>
[pid 10382] <... pselect6 resumed> ) = 0 (Timeout) <0.117717>
[pid 10436] <... read resumed> "cache 154234880nrss 507904nrss_h"..., 4096) = 660 <0.159891>
[pid 10417] <... futex resumed> ) = 0 <0.917495>
[pid 10436] <... futex resumed> ) = 0 <0.208172>
[pid 10417] <... futex resumed> ) = 0 <0.190763>
[pid 10417] <... read resumed> "cache 0nrss 0nrss_huge 0nmapped_"..., 4096) = 576 <0.154442>
Como era de esperar, vemos llamadas lentas aquí. read(). Del contenido de las operaciones de lectura y el contexto. mem_cgroup está claro que estos desafíos read() consulte el archivo memory.stat, que muestra el uso de memoria y los límites de cgroup (tecnología de aislamiento de recursos de Docker). La herramienta cadvisor consulta este archivo para obtener información sobre el uso de recursos para los contenedores. Comprobemos si es el kernel o cadvisor el que está haciendo 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 ~ $
Ahora podemos reproducir el error y comprender que el kernel de Linux se enfrenta a una patología.
¿Por qué la operación de lectura es tan lenta?
En esta etapa, es mucho más fácil encontrar mensajes de otros usuarios sobre problemas similares. Al final resultó que, en el rastreador de cadvisor este error se informó como Pero nadie se dio cuenta de que la latencia también se refleja aleatoriamente en la pila de la red. De hecho, se notó que cadvisor consumía más tiempo de CPU de lo esperado, pero no se le dio mucha importancia, ya que nuestros servidores tienen muchos recursos de CPU, por lo que el problema no se estudió detenidamente.
El problema es que los cgroups tienen en cuenta el uso de memoria dentro del espacio de nombres (contenedor). Cuando todos los procesos en este cgroup salen, Docker libera la memoria del cgroup. Sin embargo, la "memoria" no es sólo memoria de proceso. Aunque la memoria de proceso en sí ya no se utiliza, parece que el kernel aún asigna contenidos almacenados en caché, como dentries e inodos (metadatos de directorios y archivos), que se almacenan en caché en el grupo de memoria. De la descripción del problema:
zombie cgroups: cgroups que no tienen procesos y han sido eliminados, pero aún tienen memoria asignada (en mi caso, desde el caché de dentry, pero también se puede asignar desde el caché de la página o tmpfs).
La verificación por parte del kernel de todas las páginas en el caché al liberar un cgroup puede ser muy lenta, por lo que se elige el proceso diferido: esperar hasta que estas páginas se soliciten nuevamente y luego, finalmente, borrar el cgroup cuando la memoria sea realmente necesaria. Hasta este punto, cgroup todavía se tiene en cuenta al recopilar estadísticas.
Desde el punto de vista del rendimiento, sacrificaron memoria por rendimiento: aceleraron la limpieza inicial dejando algo de memoria caché. Esto esta bien. Cuando el kernel utiliza lo último de la memoria caché, el cgroup finalmente se borra, por lo que no se puede llamar "fuga". Desafortunadamente, la implementación específica del mecanismo de búsqueda. memory.stat en esta versión del kernel (4.9), combinado con la enorme cantidad de memoria en nuestros servidores, significa que lleva mucho más tiempo restaurar los datos almacenados en caché más recientes y eliminar los zombies de cgroup.
Resulta que algunos de nuestros nodos tenían tantos zombis de cgroup que la lectura y la latencia excedieron el segundo.
La solución para el problema de cadvisor es liberar inmediatamente los cachés de dentries/inodos en todo el sistema, lo que elimina inmediatamente la latencia de lectura, así como la latencia de la red en el host, ya que al borrar el caché se activan las páginas zombies del cgroup almacenadas en caché y también se liberan. Esto no es una solución, pero confirma la causa del problema.
Resultó que en las versiones más nuevas del kernel (4.19+) se mejoró el rendimiento de las llamadas. memory.stat, por lo que cambiar a este kernel solucionó el problema. Al mismo tiempo, teníamos herramientas para detectar nodos problemáticos en los clústeres de Kubernetes, vaciarlos y reiniciarlos con elegancia. Revisamos todos los clústeres, encontramos nodos con una latencia suficientemente alta y los reiniciamos. Esto nos dio tiempo para actualizar el sistema operativo en los servidores restantes.
En resumen
Debido a que este error detuvo el procesamiento de la cola RX NIC durante cientos de milisegundos, causó simultáneamente una alta latencia en conexiones cortas y latencia a mitad de conexión, como entre las solicitudes de MySQL y los paquetes de respuesta.
Comprender y mantener el rendimiento de los sistemas más fundamentales, como Kubernetes, es fundamental para la confiabilidad y velocidad de todos los servicios basados en ellos. Cada sistema que ejecuta se beneficia de las mejoras de rendimiento de Kubernetes.
Fuente: habr.com