Kurs NestJS · Moduł 8: Cache i wydajność
Profiling i Benchmarking NestJS - diagnostyka mocy Imperium
W tej lekcji5
Dowódco legionów! Po wdrożeniu użytkownicy piszą, że „jest wolniej”, a zespół spiera się, czy winna jest baza, nowy interceptor czy serializacja. Każdy ma teorię, nikt nie ma liczb. Nawet najlepiej wyszkolona armia rzymska potrzebuje regularnych przeglądów - w NestJS profiling i benchmarking to taka inspekcja: diagnozujesz, gdzie aplikacja traci czas, pamięć i zasoby.
Benchmarking z autocannon
autocannon to narzędzie do testów obciążeniowych - jak wysłanie tysięcy posłańców naraz, żeby sprawdzić przepustowość dróg Imperium:
1# -c 100 = 100 równoległych połączeń (100 posłańców naraz)
2# -d 10 = test trwa 10 sekund
3# -p 10 = 10 żądań w pipeline na połączenie - zawyża wyniki, używaj ostrożnie
4
5# Test obciążeniowy bez instalacji, przez npx
6npx autocannon -c 100 -d 10 http://localhost:3000/legions-c ustala liczbę równoległych połączeń, a -d czas testu w sekundach. Tak wyglądał wynik jednego uruchomienia na laptopie, dla endpointu zwracającego 20 legionów:
1Running 10s test @ http://localhost:3000/legions
2100 connections
3
4┌─────────┬──────┬──────┬───────┬──────┬─────────┬─────────┬────────┐
5│ Stat │ 2.5% │ 50% │ 97.5% │ 99% │ Avg │ Stdev │ Max │
6├─────────┼──────┼──────┼───────┼──────┼─────────┼─────────┼────────┤
7│ Latency │ 5 ms │ 5 ms │ 7 ms │ 8 ms │ 5.44 ms │ 3.92 ms │ 352 ms │
8└─────────┴──────┴──────┴───────┴──────┴─────────┴─────────┴────────┘
9┌───────────┬─────────┬─────────┬────────┬─────────┬───────────┬────────┬─────────┐
10│ Stat │ 1% │ 2.5% │ 50% │ 97.5% │ Avg │ Stdev │ Min │
11├───────────┼─────────┼─────────┼────────┼─────────┼───────────┼────────┼─────────┤
12│ Req/Sec │ 15,519 │ 15,519 │ 16,671 │ 16,831 │ 16,574.19 │ 344.7 │ 15,515 │
13├───────────┼─────────┼─────────┼────────┼─────────┼───────────┼────────┼─────────┤
14│ Bytes/Sec │ 23.3 MB │ 23.3 MB │ 25 MB │ 25.3 MB │ 24.9 MB │ 517 kB │ 23.3 MB │
15└───────────┴─────────┴─────────┴────────┴─────────┴───────────┴────────┴─────────┘
16
17182k requests in 11.02s, 274 MB readPierwsza tabela to latencja w percentylach, druga - żądania i bajty na sekundę, z innymi kolumnami. Twoje liczby będą inne, bo zależą od sprzętu. Ten sam test z -p 10 podniósł liczbę żądań na sekundę o około 18%, ale średnią latencję z 5,4 do 50 ms, bo żądania czekały w kolejce połączenia; przeglądarki pipeliningu nie używają, więc zostaw go w spokoju.
Autocannon działa też z kodu, co pozwala wpiąć benchmark w testy:
1// benchmark.ts - programistyczne użycie autocannon
2import autocannon from 'autocannon';
3
4async function runBenchmark() {
5 const result = await autocannon({
6 url: 'http://localhost:3000/legions',
7 connections: 100, // 100 równoległych połączeń
8 duration: 10, // 10 sekund testu
9 headers: {
10 'Authorization': 'Bearer test-token',
11 },
12 });
13
14 console.log('=== Wyniki Benchmarku ===');
15 console.log('Requests/sec:', result.requests.average);
16 console.log('Latency avg:', result.latency.average, 'ms');
17 console.log('Latency p99:', result.latency.p99, 'ms');
18 console.log('Throughput:', result.throughput.average, 'bytes/sec');
19 console.log('Errors:', result.errors);
20 console.log('Timeouts:', result.timeouts);
21
22 // Kryteria sukcesu
23 if (result.latency.p99 > 200) {
24 console.warn('UWAGA: p99 latency przekracza 200ms!');
25 }
26 if (result.errors > 0) {
27 console.error('BŁĄD: wystąpiły błędy podczas testu!');
28 }
29}
30
31runBenchmark();Wynik zawiera m.in. requests.average, latency.p99, throughput.average, errors i timeouts. Próg 200 ms dla p99 zamienia benchmark w test, który może nie przejść.
Node.js --inspect Profiling
Node.js ma wbudowany profiler, który pokazuje, co robi CPU. Flaga --inspect włącza protokół inspektora, a --cpu-prof zapisuje profil do pliku przy wyjściu z procesu:
1# Uruchomienie NestJS z inspektorem
2node --inspect dist/main.js
3
4# Następnie otwórz w Chrome: chrome://inspect
5# Kliknij "Open dedicated DevTools for Node"
6# W zakładce "Performance":
7# 1. Kliknij "Record"
8# 2. Wykonaj operacje na API (wyślij żądania)
9# 3. Kliknij "Stop"
10# 4. Analizuj flame graph
11
12# Albo zapisz profil CPU do pliku przy wyjściu z procesu
13node --cpu-prof dist/main.jsDawny panel JavaScript Profiler zniknął z Chrome w wersji 124, dlatego Node.js profilujesz w zakładce Performance.
Ten sam profiler da się sterować z kodu przez moduł node:inspector:
1// Programistyczne profilowanie CPU
2import { Session } from 'node:inspector';
3import { writeFileSync } from 'node:fs';
4
5class CpuProfiler {
6 private session: Session;
7
8 constructor() {
9 this.session = new Session();
10 this.session.connect();
11 }
12
13 async startProfiling(): Promise<void> {
14 await new Promise<void>((resolve) => {
15 this.session.post('Profiler.enable', () => {
16 this.session.post('Profiler.start', () => {
17 console.log('Profiling CPU started...');
18 resolve();
19 });
20 });
21 });
22 }
23
24 async stopProfiling(filename: string): Promise<void> {
25 return new Promise((resolve) => {
26 this.session.post('Profiler.stop', (err, params) => {
27 // Przy błędzie params jest undefined - nie destrukturyzuj go na ślepo
28 if (!err) {
29 writeFileSync(filename, JSON.stringify(params.profile));
30 console.log('Profil CPU zapisany do: ' + filename);
31 }
32 resolve();
33 });
34 });
35 }
36}
37
38// Użycie:
39// const profiler = new CpuProfiler();
40// await profiler.startProfiling();
41// ... wykonaj operacje ...
42// await profiler.stopProfiling('cpu-profile.cpuprofile');
43// Otwórz plik w Chrome DevTools -> PerformanceSession łączy się z inspektorem bieżącego procesu, a post() wysyła mu polecenia. Poprawka dotyczy stopProfiling(): przy błędzie drugi argument callbacku to undefined, więc stara destrukturyzacja { profile } wywracała proces. Od Node.js 19 istnieje też node:inspector/promises z metodami zwracającymi obietnice.
Flame Graphs - wizualizacja hot spots
Flame graph pokazuje, które funkcje zajmują najwięcej czasu CPU - jak mapa bitwy, na której widać, gdzie toczy się najcięższa walka:
1# Jak czytać flame graph:
2# - szerokość bloku = jak często funkcja była na stosie (szerszy = więcej CPU)
3# - wysokość = głębokość call stacka; oś X to nie jest czas
4# - górna krawędź = funkcje, które akurat pracują na CPU
5# - szukaj szerokich płaskich bloków na górze - to bottlenecki!
6
7# Generowanie flame graph z clinic.js (projekt nie jest już aktywnie rozwijany)
8npm install -g clinic
9
10# 1. clinic doctor - ogólna diagnoza
11clinic doctor -- node dist/main.js
12# (w drugim terminalu: npx autocannon -c 100 -d 10 http://localhost:3000/legions)
13# Ctrl+C -> otwiera raport HTML
14
15# 2. clinic flame - flame graph
16clinic flame -- node dist/main.js
17
18# 3. clinic bubbleprof - analiza operacji async (np. zapytań do bazy)
19clinic bubbleprof -- node dist/main.js
20
21# Alternatywa utrzymywana na bieżąco: 0x
22npx 0x dist/main.jsRepozytorium Clinic.js ostrzega, że projekt nie jest aktywnie rozwijany i jego wyniki mogą być nietrafne, stąd 0x jako alternatywa. Stara wersja tej lekcji kazała szukać szerokich bloków na dole i czytać czerwień jako hot path, ale dół wykresu to zawsze szerokie funkcje nadrzędne, a kolor w klasycznych flame graphach jest losowy - liczy się szerokość na górnej krawędzi.
Heap Snapshots - analiza pamięci
Heap snapshot to zrzut całej sterty - jak spis ludności Imperium, który pokazuje, kto zajmuje ile miejsca:
1// heap-snapshot.service.ts
2import { Injectable, Logger } from '@nestjs/common';
3import * as v8 from 'node:v8';
4
5@Injectable()
6export class HeapSnapshotService {
7 private readonly logger = new Logger(HeapSnapshotService.name);
8
9 // Zrób zrzut pamięci (synchronicznie - blokuje event loop!)
10 takeSnapshot(filename?: string): string {
11 const snapshotFile = filename ||
12 'heap-' + new Date().toISOString().replace(/[:.]/g, '-') + '.heapsnapshot';
13
14 const writtenFile = v8.writeHeapSnapshot(snapshotFile);
15 this.logger.log('Heap snapshot zapisany: ' + writtenFile);
16
17 return writtenFile;
18 }
19
20 // Pobierz statystyki heap
21 getHeapStatistics() {
22 const stats = v8.getHeapStatistics();
23 return {
24 totalHeapSize: Math.round(stats.total_heap_size / 1024 / 1024) + ' MB',
25 usedHeapSize: Math.round(stats.used_heap_size / 1024 / 1024) + ' MB',
26 heapSizeLimit: Math.round(stats.heap_size_limit / 1024 / 1024) + ' MB',
27 mallocedMemory: Math.round(stats.malloced_memory / 1024 / 1024) + ' MB',
28 usagePercent: ((stats.used_heap_size / stats.heap_size_limit) * 100).toFixed(1) + '%',
29 };
30 }
31
32 // Porównanie statystyk sterty przed i po operacji
33 async compareHeapUsage(operation: () => Promise<unknown>) {
34 const before = v8.getHeapStatistics();
35 await operation();
36 const after = v8.getHeapStatistics();
37
38 const diff = {
39 heapGrowth: after.used_heap_size - before.used_heap_size,
40 // Rosnąca liczba kontekstów (np. z modułu vm) to osobny rodzaj wycieku
41 nativeContextGrowth: after.number_of_native_contexts - before.number_of_native_contexts,
42 };
43
44 if (diff.heapGrowth > 10 * 1024 * 1024) { // > 10MB growth
45 this.logger.warn('Potencjalny memory leak! Heap wzrósł o ' +
46 Math.round(diff.heapGrowth / 1024 / 1024) + ' MB');
47 }
48
49 return diff;
50 }
51}v8.writeHeapSnapshot() zwraca nazwę zapisanego pliku, a nie strumień. Zrzut jest synchroniczny i blokuje event loop, a według dokumentacji Node.js wymaga około dwa razy tyle pamięci, ile zajmuje sterta - w teście 40 MB sterty dało plik 78 MB. Nie wystawiaj go więc przez publiczny endpoint: grozi zatrzymaniem produkcji, a zrzut zawiera sekrety z pamięci. Dwa zrzuty porównasz w zakładce Memory w DevTools; compareHeapUsage() robi tylko szybkie porównanie statystyk.
Identyfikowanie bottlenecków - praktyczny workflow
Oto workflow diagnostyczny, jakiego używa doświadczony inżynier Imperium:
1// performance-diagnostic.service.ts
2import { Injectable, Logger } from '@nestjs/common';
3
4@Injectable()
5export class PerformanceDiagnosticService {
6 private readonly logger = new Logger('PerformanceDiagnostic');
7
8 // Krok 1: Zmierz czas endpointów
9 async measureEndpoint(name: string, operation: () => Promise<any>) {
10 const start = process.hrtime.bigint();
11 const result = await operation();
12 const end = process.hrtime.bigint();
13 const durationMs = Number(end - start) / 1_000_000;
14
15 this.logger.log(name + ': ' + durationMs.toFixed(2) + 'ms');
16
17 if (durationMs > 200) {
18 this.logger.warn(name + ' przekracza 200ms - wymaga optymalizacji!');
19 }
20
21 return { result, durationMs };
22 }
23
24 // Krok 2: Sprawdź zużycie pamięci
25 checkMemoryUsage() {
26 const usage = process.memoryUsage();
27 return {
28 rss: Math.round(usage.rss / 1024 / 1024) + ' MB',
29 heapUsed: Math.round(usage.heapUsed / 1024 / 1024) + ' MB',
30 heapTotal: Math.round(usage.heapTotal / 1024 / 1024) + ' MB',
31 external: Math.round(usage.external / 1024 / 1024) + ' MB',
32 };
33 }
34
35 // Krok 3: Monitoruj event loop delay
36 measureEventLoopDelay(): Promise<number> {
37 return new Promise((resolve) => {
38 const start = Date.now();
39 setImmediate(() => {
40 const delay = Date.now() - start;
41 if (delay > 10) {
42 this.logger.warn('Event loop delay: ' + delay + 'ms');
43 }
44 resolve(delay);
45 });
46 });
47 }
48
49 // Krok 4: Pełny raport diagnostyczny
50 async generateDiagnosticReport() {
51 const memory = this.checkMemoryUsage();
52 const eventLoopDelay = await this.measureEventLoopDelay();
53 const uptime = process.uptime();
54
55 return {
56 timestamp: new Date().toISOString(),
57 uptime: Math.round(uptime) + 's',
58 memory,
59 eventLoopDelay: eventLoopDelay + 'ms',
60 nodeVersion: process.version,
61 platform: process.platform,
62 };
63 }
64}process.hrtime.bigint() mierzy czas w nanosekundach bez wpływu zmian zegara systemowego. Pomiar przez setImmediate to tylko jednorazowa próbka; stały nadzór daje histogram monitorEventLoopDelay() z lekcji o pamięci.
Polecam Ci stałą kolejność: benchmark ustala punkt odniesienia, profil pokazuje przyczynę, a po poprawce ten sam benchmark potwierdza efekt. W następnym module wyprowadzimy zmierzony i odchudzony fort na produkcję.
Pamiętaj zasadę Pretora Augusta: nie optymalizuj tego, czego nie zmierzyłeś.
Kod do tej lekcji: src/profiling-benchmarking.ts
1// Profiling i Benchmarking NestJS
2import { Injectable, Logger } from '@nestjs/common';
3
4// ===========================================
5// 1. Performance Measurement
6// ===========================================
7
8@Injectable()
9class PerformanceDiagnostic {
10 private readonly logger = new Logger('Diagnostic');
11
12 async measureEndpoint(name: string, operation: () => Promise<any>) {
13 const start = process.hrtime.bigint();
14 const result = await operation();
15 const end = process.hrtime.bigint();
16 const durationMs = Number(end - start) / 1_000_000;
17
18 console.log(name + ': ' + durationMs.toFixed(2) + 'ms');
19
20 if (durationMs > 200) {
21 console.warn(name + ' przekracza 200ms!');
22 }
23
24 return { result, durationMs };
25 }
26
27 checkMemoryUsage() {
28 const usage = process.memoryUsage();
29 return {
30 rss: Math.round(usage.rss / 1024 / 1024) + ' MB',
31 heapUsed: Math.round(usage.heapUsed / 1024 / 1024) + ' MB',
32 heapTotal: Math.round(usage.heapTotal / 1024 / 1024) + ' MB',
33 };
34 }
35
36 measureEventLoopDelay(): Promise<number> {
37 return new Promise((resolve) => {
38 const start = Date.now();
39 setImmediate(() => {
40 resolve(Date.now() - start);
41 });
42 });
43 }
44}
45
46// ===========================================
47// 2. Heap Statistics (v8)
48// ===========================================
49
50// import * as v8 from 'v8';
51// const stats = v8.getHeapStatistics();
52// {
53// total_heap_size: ...,
54// used_heap_size: ...,
55// heap_size_limit: ...,
56// }
57
58// Heap Snapshot:
59// v8.writeHeapSnapshot('heap.heapsnapshot');
60// Otworz w Chrome DevTools -> Memory
61
62// ===========================================
63// 3. Demonstracja
64// ===========================================
65
66const diagnostic = new PerformanceDiagnostic();
67const memory = diagnostic.checkMemoryUsage();
68
69console.log('=== Profiling & Benchmarking ===');
70console.log('Pamiec:', JSON.stringify(memory));
71console.log('');
72console.log('Narzedzia:');
73console.log(' autoballista - load testing (req/sec, latency)');
74console.log(' node --inspect - CPU profiling w Chrome');
75console.log(' clinic.js - flame graphs, doctor, bubbleprof');
76console.log(' v8.writeHeapSnapshot() - zrzut pamieci');
77console.log(' process.hrtime.bigint() - pomiar czasu');
78console.log('');
79console.log('Workflow:');
80console.log(' 1. Zmierz (autoballista)');
81console.log(' 2. Profiluj (clinic flame)');
82console.log(' 3. Zidentyfikuj bottleneck');
83console.log(' 4. Napraw');
84console.log(' 5. Zmierz ponownie');
85Widzisz błąd w tej lekcji?