Performance Optimization - increasing fort speed

In the evening, when the cohorts file their reports, the fort slows down: a response that takes 80 ms in the morning drags on for seconds after dark. Consul Caesar.js wants it faster, but nobody knows what slows it down - the database, the CPU or memory. So the first rule of a legion engineer is: measure first, optimize second.

What is performance optimization?

Imagine the application as a legion camp:

• the legionaries' strength (CPU) - must be enough for every task,
• the storehouses (memory) - must be well managed,
• the tabularium (database) - must be in order,
• the cohorts (processes) - must cooperate smoothly,
• roads and messengers (I/O operations) - must be passable.

Optimization is the art of tuning all these elements in harmony.

Four signals

Before you change anything, decide what you measure. Google's SRE book lists four golden signals, in this order:

• latency - response time, given as the p95 and p99 percentiles,
• traffic - throughput, for example requests per second,
• errors - the share of failed requests,
• saturation - resource usage, that is CPU and memory.

A p95 of 200 ms means that 95% of requests finish faster than 200 ms. An average hides the unlucky ones in the tail: a user waiting 10 seconds disappears in it among a thousand fast responses.

Four load trials

You read the signals during load tests, from the lightest to the heaviest:

• smoke test - minimal load, checks that the system works at all,
• load test - the expected, typical traffic,
• stress test - load above the expected level, looking for the breaking point,
• spike test - a sudden, short and huge jump in traffic.

That is how the k6 tool documentation divides them; you will meet the actual request firing in the profiling lesson.

Profiling - diagnosing problems

Inside the application time is measured by the Node.js perf_hooks module: performance.mark() puts a mark on the timeline, performance.measure() computes the gap between two marks, and PerformanceObserver receives every new measurement. We build a profiling service on top of it:

1// performance-profiler.service.ts
2import { Injectable } from '@nestjs/common';
3import { performance, PerformanceObserver } from 'node:perf_hooks';
4
5@Injectable()
6export class PerformanceProfilerService {
7  private measurements = new Map<string, number[]>();
8  private observer: PerformanceObserver;
9
10  constructor() {
11    this.setupPerformanceObserver();
12  }
13
14  private setupPerformanceObserver(): void {
15    this.observer = new PerformanceObserver((list) => {
16      list.getEntries().forEach((entry) => {
17        if (entry.entryType === 'measure') {
18          this.recordMeasurement(entry.name, entry.duration);
19        }
20      });
21    });
22
23    this.observer.observe({ entryTypes: ['measure'] });
24  }
25
26  private recordMeasurement(name: string, duration: number): void {
27    if (!this.measurements.has(name)) {
28      this.measurements.set(name, []);
29    }
30
31    const measurements = this.measurements.get(name)!;
32    measurements.push(duration);
33
34    // Keep only the last 100 measurements
35    if (measurements.length > 100) {
36      measurements.shift();
37    }
38
39    // Log slow operations
40    if (duration > 1000) {
41      console.warn(`Slow operation: ${name} - ${duration.toFixed(2)}ms`);
42    }
43  }

The observer passes measurements to recordMeasurement(), which keeps the last 100 results of each operation and warns about those longer than a second.

The most convenient way to measure is a decorator - a static method that wraps the original method with a measurement:

1  // Decorator measuring execution time
2  static Measure(operationName?: string) {
3    return function (target: any, propertyName: string, descriptor: PropertyDescriptor) {
4      const originalMethod = descriptor.value;
5      const measureName = operationName || `${target.constructor.name}.${propertyName}`;
6      let callId = 0;
7
8      descriptor.value = async function (...args: any[]) {
9        const id = ++callId; // separate marks for concurrent calls
10        const startMark = `${measureName}-start-${id}`;
11        const endMark = `${measureName}-end-${id}`;
12
13        performance.mark(startMark);
14
15        try {
16          const result = await originalMethod.apply(this, args);
17          performance.mark(endMark);
18          performance.measure(measureName, startMark, endMark);
19          return result;
20        } catch (error) {
21          performance.mark(endMark);
22          performance.measure(`${measureName}-error`, startMark, endMark);
23          throw error;
24        } finally {
25          // Marks stay in the global timeline until we remove them
26          performance.clearMarks(startMark);
27          performance.clearMarks(endMark);
28          performance.clearMeasures(measureName);
29          performance.clearMeasures(`${measureName}-error`);
30        }
31      };
32    };
33  }

The first version built mark names from Date.now(), so two calls in the same millisecond overwrote each other's marks; the callId counter fixes that. The finally block cleans up, because marks without clearMarks() would pile up in a server running for weeks like a memory leak. The observer has already received the measurement, so nothing is lost.

A manual measurement is handy when you time only part of a method:

1  startMeasurement(name: string): void {
2    performance.mark(`${name}-start`);
3  }
4
5  endMeasurement(name: string): number {
6    const endMark = `${name}-end`;
7    performance.mark(endMark);
8    // measure() returns the fresh measurement - no searching the history
9    const measurement = performance.measure(name, `${name}-start`, endMark);
10
11    performance.clearMarks(`${name}-start`);
12    performance.clearMarks(endMark);
13    performance.clearMeasures(name);
14    return measurement.duration;
15  }

Before, the service looked the measurement up with getEntriesByName(name)[0], which returns the oldest measurement with that name - from the second call on the result was the same every time.

From the collected numbers we compute statistics:

1  getStatistics(operationName: string) {
2    const measurements = this.measurements.get(operationName) || [];
3    if (measurements.length === 0) return null;
4
5    const sorted = [...measurements].sort((a, b) => a - b);
6    const avg = measurements.reduce((a, b) => a + b, 0) / measurements.length;
7
8    return {
9      count: measurements.length,
10      average: avg.toFixed(2),
11      median: sorted[Math.floor(sorted.length / 2)].toFixed(2),
12      min: sorted[0].toFixed(2),
13      max: sorted[sorted.length - 1].toFixed(2),
14      p95: sorted[Math.ceil(sorted.length * 0.95) - 1].toFixed(2),
15    };
16  }
17
18  getAllStatistics() {
19    const stats = {};
20    this.measurements.forEach((_, name) => {
21      stats[name] = this.getStatistics(name);
22    });
23    return stats;
24  }
25}

