Diagnozowanie wolnych API w Node.js: Pomierz opóźnienie przed optymalizacją

Przetworzenie jednego punktu końcowego trwa prawie sekundę, a wydajność CPU wynosi około jednej trzeciej swojej maksymalnej zdolności; pamięć nie wykazuje szczególnych cech, a panel sterowania bazą danych jest w stanie zielonym. Dostosowywanie elementów, które uważamy za przyczynę problemu, rzadko przynosi efektów. Ten przewodnik opisuje proces obsługi żądania krok po kroku, abyś mógł zlokalizować, gdzie traci się czas, a także przedstawia praktyki instrumentacji, które sprawiają, że badanie jest tanie i wiarygodne.

Mierz czas trwania żądania, zanim obwiniasz środowisko wykonawcze

Wybierz prostą trasę, która ładuje zamówienie podając jego identyfikator i zwraca je w formacie JSON.

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

Załóżmy, że odpowiedzi zajmują około 900 ms. Zamiast obwiniać Node.js, otocz wywołanie oczekiwane przez performance.now(), aby sprawdzić, jaki udział w całkowitym czasie zajmuje.

const start = performance.now();

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

Liczby zazwyczaj szybko rozstrzygają tę kwestię:

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

Prawie cały opóźnienie występuje wewnątrz funkcji getOrder(); otaczający ją kod JavaScript zajmuje około 40 ms. Czas ten jest wykorzystywany na czekanie na coś w kolejce przetwarzania.

Niska wydajność CPU nie oznacza sprawnego serwisu

Panel wykorzystania zasobów, taki jak poniżej, sprawia wrażenie uspokajającego:

CPU: 32%
Memory: 48%

Wydajność CPU mierzy ilość wykonywanej pracy, a żądanie czekające w kolejce prawie nie zużywa zasobów. Typowe elementy, na które czeka proces Node.js:

• uzyskanie połączenia z bazą danych
• sama zapytanie
• inny serwis HTTP
• ogólne operacje wejścia/wyjścia w sieci
• kolejka wiadomości
• blokada

Slowy serwis z nieużywanym CPU zazwyczaj nie jest zajęty – jest zablokowany.

Zwracaj uwagę na opóźnienie w pętli zdarzeń, a nie tylko na procent wykorzystania CPU

Każda funkcja powrotna w procesie Node.js korzysta z tego samego pętli wydarzeń, więc różnica między momentem, w którym timer powinien zadziałać, a rzeczywistym momentem jego uruchomienia, jest bezpośrednim sygnałem stanu systemu. Funkcja monitorEventLoopDelay z modułu node:perf_hooks pobiera te dane i przedstawia je w postaci histogramu; używa tu rozdzielczości 20 ms oraz wyświetla wartości p95 i p99 co pięć sekund.

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);

Jeśli wynik wygląda w ten sposób, pętla funkcjonuje prawidłowo i nie może tłumaczyć się 900-milisekundowym czasem obsługi żądania:

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

Liczby w zakresie setek milisekund opowiadają zupełnie inną historię:

p95: 180ms
p99: 650ms

Coś teraz monopolizuje pętlę. Typowym winowajcą jest synchroniczna, wymagająca dużo zasobów CPU funkcja wywoływana bezpośrednio wewnątrz obsługi żądania:

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

Podczas wykonywania expensiveCalculation() żadne inne żądanie w tym procesie nie może postępować. Na serwerze z wieloma rdzeniami ogólny wykres zużycia CPU może nadal wyglądać umiarkowanie, ponieważ jeden przeciążony rdzeń jest średniony z wolnymi, dlatego opóźnienie pętli jest często bardziej wiarygodne niż procent zużycia CPU. Zwykłym rozwiązaniem jest przeniesienie takiej pracy do wątku roboczego, kolejki zadań lub oddzielnego usługi. Powiązany tryb awarii, w którym planowanie mikrozadań zamiast obliczeń powoduje blokadę pętli, jest omówiony w jak process.nextTick może blokować pętlę zdarzeń.

Gdy winowajcą wydaje się baza danych

