1s bis 10ms: Reduzierung der Prometheus-Verzögerung im API Gateway

Anfragen mit Verzögerungen von 1 bis 2 Sekunden

In der APISIX-Community haben Benutzer ein mysteriöses Phänomen gemeldet: Wenn Traffic-Anfragen in einen normal bereitgestellten APISIX-Cluster eintreten, weisen einige wenige Anfragen eine ungewöhnlich lange Verzögerung von 1 bis 2 Sekunden auf. Die QPS-Skala des Benutzers liegt bei etwa 10.000, und diese Art von anomalen Anfragen ist selten und tritt nur 1 bis 3 Mal alle paar Minuten auf.

Benutzer haben ihre Aufzeichnungen von Anfragen mit hoher Latenz in Issues bereitgestellt. Aus diesen Screenshots ist ersichtlich, dass es tatsächlich Anfragen mit hoher Latenz gibt, einige können sogar das Sekunden-Niveau erreichen.

Ein weiteres auffälliges Phänomen begleitet dies: Die CPU-Auslastung eines der Worker-Prozesse erreicht 100 %.

Das Entwicklungsteam erfuhr die Bedingungen für das Auftreten dieses Phänomens:

1. Das Prometheus-Plugin ist aktiviert, und der Prometheus Exporter greift auf den APISIX-Endpunkt /apisix/prometheus/metrics zu, um Metriken zu sammeln.
2. Die Anzahl der Metriken, die das Prometheus-Plugin zählt, erreicht eine bestimmte Skala, normalerweise Zehntausende.

Dieses Phänomen wird in der Branche als "Long-Tail-Anfragen" bezeichnet. Es bezieht sich auf die Situation, wenn ein kleiner Prozentsatz von Anfragen eine ungewöhnlich lange Anfragezeit aufweist, während die meisten Anfragen eine normale Antwortzeit in einer Anfragegruppe haben. Es könnte auf einen Leistungsengpass im Backend-System, unzureichende Ressourcen oder andere Gründe zurückzuführen sein. Es ist kein fataler Bug, aber es beeinträchtigt das Benutzererlebnis erheblich.

Zerlegung des Problems

Basierend auf einer Open-Source-Lua-Bibliothek nginx-lua-prometheus hat APISIX ein Prometheus-Plugin entwickelt, das die Funktion zur Verfolgung und Sammlung von Metriken bietet. Wenn der Prometheus Exporter auf den Endpunkt der von APISIX bereitgestellten Prometheus-Metriken zugreift, ruft APISIX die Funktion auf, die von der nginx-lua-prometheus-Bibliothek bereitgestellt wird, um die Berechnungsergebnisse der Metriken zu veröffentlichen.

Das Entwicklungsteam lokalisierte das Problem: die Funktion prometheus:metric_data(), die in nginx-lua-prometheus verwendet wird, um Metrikenindikatoren zu veröffentlichen.

Dies ist jedoch nur eine vorläufige Schlussfolgerung, und direkte Beweise sind erforderlich, um zu beweisen, dass Long-Tail-Anfragen damit zusammenhängen, und die folgenden Fragen müssen geklärt werden:

1. Was genau macht diese Funktion?
2. Warum verursacht diese Funktion Long-Tail-Anfragen?

Das Entwicklungsteam konstruierte eine lokale Umgebung, um das Problem zu reproduzieren, die hauptsächlich die folgenden Szenarien simuliert:

1. Der simulierte Client sendet eine normale Anfrage, die von APISIX an das Upstream weitergeleitet wird.
2. Simuliert, dass der Prometheus Exporter alle 5 Sekunden auf /apisix/prometheus/metrics zugreift, wodurch APISIX die Funktion prometheus:metric_data() aufruft.

Reproduzierte Umgebung:

Bei der Durchführung des Tests beobachteten wir P100 und andere Indikatoren in den Testergebnissen von wrk2, um festzustellen, ob ein Long-Tail-Anfragephänomen vorliegt. Wir erstellten ein Flame-Graph von APISIX, um die CPU-Auslastung zu beobachten, wenn eine Long-Tail-Anfrage auftritt.

