Performance Profiling & Bottleneck Analysis Questions

What a heap dump is

A heap dump is a snapshot of every live object on a process's managed heap (for a garbage-collected runtime such as the JVM, Java Virtual Machine) at one instant, including each object's fields, size, and references to other objects. It's effectively a full memory census you can load into an analyzer afterward.

When to capture one in production

• When heap usage is trending toward an OOM (Out Of Memory, when the process is killed or fails because it exceeded available memory) and you need to identify exactly which objects are being retained.
• When you have a specific, already-suspected leak and need to confirm which class is actually growing.
• At the moment of an OOM itself, many runtimes support a "dump heap automatically on OOM" flag, so you capture the exact state that caused the failure instead of trying to reconstruct it afterward.

Live heap dump vs allocation sampling

• A live heap dump captures everything CURRENTLY retained, exactly, you see every live object and its reference chain. The cost is real: taking one is expensive, it commonly triggers a full stop-the-world pause (the runtime freezes application threads to take a consistent snapshot) and produces a large file, so it's not something to do routinely, only for a deliberate, specific investigation.
• Allocation sampling instead records a statistical sample of allocation call sites over time (WHERE objects are being created), with much lower overhead, low enough to run continuously or on demand without freezing the process. It tells you where churn is happening, which is great for finding an allocation hotspot driving GC (garbage collection) pressure, but it does not give you the full retained-object graph a heap dump gives you.

Minimizing production impact

• Default to allocation sampling for ongoing, low-overhead visibility.
• Reserve full heap dumps for one deliberate capture, ideally on a single canary instance pulled out of the load balancer's rotation first, not across the whole fleet simultaneously.
• Use dump-on-OOM flags so the one dump you actually need gets captured automatically, without needing to guess the right moment.

Approach

For a suspected tail-latency problem, start broad with a sampling profiler (low overhead, works across the whole request, works safely in production) to find WHICH section of the handler is slow, then narrow to targeted timing around that one critical section so you get exact numbers for it without instrumenting the whole request path.

Sampling vs instrumentation for this scenario

A sampling profiler (e.g. py-spy for Python, or async-profiler for the JVM) attached to the live process, interrupting periodically to record the call stack, is the safe first move: it needs no code changes and its overhead is low enough to run against production traffic. Once that points at a specific function or block, wrap JUST that section in explicit timing to get exact per-call numbers and log only the slow outliers, this is instrumentation used narrowly instead of broadly, which keeps its overhead contained.

import time
import logging
from contextlib import contextmanager

logging.basicConfig(level=logging.INFO, format="%(message)s")
logger = logging.getLogger("latency")


@contextmanager
def timed_section(name, slow_threshold_ms=50.0):
    """Times a critical section and only logs when it crosses a
    threshold, so the common fast path never pays a logging cost."""
    start = time.perf_counter()
    try:
        yield
    finally:
        elapsed_ms = (time.perf_counter() - start) * 1000
        if elapsed_ms >= slow_threshold_ms:
            logger.info("SLOW %s: %.2fms", name, elapsed_ms)


def handle_request(request_id, simulate_slow):
    with timed_section("serialize_response"):
        if simulate_slow:
            time.sleep(0.06)  # stand-in for a slow serialization path
        else:
            time.sleep(0.005)
    return f"handled {request_id}"


if __name__ == "__main__":
    import random
    random.seed(3)
    for i in range(20):
        slow = random.random() < 0.1
        handle_request(i, slow)

Sample output (exact millisecond values vary by machine, the pattern does not):

SLOW serialize_response: 61.27ms
SLOW serialize_response: 65.02ms

Out of 20 simulated requests, only the two that hit the slow path logged anything, exactly the tail-latency behavior being investigated: most requests are fine, a minority spike.

Key points