Następnie należy w ten sam sposób zinstrumentować zapytanie.

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`
);

Teraz przyczyna problemu wskazuje bezpośrednio na bazę danych:

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

Zanim przepiszesz zapytanie SQL, sprawdź, czy było ono wolne, czy też żądanie czekało na połączenie.

wyczerpanie puli połączeń maskowane jako wolne zapytanie

Rozważmy taką strukturę puli połączeń:

API instances:        10
Connections/instance: 20

Total connections:   200

Następnie nadchodzi nagły wzrost ruchu:

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

Na jedną instancję może zostać uruchomionych tylko 20 zapytań, więc pozostałe trafiają do kolejki w puli. Jedno zapytanie może zająć 30 ms, ale żądanie na końcu kolejki musi czekać setki milisekund, zanim dotrze do bazy danych. Zegar aplikacji pokazuje:

DB call = 500ms

Sama baza danych podaje informacje o:

Query = 30ms

Wolne zapytanie wymaga użycia indeksów lub lepszego planu wykonywania; długi czas oczekiwania wymaga większej puli połączeń, krótszych transakcji lub mniej ruchów tam i z powrotem. Mierz poszczególne etapy oddzielnie, zamiast używać jednej wartości „opóźnienia bazy danych”:

Connection wait
      +
Query execution
      +
Result processing

Większość bibliotek do zarządzania zasobami udostępnia liczbę wolnych, całkowitą oraz liczbę czekających zapytań; ich eksport jest najszybszym sposobem na odróżnienie tych przypadków.

Słudzy poniżej w łańcuchu i sekwencyjne wywołania await

Wiele punktów końcowych buduje odpowiedź z kilku zależności, po jednej za drugą:

const customer = await customerService.get(id);

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

Indywidualne mierzenie czasu każdego wywołania pozwala zidentyfikować wyjątki:

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

Służba płatności dominuje, a ponieważ każde await czeka na poprzednie, opóźnienia się kumulują:

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

Niezależne wywołania mogą zostać rozpoczęte jednocześnie. Wyszukiwanie klienta i zamówienia wymaga tylko id, więc Promise.all łączy je w jedno:

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

Wywołanie związane z płatnością nadal czeka, ponieważ potrzebuje wartości customer.paymentId. Nie paralelizuj automatycznie – dodatkowa równoległość zwiększa obciążenie zasobów, API i pamięci, a przy dużym obciążeniu może pogorszyć sytuację.

Procentyle pokazują, co ukrywają średnie wartości

Panel sterowania prezentujący te dane wydaje się w porządku:

Average latency: 120ms

Widok procentylowy tego samego ruchu jest mniej przyjazny:

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

Średnia wartość opisuje zwykłą prośbę; „ogon” statystyk pokazuje użytkowników, którzy napotykają przeciążony zasób lub wolną zależność. Należy śledzić rozkład tych danych:

p50
p95
p99

Narzędzia pomocne, a nie szkodliwe

Pomiar wymaga zasobów CPU, pamięci oraz uwagi. Kilka dobrych nawyków sprawia, że pozostają one przydatne.

Mierz na granicach, a nie w każdej funkcji pomocniczej

Mierzenie czasu wykonywania każdej funkcji w ten sposób generuje więcej szumu niż rzeczywistych informacji:

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

Mierz w momencie, gdy prośba przechodzi do innego systemu – to właśnie wtedy następuje oczekiwanie:

HTTP request
   ↓
Database
   ↓
External API
   ↓
Queue
   ↓
Response

Kontroluj logowanie na poziomie każdej prośby

Zapis jednej linii w logu na każdą prośbę staje się kosztowny przy wysokim obrocie:

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

Niech logowanie będzie ustrukturyzowane z poziomami i próbkowaniem, a te elementy należy całkowicie pominąć z logów:

passwords
tokens
authorization headers
payment information

Czas trwania to nie diagnoza

Widok takiej wartości nie dowodzi, że zapytanie SQL trwało aż tyle czasu:

DB: 700ms

Ten okres może obejmować kilka różnych kosztów:

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

Gdy jakaś liczba cię zaskoczy, rozdziel ją na poszczególne składowe przed podjęciem działań.

Oznaczanie metryki opóźnienia identyfikatorem użytkownika wydaje się nieszkodliwe:

http_request_duration{user_id="123456"}

Przy milionach użytkowników oznacza to miliony serii czasowych. Zamiast tego używaj ograniczonych wymiarów:

route
method
status_code
service

Dobrze oznaczona seria wygląda wtedy w ten sposób:

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

Detale dotyczące poszczególnych żądań powinny znajdować się w logach i śladach.

Zwykła polityka śledzi niewielką część normalnego ruchu oraz wszystko, co istotne:

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

Stosunek ten zależy od ruchu, narzędzi i budżetu; celem jest posiadanie wystarczających dowodów na wyjaśnienie awarii, a nie kompletność danych.

Porównaj stan przed i po zmianie, na podstawie kilku wskaźników

„Wydaje się szybsze” to nie jest dowód. Zapisz wartość procentylową przed wprowadzeniem zmiany:

Before:
p95 = 820ms

A potem ponownie po niej:

After:
p95 = 410ms

Następnie upewnij się, że nic innego nie zmieniło się w niewłaściwym kierunku:

error rate
CPU
memory
DB load
connection pool usage

Szybsze zapytanie, które podwaja użycie zasobów lub obciążenie bazy danych, po prostu przenosi problem w inne miejsce.

Sledź pojedynczą prośbę za pomocą śledzenia

Metryka na poziomie trasy podaje jedynie wartość całkowitą:

GET /orders = 980ms

Rozproszone śledzenie dzieli tę samą prośbę na poszczególne etapy, dzięki czemu koszt każdego z nich jest od razu widoczny:

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

Tę podział prac warto zapamiętać: metryki ostrzegają, że coś jest nie tak, a ślady pokazują, gdzie dokładnie występuje problem.

Lista kontrolna przy śledzeniu ścieżki żądania

Gdy opóźnienie rośnie, unikaj najpierw dodawania serwerów lub zasobów CPU. Prześledź ścieżkę, którą przebywa żądanie, i zmierz każdy etap:

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

Na każdym etapie postaw konkretne pytanie:

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?

Każde z tych pytań można odpowiedzieć za pomocą danych, więc nie ma potrzeby zgadywać.

Co zwykle pokazują dowody

Wróćmy do początkowego scenariusza:

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

Po zmierzeniu każdego etapu obraz sytuacji jest zupełnie inny:

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

Brak możliwości przepisania kodu w czasie wykonywania – pomocne byłoby większe instancje lub dodatkowa pamięć. Głównymi problemami są zależność od procesu płatności trwająca 700 ms (kaching, timeout z alternatywą lub przeniesienie go poza ścieżkę żądania) oraz czas oczekiwania na połączenie wynoszący 120 ms (rozmiar puli połączeń lub objętość zapytań).

Główne wnioski

Pierwotny schemat działania wygląda tak:

Slow API
   ↓
Add more servers

Skuteczny schemat działania wygląda tak:

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

• Najpierw zmierz całkowity czas trwania żądania, a następnie podziel go na części w każdym miejscu, gdzie opuszcza on proces.
• Traktuj opóźnienia w pętli zdarzeń jako główny wskaźnik stanu Node.js; procent wykorzystania CPU może maskować blokowanie pojedynczego rdzenia.
• Rozdziel czas oczekiwania na połączenie od wykonywania zapytań, zanim przejdziesz do SQL.
• Oceniaj opóźnienia na podstawie wartości p95 i p99, a nie średnich.
• Zachowuj metryki o niskiej kardynalności, logi powinny być próbkowane i wolne od poufnych danych, a szczegóły dotyczące poszczególnych żądań umieszczaj w śladach.

Sprawdź każdą poprawkę w odniesieniu do tych samych percentylów oraz sąsiednich sygnałów, na które mogła wpłynąć.

System wolny w działaniu da się zarządzać, gdy tylko można go zaobserwować; do tego momentu każda zmiana jest jedynie domysłem. Aby dowiedzieć się, które poprawki należy priorytetyzować po zidentyfikowaniu wąskiego gardła, zapoznaj się z ramową strukturą uporządkowaną według priorytetów dla optymalizacji wydajności API Node.js.