Análisis de la Distribución Inexacta de la Latencia de Wrk

wrk es una excelente herramienta de prueba de estrés HTTP construida sobre los proyectos de código abierto Redis, NGINX, Node.js y LuaJIT, aprovechando sus fortalezas en manejo de eventos, análisis HTTP, alto rendimiento y flexibilidad, además de la capacidad de escribir tus propios scripts en Lua para generar solicitudes de prueba.

Aunque wrk no tiene casos de prueba y el autor aparece aproximadamente una vez al año para fusionar el código, eso no nos impide usar wrk como nuestra herramienta preferida para pruebas de rendimiento y fuzz testing. Si todavía estás usando el multi-hilo ab, vale la pena probar wrk.

A continuación se muestra la parte estadística de la distribución de latencia de los resultados de wrk.

    Latency Distribution
     50%    1.20ms
     75%  595.78ms
     90%  899.11ms
     99%    1.00s

Este ejemplo significa que el 50% de las solicitudes se completan en 1.2 ms, el 90% de las solicitudes se completan en 899 ms y el 99% de las solicitudes se completan en 1 s.

Cuando usamos wrk para realizar pruebas de estrés en nuestro propio producto, descubrimos que la mayoría de las solicitudes en las estadísticas de latencia de wrk se completaban en unos pocos milisegundos, pero un pequeño porcentaje de solicitudes tenía una latencia de más de 100 milisegundos. Para un sistema construido con OpenResty, no es muy científico tener una latencia tan grande.

Aunque la solución final a este problema fue muy simple, el análisis y la localización específicos fueron un poco complicados y tomaron varios días. La solución final no es lo importante; lo interesante es el proceso y la forma de pensar sobre el problema.

Cuando nos encontramos con problemas de latencia, nuestra primera reacción es que hay un bloqueo en algún lugar del código o del sistema. Dado que el sistema es complejo, ofrecemos gráficos de llamadas (flame charts).

No hay un script de systemtap listo para analizar este tipo de problema, por lo que tomó algo de tiempo escribir uno. Sin embargo, después de ajustar el script de systemtap varias veces, no se capturó un retraso significativo, lo que claramente no coincide con los resultados de wrk. Supusimos que el script podría no ser perfecto y podría haber omitido algunas funciones que no estaban enganchadas. Pero también tenemos dudas sobre la corrección de los resultados de wrk.

Nos dimos la vuelta e intentamos determinar si las estadísticas de wrk estaban mal o si realmente era un problema del servidor. Volcamos todos los paquetes de la prueba de estrés en el servidor donde se encuentra wrk, los ordenamos por tiempo invertido y nos sorprendió descubrir que los resultados eran muy diferentes a las estadísticas de latencia de wrk, sin solicitudes que superaran los 100 milisegundos. Repetí la prueba anterior varias veces y los resultados fueron consistentes.

Ahora el objetivo es claro, solo hay que revisar el código de wrk sobre las estadísticas de latencia. La mayor preocupación es que haya un error en las estadísticas internas de wrk, lo cual no es fácil de solucionar, ya que es un proyecto sin casos de prueba.

Revisamos la lógica de estadísticas de wrk y agregamos registros al principio y al final, y nos alivió descubrir que las estadísticas sobre la latencia eran correctas. Pero antes de imprimir los resultados finales, hay un código de corrección de estadísticas.

    if (complete / cfg.connections > 0) {
        int64_t interval = runtime_us / (complete / cfg.connections);
        stats_correct(statistics.latency, interval);
    }

Según este condicional, siempre que se generen datos piezométricos, se corregirán. Si estás interesado, puedes revisar el código de la función stats_correct, tiene solo 10 líneas, y no lo entendí incluso después de leerlo varias veces.

Revisé nuevamente el registro de commits del código, podría haber algo, pero solo encontré la siguiente línea, y no la entendí:

remove calibration & improve CO correction

Bajo el Tucao, si el registro de envío fuera un poco más detallado, sin abreviaturas, o agregando un comentario en el código, se podrían ahorrar muchas cosas.

El problema se ha verificado aquí, y se puede confirmar que no es un problema del producto, y la solución ya está ahí, que es comentar el código de corrección anterior. Pero debe haber una razón por la cual el autor de wrk lo agregó deliberadamente, y no entender la razón siempre es un problema oculto. Naturalmente, tuve que abrir un issue para preguntarle al autor, y wg, que aparece una vez al año, respondió 15 días después, y resulta que la abreviatura CO en la información del commit se refiere a Coordinated Omission, y proporcionó un artículo dedicado a este problema, los estudiantes interesados pueden usar esta palabra clave para buscar por su cuenta.

En resumen, Coordinated Omission significa que al realizar pruebas de estrés, no es suficiente contar solo el tiempo entre el envío y la recepción de una respuesta, esto se refiere al tiempo de servicio, lo que omitirá muchos problemas potenciales, y el tiempo de espera de la solicitud de prueba también debe contarse, para que se considere como el tiempo de respuesta que les importa a los usuarios.

Gil Tene, quien propuso el problema de CO, también hizo una modificación a wrk para abordar específicamente el problema de CO: https://github.com/giltene/wrk2, y el README de este proyecto tiene algunas explicaciones sobre esto, que puedes leer si estás interesado, así que no lo mencionaré aquí.

Para nuestro propio producto, ciertamente no hay bloqueos en el código, y al realizar pruebas de estrés, está utilizando la CPU al máximo. Incluso si hay un bloqueo, hay un gráfico de llamadas para muestrear y analizar. Por lo tanto, la corrección simple y brutal que wrk hace aquí para Coordinated Omission es bastante engañosa.