• The threshold-gated log means normal, fast requests add essentially zero logging overhead, which matters because logging every request's timing at high volume can itself become a bottleneck.
• time.perf_counter() (monotonic, high resolution) inside a context manager keeps the timing code out of the request-handling logic itself, so it's easy to wrap around any critical section without cluttering business logic.
• For a Java handler, the equivalent pattern is System.nanoTime() around the section (or better, JFR, Java Flight Recorder, a built-in low-overhead production profiling and event-recording facility) rather than hand-rolled timers everywhere.

Edge cases

• If the slow path itself throws, the finally block still logs the elapsed time before the exception propagates, so a slow-then-failing request is still visible in the data.
• A threshold set too low turns this back into "log everything," recreating the overhead problem it was meant to avoid; the threshold should be set from the observed p95/p99 (95th/99th percentile latency) of the section, not an arbitrary guess.

Approach

A bounded object pool trades a small, fixed amount of memory (the pool's capacity) for fewer allocations under high-churn workloads: instead of allocating and immediately discarding a short-lived object on every request, the pool hands out an existing one and takes it back afterward, so the allocator and garbage collector see far fewer objects to create and reclaim. "Bounded" specifically means the pool has a capacity ceiling, unlike Go's built-in sync.Pool, whose contents the runtime can silently clear at any garbage collection, which is fine as a pure optimization hint but not when you need a guaranteed-available object and a hard memory ceiling.

Code

package main

import (
	"fmt"
	"runtime"
)

// Buffer is the short-lived object churned through at a high rate,
// e.g. a per-request scratch buffer.
type Buffer struct {
	data [4096]byte
}

// sink forces the compiler's escape analysis to allocate each Buffer
// on the heap, matching real code where the buffer is handed to
// another function (like a request handler) that outlives this scope.
var sink *Buffer

// BoundedPool is a fixed-capacity pool backed by a buffered channel.
type BoundedPool struct {
	free chan *Buffer
}

func NewBoundedPool(capacity int) *BoundedPool {
	return &BoundedPool{free: make(chan *Buffer, capacity)}
}

func (p *BoundedPool) Get() *Buffer {
	select {
	case b := <-p.free:
		return b
	default:
		return &Buffer{} // pool empty: allocate a new one
	}
}

func (p *BoundedPool) Put(b *Buffer) {
	select {
	case p.free <- b:
	default:
		// pool already at capacity: drop it, GC reclaims it normally
	}
}

func allocsDuring(f func()) (mallocs, bytes uint64) {
	var before, after runtime.MemStats
	runtime.GC()
	runtime.ReadMemStats(&before)
	f()
	runtime.ReadMemStats(&after)
	return after.Mallocs - before.Mallocs, after.TotalAlloc - before.TotalAlloc
}

func work(b *Buffer) {
	b.data[0]++
	sink = b
}

func main() {
	const iterations = 200000

	mallocsNoPool, bytesNoPool := allocsDuring(func() {
		for i := 0; i < iterations; i++ {
			b := &Buffer{}
			work(b)
		}
	})

	pool := NewBoundedPool(64)
	mallocsPool, bytesPool := allocsDuring(func() {
		for i := 0; i < iterations; i++ {
			b := pool.Get()
			work(b)
			pool.Put(b)
		}
	})

	fmt.Printf("iterations:           %d\n", iterations)
	fmt.Printf("mallocs without pool: %d (%.1f MB)\n", mallocsNoPool, float64(bytesNoPool)/1e6)
	fmt.Printf("mallocs with pool:    %d (%.1f MB)\n", mallocsPool, float64(bytesPool)/1e6)
	fmt.Printf("allocation reduction: %.1f%%\n", 100*(1-float64(mallocsPool)/float64(mallocsNoPool)))
}

Output from running it unchanged:

iterations:           200000
mallocs without pool: 200123 (819.2 MB)
mallocs with pool:    1 (0.0 MB)
allocation reduction: 100.0%

(The exact without-pool count drifts by roughly plus or minus 100 across runs from unrelated Go runtime background allocations; the pattern, tens of thousands of mallocs collapsing to one, is stable.)

Key points

• The channel acts as both the free list and the capacity bound: Get falls through to default (allocate) only when the channel is empty, and Put falls through to default (drop) only when the channel is already full, so the pool never grows past its configured capacity.
• This single-goroutine benchmark reuses one Buffer forever after the first allocation, which is why mallocs with pool is 1, not 0: under real concurrent load with many goroutines pulling from the pool at once, allocations converge to roughly the number of objects actually in flight simultaneously, bounded by the pool's capacity, not to exactly one, but still to a small constant instead of growing with request count.
• The sink assignment in work exists specifically to stop the compiler's escape analysis (the compiler's decision about whether an object can stay on the fast, automatically-cleaned-up stack, or must move to the heap because it might outlive the function) from proving the buffer never leaves the function and stack-allocating it, which would hide the very allocation behavior this benchmark exists to measure.