Testergebnisse von 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

Laut diesem Testergebnis kann geschlossen werden, dass während des Tests 99 % der Anfragen innerhalb von 14,70 Millisekunden abgeschlossen wurden, und eine kleine Anzahl von Anfragen mehr als 100 Millisekunden benötigte. Und wir verwendeten die Anzahl der Metriken als Variable, um mehrere Tests durchzuführen, und stellten fest, dass die Anzahl der Metriken linear mit der Verzögerung von P100 zunahm. Wenn die Metriken das 100.000-Niveau erreichen, wird P100 das Sekunden-Niveau erreichen.

Das resultierende Flame-Graph:

Wie aus dem Funktionsstapel des Flame-Graphs ersichtlich ist, nimmt prometheus:metric_data() die längste horizontale Breite ein, was einen hohen CPU-Verbrauch beweist, und bestimmt direkt, dass prometheus:metric_data() Long-Tail-Anfragen verursacht.

Lassen Sie uns kurz analysieren, was die Funktion prometheus:metric_data() macht.

prometheus:metric_data() holt Metriken aus dem Shared Memory, kategorisiert sie und verarbeitet sie in ein Prometheus-kompatibles Textformat. In diesem Prozess werden alle Metriken in lexikografischer Reihenfolge sortiert, und das Präfix der Metriken wird mit regulären Ausdrücken verarbeitet. Erfahrungsgemäß sind dies sehr teure Operationen.

Ein unvollkommener Optimierungsversuch

Sobald wir den Code, der die Verzögerung verursacht hat, lokalisiert haben, besteht der nächste Schritt darin, den Code anhand des Flame-Graphs detailliert zu analysieren und Optimierungspotenzial zu finden.

Aus dem Flame-Graph haben wir die Funktion fix_histogram_bucket_labels lokalisiert. Bei der Überprüfung dieser Funktion fanden wir zwei sensible Funktionen: string:match und string:gusb. Keine dieser beiden Funktionen kann von LuaJIT JIT-kompiliert werden. Sie können nur interpretiert und ausgeführt werden.

LuaJIT ist ein JIT-Compiler für die Programmiersprache Lua, der Lua-Code in Maschinencode kompilieren und ausführen kann. Dies kann eine höhere Leistung bieten als die Ausführung von Lua-Code mit einem Interpreter.

Einer der Vorteile der Verwendung von LuaJIT zur Ausführung von Lua-Code ist, dass es die Ausführungsgeschwindigkeit des Codes erheblich erhöhen kann. Dies ermöglicht es APISIX, bei der Verarbeitung einer großen Anzahl von Anfragen eine niedrige Latenz beizubehalten und in einer Umgebung mit hoher Parallelität besser zu performen.

Daher wird Code, den LuaJIT nicht kompilieren kann, zu einem potenziellen Leistungsengpass.

Wir haben die obigen Informationen zusammengestellt und issue: optimize the long tail request phenomenon an nginx-lua-prometheus übermittelt, wo wir mit dem Autor Knyar dieses Projekts in Kontakt kamen und den Raum erkundeten, der optimiert werden könnte. Knyar antwortete prompt, und wir klärten die Stellen, die optimiert werden könnten. Also wurde ein PR eingereicht: chore: use ngx.re.match instead of string match to improve performance zur Optimierung.

In diesem PR haben wir hauptsächlich Folgendes erreicht:

• Verwendung von ngx.re.match anstelle von string:match
• Ersetzung von string:gusb durch ngx.re.gsub

Nach Abschluss dieser Optimierung wissen wir, dass die verbesserte Leistung begrenzt ist und das Problem nicht grundlegend lösen kann. Das Kernproblem ist:

NGINX ist eine Multi-Prozess-Single-Thread-Architektur. Alle Worker-Prozesse überwachen TCP-Verbindungen (Transmission Control Protocol), aber sobald eine Verbindung in einen Worker-Prozess eintritt, kann sie nicht mehr in andere Worker-Prozesse zur Verarbeitung migriert werden.

