De 1s a 10ms: Reduciendo el retraso de Prometheus en API Gateway

Solicitudes con retrasos de 1 a 2 segundos

En la comunidad de APISIX, los usuarios han reportado un fenómeno misterioso: cuando las solicitudes de tráfico entran en un clúster de APISIX desplegado normalmente, un pequeño número de solicitudes tiene un retraso excepcionalmente largo de 1 a 2 segundos. La escala de QPS del usuario es de aproximadamente 10,000, y este tipo de solicitud anormal es rara, apareciendo solo 1 a 3 veces cada pocos minutos.

Los usuarios proporcionaron capturas de solicitudes de alta latencia en los issues. Se puede ver en estas capturas de pantalla que, efectivamente, hay solicitudes con alta latencia, algunas incluso pueden alcanzar el nivel de segundos.

Otro fenómeno notable que acompaña a esto es que el uso de CPU de uno de los procesos worker alcanza el 100%.

El equipo de desarrollo aprendió las condiciones para que este fenómeno ocurra:

1. El plugin de Prometheus está habilitado, y el Prometheus Exporter accede al endpoint /apisix/prometheus/metrics de APISIX para recopilar métricas.
2. El número de métricas que cuenta el plugin de Prometheus alcanza una cierta escala, generalmente decenas de miles.

Este fenómeno se llama "solicitudes de cola larga" en la industria. Se refiere a la situación en la que un pequeño porcentaje de solicitudes tiene un tiempo de solicitud anormalmente largo, mientras que la mayoría de las solicitudes tienen un tiempo de respuesta normal en un grupo de solicitudes. Podría deberse a un cuello de botella en el rendimiento del sistema backend, recursos insuficientes u otras razones. No es un error fatal, pero afecta seriamente la experiencia del usuario final.

Desglosando el problema

Basado en una biblioteca Lua de código abierto nginx-lua-prometheus, APISIX ha desarrollado un plugin de Prometheus que proporciona la función de rastrear y recopilar métricas. Cuando Prometheus Exporter accede al endpoint de indicadores de Prometheus expuestos por APISIX, APISIX llamará a la función proporcionada por la biblioteca nginx-lua-prometheus para exponer los resultados del cálculo de las métricas.

El equipo de desarrollo localizó el problema: la función prometheus:metric_data() utilizada para exponer los indicadores de métricas en nginx-lua-prometheus.

Sin embargo, esto es solo una inferencia preliminar, y se necesita evidencia directa para probar que las solicitudes de cola larga están relacionadas con esto, y se deben aclarar los siguientes problemas:

1. ¿Qué hace exactamente esta función?
2. ¿Por qué esta función causa solicitudes de cola larga?

El equipo de desarrollo construyó un entorno local para reproducir el problema, que principalmente simula los siguientes escenarios:

1. El cliente simulado envía una solicitud normal que es proxyada al upstream por APISIX.
2. Simula que Prometheus Exporter visita /apisix/prometheus/metrics cada 5 segundos, lo que desencadena que APISIX llame a la función prometheus:metric_data().

Entorno reproducido:

Al realizar la prueba, observamos P100 y otros indicadores en los resultados de la prueba de wrk2 para confirmar si existe el fenómeno de solicitudes de cola larga. Generamos un gráfico de llamadas (flame graph) de APISIX para observar el uso de CPU cuando ocurre una solicitud de cola larga.

Resultados de la prueba de wrk2:

  Distribución de Latencia (HdrHistogram - Latencia no Corregida (medida sin tener en cuenta los inicios retrasados))
   50.000%    1.13ms
   75.000%    2.56ms
   90.000%    4.82ms
   99.000%   14.70ms
   99.900%   27.95ms
   99.990%   74.75ms
   99.999%  102.78ms
  100.000%  102.78ms

Según este resultado de la prueba, se puede concluir que durante la prueba, el 99% de las solicitudes se completaron en 14.70 milisegundos, y un pequeño número de solicitudes tardó más de 100 milisegundos. Y usamos el número de métricas como una variable para realizar múltiples pruebas, y encontramos que el número de métricas aumentó linealmente con el retraso de P100. Si las métricas alcanzan el nivel de 100,000, el P100 alcanzará el nivel de segundos.

El gráfico de llamadas resultante:

Como se ve en la pila de funciones del gráfico de llamadas, prometheus:metric_data() ocupa el ancho horizontal más largo, lo que prueba un gran consumo de CPU, y determina directamente que prometheus:metric_data() causa solicitudes de cola larga.

Analicemos brevemente qué hace la función prometheus:metric_data().

prometheus:metric_data() obtendrá métricas de la memoria compartida, las clasificará y las procesará en un formato de texto compatible con Prometheus. En este proceso, todas las métricas se ordenarán en orden lexicográfico, y el prefijo de las métricas se procesará con expresiones regulares. Como regla general, estas son operaciones muy costosas.

Un intento de optimización imperfecto

