1s à 10ms : Réduction du délai de Prometheus dans l'API Gateway

Requêtes avec des délais de 1 à 2 secondes

Dans la communauté APISIX, les utilisateurs ont signalé un phénomène mystérieux : lorsque des requêtes de trafic entrent dans un cluster APISIX normalement déployé, un petit nombre de requêtes présente un délai exceptionnellement long de 1 à 2 secondes. L'échelle de QPS de l'utilisateur est d'environ 10 000, et ce type de requête anormale est rare, apparaissant seulement 1 à 3 fois toutes les quelques minutes.

Les utilisateurs ont fourni leurs captures de requêtes à haute latence dans des issues. On peut voir à partir de ces captures d'écran qu'il y a effectivement des requêtes avec une latence élevée, certaines pouvant même atteindre le niveau de la seconde.

Un autre phénomène notable accompagne cela : l'utilisation du CPU de l'un des processus worker atteint 100 %.

L'équipe de développement a appris les conditions pour que ce phénomène se produise :

1. Le plugin Prometheus est activé, et le Prometheus Exporter accède au point de terminaison APISIX /apisix/prometheus/metrics pour collecter les métriques.
2. Le nombre de métriques comptées par le plugin Prometheus atteint une certaine échelle, généralement des dizaines de milliers.

Ce phénomène est appelé "requêtes à longue queue" dans l'industrie. Il fait référence à la situation où un petit pourcentage de requêtes a un temps de réponse anormalement long alors que la plupart des requêtes ont un temps de réponse normal dans un groupe de requêtes. Cela pourrait être dû à un goulot d'étranglement de performance dans le système backend, à des ressources insuffisantes ou à d'autres raisons. Ce n'est pas un bug fatal, mais il affecte sérieusement l'expérience de l'utilisateur final.

Analyse détaillée

Basé sur une bibliothèque Lua open source nginx-lua-prometheus, APISIX a développé un plugin Prometheus qui fournit la fonction de suivi et de collecte des métriques. Lorsque le Prometheus Exporter accède au point de terminaison des indicateurs Prometheus exposés par APISIX, APISIX appellera la fonction fournie par la bibliothèque nginx-lua-prometheus pour exposer les résultats de calcul des métriques.

L'équipe de développement a localisé le problème : la fonction prometheus:metric_data() utilisée pour exposer les indicateurs de métriques dans nginx-lua-prometheus.

Cependant, ce n'est qu'une inférence préliminaire, et des preuves directes sont nécessaires pour prouver que les requêtes à longue queue sont liées à cela, et les questions suivantes doivent être clarifiées :

1. Que fait exactement cette fonction ?
2. Pourquoi cette fonction provoque-t-elle des requêtes à longue queue ?

L'équipe de développement a construit un environnement local pour reproduire le problème, qui simule principalement les scénarios suivants :

1. Le client simulé envoie une requête normale proxée vers l'amont par APISIX.
2. Simuler que le Prometheus Exporter visite /apisix/prometheus/metrics toutes les 5 secondes, déclenchant APISIX pour appeler la fonction prometheus:metric_data().

Environnement reproduit :

Lors de l'exécution du test, nous avons observé P100 et d'autres indicateurs dans les résultats des tests de wrk2 pour confirmer s'il y a un phénomène de requêtes à longue queue. Nous avons généré un graphique enflammé d'APISIX pour observer l'utilisation du CPU lorsqu'une requête à longue queue se produit.

Résultats des tests de wrk2 :

  Latency Distribution (HdrHistogram - Uncorrected Latency (measured without taking delayed starts into account))
   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

Selon ces résultats de test, on peut conclure que pendant le test, 99 % des requêtes ont été complétées en moins de 14,70 millisecondes, et un petit nombre de requêtes ont pris plus de 100 millisecondes. Et nous avons utilisé le nombre de métriques comme variable pour effectuer plusieurs tests, et avons constaté que le nombre de métriques augmentait linéairement avec le délai de P100. Si les métriques atteignent le niveau de 100 000, le P100 atteindra le niveau de la seconde.

Le graphique enflammé résultant :

Comme on peut le voir à partir de la pile de fonctions du graphique enflammé, prometheus:metric_data() occupe la plus grande largeur horizontale, prouvant une grande consommation de CPU, et déterminant directement que prometheus:metric_data() provoque des requêtes à longue queue.

Analysons brièvement ce que fait la fonction prometheus:metric_data().

prometheus:metric_data() récupère les métriques de la mémoire partagée, les catégorise et les traite dans un format texte compatible avec Prometheus. Dans ce processus, toutes les métriques sont triées par ordre lexicographique, et le préfixe des métriques est traité avec des expressions régulières. En règle générale, ce sont des opérations très coûteuses.

