Node.js Performance Profiling — Finding Bottlenecks With Clinic.js and Flame Graphs

// Install clinic
// npm install -g clinic

// Profile your app (simulates production-like load)
// clinic doctor -- node app.js

// Clinic Doctor output shows:
// - CPU bottlenecks (red: overloaded)
// - Memory issues (growing heap)
// - I/O latency (event loop delays)
// - Async queue buildup

// Example slow application
import express from 'express';

const app = express();

// Problem 1: Synchronous blocking work on event loop
app.get('/slow-cpu', (req, res) => {
  let sum = 0;
  for (let i = 0; i < 1_000_000_000; i++) {
    sum += Math.sqrt(i);
  }
  res.json({ result: sum });
});

// Problem 2: Memory leak (unbounded cache)
const cache = new Map();

app.get('/memory-leak', (req, res) => {
  const data = Buffer.alloc(1024 * 1024); // 1MB per request
  cache.set(Date.now(), data); // Never evicted!
  res.json({ cached: cache.size });
});

// Problem 3: Slow database queries
app.get('/slow-db', async (req, res) => {
  // N+1 problem: fetches user, then all posts individually
  const users = await db.user.findMany();
  for (const user of users) {
    user.posts = await db.post.findMany({ where: { userId: user.id } });
  }
  res.json(users);
});

app.listen(3000);

# Run with clinic doctor
clinic doctor -- node app.js

# Then hit it with load:
# curl http://localhost:3000/slow-cpu &
# curl http://localhost:3000/memory-leak &
# curl http://localhost:3000/slow-db &

# Generates: clinic-xxxxx.html
# Shows: High CPU, growing memory, event loop stalls

// clinic flame -- node app.js
// Generates flame graph showing call stack distribution

// Flame graph interpretation:
// - X-axis: Cumulative time (width = how long this stack ran)
// - Y-axis: Call stack depth
// - Colors: Different functions (red often = hot, but arbitrary)
// - Wide bars at top = main CPU consumer

// Example: identifying the expensive operation
function expensiveComputation(n: number): number {
  let result = 0;

  // This loop is the "hot path"
  for (let i = 0; i < n; i++) {
    result += Math.sqrt(i) * Math.log(i);
  }

  return result;
}

app.get('/compute', (req, res) => {
  const n = parseInt(req.query.n as string) || 1000000;
  const result = expensiveComputation(n);
  res.json({ result });
});

// Flame graph would show:
// ├─ expensiveComputation [████████████████████] 85% CPU
// │ ├─ Math.sqrt [██████████] 50%
// │ └─ Math.log [██████] 35%
// └─ Other [███] 15%

// Optimization: Use tighter algorithm
function expensiveComputationOptimized(n: number): number {
  // Pre-compute sqrt lookup for repeated values
  const sqrtCache = new Map<number, number>();

  return Array.from({ length: n }, (_, i) => {
    const sqrtVal = sqrtCache.get(i) ?? Math.sqrt(i);
    if (!sqrtCache.has(i)) sqrtCache.set(i, sqrtVal);
    return sqrtVal * Math.log(i);
  }).reduce((a, b) => a + b, 0);
}

// clinic bubbleprof -- node app.js
// Shows where time is spent waiting (I/O, timers, etc)

// Common async bottleneck patterns

// Problem: Sequential I/O (requests wait for prior request)
async function sequentialFetch(urls: string[]) {
  const results = [];

  for (const url of urls) {
    const response = await fetch(url); // Wait for each sequentially
    results.push(await response.json());
  }

  return results;
}

// Better: Parallel I/O (all requests fire simultaneously)
async function parallelFetch(urls: string[]) {
  const promises = urls.map(url =>
    fetch(url).then(r => r.json())
  );

  return Promise.all(promises);
}

// BubbleProf shows:
// Sequential: Long timeline, narrow bubble (bottleneck)
// Parallel: Same wall-clock time, wide bubble (concurrency)

// Another pattern: Unnecessary await in loops
async function processUsersSequential(userIds: string[]) {
  for (const id of userIds) {
    const user = await fetchUser(id);
    console.log(user.name); // Serialized processing
  }
}

// Better: Batch process with concurrency limit
async function processUsersParallel(userIds: string[]) {
  const batchSize = 10;

  for (let i = 0; i < userIds.length; i += batchSize) {
    const batch = userIds.slice(i, i + batchSize);
    const users = await Promise.all(batch.map(fetchUser));
    users.forEach(u => console.log(u.name));
  }
}

// Example app that would produce interesting flame graph
import express from 'express';
import crypto from 'crypto';

const app = express();

app.get('/hash', (req, res) => {
  const iterations = parseInt(req.query.iterations as string) || 1000;
  const data = 'data-to-hash';
  let result = data;

  // Creates wide flame bar for loop
  for (let i = 0; i < iterations; i++) {
    result = crypto.createHash('sha256').update(result).digest('hex');
  }

  res.json({ result, iterations });
});

app.get('/sort', (req, res) => {
  const size = parseInt(req.query.size as string) || 100000;
  const arr = Array.from({ length: size }, () => Math.random());

  // Creates tall flame for recursive sort
  const sorted = arr.sort((a, b) => a - b);

  res.json({ length: sorted.length });
});