Una vez que hemos localizado el código que causó el retraso, el siguiente paso es combinar el gráfico de llamadas para analizar el código en detalle y encontrar espacio para la optimización.

Desde el gráfico de llamadas, localizamos la función fix_histogram_bucket_labels. Al revisar esta función, encontramos dos funciones sensibles: string:match y string:gusb. Ninguna de estas dos funciones puede ser compilada por JIT por LuaJIT. Solo pueden ser interpretadas y ejecutadas.

LuaJIT es un compilador JIT para el lenguaje de programación Lua, que puede compilar código Lua en código de máquina y ejecutarlo. Esto puede proporcionar un mayor rendimiento que usar un intérprete para ejecutar código Lua.

Una de las ventajas de usar LuaJIT para ejecutar código Lua es que puede aumentar enormemente la velocidad de ejecución del código. Esto permite que APISIX mantenga una baja latencia al procesar un gran número de solicitudes y que tenga un mejor rendimiento en un entorno de alta concurrencia.

Por lo tanto, el código que LuaJIT no puede compilar se convertirá en un cuello de botella de rendimiento potencial.

Compilamos la información anterior y presentamos issue: optimizar el fenómeno de solicitudes de cola larga a nginx-lua-prometheus, donde nos conectamos con el autor Knyar de este proyecto y exploramos el espacio que podría optimizarse. Knyar respondió rápidamente, y aclaramos los lugares que podrían optimizarse. Así que se presentó un PR: chore: usar ngx.re.match en lugar de string match para mejorar el rendimiento para la optimización.

En este PR, principalmente completamos:

• Usar ngx.re.match en lugar de string:match
• Reemplazar string:gusb con ngx.re.gsub

Después de completar esta optimización, sabemos que el rendimiento que mejora es limitado, no puede resolver fundamentalmente el problema. El problema raíz es:

NGINX es una arquitectura multiproceso de un solo hilo. Todos los procesos worker monitorean las conexiones TCP (Protocolo de Control de Transmisión), pero una vez que una conexión entra en un proceso worker, no puede migrarse a otros procesos worker para su procesamiento.

Esto significa que si un proceso worker está muy ocupado, otras conexiones dentro de ese proceso worker pueden no procesarse a tiempo. Por otro lado, el modelo de un solo hilo dentro de un proceso significa que todas las tareas intensivas en CPU y E/S deben realizarse secuencialmente. Si una tarea tarda mucho tiempo en ejecutarse, otras tareas pueden ignorarse, lo que resulta en tiempos de procesamiento de tareas desiguales.

prometheus:metric_data() ocupa una gran cantidad de segmentos de tiempo de CPU para el cálculo, exprimiendo los recursos de CPU para procesar solicitudes normales. Es por eso que se ve un proceso worker con un uso de CPU del 100%.

Basándonos en este problema, continuamos analizando después de completar la optimización anterior y capturamos el gráfico de llamadas:

El gráfico de llamadas anterior builtin#100 representa funciones de la biblioteca luajit/lua (como string.find), que se puede acceder a través de https://github.com/openresty/openresty-devel-utils/blob/master/ljff.lua en este proyecto para obtener el nombre de la función correspondiente.

Cómo usarlo:

$ luajit ljff.lua 100
FastFunc table.sort

Dado que el cálculo de métricas ocupa una cantidad excesiva de CPU, consideramos renunciar a los segmentos de tiempo de CPU al calcular métricas.

Para APISIX, la prioridad de procesar solicitudes normales es la más alta, y los recursos de CPU deben inclinarse hacia esto. Al mismo tiempo, prometheus:metric_data() solo afectará la eficiencia de obtener métricas de Prometheus Exporter.

En el mundo de OpenResty, hay una forma oculta de ceder segmentos de tiempo de CPU: ngx.sleep(0). Introducimos este método en prometheus:metric_data(). Al procesar métricas, renunciaremos a los segmentos de tiempo de CPU después de procesar un cierto número de métricas (por ejemplo, 200 métricas) para que las nuevas solicitudes entrantes tengan la oportunidad de ser procesadas.

Presentamos un PR para esta optimización: feat: optimización de rendimiento.

En nuestro escenario de prueba, cuando el número total de métricas alcanza niveles de 100,000, los resultados obtenidos al probar con wrk2 antes de introducir esta optimización:

  Distribución de Latencia (HdrHistogram - Latencia no Corregida (medida sin tener en cuenta los inicios retrasados))
 50.000%   10.21ms
 75.000%   12.03ms
 90.000%   13.25ms
 99.000%   92.80ms
 99.900%  926.72ms
 99.990%  932.86ms
 99.999%  934.40ms
100.000%  934.91ms

Resultados de wrk2 después de la optimización:

  Distribución de Latencia (HdrHistogram - Latencia no Corregida (medida sin tener en cuenta los inicios retrasados))
 50.000%    4.34ms
 75.000%   12.81ms
 90.000%   16.12ms
 99.000%   82.75ms
 99.900%  246.91ms
 99.990%  349.44ms
 99.999%  390.40ms