Une tentative d'optimisation imparfaite

Une fois que nous avons localisé le code qui a causé le délai, l'étape suivante consiste à combiner le graphique enflammé pour analyser le code en détail et trouver des possibilités d'optimisation.

À partir du graphique enflammé, nous avons localisé la fonction fix_histogram_bucket_labels. En examinant cette fonction, nous avons trouvé deux fonctions sensibles : string:match et string:gusb. Aucune de ces deux fonctions ne peut être compilée JIT par LuaJIT. Elles ne peuvent être qu'interprétées et exécutées.

LuaJIT est un compilateur JIT pour le langage de programmation Lua, qui peut compiler du code Lua en code machine et l'exécuter. Cela peut fournir une performance plus élevée que l'utilisation d'un interpréteur pour exécuter du code Lua.

L'un des avantages de l'utilisation de LuaJIT pour exécuter du code Lua est qu'il peut grandement augmenter la vitesse d'exécution du code. Cela permet à APISIX de maintenir une faible latence lors du traitement d'un grand nombre de requêtes, et de mieux performer dans un environnement à haute concurrence.

Par conséquent, le code que LuaJIT ne peut pas compiler deviendra un goulot d'étranglement de performance potentiel.

Nous avons compilé les informations ci-dessus et soumis issue: optimize the long tail request phenomenon à nginx-lua-prometheus, où nous avons été mis en contact avec l'auteur Knyar de ce projet et avons exploré les espaces qui pourraient être optimisés. Knyar a répondu rapidement, et nous avons clarifié les endroits qui pourraient être optimisés. Ainsi, un PR a été soumis : chore: use ngx.re.match instead of string match to improve performance pour l'optimisation.

Dans ce PR, nous avons principalement accompli :

• Utilisation de ngx.re.match au lieu de string:match
• Remplacement de string:gusb par ngx.re.gsub

Après avoir terminé cette optimisation, nous savons que la performance qu'elle améliore est limitée, elle ne peut pas résoudre fondamentalement le problème. Le problème racine est :

NGINX est une architecture multi-processus mono-thread. Tous les processus worker surveilleront les connexions TCP (Transmission Control Protocol), mais une fois qu'une connexion entre dans un processus worker, elle ne peut pas être migrée vers d'autres processus worker pour traitement.

Cela signifie que si un processus worker est très occupé, d'autres connexions dans ce processus worker peuvent ne pas être traitées à temps. D'autre part, le modèle mono-thread au sein d'un processus signifie que toutes les tâches intensives en CPU et en IO doivent être exécutées séquentiellement. Si une tâche prend beaucoup de temps à s'exécuter, d'autres tâches peuvent être ignorées, entraînant des temps de traitement de tâches inégaux.

prometheus:metric_data() occupe une grande quantité de tranches de temps CPU pour le calcul, réduisant les ressources CPU pour le traitement des requêtes normales. C'est pourquoi vous voyez un processus worker à 100 % d'utilisation du CPU.

Sur la base de ce problème, nous avons continué à analyser après avoir terminé l'optimisation ci-dessus, et avons capturé le graphique enflammé :

Le graphique enflammé ci-dessus builtin#100 représente les fonctions de la bibliothèque luajit/lua (comme string.find), qui peuvent être accédées via https://github.com/openresty/openresty-devel-utils/blob/master/ljff.lua dans ce projet pour obtenir le nom de la fonction correspondante.

Comment utiliser :

$ luajit ljff.lua 100
FastFunc table.sort

Comme le calcul des métriques prend une quantité excessive de CPU, nous envisageons d'abandonner les tranches de temps CPU lors du calcul des métriques.

Pour APISIX, la priorité du traitement des requêtes normales est la plus élevée, et les ressources CPU devraient être inclinées vers cela. En même temps, prometheus:metric_data() n'affectera que l'efficacité de l'obtention des métriques du Prometheus Exporter.

Dans le monde OpenResty, il existe un moyen caché de céder des tranches de temps CPU : ngx.sleep(0). Nous introduisons cette méthode dans prometheus:metric_data(). Lors du traitement des métriques, nous abandonnerons les tranches de temps CPU après avoir traité un certain nombre de métriques (comme 200 métriques) afin que les nouvelles requêtes entrantes aient une chance d'être traitées.

Nous avons soumis un PR pour cette optimisation : feat: performance optimization.

Dans notre scénario de test, lorsque le nombre total de métriques atteint le niveau de 100 000, les résultats obtenus en testant avec wrk2 avant l'introduction de cette optimisation :

  Latency Distribution (HdrHistogram - Uncorrected Latency (measured without taking delayed starts into account))
 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

