Module 12 — Production Observability, Performance Profiling & Flame Graphs
What this module covers: A blockchain indexer at 50,000 events/second produces hundreds of thousands of function calls per second. When performance degrades, the cause is buried in microseconds — one function accounting for 40% of CPU, one allocation pattern triggering GC every 200ms, one async chain adding 15ms of hidden latency per request. Structured logs, Prometheus metrics, and distributed traces tell you that something is wrong. V8 CPU profiles, flame graphs, and the clinic.js toolchain tell you exactly where and why. This module covers the complete production diagnostic stack for Node.js systems under high-throughput stress.
The Three Pillars: Logs, Metrics, Traces
Every production Node.js service needs all three. They answer different questions:
Logs: what happened? (event-level detail)
Metrics: how is the system behaving over time? (aggregate measurements)
Traces: how does a single request flow through the system? (distributed causality)
Pino: The Fastest Structured Logger
javascript
Why Pino over Winston at high throughput: Pino's speed has nothing to do with offloading serialization to a worker thread — every logger.info() call still serializes synchronously on the main thread, same as Winston. The difference is how it serializes: Pino precompiles a serialization function per log shape ahead of time and writes the JSON string directly, avoiding the generic, reflection-heavy JSON.stringify() path that Winston goes through on every call. What genuinely can move off the main thread is the transport — the step that takes an already-serialized line and does something with it (pretty-printing via pino-pretty, writing to a file, shipping to a log aggregator over the network). pino.transport() runs that in a worker_threads worker so a slow write never blocks the event loop, but the log-line serialization itself is synchronous by design, not deferred. At 50K events/second where each event emits 2–3 log entries — 100K log statements/sec — that synchronous-serialization gap between Pino's precompiled path and Winston's JSON.stringify() path is what compounds into a measurable CPU difference at scale.
Prometheus Metrics with prom-client
javascript
Key metrics for a blockchain indexer:
Metric
Type
Alert Condition
nodejs_event_loop_utilization
Gauge
> 0.85
nodejs_gc_duration_seconds (P99)
Histogram
> 50ms
transactions_ingested_total rate
Counter
Drop > 20%
transaction_processing_duration_seconds P99
Histogram
> 100ms
db_pool_utilization_ratio
Gauge
> 0.9
nodejs_heap_used_bytes
Gauge
> 80% of max
OpenTelemetry: Distributed Traces
javascript
With distributed tracing, a single block processing request shows its full latency breakdown across: HTTP receive → parse → signature verification (worker thread) → database write → Kafka publish. You can see exactly which step is slow without guessing.
Production story: Auto-instrumenting HTTP, pg, and Kafka via getNodeAutoInstrumentations() at 100% sampling looked harmless in staging. Turned on against the full 50K TPS ingestion pipeline, it overwhelmed the Jaeger collector within minutes — every single transaction was generating a full multi-span trace, and the collector wasn't sized to ingest that volume. The fix was tail-based sampling: buffer each trace briefly and only persist it if the request errored or exceeded 500ms. Fast, successful transactions — the overwhelming majority — are sampled out before they ever reach storage, while every failure and every slow outlier is kept. Sampling on the outcome (tail-based) instead of a fixed percentage decided up front (head-based) is what made tracing viable at this throughput.
Propagating Trace Context Across Kafka
Auto-instrumentation traces HTTP and database calls transparently, but Kafka breaks the chain by default — a message sitting in a topic carries no notion of "which trace is this part of." To get one trace spanning producer → topic → consumer, the trace context has to travel inside the message itself, via the W3C traceparent header.
javascript
With this in place, a single traceparent travels HTTP ingest span → Kafka publish span → (message header, across the wire) → Kafka consume span → database write span. Jaeger renders it as one continuous waterfall across two separate Node.js processes, instead of two disconnected traces that happen to touch the same topic.
Correlating Traces with Logs
The logging and tracing sections above are covered as separate tools, but in production you want to go from "this trace was slow" to "here are the exact log lines emitted during that span" without manually lining up timestamps. The bridge: read the active span's IDs and attach them to every log line.
javascript
traceId and spanId now show up as queryable fields alongside every other structured field from the Pino section above. Click a slow span in Jaeger, copy its traceId, and pull every log line emitted during that request with a single query — no timestamp guesswork.
Event Loop Utilization: The First Metric to Check
ELU was introduced in Module 2. In production, it is the first metric to check during a latency incident.
javascript
Generating V8 CPU Profiles
A CPU profile samples the call stack every N microseconds. The result: a list of functions and how many samples they appear in. Functions that appear in many samples are consuming CPU time.
Method 1: --cpu-prof Flag
bash
Method 2: V8 Profiler API
javascript
Reading Flame Graphs
A flame graph is an X-ray of your event loop — the widest bones are exactly where all the weight is sitting.
A flame graph visualizes CPU time as a stack of colored bars:
X axis: total CPU time (wider = more CPU)
Y axis: call stack depth (higher = deeper in the call chain)
Color: random, for visual distinction
Width of a bar: proportion of CPU time spent in that function and its callees
text
Reading rules:
Wide plateaus at the top are hot spots — functions that consume a large fraction of CPU
Narrow spikes are expected call depths — not performance problems
Look for width at the TOP of the stack — if JSON.parse is 35% wide at the top level, it's consuming 35% of total CPU
Actionable patterns:
text
The clinic.js Diagnostic Toolchain
clinic.js is the most comprehensive Node.js diagnostic suite. Three tools, each answering a different question.
clinic doctor: What Is Wrong?
bash
clinic doctor analyzes four signals:
Event loop delay — is the event loop lagging? (indicates blocking code)
CPU usage — is the process CPU-bound?
Memory — is memory growing continuously? (indicates leak)
Handles/requests — are there open handles preventing process exit? (indicates resource leak)
What the report tells you:
text
clinic flame: Where Is the CPU Going?
bash
clinic flame generates a proper flamegraph from --perf profiling data, with:
Merged V8 and native frames (you see both JS and C++ in one view)
Click-to-zoom for deep inspection
Filtering by function name
Interpreting clinic flame output for a transaction parser:
text
clinic bubbleprof: Where Is the Async Time Going?
bash
bubbleprof visualizes async operations as bubbles — the size of each bubble represents how long async operations took. It shows where time is spent waiting rather than executing.
Useful for diagnosing:
Database queries that are slower than expected
HTTP client calls with unexpected latency
Async chains that add unnecessary await depth
Always-On Production Profiling: Datadog Continuous Profiler & Pyroscope
--cpu-prof and clinic flame are one-off sessions: you start them deliberately, during a known incident or load test, then stop. They answer "what is this process doing right now?" They cannot answer "what was this process doing at 3am last Tuesday, five minutes before the alert fired?" — by the time you're looking, the moment is gone.
Always-on profilers close that gap by sampling CPU (and often heap) continuously in production, at low enough overhead to leave running permanently, and retaining the samples the same way you retain metrics — queryable by service, by tag, by time range.
javascript
Grafana Pyroscope follows the same model with an open-source agent and storage backend, if you'd rather not depend on a vendor.
One-off (clinic, --cpu-prof)
Always-on (Datadog, Pyroscope)
When it runs
Only when you start it
Continuously, in production
Overhead
Higher, but bounded to the session
Low (typically 1–5% CPU), but permanent
Historical incidents
Can't retroactively profile the past
Flame graph available for any point in the retention window
Best for
Deep investigation of a reproducible hot path
Catching the regression you didn't know to look for yet
In practice these are complementary, not competing: continuous profiling tells you when and roughly where a regression started ("CPU time in parseTransaction doubled the moment deploy X went out"), and a targeted clinic flame session gets you the rest of the way to the exact line.
Heap Snapshots: Finding Memory Leaks
When clinic doctor shows continuously growing memory, take a heap snapshot:
javascript
bash
Common memory leak patterns in Node.js:
javascript
auto_explain for Node.js: async_hooks + Performance Timing
The equivalent of PostgreSQL's auto_explain for Node.js: automatically log slow async operations above a threshold.
javascript
Caveat:async_hooks is not free to run. Every async resource creation and teardown fires an init/destroy callback, and at 50K events/second with several async resources per transaction (socket reads, timers, DB queries), that adds up to real per-operation overhead — async_hooks has a well-documented history of measurably regressing the exact event loop it's meant to be monitoring, particularly under heavy async churn. Treat this as a tool you enable for a bounded window during a targeted debugging session — behind a flag, or toggled via a signal handler — rather than as always-on production instrumentation.
The Production Incident: Undetected Memory Leak via Event Listener
Context: A blockchain indexer WebSocket subscription service. Engineers received an alert: process memory at 94% of limit after 6 hours of operation. Restart fixed it temporarily.
183,000 EventEmitter instances — one per WebSocket subscriber (12,000 subscribers × ~15 listeners each = 180,000 accumulated listener objects that were never cleaned up).
The broken code:
javascript
The fix:
javascript
After the fix: memory stabilized at 220MB regardless of subscriber count or runtime duration.
Summary
Concept
Key Takeaway
Pino
5x faster than Winston. Structured JSON logging. Use child loggers for request context.
Prometheus + prom-client
Counter/Histogram/Gauge. Export /metrics. Alert on ELU, GC duration, pool utilization.
OpenTelemetry
Auto-instruments HTTP, pg, Kafka. Use startSpan for custom instrumentation.
ELU gauge
First metric to check during latency incident. > 0.85 = investigate CPU hotspot.
--cpu-prof
Generate V8 CPU profile. Open in Chrome DevTools. Identify hot functions.
Flame graph
X axis = CPU time. Wide plateau at top = hot spot. Narrow spike = expected depth.
clinic doctor
Diagnoses event loop delay, memory leaks, CPU saturation. First tool in the diagnostic workflow.
clinic flame
CPU flamegraph with V8 + native frames. Identifies exact function consuming CPU.
clinic bubbleprof
Async operation visualization. Shows where time is waiting vs executing.
Heap snapshots
Two snapshots + comparison view = pinpoint leaked object type. kill -SIGUSR2 to trigger.
EventEmitter leak
Always off() listeners when the subscriber closes. Most common Node.js memory leak.
You can now diagnose performance problems with precision. Module 13 covers the connection layer — the pool configurations and process management patterns that determine how many requests your service can actually handle concurrently.
When analyzing a flame graph generated from a Node.js CPU profile, what does a "wide plateau" at the top of a stack represent?
Which diagnostic tool from the clinic.js toolchain is best suited for visualizing where an application is spending time *waiting* for asynchronous operations (like database queries or HTTP calls) rather than executing CPU instructions?
What is identified as one of the most common causes of memory leaks in Node.js applications?
Test your knowledge with more question sets
Sign in to access a wider variety of questions and get notified when new practice sets are added to this module.
importpinofrom'pino';const logger =pino({level: process.env.LOG_LEVEL??'info',// Serialize in JSON for log aggregators (Datadog, Splunk, CloudWatch)// pino is 5x faster than Winston, 8x faster than console.logtransport: process.env.NODE_ENV==='development'?{target:'pino-pretty'}// human-readable in dev:undefined,// raw JSON in production});// Structured logging — queryable fields, not string concatenationlogger.info({event:'transaction_ingested',transactionHash: tx.hash.toString('hex'),blockHeight: tx.blockHeight,sender: tx.sender,amount: tx.amount.toString(),processingMs:Date.now()- startTime,},'Transaction ingested successfully');// Child loggers for request-scoped contextexportfunctioncreateRequestLogger(requestId: string){return logger.child({ requestId });// all logs include requestId}
import{Counter,Histogram,Gauge, register }from'prom-client';import{ collectDefaultMetrics }from'prom-client';// Collect Node.js runtime metrics (GC, heap, event loop)collectDefaultMetrics({prefix:'nodejs_'});// Custom application metricsconst transactionCounter =newCounter({name:'transactions_ingested_total',help:'Total transactions ingested',labelNames:['status','network'],});const processingDuration =newHistogram({name:'transaction_processing_duration_seconds',help:'Time to process a single transaction',buckets:[0.001,0.005,0.01,0.025,0.05,0.1,0.25,0.5,1],labelNames:['network'],});const dbPoolUtilization =newGauge({name:'db_pool_utilization_ratio',help:'Database connection pool utilization (0-1)',});// Instrument the hot pathasyncfunctionprocessTransaction(tx){const end = processingDuration.startTimer({network: tx.network});try{awaitwriteToDatabase(tx); transactionCounter.inc({status:'success',network: tx.network});}catch(err){ transactionCounter.inc({status:'error',network: tx.network});throw err;}finally{end();// records duration in histogram}}// Expose metrics endpoint for Prometheus scrapingfastify.get('/metrics',async(req, reply)=>{ reply.header('Content-Type', register.contentType);return register.metrics();});
import{NodeSDK}from'@opentelemetry/sdk-node';import{OTLPTraceExporter}from'@opentelemetry/exporter-trace-otlp-grpc';import{ getNodeAutoInstrumentations }from'@opentelemetry/auto-instrumentations-node';const sdk =newNodeSDK({traceExporter:newOTLPTraceExporter({url:'http://jaeger:4317',}),instrumentations:[getNodeAutoInstrumentations()],// auto-instruments http, pg, kafka});sdk.start();// Manual span for custom instrumentationimport{ context, trace,SpanStatusCode}from'@opentelemetry/api';const tracer = trace.getTracer('blockchain-indexer');asyncfunctionprocessBlock(block){const span = tracer.startSpan('process_block',{attributes:{'block.height': block.height,'block.txCount': block.transactions.length}});try{// There is no `parent` option on SpanOptions in the stable @opentelemetry/api.// Parent-child linkage comes from running the child span's creation inside// the parent's context — context.with(trace.setSpan(...)) — not from a config field.await context.with(trace.setSpan(context.active(), span),async()=>{for(const tx of block.transactions){const txSpan = tracer.startSpan('process_transaction');await context.with(trace.setSpan(context.active(), txSpan),async()=>{awaitprocessTransaction(tx);}); txSpan.end();}}); span.setStatus({code:SpanStatusCode.OK});}catch(err){ span.recordException(err); span.setStatus({code:SpanStatusCode.ERROR});throw err;}finally{ span.end();}}
import{ propagation, context, trace }from'@opentelemetry/api';// Producer: inject the active trace context into Kafka message headersasyncfunctionpublishTransaction(tx){const span = tracer.startSpan('kafka_publish_transaction');const headers ={}; context.with(trace.setSpan(context.active(), span),()=>{// Writes a `traceparent` header (00-<trace-id>-<span-id>-01) into the carrier propagation.inject(context.active(), headers);});await producer.send({topic:'blockchain-transactions',messages:[{value:JSON.stringify(tx), headers }],}); span.end();}// Consumer: extract the trace context and continue the SAME traceasyncfunctionconsumeTransaction(kafkaMessage){const carrier =Object.fromEntries(Object.entries(kafkaMessage.headers??{}).map(([k, v])=>[k, v.toString()]));const extractedContext = propagation.extract(context.active(), carrier);await context.with(extractedContext,async()=>{const span = tracer.startSpan('kafka_consume_transaction');await context.with(trace.setSpan(context.active(), span),async()=>{awaitprocessTransaction(JSON.parse(kafkaMessage.value.toString()));}); span.end();});}
import{ eventLoopUtilization }from'node:perf_hooks';import{Gauge}from'prom-client';const eluGauge =newGauge({name:'nodejs_event_loop_utilization',help:'Event loop utilization ratio (0-1)',});let previousELU =eventLoopUtilization();setInterval(()=>{const elu =eventLoopUtilization(previousELU); eluGauge.set(elu.utilization); previousELU =eventLoopUtilization();if(elu.utilization>0.90){ logger.warn({elu: elu.utilization},'Event loop saturated — investigate CPU hotspot');}},1_000);
# Generate a CPU profile for 30 seconds of loadnode --cpu-prof --cpu-prof-interval=100 your-indexer.js &PID=$!# Apply loadautocannon -c100-d30 http://localhost:3000/api/v2/payments
# Send SIGINT to stop profilingkill-SIGINT$PID# Profile file: isolate-XXXXX-XXXXX-v8.cpuprofile# Open in Chrome DevTools: chrome://inspect → Open dedicated DevTools
importv8Profilerfrom'v8-profiler-next';// Profile a specific workloadasyncfunctionprofileCriticalPath(){ v8Profiler.startProfiling('ingestion-hot-path',true);// Run the workload you want to profilefor(let i =0; i <100_000; i++){awaitprocessTransaction(generateTestTransaction());}const profile = v8Profiler.stopProfiling('ingestion-hot-path'); profile.export((err, result)=>{require('fs').writeFileSync('profile.cpuprofile', result); profile.delete();});}
The anatomy of a flame graph:
│ ←────────────────────────────────────────────────────────────→ 100% CPU time
│ ┌───────────────────────────────────────────────────────────┐
│ │ processBlock (top of stack) │
│ ├────────────────────────────────┬──────────────────────────┤
│ │ parseTransactions (60%) │ validateSignatures (40%) │
│ ├───────────────┬────────────────┤ ┌────────────────────┐ │
│ │ JSON.parse │ normalizeField │ │ crypto.verify │ │
│ │ (35%) │ (25%) │ │ (40%) │ │
│ └───────────────┴────────────────┘ └────────────────────┘ │
PROBLEM: Deep stack with wide base in JSON.parse
└── processBlock
└── parsePayload
└── JSON.parse ←── 40% of CPU
FIX: Move to worker thread or use streaming JSON parser
PROBLEM: GC taking significant width
└── (GC) Scavenge ←── 15% of CPU
FIX: Reduce allocation rate, increase --max-semi-space-size
PROBLEM: Crypto operation dominating
└── processTransaction
└── verifySignature
└── crypto.createVerify ←── 35% of CPU
FIX: Already in thread pool? If not, move to worker_threads
npminstall-g clinic
# Run your server under clinic doctorclinic doctor -- node your-indexer.js &SERVER_PID=$!# Apply representative loadautocannon -c100-d30 http://localhost:3000/api/v2/payments
# Stop and analyzekill$SERVER_PID# Opens interactive HTML report in browser
Issue detected: Event loop delay is high (avg 45ms)
Possible cause: Heavy synchronous computation
Recommendation: Use worker_threads for CPU-intensive operations
Or consider async alternatives
Issue detected: Heap usage growing without GC collection
Possible cause: Memory leak (event listeners, closures retaining references)
Recommendation: Take heap snapshot and analyze retained object graph
Before optimization (clinic flame shows):
processBlock (100%)
└── parseTransaction (72%)
└── JSON.parse (72%) ←── 72% of CPU in JSON.parse!
└── writeToDatabase (28%)
After moving JSON.parse to worker_threads:
processBlock (100%)
└── parseTransaction (12%) ←── down from 72%!
└── Buffer.toString (12%) ←── just converting to string for worker
└── writeToDatabase (48%)
└── worker coordination (40%)
// Trigger heap snapshot on demand (safe in production for 1–2 seconds)importv8from'v8';importfsfrom'fs';process.on('SIGUSR2',()=>{const timestamp =newDate().toISOString().replace(/:/g,'-');const filename =`heap-${timestamp}.heapsnapshot`;const stream = v8.writeHeapSnapshot(filename); logger.info({ filename },'Heap snapshot written');});// Trigger: kill -SIGUSR2 $(pgrep -f your-indexer)
# Take two snapshots 5 minutes apartkill-SIGUSR2$PID# snapshot 1sleep300kill-SIGUSR2$PID# snapshot 2# Open Chrome DevTools → Memory tab → Load both snapshots# Use "Comparison" view to see what objects grew between snapshots
// LEAK 1: EventEmitter listener accumulationclassTransactionProcessorextendsEventEmitter{processBlock(block){ block.transactions.forEach(tx=>{this.on('validate',()=> tx.validate());// ← listener added per transaction// Never removed! Listener count grows with each transaction});}}// FIX: use this.once() or explicitly removeListener()// LEAK 2: Closure retaining large objectsfunctioncreateHandler(largeBuffer){returnfunctionhandler(req){// largeBuffer is in scope → never GC'd while handler existsreturnprocess(req, largeBuffer);};}// FIX: pass largeBuffer as parameter, don't close over it// LEAK 3: Map/Set growing without boundconst requestCache =newMap();app.get('/api/payment/:id',(req, res)=>{ requestCache.set(req.params.id, req);// ← never evicted!// ...});// FIX: use LRU cache with bounded size, or TTL
Object type Count (snapshot 1) Count (snapshot 2) Delta
EventEmitter 42 183,492 +183,450
Function 8,240 1,240,830 +1,232,590
// WebSocket subscription handlerwsServer.on('connection',(ws)=>{// Register listener on shared blockEventBus for this subscriber blockEventBus.on('new-block',(block)=>{ ws.send(JSON.stringify(block));// ← closure captures 'ws'}); ws.on('close',()=>{// ← listener NEVER REMOVED from blockEventBus// ws is closed but the listener still exists// blockEventBus still holds reference to the listener// which holds reference to 'ws'// Memory leak: closed WebSocket + listener permanently retained});});
wsServer.on('connection',(ws)=>{consthandler=(block)=>{if(ws.readyState===WebSocket.OPEN){ ws.send(JSON.stringify(block));}}; blockEventBus.on('new-block', handler); ws.on('close',()=>{ blockEventBus.off('new-block', handler);// ← explicitly remove listener// handler (and its closure over 'ws') can now be GC'd});});