Diagnose von langsamen Node.js-APIs: Messen Sie die Latenz, bevor Sie optimieren

Ein Endpunkt benötigt fast eine Sekunde, doch die CPU ist nur zu etwa einem Drittel ausgelastet, der Speicher ist unbedeutend und das Datenbank-Dashboard zeigt grün an. Die Anpassung derjenigen Komponenten, die man für schuldig hält, hilft selten. Diese Anleitung führt Sie Schritt für Schritt durch den Anfrageablauf, damit Sie herausfinden können, wohin die Zeit geht, sowie durch die Methoden der Messung, die eine kostengünstige und zuverlässige Untersuchung ermöglichen.

Messen Sie die Anfragezeit, bevor Sie den Laufzeitumgebungen die Schuld geben

Nutzen Sie einen einfachen Weg, bei dem eine Bestellung anhand ihrer ID geladen und als JSON zurückgegeben wird.

app.get("/orders/:id", async (req, res) => {
  const order = await getOrder(req.params.id);
  res.json(order);
});

Nehmen wir an, die Antworten dauern etwa 900 Millisekunden. Anstatt Node.js die Schuld zu geben, umhüllen Sie den wartenden Aufruf mit performance.now() und prüfen Sie, welchen Anteil er am Gesamtdaueranteil ausmacht.

const start = performance.now();

const order = await getOrder(req.params.id);
console.log(
  `getOrder: ${performance.now() - start}ms`
);
res.json(order);

Die Zahlen klären die Frage in der Regel schnell:

Request:       910ms
getOrder():    870ms
Node.js:        40ms

Nähezu die gesamte Verzögerung entsteht innerhalb von getOrder(); der umgebende JavaScript-Code kostet etwa 40 ms. Die Zeit wird damit verbracht, auf etwas weiter im System zu warten.

Niedrige CPU-Auslastung bedeutet nicht einen funktionierenden Service

Ein Auslastungsdisplay wie das folgende wirkt beruhigend:

CPU: 32%
Memory: 48%

Die CPU-Messung gibt an, wie viel Arbeit erledigt wird, und eine wartende Anfrage verbraucht fast keine Ressourcen. Typische Dinge, auf die ein Node.js-Prozess wartet:

• die Herstellung einer Datenbankverbindung
• die eigentliche Abfrage
• einen anderen HTTP-Service
• Allgemeine Netzwerk-Eingabe/Ausgabe
• eine Nachrichtenwarteschlange
• einen Sperrmechanismus

Ein langsamer Service mit inaktiver CPU ist in der Regel nicht beschäftigt – er ist blockiert.

Achten Sie auf die Verzögerung im Event-Loop, nicht nur auf den CPU-Prozentsatz

Jeder Callback in einem Node.js-Prozess teilt sich einen Event-Loop, wodurch die Differenz zwischen dem Zeitpunkt, zu dem ein Timer auslösen sollte, und dem tatsächlichen Auslösungstermin ein direktes Signal zum Zustand des Systems darstellt. monitorEventLoopDelay aus node:perf_hooks misst diese Differenz und stellt sie in einem Histogramm dar; dabei wird eine Auflösung von 20 ms verwendet, und alle fünf Sekunden werden die Werte p95 sowie p99 ausgegeben.

import { monitorEventLoopDelay } from "node:perf_hooks";

const histogram = monitorEventLoopDelay({
  resolution: 20
});
histogram.enable();
setInterval(() => {
  console.log({
    p95: histogram.percentile(95),
    p99: histogram.percentile(99)
  });
}, 5000);

Falls die Ausgabe so aussieht, ist der Event-Loop in Ordnung und kann keine Erklärung für eine 900-millisecondige Anfrage liefern:

p95 event-loop delay: 8ms
p99 event-loop delay: 14ms

Zahlen im Bereich von Hunderten Millisekunden erzählen eine völlig andere Geschichte:

p95: 180ms
p99: 650ms

Jetzt wird der Event-Loop von etwas monopolisiert. Ein typischer Übeltäter ist eine synchron ausgeführte, rechenintensive Funktion, die direkt innerhalb eines Handlers aufgerufen wird:

app.get("/report", (req, res) => {
  const result = expensiveCalculation();
  res.json(result);
});

Während expensiveCalculation() ausgeführt wird, macht keine andere Anfrage in diesem Prozess Fortschritte. Auf einem Mehrkern-Host kann das Gesamtkennfeld der CPU dennoch moderat aussehen, da ein gesättigter Kern mit inaktiven Kernen durchschnittlich wird – deshalb ist die Schleifenverzögerung oft aussagekräftiger als der CPU-Anteil. Die übliche Lösung besteht darin, diese Arbeiten auf einen Worker-Thread, eine Aufgabenwarteschlange oder einen separaten Dienst zu verlagern. Ein damit verbundener Fehlermodus, bei dem die Schleife durch Mikrotask-Planung statt durch Berechnungen zurückgehalten wird, wird in wie process.nextTick den Event-Loop zurückhalten kann erläutert.

Wenn die Datenbank schuldig erscheint

Dann sollte man die Abfrage auf dieselbe Weise instrumentieren.

const start = performance.now();
const result = await db.query(
  "SELECT * FROM orders WHERE customer_id = $1",
  [customerId]
);
console.log(
  `DB query: ${performance.now() - start}ms`
);

Der Fehler zeigt nun eindeutig auf die Datenbank:

Total request: 850ms
Node.js:        15ms
DB query:      810ms
Serialization:  25ms

Bevor Sie den SQL-Code umschreiben, überprüfen Sie, ob die Abfrage langsam war oder der Anfragenprozess auf eine Verbindung wartete.

Ausnutzung des Pools, die sich als langsame Abfrage ausgibt

Betrachten Sie einen Pool mit folgender Größe:

API instances:        10
Connections/instance: 20

Total connections:   200

Dann tritt plötzlich ein Anstieg des Datenverkehrs auf:

Requests:          500
Active DB queries:  20
Waiting requests: 480

Pro Instanz können nur 20 Abfragen ausgeführt werden, wodurch die übrigen im Pool in der Warteschlange landen. Eine Abfrage kann 30 Millisekunden dauern, doch eine Anfrage ganz hinten in der Warteschlange muss Hunderte von Millisekunden warten, bis sie die Datenbank erreicht. Der Anwendungs-Timer gibt an:

DB call = 500ms

Die Datenbank selbst meldet:

Query = 30ms

Eine langsame Abfrage erfordert Indizes oder einen besseren Ausführungsplan; eine lange Wartezeit erfordert eine angepasste Pool-Größe, kürzere Transaktionen oder weniger Kommunikationswege. Messen Sie die einzelnen Phasen getrennt voneinander an, anstatt nur eine einzige „Datenbank-Latenz“-Wert anzugeben:

Connection wait
      +
Query execution
      +
Result processing

Die meisten Pool-Bibliotheken geben die Zahlen für inaktive, gesamte sowie wartende Elemente an; deren Ausgabe ist der schnellste Weg, um diese Fälle voneinander zu unterscheiden.

Nachgeschaltete Dienste und sequenzielle Await-Anfragen

Viele Endpunkte erstellen eine Antwort aus mehreren Abhängigkeiten nacheinander:

const customer = await customerService.get(id);

const payment = await paymentApi.get(
  customer.paymentId
);
const orders = await orderService.get(id);

Die getrennte Messung jeder Anfrage macht den Ausreißer sichtbar:

Customer API:    40ms
Payment API:    700ms  ← 🚨
Orders DB:       35ms
Node.js:         15ms

Der Zahlungsdienst dominiert, und da jedes await auf das vorherige wartet, stapeln sich die Verzögerungen:

40ms + 700ms + 35ms + 15ms
≈ 790ms

Unabhängige Anfragen können gleichzeitig starten. Für die Abfrage von Kunde und Bestellung reicht nur die id, weshalb Promise.all sie überschneidet:

const [customer, orders] = await Promise.all([
  customerService.get(id),
  orderService.get(id)
]);

Die Zahlungsanfrage wartet weiterhin, da sie customer.paymentId benötigt. Parallelisieren Sie nicht reflexartig: Zusätzliche Konkurrenz belastet Pools, APIs und den Speicher und kann unter Last die Verzögerungen verschlimmern.