Measuring impact on GC pause time and throughput

runtime.ReadMemStats also exposes PauseTotalNs and NumGC, so the same before-and-after pattern used above for allocation count works for GC pause time: run a sustained, concurrent load test, not this single-threaded microbenchmark, with and without the pool, and compare total GC pause time and GCCPUFraction, the share of CPU time spent in garbage collection, over an equal wall-clock window. For throughput, run both versions under go test -bench with -benchmem, or drive real concurrent load with a tool like hey or k6 against a staging deployment, and compare requests-per-second and p99 latency (the response time 99% of requests are faster than, which surfaces worst-case behavior an average would hide), since fewer allocations only matters if it measurably moves GC pause time and throughput, not just the allocation counter itself.

Edge cases

• Under high concurrency, a channel-based pool can become a contention point of its own, since many goroutines hit the same channel; if profiling shows that, consider sharding the pool per worker or per CPU.
• An object returned to the pool must be reset before reuse if it holds any state. This Buffer does not need resetting since only data[0] is touched and immediately overwritten, but a pooled object holding, say, a slice with old data could leak stale content into the next user if not cleared.

Approach

A signal-based sampling profiler periodically interrupts the process (via a POSIX interval timer) and records the current call stack, the same idea a general sampling profiler uses, implemented directly in Python. The tricky part in a MULTI-THREADED process is that SIGPROF (the profiling signal) only ever interrupts the main thread, so to see what OTHER threads are doing at that instant, you have to separately snapshot sys._current_frames(), which returns the current frame of every live thread.

import signal
import sys
import threading
import time
from collections import Counter

samples = Counter()


def _on_sigprof(signum, frame):
    # SIGPROF only ever interrupts the main thread, and `frame` is the
    # exact frame the main thread was executing when the signal landed.
    # Every OTHER thread was not interrupted, so we read its live frame
    # from sys._current_frames() instead.
    current_thread_id = threading.get_ident()
    for thread_id, stack in sys._current_frames().items():
        top_frame = frame if thread_id == current_thread_id else stack
        samples[top_frame.f_code.co_name] += 1


def start_sampler(interval_sec=0.01):
    signal.signal(signal.SIGPROF, _on_sigprof)
    signal.setitimer(signal.ITIMER_PROF, interval_sec, interval_sec)


def stop_sampler():
    signal.setitimer(signal.ITIMER_PROF, 0)


def cpu_heavy():
    total = 0
    for i in range(3_000_000):
        total += i * i
    return total


def io_like_wait():
    time.sleep(0.05)


if __name__ == "__main__":
    start_sampler(interval_sec=0.005)

    t = threading.Thread(target=io_like_wait)
    t.start()
    cpu_heavy()
    t.join()

    stop_sampler()

    print("samples collected:", sum(samples.values()))
    for func_name, count in samples.most_common(5):
        print(f"  {func_name}: {count}")

Sample output (counts vary slightly run to run, since sampling is statistical):

samples collected: 19
  cpu_heavy: 10
  io_like_wait: 8
  join: 1