We compute p95 with the nearest-rank method: with 100 measurements it is the 95th result after sorting.

In a service the decorator sits above a method, and the manual measurement surrounds the chosen fragment:

1// Usage in a service
2@Injectable()
3export class TributeService {
4  constructor(private profiler: PerformanceProfilerService) {}
5
6  @PerformanceProfilerService.Measure('tribute-search')
7  async findTributes(criteria: any) {
8    // Complex tribute search
9    await this.complexDatabaseQuery(criteria);
10    return [];
11  }
12
13  async manualMeasurement() {
14    this.profiler.startMeasurement('manual-operation');
15
16    // Some operation
17    await this.doSomething();
18
19    const duration = this.profiler.endMeasurement('manual-operation');
20    console.log(`Operation took: ${duration}ms`);
21  }
22
23  private async complexDatabaseQuery(criteria: any) {
24    await new Promise((r) => setTimeout(r, 20)); // query stub
25  }
26
27  private async doSomething() {
28    await new Promise((r) => setTimeout(r, 30)); // work stub
29  }
30}

The decorator does not change the body of findTributes - the method still only searches, and the measurement happens alongside.

Database Query Optimization

The most common culprit is the database. The classic N+1 problem looks innocent:

1// query-optimizer.service.ts
2@Injectable()
3export class QueryOptimizerService {
4  constructor(
5    @InjectRepository(Tribute) private tributeRepo: Repository<Tribute>,
6  ) {}
7
8  // Instead of N+1 queries
9  async getBadTributesWithOwners(): Promise<any[]> {
10    const tributes = await this.tributeRepo.find();
11
12    // This generates N extra queries!
13    const tributesWithOwners = [];
14    for (const tribute of tributes) {
15      const owner = await this.getOwner(tribute.ownerId);
16      tributesWithOwners.push({ ...tribute, owner });
17    }
18
19    return tributesWithOwners;
20  }

One query for the list and one more for every owner: in a test on PostgreSQL, 120 tributes cost 121 queries.

The solution is a JOIN, which TypeORM builds from the relations option:

1  // Optimal version with a JOIN
2  async getOptimizedTributesWithOwners(): Promise<any[]> {
3    // One query with a JOIN
4    return await this.tributeRepo.find({
5      relations: { owner: true },
6      select: {
7        id: true,
8        name: true,
9        value: true,
10        owner: {
11          id: true,
12          name: true,
13          rank: true,
14        },
15      },
16    });
17  }

The same result came back in one query, and select fetched only the columns we need. TypeORM 1.x removed the array syntax relations: ['owner'] - the object form is now required.

We process large sets in batches instead of loading everything into memory:

1  // Batch processing for large sets
2  async processTributesInBatches(batchSize: number = 100): Promise<void> {
3    let offset = 0;
4    let batch;
5
6    do {
7      batch = await this.tributeRepo.find({
8        skip: offset,
9        take: batchSize,
10        order: { id: 'ASC' },
11      });
12
13      if (batch.length > 0) {
14        await this.processTributeBatch(batch);
15        offset += batchSize;
16
17        // Briefly hand the event loop over to other requests
18        await this.delay(10);
19      }
20    } while (batch.length === batchSize);
21  }

The pause hands the event loop over to other requests; the first version claimed it "gives the garbage collector time", but GC runs whenever it decides to. skip grows with every batch, and the database still walks through the skipped rows, so with millions of records a cursor is better:

1  // Cursor pagination for very large sets
2  async getTributesWithCursor(cursor?: number, limit: number = 50) {
3    const qb = this.tributeRepo.createQueryBuilder('tribute');
4
5    if (cursor) {
6      qb.where('tribute.id > :cursor', { cursor });
7    }
8
9    const tributes = await qb
10      .orderBy('tribute.id', 'ASC')
11      .limit(limit + 1) // +1 to check whether there are more
12      .getMany();
13
14    const hasNext = tributes.length > limit;
15    const items = hasNext ? tributes.slice(0, -1) : tributes;
16    const nextCursor = hasNext ? tributes[tributes.length - 2].id : null;
17
18    return {
19      items,
20      nextCursor,
21      hasNext,
22    };
23  }

The cursor is the id of the last returned row, and WHERE id > :cursor uses the primary key index, so the hundredth page is as fast as the first. One extra row tells you whether a next page exists, without a separate COUNT.

Filters also decide the speed:

1  // Optimization with indexes
2  async searchTributesOptimized(filters: any) {
3    const qb = this.tributeRepo.createQueryBuilder('tribute');
4
5    // Use indexed columns in WHERE
6    if (filters.type) {
7      qb.andWhere('tribute.type = :type', { type: filters.type });
8    }
9
10    if (filters.minValue) {
11      qb.andWhere('tribute.value >= :minValue', { minValue: filters.minValue });
12    }
13
14    // Use the index on created_at
15    if (filters.dateRange) {
16      qb.andWhere('tribute.createdAt BETWEEN :start AND :end', {
17        start: filters.dateRange.start,
18        end: filters.dateRange.end,
19      });
20    }
21
22    return await qb
23      .orderBy('tribute.value', 'DESC') // Index on value
24      .limit(filters.limit || 100)
25      .getMany();
26  }
27
28  private async delay(ms: number): Promise<void> {
29    return new Promise(resolve => setTimeout(resolve, ms));
30  }
31
32  private async processTributeBatch(tributes: Tribute[]): Promise<void> {
33    // Processing a batch
34    console.log(`Processing ${tributes.length} tributes...`);
35  }
36}