Dies bedeutet, dass, wenn ein Worker-Prozess sehr beschäftigt ist, andere Verbindungen innerhalb dieses Worker-Prozesses möglicherweise nicht rechtzeitig verarbeitet werden. Andererseits bedeutet das Single-Thread-Modell innerhalb eines Prozesses, dass alle CPU-intensiven und IO-intensiven Aufgaben sequentiell ausgeführt werden müssen. Wenn eine Aufgabe lange Zeit zur Ausführung benötigt, können andere Aufgaben ignoriert werden, was zu ungleichmäßigen Aufgabenverarbeitungszeiten führt.

prometheus:metric_data() belegt eine große Menge an CPU-Zeitscheiben für Berechnungen und verdrängt CPU-Ressourcen für die Verarbeitung normaler Anfragen. Deshalb sehen Sie einen Worker-Prozess mit 100 % CPU-Auslastung.

Basierend auf diesem Problem analysierten wir weiter, nachdem wir die obige Optimierung abgeschlossen hatten, und erstellten das Flame-Graph:

Das obige Flame-Graph builtin#100 repräsentiert luajit/lua-Bibliotheksfunktionen (wie string.find), die über https://github.com/openresty/openresty-devel-utils/blob/master/ljff.lua in diesem Projekt aufgerufen werden können, um den entsprechenden Funktionsnamen zu erhalten.

Verwendung:

$ luajit ljff.lua 100
FastFunc table.sort

Da die Berechnung der Metriken eine übermäßige Menge an CPU belegt, erwägen wir, CPU-Zeitscheiben bei der Berechnung der Metriken aufzugeben.

Für APISIX hat die Verarbeitung normaler Anfragen die höchste Priorität, und CPU-Ressourcen sollten darauf ausgerichtet sein. Gleichzeitig wird prometheus:metric_data() nur die Effizienz der Erfassung von Prometheus Exporter-Metriken beeinflussen.

In der OpenResty-Welt gibt es eine versteckte Möglichkeit, CPU-Zeitscheiben freizugeben: ngx.sleep(0). Wir führen diese Methode in prometheus:metric_data() ein. Bei der Verarbeitung von Metriken geben wir CPU-Zeitscheiben nach der Verarbeitung einer bestimmten Anzahl von Metriken (z. B. 200 Metriken) auf, sodass neue eingehende Anfragen eine Chance haben, verarbeitet zu werden.

Wir haben einen PR für diese Optimierung eingereicht: feat: performance optimization.

In unserem Testszenario, wenn die Gesamtzahl der Metriken das 100.000-Niveau erreicht, waren die Ergebnisse, die wir mit wrk2 vor der Einführung dieser Optimierung erhalten haben:

  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

Wrk2-Ergebnisse nach der Optimierung:

  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

Der P100-Index beträgt etwa 1/3 bis 1/2 des Wertes vor der Optimierung.

Dies löst das Problem jedoch nicht perfekt. Durch die Analyse des optimierten Flame-Graphs:

Sie können sehen, dass builtin#100 (table.sort) und builtin#92 (string.format) immer noch eine beträchtliche Breite der horizontalen Achse einnehmen, weil:

1. prometheus:metric_data() ruft zuerst table.sort auf, um alle Metriken zu sortieren. Wenn die Metriken das 100.000-Niveau erreichen, entspricht dies dem Sortieren von 100.000 Zeichenfolgen, und table.sort kann nicht durch ngx.sleep(0) unterbrochen werden.
2. Die Stellen, an denen string.format und fix_histogram_bucket_labels verwendet werden, können nicht optimiert werden. Nach der Kommunikation mit knyar habe ich erfahren, dass diese Schritte notwendig sind, um sicherzustellen, dass prometheus:metric_data() Metriken im richtigen Format erzeugen kann.

Bisher sind die Optimierungsmethoden auf Code-Ebene erschöpft, aber leider ist das Problem immer noch nicht perfekt gelöst. Es gibt immer noch eine spürbare Verzögerung in den P100-Metriken.