100.000%  397.31ms

El índice P100 es aproximadamente 1/3 a 1/2 del que era antes de la optimización.

Sin embargo, esto no resuelve perfectamente este problema. Al analizar el gráfico de llamadas optimizado:

Se puede ver que builtin#100 (table.sort) y builtin#92 (string.format) todavía ocupan un ancho considerable del eje horizontal porque:

1. prometheus:metric_data() primero llamará a table.sort para ordenar todas las métricas. Cuando las métricas alcanzan niveles de 100,000, es equivalente a ordenar 100,000 cadenas, y table.sort no puede ser interrumpido por ngx.sleep(0).
2. El lugar donde se usan string.format y fix_histogram_bucket_labels no se puede optimizar. Después de comunicarnos con knyar, aprendimos que estos pasos son necesarios para garantizar que prometheus:metric_data() pueda producir métricas en el formato correcto.

Hasta ahora, los métodos de optimización a nivel de código se han agotado, pero desafortunadamente, el problema aún no se ha resuelto perfectamente. Todavía hay un retraso notable en las métricas de P100.

¿Qué hacer?

Volvamos al problema central: prometheus:metric_data() ocupa una gran cantidad de segmentos de tiempo de CPU para el cálculo, exprimiendo los recursos de CPU para procesar solicitudes normales.

En el sistema Linux, ¿los segmentos de tiempo que la CPU está asignando son para un hilo o un proceso? Para ser precisos, es para un hilo, y el hilo es la unidad real de trabajo. Sin embargo, NGINX es una arquitectura multiproceso de un solo hilo con solo un hilo en cada proceso.

En este punto pensamos en una dirección de optimización: mover prometheus:metric_data() a otros hilos (o, más precisamente, procesos). Así que investigamos dos direcciones:

1. Usar ngx.run_worker_thread para ejecutar tareas de cálculo de prometheus:metric_data(), equivalente a entregar tareas intensivas en CPU al grupo de hilos.
2. Usar un proceso separado para manejar las tareas de cálculo de prometheus:metric_data(), este proceso no manejará solicitudes normales.

Después de un PoC (prueba de concepto), rechazamos la opción 1 y adoptamos la opción 2. La opción 1 se rechaza porque ngx.run_worker_thread solo es adecuado para ejecutar tareas de cálculo independientes de la solicitud, mientras que prometheus:metric_data() está relacionada con la solicitud.

Implementación de la opción 2: Hacer que privileged agent (proceso privilegiado) maneje prometheus:metric_data(). Pero el proceso privilegiado no escucha ningún puerto ni maneja ninguna solicitud. Por lo tanto, necesitamos modificar el proceso privilegiado para que pueda escuchar el puerto.

Finalmente, usamos feat: permitir que el agente privilegiado escuche el puerto y feat(prometheus): soportar la recopilación de métricas en el agente privilegiado para implementar la opción 2.

Usamos APISIX con esta optimización para probar y encontramos que el retraso del índice P100 se ha reducido a un rango razonable, y el problema de las solicitudes de cola larga ya no existe.

  Distribución de Latencia (HdrHistogram - Latencia no Corregida (medida sin tener en cuenta los inicios retrasados))
 50.000%    3.74ms
 75.000%    4.66ms
 90.000%    5.77ms
 99.000%    9.99ms
 99.900%   13.41ms
 99.990%   16.77ms
 99.999%   18.38ms
100.000%   18.40ms

Esta es una solución delicada y resuelve el problema central. Observamos y verificamos esta solución en el entorno de producción. Eliminó el fenómeno de las solicitudes de cola larga y no causó excepciones adicionales.

Resumen

Cuando estábamos solucionando este problema, surgió un nuevo pensamiento: ¿es la biblioteca de código abierto nginx-lua-prometheus adecuada para APISIX?

Resolvimos el problema de prometheus:metric_data() en el lado de APISIX. Al mismo tiempo, también encontramos otros problemas en nginx-lua-prometheus y los solucionamos. Como corregir la fuga de memoria y eliminación de caché LRU.

nginx-lua-prometheus fue diseñado originalmente para NGINX, no para OpenResty y aplicaciones basadas en OpenResty. Sin embargo, ningún proyecto de código abierto en el ecosistema de OpenResty se conecta al ecosistema de Prometheus de manera más madura que nginx-lua-prometheus. Por lo tanto, nginx-lua-prometheus ha sido constantemente promovido por la comunidad de código abierto para el ecosistema de OpenResty.

Quizás deberíamos explorar más y encontrar una manera de conectarnos al ecosistema de Prometheus sin modificar el código fuente de APISIX. Por ejemplo, diseñar una biblioteca de dependencias más adecuada para APISIX, o conectarnos a proyectos maduros en el ecosistema de Prometheus de alguna manera, y mover el proceso de recopilación y cálculo de métricas a esos proyectos maduros.