Analyse de la distribution inexacte de la latence Wrk

wrk est un excellent outil de test de stress HTTP construit sur les projets open source Redis, NGINX, Node.js et LuaJIT, exploitant leurs forces dans les domaines de l'événementiel, de l'analyse HTTP, des hautes performances et de la flexibilité, ainsi que la possibilité d'écrire vos propres scripts Lua pour générer des requêtes de test.

Bien que wrk n'ait pas de cas de test et que l'auteur apparaisse environ une fois par an pour fusionner le code, cela ne nous empêche pas d'utiliser wrk comme notre outil de choix pour les tests de performance et de fuzzing. Si vous utilisez encore l'outil multi-threadé ab, il vaut vraiment la peine d'essayer wrk.

Voici la partie statistique de la distribution des délais des résultats de wrk.

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

Cet exemple signifie que 50 % des requêtes sont terminées en 1,2 ms, 90 % des requêtes sont terminées en 899 ms, et 99 % des requêtes sont terminées en 1 s.

Lorsque nous avons utilisé wrk pour tester en charge notre propre produit, nous avons constaté que la plupart des requêtes dans les statistiques de latence de wrk étaient terminées en quelques millisecondes, mais qu'un petit pourcentage de requêtes avait une latence de plus de 100 millisecondes. Pour un système construit avec OpenResty, il n'est pas très scientifique d'avoir une telle latence.

Bien que la solution finale à ce problème ait été très simple, l'analyse et la localisation spécifiques ont été un peu compliquées et ont pris plusieurs jours. La solution finale n'est pas importante ; c'est le processus et la manière de penser au problème qui sont intéressants.

Lorsque nous rencontrons des problèmes de latence, notre première réaction est qu'il y a un blocage quelque part dans le code ou le système. Comme le système est complexe, nous proposons des flame charts.

Il n'y a pas de script systemtap prêt à l'emploi pour analyser ce genre de problème, donc il a fallu un certain temps pour en écrire un. Cependant, après avoir ajusté plusieurs fois le script systemtap, aucun délai significatif n'a été capturé, ce qui est clairement incompatible avec les résultats de wrk. Nous avons supposé que le script pourrait ne pas être parfait et pourrait avoir manqué certaines fonctions qui n'étaient pas hookées. Mais nous avons aussi des doutes sur la justesse des résultats de wrk.

Nous nous retournons et essayons de déterminer si les statistiques de wrk sont erronées, ou si c'est vraiment un problème de serveur. Nous avons capturé tous les paquets du test de charge sur le serveur où wrk est installé, les avons triés par temps passé, et avons été surpris de constater que les résultats étaient très différents des statistiques de latence de wrk, avec aucune requête dépassant 100 millisecondes. J'ai répété le test ci-dessus plusieurs fois et les résultats étaient cohérents.

Maintenant, l'objectif est clair, il suffit de lisser le code de wrk concernant les statistiques de latence. La plus grande inquiétude est qu'il y ait un bug dans les statistiques internes de wrk, ce qui n'est pas facile à corriger, après tout, c'est un projet sans aucun cas de test.

Nous avons parcouru la logique des statistiques de wrk et ajouté des logs au début et à la fin, et avons été soulagés de constater que les statistiques sur la latence étaient correctes. Mais avant d'imprimer les résultats finaux, il y a un code de correction statistique.

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

Selon cette condition if, chaque fois que des données piézométriques sont générées, elles seront corrigées. Si vous êtes intéressé, vous pouvez regarder le code de la fonction stats_correct, il ne fait que 10 lignes, et je ne l'ai pas compris même après l'avoir lu plusieurs fois.

Vérifiez à nouveau l'historique des commits du code, il pourrait y avoir quelque chose, mais seulement la ligne suivante, et je n'ai pas compris :

remove calibration & improve CO correction

Sous Tucao, si l'enregistrement des soumissions était un peu plus détaillé, sans abréviation, ou en ajoutant un commentaire de code, cela pourrait sauver beaucoup de choses.

Le problème a été vérifié ici, et il peut être confirmé que ce n'est pas un problème de produit, et la solution est déjà là, qui est de commenter le code de correction ci-dessus. Mais il doit y avoir une raison pour laquelle l'auteur de wrk l'a délibérément ajouté, et ne pas comprendre la raison est toujours un problème caché. Naturellement, j'ai dû ouvrir un issue pour demander à l'auteur, et wg, qui apparaît une fois par an, a donné une réponse 15 jours plus tard, et il s'avère que l'abréviation CO dans l'info de commit ci-dessus fait référence à Coordinated Omission, et donne un article dédié à ce problème, les étudiants intéressés peuvent utiliser ce mot-clé pour rechercher par eux-mêmes.

En bref, Coordinated Omission signifie que lors de tests de stress, il ne suffit pas de compter uniquement le temps entre l'envoi et la réception d'une réponse, cela fait référence au temps de service, ce qui manquerait beaucoup de problèmes potentiels, et le temps d'attente de la requête de test doit également être compté, afin d'être considéré comme le temps de réponse qui intéresse les utilisateurs.

Gil Tene, qui a proposé le problème CO, a également apporté une modification à wrk pour spécifiquement résoudre le problème CO : https://github.com/giltene/wrk2, et le README de ce projet contient quelques explications à ce sujet, que vous pouvez lire si vous êtes intéressé, donc je ne le mentionnerai pas ici.

Pour notre propre produit, il n'y a certainement aucun blocage dans le code, et lors des tests de stress, il utilise pleinement le CPU. Même s'il y a un blocage, il y a un flame chart pour échantillonner et analyser. Donc, la correction simple et brutale que wrk fait ici pour Coordinated Omission est plutôt trompeuse.