cpu_heavy dominates the samples because it's actually consuming CPU on the main thread the whole time, while io_like_wait shows up on the other thread because sys._current_frames() captures its true current frame (inside time.sleep) at each tick, even though that thread never received the signal itself.

Trade-offs: sampling interval vs overhead and accuracy

• A SHORT interval (e.g. 1ms) gives finer-grained, more accurate attribution, catching even brief hot spots, but the signal handler itself fires far more often, and each firing costs CPU time, so overhead rises and can itself distort the very measurement you're taking (the probe effect).
• A LONG interval (e.g. 50 to 100ms) is nearly free in overhead but can completely miss short-lived functions that finish between two samples, and gives a coarser, noisier picture overall since fewer total samples are collected in the same wall-clock window.
• A practical default is in the low tens of milliseconds for production use (similar to what most general-purpose sampling profilers default to), trading some resolution for safety.

Key points

• ITIMER_PROF measures CPU time (user plus system), not wall-clock time, so it won't fire while the process is entirely idle waiting on I/O with no CPU activity, which is why this specific example also demonstrates the frame-snapshot trick for the sleeping thread rather than relying on the timer alone to "see" it.
• This whole technique only works within a single process; it cannot see across process boundaries, and on Windows there is no SIGPROF/setitimer equivalent, so this approach is POSIX-specific (Linux/macOS).

Edge cases

• If the handler itself does expensive work, that cost gets attributed to the sampler, biasing results toward the handler; keep _on_sigprof as cheap as possible.
• A signal can arrive while Python is inside C-extension code with the GIL (Global Interpreter Lock, CPython's lock ensuring only one thread runs Python bytecode at a time) released; behavior there depends on the extension and interpreter version, worth validating rather than assuming.

Framing

A feature-serving pipeline with occasional p95 (95th percentile latency) spikes to 2 seconds needs the spike CHARACTERIZED before it can be triaged: is it periodic (tied to a batch job, cache eviction, or GC pause) or effectively random? Pulling a trace from a few actual spike instances, if distributed tracing exists, is the fastest way to see where time in ONE slow request actually went.

1. Break the pipeline into stages and instrument each

Split the flow into stages: fetch raw data, compute/transform features, I/O to a feature store or model, serialize and respond. Time each stage (via existing tracing spans, or added timing) so you can see which stage owns the tail, since an average across the whole pipeline will hide a spike that lives entirely in one stage.

2. Apply the right diagnostic lens per stage

• If the slow stage is CPU-bound feature computation, take a CPU profile during an actual spike and read the flame graph.
• If it's I/O (feature-store lookups, calls to another service), check connection pool exhaustion, cache miss rate, and the downstream service's own latency.
• If it correlates with memory pressure, check whether GC (garbage collection, the runtime automatically reclaiming unused memory, which can briefly pause the program) pauses line up with the spike timing.

3. Prioritize using tail behavior, not averages

A stage that's only 5% of TYPICAL latency isn't where an occasional 2s spike is hiding even if it's individually inefficient; focus on whichever stage's tail (p99, not its average) is worst, since the reported symptom is a tail event, not a general slowdown.

4. Fix by category

• Infrastructure: add caching or connection pooling, autoscale ahead of load, isolate noisy-neighbor workloads onto separate capacity.
• Algorithmic: eliminate an accidental quadratic feature join, batch many small calls into one.
• I/O: cut round-trips to the feature store, add a local cache with a TTL (Time To Live, an expiration window) so repeat lookups don't hit the network every time.

5. Validate under a production-like load test

Reproduce the fix under the SAME request mix and concurrency the production traffic actually has, not a single-request smoke test, and compare the FULL latency distribution before and after, specifically p95/p99, not the average, since a fix that only improves the average while leaving the tail untouched hasn't solved the reported 2-second-spike problem. Run it long enough to catch periodic effects (cache warm-up cycles, GC cycles) that a short test would miss entirely.