Performance Logging

Finding bottlenecks in logs

The request-response log from Section 3 includes the total duration. But a slow request (300ms) could be slow because of a database query, an external API call, a cache miss, or a combination. Performance logging breaks down the duration into components.

Timing database queries

Wrap database calls with timing:

// src/shared/queries.ts
export function getAllBooks(db: Database.Database, log?: Logger): BookRow[] {
  const start = performance.now();
  const books = db.prepare("SELECT ...").all() as BookRow[];
  const duration = Math.round(performance.now() - start);

  if (log) {
    log.debug("query executed", {
      query: "getAllBooks",
      rows: books.length,
      duration,
    });

    if (duration > 50) {
      log.warn("slow query", { query: "getAllBooks", duration, threshold: 50 });
    }
  }

  return books;
}

Normal queries log at debug (hidden in production). Slow queries log at warn (always visible).

A timing helper

// src/shared/timing.ts
export function timed<T>(label: string, fn: () => T, log: Logger, warnThreshold: number = 100): T {
  const start = performance.now();
  const result = fn();
  const duration = Math.round(performance.now() - start);

  log.debug("operation completed", { operation: label, duration });

  if (duration > warnThreshold) {
    log.warn("slow operation", { operation: label, duration, threshold: warnThreshold });
  }

  return result;
}

// Async version
export async function timedAsync<T>(
  label: string,
  fn: () => Promise<T>,
  log: Logger,
  warnThreshold: number = 100,
): Promise<T> {
  const start = performance.now();
  const result = await fn();
  const duration = Math.round(performance.now() - start);

  log.debug("async operation completed", { operation: label, duration });

  if (duration > warnThreshold) {
    log.warn("slow async operation", { operation: label, duration, threshold: warnThreshold });
  }

  return result;
}

// Usage
const books = timed("getAllBooks", () => getAllBooks(db), c.locals.log, 50);
const payment = await timedAsync("chargeCard", () => chargeCard(amount, token), c.locals.log, 2000);

Logging cache performance

function getCachedBooks(genre: string, log: Logger): BookRow[] {
  const cacheKey = `books:${genre}`;
  const cached = cache.get(cacheKey);

  if (cached) {
    log.debug("cache hit", { key: cacheKey });
    return cached;
  }

  log.debug("cache miss", { key: cacheKey });
  const books = getAllBooks(db);
  cache.set(cacheKey, books, 300); // 5 minute TTL
  return books;
}

[!NOTE] The Caching course built cache-aside patterns with TTL. Performance logging adds visibility: how often does the cache hit? How often does it miss? Is the TTL too short (frequent misses) or too long (stale data)?

Logging external API calls

async function callGoodreadsApi(isbn: string, log: Logger) {
  const start = performance.now();

  try {
    const response = await fetch(`https://api.goodreads.com/book/${isbn}`);
    const duration = Math.round(performance.now() - start);

    log.info("external api call", {
      service: "goodreads",
      endpoint: `/book/${isbn}`,
      status: response.status,
      duration,
    });

    return response.json();
  } catch (err) {
    const duration = Math.round(performance.now() - start);

    log.error("external api call failed", {
      service: "goodreads",
      endpoint: `/book/${isbn}`,
      error: err instanceof Error ? err.message : String(err),
      duration,
    });

    throw err;
  }
}

External calls are the most common performance bottleneck. Logging their duration and status makes slowdowns visible immediately.

Exercises

Exercise 1: Add timing to a database query. Log at debug for normal, warn for slow. Verify the threshold works.

Exercise 2: Build the timed and timedAsync helpers. Use them to time three operations in a route handler.

Exercise 3: Log cache hits and misses. Make 10 requests. Count hits vs misses in the logs.

Why log slow operations at 'warn' level instead of 'info'?