Performance Profiling & Bottleneck Analysis Questions

Approach

For a Go service with intermittent CPU spikes, capture a CPU profile (periodic stack samples showing which function was running) and a heap profile (a snapshot of allocation call sites) during or immediately after a spike, then use go tool pprof to attribute the cost to a specific function and source line before proposing any fix. The commands below are self-contained and reproducible; the same go tool pprof analysis applies whether the .prof files came from this program or from a live production process.

package main

import (
	"fmt"
	"os"
	"runtime/pprof"
	"strings"
)

// buildReport is the suspected hotspot: it concatenates strings with +=,
// which reallocates and copies the whole buffer on every append, an O(n^2)
// pattern that gets worse as report size grows under load.
func buildReport(lines int) string {
	report := ""
	for i := 0; i < lines; i++ {
		report += fmt.Sprintf("line %d: request processed\n", i)
	}
	return report
}

// buildReportFast is the candidate fix: a pre-sized strings.Builder, O(n).
func buildReportFast(lines int) string {
	var b strings.Builder
	b.Grow(lines * 32)
	for i := 0; i < lines; i++ {
		fmt.Fprintf(&b, "line %d: request processed\n", i)
	}
	return b.String()
}

func main() {
	cpuFile, _ := os.Create("cpu.prof")
	defer cpuFile.Close()
	pprof.StartCPUProfile(cpuFile)

	var total int
	for i := 0; i < 400; i++ {
		total += len(buildReport(6000))
	}
	fmt.Println("processed bytes:", total)

	pprof.StopCPUProfile()

	memFile, _ := os.Create("mem.prof")
	defer memFile.Close()
	pprof.WriteHeapProfile(memFile)
	fmt.Println("wrote cpu.prof and mem.prof")
}