Was tun?

Kehren wir zum Kernproblem zurück: prometheus:metric_data() belegt eine große Menge an CPU-Zeitscheiben für Berechnungen und verdrängt CPU-Ressourcen für die Verarbeitung normaler Anfragen.

Im Linux-System werden die Zeitscheiben, die die CPU einem Thread oder einem Prozess zuweist? Genau genommen ist es ein Thread, und der Thread ist die tatsächliche Arbeitseinheit. NGINX ist jedoch eine Multi-Prozess-Single-Thread-Architektur mit nur einem Thread in jedem Prozess.

An diesem Punkt dachten wir an eine Optimierungsrichtung: Verschieben Sie prometheus:metric_data() in andere Threads (oder genauer gesagt, Prozesse). Also untersuchten wir zwei Richtungen:

1. Verwenden Sie ngx.run_worker_thread, um die Berechnungsaufgaben von prometheus:metric_data() auszuführen, was dem Übergeben von CPU-intensiven Aufgaben an den Thread-Pool entspricht.
2. Verwenden Sie einen separaten Prozess, um die Berechnungsaufgaben von prometheus:metric_data() zu behandeln, dieser Prozess wird keine normalen Anfragen verarbeiten.

Nach einem PoC (Proof of Concept) haben wir Option 1 abgelehnt und Option 2 übernommen. Option 1 wird abgelehnt, weil ngx.run_worker_thread nur für die Ausführung von anfrageunabhängigen Berechnungsaufgaben geeignet ist, während prometheus:metric_data() anfrageabhängig ist.

Implementierung von Option 2: Lassen Sie privileged agent (privilegierter Prozess) prometheus:metric_data() behandeln. Aber der privilegierte Prozess überwacht keine Ports und verarbeitet keine Anfragen. Daher müssen wir den privilegierten Prozess so ändern, dass er den Port überwachen kann.

Schließlich haben wir feat: allow privileged agent to listen port und feat(prometheus): support collect metrics works in the privileged agent verwendet, um Option 2 zu implementieren.

Wir haben APISIX mit dieser Optimierung getestet und festgestellt, dass die Verzögerung des P100-Index auf einen vernünftigen Bereich reduziert wurde und das Problem der Long-Tail-Anfragen nicht mehr existiert.

  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

Dies ist eine delikate Lösung und löst das Kernproblem. Wir haben diese Lösung in der Produktionsumgebung beobachtet und verifiziert. Sie beseitigte das Long-Tail-Anfragephänomen und verursachte keine zusätzlichen Ausnahmen.

Zusammenfassung

Als wir dieses Problem behoben haben, entstand ein neuer Gedanke: Ist die Open-Source-Bibliothek nginx-lua-prometheus für APISIX geeignet?

Wir haben das Problem von prometheus:metric_data() auf der APISIX-Seite gelöst. Gleichzeitig haben wir auch andere Probleme in nginx-lua-prometheus gefunden und behoben. Wie fix memory leak und LRU cache elimination.

nginx-lua-prometheus wurde ursprünglich für NGINX entwickelt, nicht für OpenResty und OpenResty-basierte Anwendungen. Es gibt jedoch kein Open-Source-Projekt im OpenResty-Ökosystem, das reifer mit dem Prometheus-Ökosystem verbunden ist als nginx-lua-prometheus. Daher wurde nginx-lua-prometheus ständig von der Open-Source-Community für das OpenResty-Ökosystem gefördert.

Vielleicht sollten wir mehr erkunden und einen Weg finden, um sich mit dem Prometheus-Ökosystem zu verbinden, ohne den Quellcode von APISIX zu ändern. Zum Beispiel eine Abhängigkeitsbibliothek entwerfen, die besser für APISIX geeignet ist, oder sich auf eine bestimmte Weise mit reifen Projekten im Prometheus-Ökosystem verbinden und den Prozess der Sammlung und Berechnung von Metriken in diese reifen Projekte verschieben.