Conditions on indexed columns let the database jump straight to the right rows. limit() is safe here because the query has no JOINs; with them use take().

Layers of speed

The fastest request is the one that never reaches the fort. From the layer closest to the user:

• browser cache - controlled by Cache-Control headers,
• CDN, that is edge cache - copies of content on servers close to users, which shortens the route and the latency,
• application cache - Redis from the previous lessons,
• query cache on the database side.

I recommend one order of work: measure, fix the biggest problem, measure again - without the second measurement you do not know whether you helped. In the next lessons we will deal with indexes, spreading traffic and memory.

Remember: a fast cohort does not run faster, it simply carries no dead weight - weigh it first, then drop it.

1// Performance Optimization - Increasing the Cohort's Speed
2import { Injectable, NestInterceptor, ExecutionContext, CallHandler } from '@nestjs/common';
3import { Observable } from 'rxjs';
4import { tap } from 'rxjs/operators';
5
6// 1. Interceptor measuring response time
7@Injectable()
8export class PerformanceInterceptor implements NestInterceptor {
9  intercept(context: ExecutionContext, next: CallHandler): Observable<any> {
10    const start = Date.now();
11    const req = context.switchToHttp().getRequest();
12
13    return next.handle().pipe(
14      tap(() => {
15        const duration = Date.now() - start;
16        const method = req.method;
17        const url = req.url;
18        console.log(`[${method}] ${url} - ${duration}ms`);
19
20        if (duration > 1000) {
21          console.warn(`SLOW REQUEST: ${url} took ${duration}ms`);
22        }
23      }),
24    );
25  }
26}
27
28// 2. Lazy loading of modules
29// @Module({
30//   imports: [
31//     LazyModuleLoader, // NestJS lazy loading
32//   ],
33// })
34// class AppModule {}
35//
36// // In the service:
37// const { ProvinceModule } = await import('./province.module');
38// const moduleRef = await this.lazyModuleLoader.load(
39//   () => ProvinceModule
40// );
41// const service = moduleRef.get(ProvinceService);
42
43// 3. Pagination - don't load everything at once
44@Injectable()
45class PaginationService {
46  async findPaginated<T>(
47    query: any,
48    page: number = 1,
49    limit: number = 20
50  ): Promise<{
51    data: T[];
52    total: number;
53    page: number;
54    lastPage: number;
55  }> {
56    const skip = (page - 1) * limit;
57    // const [data, total] = await repo.findAndCount({
58    //   skip, take: limit,
59    //   order: { createdAt: 'DESC' },
60    // });
61
62    const total = 100; // simulation
63    const data = [] as T[];
64
65    return {
66      data,
67      total,
68      page,
69      lastPage: Math.ceil(total / limit),
70    };
71  }
72}
73
74// 4. Connection pooling
75const databaseConfig = {
76  type: 'postgres',
77  host: 'localhost',
78  port: 5432,
79  // Pool configuration
80  extra: {
81    max: 20,        // Max connections in the pool
82    min: 5,         // Min connections
83    idle: 10000,    // Idle timeout (ms)
84    acquire: 30000, // Connection acquisition timeout
85  },
86};
87
88// 5. Response compression
89// import * as compression from 'compression';
90// app.use(compression());
91// Reduces response size by 60-80%!
92