Prozentswerte zeigen, was durch Durchschnitte verborgen bleibt

Ein Dashboard, das dies anzeigt, scheint in Ordnung zu sein:

Average latency: 120ms

Die Prozentswertansicht desselben Traffics ist weniger beruhigend:

p50:  80ms
p95: 180ms
p99: 2.8s

Der Durchschnitt beschreibt eine gewöhnliche Anfrage; die Ausreißer beschreiben Benutzer, die auf einen überlasteten Pool oder eine langsame Abhängigkeit stoßen. Verfolgen Sie die Verteilung:

p50
p95
p99

Instrumentierung, die hilft statt zu schaden

Messungen kosten CPU-Ressourcen, Speicherplatz und Aufmerksamkeit. Einige Gewohnheiten sorgen dafür, dass sie nützlich bleiben.

Messen Sie an Grenzen, nicht in jeder Hilfsfunktion

Die Zeitmessung jeder Funktion auf diese Weise erzeugt mehr Rauschen als Erkenntnisse:

const start = performance.now();
// ...
console.log(performance.now() - start);

Messen Sie dort, wo eine Anfrage in ein anderes System übergeht – denn genau dort findet das Warten statt:

HTTP request
   ↓
Database
   ↓
External API
   ↓
Queue
   ↓
Response

Halten Sie die Protokollierung pro Anfrage unter Kontrolle

Eine Protokollzeile pro Anfrage wird bei hohem Durchsatz teuer:

console.log({
  path: req.path,
  duration,
  userId: req.user.id
});

Verwenden Sie strukturiertes Logging mit Ebenen und Stichprobenziehung, und halten Sie diese Elemente vollständig aus den Logs raus:

passwords
tokens
authorization headers
payment information

Eine Dauer ist keine Diagnose

Eine solche Zahl beweist nicht, dass der SQL-Befehl tatsächlich so lange gebraucht hat:

DB: 700ms

Diese Zeitspanne kann mehrere unterschiedliche Kosten umfassen:

Connection acquisition
+
Query execution
+
Network
+
Result transfer
+
Client-side processing

Wenn eine Zahl Sie überrascht, teilen Sie sie in ihre Bestandteile auf, bevor Sie darauf reagieren.

Vermeiden Sie Metriken mit hoher Kardinalität

Das Beschriften einer Latenzmetrik mit einer Benutzer-ID erscheint unbedenklich:

http_request_duration{user_id="123456"}

Mit Millionen von Benutzern bedeutet das Millionen von Zeitreihen. Verwenden Sie stattdessen begrenzte Dimensionen:

route
method
status_code
service

Eine gut beschriftete Zeitreihe sieht dann so aus:

http_request_duration{
  route="/orders/:id",
  method="GET",
  status="200"
}

Detaillierte Informationen pro Anfrage gehören in Logs und Spuren.

Stichproben ziehen Sie bewusst

Eine gängige Vorgehensweise verfolgt einen kleinen Teil des normalen Traffics sowie alles Interessante:

Normal traffic → sample a percentage
Errors         → capture aggressively
Slow requests  → capture aggressively

Das Verhältnis hängt vom Traffic, den verwendeten Werkzeugen und dem Budget ab; das Ziel sind ausreichende Beweise zur Erklärung von Fehlern, nicht Vollständigkeit.

Vergleichen Sie vor und nach über mehrere Signale hinweg

„Es fühlt sich schneller an“ ist kein Beweis. Erfassen Sie den Prozentsatz vor einer Änderung:

Before:
p95 = 820ms

Und erneut danach:

After:
p95 = 410ms

Stellen Sie anschließend sicher, dass sich nichts anderes in die falsche Richtung entwickelt hat:

error rate
CPU
memory
DB load
connection pool usage

Eine schnellere Abfrage, die die Nutzung des Pools oder die Last der Datenbank verdoppelt, hat das Problem lediglich verschoben.

Verfolgen Sie eine einzelne Anfrage mit Tracing

Eine Metrik auf Route-Ebene gibt Ihnen nur den Gesamtwert an:

GET /orders = 980ms

Ein verteiltes Tracing teilt dieselbe Anfrage in Abschnitte auf, sodass die Kosten jeder Phase auf einen Blick sichtbar sind:

GET /orders
│
├── Node.js processing       15ms
├── DB connection wait      120ms
├── PostgreSQL query         40ms
├── Payment API             700ms
├── JSON serialization       20ms
└── Network                   5ms
                              ───
                              900ms

Diese Aufteilung der Arbeit ist es wert, im Gedächtnis zu bleiben: Metriken warnen Sie davor, dass etwas nicht in Ordnung ist, und Spuren zeigen Ihnen an, wo das Problem liegt.

Checkliste zur Verfolgung des Anfragenweges

Wenn die Latenz steigt, widerstehen Sie dem Drang, zunächst Server oder CPU hinzuzufügen. Verfolgen Sie den Weg, den eine Anfrage nimmt, und messen Sie jeden Schritt:

Request
   ↓
Queue / Load Balancer
   ↓
Node.js
   ↓
Event Loop
   ↓
Connection Pool
   ↓
Database
   ↓
External APIs
   ↓
Network
   ↓
Response

Stellen Sie in jeder Phase eine konkrete Frage:

Is the event loop blocked?

Are requests waiting for connections?

Are database queries slow?

Are downstream APIs slow?

Are we waiting on network I/O?

Is the queue growing?

Is garbage collection causing pauses?

Is the response itself expensive to serialize?

Jede dieser Fragen lässt sich mit Daten beantworten, daher ist es nicht notwendig, zu raten.

Was die Beweise in der Regel zeigen

Kehren wir zum ursprünglichen Szenario zurück:

API latency: 900ms
CPU: 35%
Memory: 48%

Nach der Messung jeder Phase sieht das Bild völlig anders aus:

Event loop:          12ms
DB query:            35ms
Connection wait:    120ms
Payment API:        700ms
Serialization:       20ms
Network:              5ms

Ohne Laufzeit-Umwandlung würden größere Instanzen oder zusätzliches Speicherplatz helfen. Die Hauptprobleme sind die 700-Millisekunden-Dauer der Zahlungsabwicklung (durch Caching, Timeout mit Fallback oder Verlegung außerhalb des Anfragenpfades) sowie die 120-Millisekunden-Wartezeit auf eine Verbindung (durch Anpassung der Pool-Größe oder Reduzierung des Abfragedrucks).

Kernpunkte

Der instinktive Ansatz sieht so aus:

Slow API
   ↓
Add more servers

Der effektive Ansatz sieht so aus:

Slow API
   ↓
Measure
   ↓
Break down latency
   ↓
Find the bottleneck
   ↓
Fix the bottleneck
   ↓
Measure again

• Messen Sie zunächst die gesamte Anfragezeit und teilen Sie sie anschließend an allen Stellen auf, an denen der Prozess verlassen wird.
• Betrachten Sie die Verzögerung im Event-Loop als wichtigstes Signal für den Zustand von Node.js; der CPU-Auslastungsprozentsatz kann einen blockierten Kern verbergen.
• Trennen Sie die Wartezeit auf eine Verbindung von der Ausführung der Abfrage, bevor SQL verwendet wird.
• Bewerten Sie die Latenz anhand von p95 und p99 statt durchschnittlicher Werte.
• Achten Sie darauf, dass Metriken eine geringe Kardinalität aufweisen, Logs stichprobenartig erfasst werden und keine sensiblen Daten enthalten, sowie dass detaillierte Informationen pro Anfrage in Traces gespeichert werden.

Überprüfen Sie jeden Fix anhand derselben Prozentwerte sowie der benachbarten Signale, die er möglicherweise beeinflusst hat.

Ein langsames System ist beherrschbar, sobald man es erkennen kann; bis dahin ist jede Änderung nur eine Vermutung. Für einen Überblick darüber, welche Fixes priorisiert werden sollten, sobald das Engpassproblem bekannt ist, siehe ein nach Priorität geordnetes Framework für die Leistungssteigerung von Node.js-APIs.