// To understand flame graph output:
// 1. Widest bar at top = function using most CPU
// 2. Click bars to zoom into specific call paths
// 3. Colors help distinguish functions (same function = same color across invocations)
// 4. Absence of a function = not significant CPU consumer (don't optimize)
// 5. Jagged tops = multiple competing functions
// 6. Smooth plateau = single bottleneck

// Flame graph interpretation tips:
// - Only optimize hot paths (wide bars)
// - Work backwards from wide bar to understand call chain
// - Context matters: 1% CPU in a hot loop = 100ms at 10K RPS
// - Profile under realistic load (low load profiles differently)

# Run with profiling
node --prof app.js

# This creates isolate-0xAAAABBBBCCCC-v8.log

# Process the log
node --prof-process isolate-0xAAAABBBBCCCC-v8.log > processed.txt

# Shows similar output to flame graphs
# Statistical sampling (low overhead ~1%)

// app.ts
function fibonacci(n: number): number {
  if (n <= 1) return n;
  return fibonacci(n - 1) + fibonacci(n - 2);
}

function efficientFibonacci(n: number): number {
  const memo = new Map<number, number>();

  function fib(n: number): number {
    if (memo.has(n)) return memo.get(n)!;
    if (n <= 1) return n;

    const result = fib(n - 1) + fib(n - 2);
    memo.set(n, result);
    return result;
  }

  return fib(n);
}

// Run with profiling
async function main() {
  console.time('fibonacci');
  const result = fibonacci(35); // Exponentially slow
  console.timeEnd('fibonacci');

  console.time('efficientFibonacci');
  const result2 = efficientFibonacci(35); // Linear
  console.timeEnd('efficientFibonacci');

  console.log('Results match:', result === result2);
}

main();

// Output:
// fibonacci: 8234.567ms
// efficientFibonacci: 0.234ms
// Results match: true

// Profile shows fibonacci consuming 99.9% of CPU

import { performance, PerformanceObserver } from 'perf_hooks';

// Mark start and end of operations
performance.mark('database-query-start');

const results = await db.query('SELECT * FROM large_table');

performance.mark('database-query-end');
performance.measure(
  'database-query',
  'database-query-start',
  'database-query-end'
);

// Get measured duration
const measure = performance.getEntriesByName('database-query')[0];
console.log(`Query took ${measure.duration}ms`);

// Production monitoring with PerformanceObserver
const observer = new PerformanceObserver(list => {
  for (const entry of list.getEntries()) {
    if (entry.duration > 100) { // Alert on slow operations
      console.warn(`Slow operation detected: ${entry.name} took ${entry.duration}ms`);

      // Send to monitoring system
      sendMetric({
        name: entry.name,
        duration: entry.duration,
        timestamp: Date.now(),
      });
    }
  }
});

observer.observe({ entryTypes: ['measure'] });

// Reusable timer utility
class Timer {
  private marks = new Map<string, number>();

  start(label: string): void {
    this.marks.set(label, performance.now());
  }

  end(label: string): number {
    const start = this.marks.get(label);
    if (!start) throw new Error(`Timer ${label} not started`);

    const duration = performance.now() - start;
    this.marks.delete(label);

    return duration;
  }

  async measure<T>(label: string, fn: () => Promise<T>): Promise<T> {
    this.start(label);
    try {
      return await fn();
    } finally {
      const duration = this.end(label);
      console.log(`${label}: ${duration.toFixed(2)}ms`);
    }
  }
}

// Usage
const timer = new Timer();

await timer.measure('fetch-data', async () => {
  return db.user.findMany();
});

// 1. Unbounded object growth
const cache = {}; // Grows without limit

app.get('/', (req, res) => {
  const key = req.query.key as string;
  if (!cache[key]) {
    cache[key] = expensiveComputation(key); // Memory leak!
  }
  res.json(cache[key]);
});

// Fix: Use LRU cache with max size
import LRU from 'lru-cache';
const cache = new LRU<string, any>({ max: 10000 });

// 2. Blocking event loop with sync work
app.get('/json', (req, res) => {
  const huge = { /* 100KB of data */ };
  res.json(huge); // Synchronous JSON.stringify blocks!
});

// Fix: Stream large responses
app.get('/json', (req, res) => {
  res.setHeader('Content-Type', 'application/json');
  const huge = { /* 100KB of data */ };
  res.write(JSON.stringify(huge));
  res.end();
});

// 3. Creating new functions in hot paths
app.get('/endpoint', (req, res) => {
  // New array allocation on EVERY request
  const headers = Object.keys(req.headers).map(k => k.toUpperCase());
  res.json(headers);
});

// Fix: Pre-allocate
const parseHeaders = (headers: any) => Object.keys(headers).map(k => k.toUpperCase());
app.get('/endpoint', (req, res) => {
  res.json(parseHeaders(req.headers));
});

// 4. Regex recompilation
app.get('/match', (req, res) => {
  const text = req.query.text as string;
  // Recompiles regex on every request!
  const match = text.match(/\d+/g);
  res.json(match);
});

// Fix: Pre-compile
const digitRegex = /\d+/g;
app.get('/match', (req, res) => {
  const text = req.query.text as string;
  const match = text.match(digitRegex);
  res.json(match);
});