Résultats de wrk2 après l'optimisation :

  Latency Distribution (HdrHistogram - Uncorrected Latency (measured without taking delayed starts into account))
 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

L'indice P100 est d'environ 1/3 à 1/2 de celui avant l'optimisation.

Cependant, cela ne résout pas parfaitement ce problème. En analysant le graphique enflammé optimisé :

Vous pouvez voir que builtin#100 (table.sort) et builtin#92 (string.format) occupent encore une largeur considérable de l'axe horizontal car :

1. prometheus:metric_data() appellera d'abord table.sort pour trier toutes les métriques. Lorsque les métriques atteignent le niveau de 100 000, cela équivaut à trier 100 000 chaînes de caractères, et table.sort ne peut pas être interrompu par ngx.sleep(0).
2. L'endroit où string.format et fix_histogram_bucket_labels sont utilisés ne peut pas être optimisé. Après avoir communiqué avec knyar, j'ai appris que ces étapes sont nécessaires pour garantir que prometheus:metric_data() peut produire des métriques dans le format correct.

Jusqu'à présent, les méthodes d'optimisation au niveau du code ont été épuisées, mais malheureusement, le problème n'est toujours pas résolu parfaitement. Il y a encore un décalage notable dans les métriques de P100.

Que faire ?

Revenons au problème central : prometheus:metric_data() occupe une grande quantité de tranches de temps CPU pour le calcul, réduisant les ressources CPU pour le traitement des requêtes normales.

Dans le système Linux, les tranches de temps que le CPU alloue sont-elles à un thread ou à un processus ? Pour être précis, c'est un thread, et le thread est l'unité de travail réelle. Cependant, NGINX est une architecture multi-processus mono-thread avec un seul thread dans chaque processus.

À ce stade, nous avons pensé à une direction d'optimisation : déplacer prometheus:metric_data() vers d'autres threads (ou, plus précisément, processus). Nous avons donc exploré deux directions :

1. Utiliser ngx.run_worker_thread pour exécuter les tâches de calcul de prometheus:metric_data(), équivalent à confier les tâches intensives en CPU au pool de threads.
2. Utiliser un processus séparé pour gérer les tâches de calcul de prometheus:metric_data(), ce processus ne gérera pas les requêtes normales.

Après un PoC (proof of concept), nous avons rejeté l'option 1 et adopté l'option 2. L'option 1 est rejetée car ngx.run_worker_thread est uniquement adapté pour exécuter des tâches de calcul indépendantes des requêtes, alors que prometheus:metric_data() est lié aux requêtes.

Mise en œuvre de l'option 2 : Faire en sorte que privileged agent (processus privilégié) gère prometheus:metric_data(). Mais le processus privilégié n'écoute aucun port et ne gère aucune requête. Par conséquent, nous devons modifier le processus privilégié pour qu'il puisse écouter le port.

Enfin, nous avons utilisé feat: allow privileged agent to listen port et feat(prometheus): support collect metrics works in the privileged agent pour implémenter l'option 2.

Nous avons utilisé APISIX avec cette optimisation pour tester, et avons constaté que le délai de l'indice P100 a été réduit à une plage raisonnable, et le problème des requêtes à longue queue n'existe plus.

  Latency Distribution (HdrHistogram - Uncorrected Latency (measured without taking delayed starts into account))
 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

C'est une solution délicate et elle résout le problème central. Nous avons observé et vérifié cette solution dans l'environnement de production. Elle a éliminé le phénomène des requêtes à longue queue et n'a pas causé d'exceptions supplémentaires.

Résumé

Lorsque nous résolvions ce problème, une nouvelle pensée est apparue : la bibliothèque open source nginx-lua-prometheus est-elle adaptée à APISIX ?

Nous avons résolu le problème de prometheus:metric_data() du côté d'APISIX. En même temps, nous avons également trouvé d'autres problèmes dans nginx-lua-prometheus et les avons corrigés. Comme fix memory leak, et LRU cache elimination.

nginx-lua-prometheus a été initialement conçu pour NGINX, pas pour OpenResty et les applications basées sur OpenResty. Cependant, aucun projet open source dans l'écosystème OpenResty ne se connecte à l'écosystème Prometheus de manière plus mature que nginx-lua-prometheus. Par conséquent, nginx-lua-prometheus a été constamment promu par la communauté open source pour l'écosystème OpenResty.

Peut-être devrions-nous explorer davantage et trouver un moyen de nous connecter à l'écosystème Prometheus sans modifier le code source d'APISIX. Par exemple, concevoir une bibliothèque de dépendances plus adaptée à APISIX, ou se connecter à des projets matures dans l'écosystème Prometheus d'une certaine manière, et déplacer le processus de collecte et de calcul des métriques vers ces projets matures.