On a real production HTTP service you would not usually wrap one function like this; instead import net/http/pprof (it registers /debug/pprof/* handlers on the default mux) and pull profiles from the running process without a restart: go tool pprof http://host:6060/debug/pprof/profile?seconds=30 for CPU, go tool pprof http://host:6060/debug/pprof/heap for the heap. The overhead is limited to the sampling window you request. The analysis commands below are identical either way once you have the .prof file.

Running the program above and analyzing the result:

$ go run main.go
processed bytes: 69156000
wrote cpu.prof and mem.prof

$ go tool pprof -list='^main.buildReport$' cpu.prof
ROUTINE ======================== main.buildReport
         0      1.27s (flat, cum) 10.94% of Total
         .          .     report := ""
         .          .     for i := 0; i < lines; i++ {
         .      1.27s         report += fmt.Sprintf("line %d: request processed\n", i)
         .          .     }
         .          .     return report

$ go tool pprof -top -sample_index=alloc_space -nodecount=3 mem.prof
      flat  flat%   sum%        cum   cum%
  199.78GB 99.90% 99.90%   199.99GB   100%  main.buildReport

Key points

• -list=<function> gives line-level attribution: in the pprof output, flat is time spent in that line's own code and cum (cumulative) is flat plus everything it calls; here, 1.27s of cumulative time (10.94% of the whole run) sits on the single report += fmt.Sprintf(...) line, which shows 0 in the flat column since all the time is spent inside the called fmt.Sprintf, not the line itself. That is direct evidence, not a guess from reading the source.
• alloc_space in the heap profile is cumulative bytes ever allocated at that call site over the profile's lifetime, not live memory in use. 199.78GB does not mean the process used 200GB of RAM; it means this call site accounts for essentially all bytes ever allocated during the run, which is exactly what drives the GC-triggered CPU cost you'd see in a CPU profile too. Contrast this with inuse_space, which shows the live heap and is what you'd check for an actual leak.
• An unfiltered go tool pprof -top -cum on this same run is dominated by scheduler and GC frames like runtime.pthread_cond_wait, not main.buildReport, on a short, highly parallel run. That is a known pprof gotcha, not the real hotspot; filter with -focus='main\.' or go straight to -list on the function you already suspect instead of trusting the raw top view.
• A flame graph of this profile would show main.main -> main.buildReport -> runtime.concatstrings -> runtime.concatstring2 as a tall, wide tower, with width proportional to that 10.94% cumulative time (flame graphs are not time-ordered left to right, width means frequency of appearing in a sample).

Validating the fix

$ go test -bench=. -benchmem
BenchmarkBuildReport-14         28    41,038,103 ns/op   537,474,762 B/op   18,491 allocs/op
BenchmarkBuildReportFast-14   4465       295,609 ns/op       242,736 B/op    5,746 allocs/op

Switching to buildReportFast cut latency about 139x and allocations from roughly 18,500 to 5,700 per call in this benchmark; that is the kind of proportional (not exact) improvement you would expect to see reflected in the production CPU and latency graphs once redeployed and re-profiled under real traffic.

Edge cases and pitfalls

• Default Go CPU profiling samples at 100Hz and is safe to run continuously in most services, but confirm actual overhead on your own workload before leaving it always-on; don't assume a number without measuring it locally first.
• A stripped binary or one built without matching debug info will not resolve function names in pprof output; keep symbols available for whatever build you're profiling.
• A profile taken during a quiet period will not reproduce an intermittent spike; trigger the capture from the alert that fires during the spike, or run a long enough continuous low-rate profile that you have a real chance of catching it in the sample.

Framing

p95 latency (the response time below which 95% of requests complete) spiking alongside CPU saturation and I/O wait could mean the system is CPU-bound, I/O-bound, or stuck on thread contention, three different diagnoses with three different fixes. Work through the USE method (Utilization, Saturation, Errors, checked per resource) before touching code.

Step 1: Split CPU time by category

Use top, vmstat, or mpstat during the spike window and separate: %user + %sys (CPU actually computing) from %iowait (CPU sitting idle while waiting on outstanding disk or network I/O) from run-queue length (vmstat's r column: how many threads are runnable but waiting for a core).

• Signal for I/O-bound: %iowait is meaningfully elevated, and iostat -x shows elevated await/service time on disk, or network calls are the slow leg.
• Signal for CPU-bound: %user/%sys near saturation across cores, %iowait near zero, and run-queue length persistently exceeding the core count.
• Neither of the above cleanly: check for contention next.

Step 2: If CPU-bound, profile it

Take a CPU sampling profile (e.g. perf record, async-profiler, or a language-specific sampler) during the spike and read the resulting flame graph: a wide plateau in application code is genuine compute cost; a wide plateau in GC (garbage collection) or in kernel lock/futex frames tells a very different story than "the algorithm is slow."

Step 3: If not clearly CPU or I/O, check for lock contention

Take a thread dump (ideally a few, seconds apart) and count how many threads are BLOCKED waiting to enter the same synchronized method or lock. The signature of contention is: overall CPU is NOT saturated (there's spare capacity) yet requests still queue, and the thread dumps show a cluster of threads blocked on one lock while only one or two threads are actually running. perf can corroborate this by showing elevated time in futex/pthread_mutex_lock syscalls (futex is the Linux kernel primitive used to implement locks and mutexes, so time spent there means threads are waiting on a lock, not doing work).

Step 4: Corroborate with an off-CPU view if available

An off-CPU flame graph (captures time threads spend BLOCKED, not running) pinpoints the exact call site where threads are waiting, whether that's a lock, a socket read, or a disk write, which a normal CPU-only flame graph cannot show since blocked threads aren't consuming CPU.

Putting it together

I/O-bound: elevated iowait plus elevated disk/network latency in the same window. CPU-bound: near-100% user+sys with a growing run queue and iowait near zero. Lock contention: CPU has headroom, yet thread dumps show many threads blocked on one lock, that's queuing caused by serialization, not by resource exhaustion.

Framing

QPS staying flat while both average read latency and connection wait time climb points at a change in how long each query takes to complete, not a change in how many queries arrive. Since each connection can only serve one query at a time, if service time per query goes up, the same arrival rate starts backing up waiting for a free connection, which is exactly the connection-wait growth you are seeing; the read-latency increase and the connection-wait increase are very likely the same underlying cause showing up twice.

Profile the queries

SELECT query, calls, mean_exec_time, rows
FROM pg_stat_statements
ORDER BY mean_exec_time DESC LIMIT 10;

Compare mean_exec_time against a recent baseline, like yesterday's snapshot if you keep one, rather than looking at it in isolation, since you are hunting for what changed, not just what is currently slowest.

Analyze index usage

Run EXPLAIN ANALYZE on the specific slow query. Look for a Seq Scan where you would expect an Index Scan, or an index that is used but returning far more rows than the query actually needs. Also check pg_stat_user_indexes for a trend of falling idx_scan relative to seq_scan on the affected table, which can indicate index bloat (wasted space from stale or dead index entries that makes the index itself slower to scan) or stale planner statistics rather than a missing index outright.

Check buffer pool and cache behavior

SELECT relname,
  round(heap_blks_hit::numeric / NULLIF(heap_blks_hit + heap_blks_read, 0), 3) AS cache_hit_ratio
FROM pg_statio_user_tables ORDER BY heap_blks_read DESC LIMIT 10;

A falling cache hit ratio, well below roughly 0.99, means more queries are going to physical disk than before, which directly raises per-query latency even with an unchanged query plan; this commonly happens when the table's data volume has grown past what fits comfortably in memory.

At least four tuning steps, mixing schema/query and server-level

1. Schema/query: add or rebuild the index the slow query's WHERE or JOIN clause actually needs, based on the EXPLAIN ANALYZE output.
2. Schema/query: rewrite any predicate that wraps the filtered column in a function, for example WHERE date(created_at) = '2026-09-01', which defeats a plain index, into a sargable range condition (sargable meaning the database can use an index to satisfy the condition directly, without first computing a function on every row) such as created_at >= '2026-09-01' AND created_at < '2026-09-02'.
3. Server-level: run ANALYZE, or VACUUM ANALYZE, if planner statistics are stale, since a stale row-count estimate can cause the planner to choose a sequential scan even when a good index exists.
4. Server-level: increase shared_buffers (Postgres) or the InnoDB buffer pool size (MySQL) if the cache hit ratio has genuinely fallen because the working set outgrew available memory.
5. Server-level: set or tighten a statement timeout so one runaway query cannot monopolize connections and starve the rest, which directly targets the connection-wait symptom even before the root query is fully fixed.

The two approaches

• Sampling profilers periodically interrupt execution (e.g. every 1 to 10ms) and record the current call stack. After enough samples, functions that show up often are statistically the hot ones.
• Instrumentation profilers insert explicit measurement code (timers, counters) at function entry/exit or around chosen blocks, recording exact call counts and durations for every invocation.

Overhead

• Sampling: low and roughly constant, since cost is proportional to the sampling rate, not to how many times the profiled code runs. This is what makes it safe to leave running in production.
• Instrumentation: proportional to how often the instrumented code is called. A function called a million times a second, wrapped in instrumentation, can itself become a meaningful fraction of total runtime, this is called the probe effect (the act of measuring changes the thing being measured), and it can even distort WHICH function looks hottest.

Accuracy

• Sampling gives a statistical approximation. Long-running, frequently-hit functions are represented accurately; very short-lived functions that happen to fall between samples can be under-counted or missed entirely.
• Instrumentation is exact for whatever it wraps: precise call counts and durations, including rare or short-lived calls that sampling could miss. The trade-off is it only sees what you deliberately instrumented, unlike sampling's whole-process view.

When to choose which, as an SRE

• Default to sampling for open-ended, production, "where is the time going in this whole service" investigations, because its overhead is safe to run live and it needs no code changes.
• Reach for instrumentation once sampling has already narrowed the problem to a specific function or code path and you need EXACT counts or durations (e.g. confirming a cache is actually being hit 95% of the time, or timing a specific external call), and preferably run it in staging, or scope it tightly and temporarily if it must run in production.
• A common combined pattern: use sampling first to find the candidate hotspot cheaply and broadly, then apply narrow instrumentation only around that hotspot to confirm and quantify it precisely.

What a flame graph is

A flame graph is a visualization built from many CPU stack samples collapsed together, showing which call stacks were running and how often.

The axes

• X-axis is NOT time. Boxes are typically sorted alphabetically (or by tool convention) left to right, and a box's WIDTH represents how often that function appeared across all samples, i.e. its share of total CPU time. Wide = expensive.
• Y-axis is call-stack depth. The bottom row is the root (e.g. a thread's entry point or main), and each box stacked directly above another is a function CALLED BY the box below it. Moving up the stack means descending deeper into callees.

Wide vs tall

• A wide, flat "plateau" (a box that is wide but has no boxes stacked above it, or only thin ones) means that function itself is doing expensive work, it is a leaf-level hotspot.
• A tall, narrow "tower" (many boxes stacked on top of each other, each fairly narrow) shows a deep call chain, lots of nested calls, but tallness alone does not mean expensive; a narrow tower can represent very little total CPU time even though it looks visually striking.

How inlining and shared libraries distort the picture

• A JIT (Just-In-Time compiler, one that compiles code to machine instructions while the program runs) or an ahead-of-time compiler will often inline small, frequently-called functions directly into their caller for speed. An inlined function may not appear as its own box at all, its cost gets folded into the caller, making the caller look more expensive than its own source code would suggest.
• Frames from shared libraries without debug symbols can show up as raw addresses or a single generic library name (e.g. everything collapsing into one libc box), hiding what is really many distinct functions behind one wide box. Loading proper symbol tables (or using a profiler build with symbols) is often needed before a flame graph is trustworthy for prioritization.

Worked example

Picture a flame graph with main at the bottom spanning 100% of the width, calling handle_request (also ~100% width, since it wraps almost the whole request), which splits into two children: parse_json (10% width) and render_template (85% width). Inside render_template, there is a leaf box format_currency at 60% width with nothing stacked above it. That plateau tells you format_currency itself, not something it calls, is the single best optimization target, it accounts for more CPU than everything else in the request combined.