Performance Profiling & Bottleneck Analysis Questions

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.

What profiling is

Profiling is measuring where a running program actually spends its CPU time, memory, I/O (input/output, e.g. disk and network operations), or network calls, instead of guessing. In Site Reliability Engineering (SRE, the discipline of keeping production systems reliable through engineering practice), profiling turns "the API feels slow" into a data-backed answer: which function, query, or syscall is actually consuming the resource.

Goals of profiling

• Locate the dominant cost, not every cost. The aim is to find the one or two paths that account for most of the time or memory, because fixing those gives the biggest return.
• Separate symptom from root cause (high CPU might really be garbage collection thrashing, not your business logic).
• Produce evidence you can attach to a change request, instead of an opinion.

Sampling vs instrumentation profilers

• Sampling profilers interrupt the program at a fixed interval (say every 10ms) and record which function is on-CPU at that instant. Over thousands of samples, functions that show up often are the hot ones. Low overhead, safe to run in production, but statistical, very short functions can be under-sampled.
• Instrumentation profilers insert timing code around specific calls, giving exact counts and durations. Precise, but adds real overhead since every instrumented call now does extra work, so it is usually run in staging or narrowed to one deliberately chosen section in production.

Metrics typically collected

• CPU: time-on-CPU per function or thread, often visualized as a flame graph.
• Memory: allocation rate, heap size over time, retained objects.
• I/O: disk read/write latency and throughput, syscall counts.
• Network: request/response latency, bytes transferred, connection counts.

Worked example

A checkout API's p95 latency (95th percentile response time, meaning 95% of requests finish faster than this number) rises from 120ms to 300ms. A CPU sampling profile taken during the slow window shows 70% of samples land inside one function, calculate_discount(). That single number tells you exactly where to look before touching any code.

Why measure-first, change-later

Without a profile, "optimizing" is guessing: you might rewrite a function that is only 2% of runtime and see no improvement, while the real 70% offender goes untouched. Measuring first also gives you a baseline to prove a fix actually worked, and it keeps each change small and reversible if the hypothesis turns out wrong, which fits SRE's broader preference for low-risk, evidence-driven production changes over large speculative rewrites.

Approach

Time and memory instrumentation are cheap individually, but wrapping EVERY call in a hot function with full memory tracing adds real overhead. The production-safe version samples: measure only a random fraction of calls, and only log when something is actually worth seeing (e.g. slower than a threshold), so the fast, common case pays almost nothing.

import time
import tracemalloc
import random
import functools
import threading
import logging

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

# tracemalloc's tracing state is PROCESS-GLOBAL, not per-thread: start()/stop()
# affect every thread at once. An RLock (reentrant, so a recursive call from the
# SAME thread doesn't deadlock on itself) serializes only the sampled calls.
_trace_lock = threading.RLock()


def profile(sample_rate=0.1, log_threshold_ms=0.0):
    """Times a function and measures its memory delta, but only on a
    random sample of calls, so overhead stays safe for production."""
    def decorator(func):
        @functools.wraps(func)
        def wrapper(*args, **kwargs):
            if random.random() > sample_rate:
                return func(*args, **kwargs)

            with _trace_lock:
                tracemalloc.start()
                start = time.perf_counter()
                try:
                    result = func(*args, **kwargs)
                finally:
                    elapsed_ms = (time.perf_counter() - start) * 1000
                    _, peak = tracemalloc.get_traced_memory()
                    tracemalloc.stop()
                    if elapsed_ms >= log_threshold_ms:
                        logger.info(
                            "%s took %.3fms, peak_traced_memory=%.1fKB",
                            func.__name__, elapsed_ms, peak / 1024,
                        )
            return result
        return wrapper
    return decorator


@profile(sample_rate=1.0)  # 1.0 here only so this demo always logs
def build_lookup(n):
    return {i: str(i) * 4 for i in range(n)}


if __name__ == "__main__":
    random.seed(7)
    for size in (1_000, 50_000):
        build_lookup(size)

Sample output (exact numbers vary by machine, the shape doesn't):

build_lookup took 0.500ms, peak_traced_memory=107.5KB
build_lookup took 26.345ms, peak_traced_memory=7753.5KB

Key points

• time.perf_counter() is used instead of time.time() because it's monotonic (never goes backward, e.g. from an NTP clock adjustment) and has the highest available resolution, exactly what a duration measurement needs.
• tracemalloc gives an accurate peak-memory delta for the wrapped call, but it has to trace every allocation while active, which is not free; that cost is why it's gated behind sample_rate instead of running on every call.
• Sampling (random.random() > sample_rate) means only a configurable fraction of calls pay the tracing cost at all, and log_threshold_ms further avoids flooding logs with entries for calls that were fast anyway.

Making it safe for production

• Keep sample_rate low (1 to 10 percent) on hot paths; it's a statistical view, not a complete record, the same trade-off sampling profilers make generally.
• Prefer functools.wraps so the decorator doesn't silently break introspection (__name__, docstrings) that other tooling or frameworks may depend on.
• tracemalloc.start()/tracemalloc.stop() are PROCESS-GLOBAL, not per-call or per-thread: if two sampled calls run concurrently on different threads, one thread's stop() turns off tracing for the other mid-measurement. Executed against a real multi-threaded workload, the unguarded version doesn't raise an error, it silently reports peak_traced_memory=0.0KB for every thread except whichever one happened to call stop() last, plausible-looking output that is simply wrong. Wrapping the whole start/measure/stop block in the module-level _trace_lock (an RLock, not a plain Lock, so a sampled call that recurses into itself on the same thread doesn't deadlock waiting on a lock it already holds) fixes this: sampled calls across threads are serialized instead of corrupting each other's readings, at the cost of a small amount of added latency on the (already rare) sampled path only.
• If even sampled tracemalloc overhead is too much for a very hot path, fall back to timing only (drop the memory block) and get memory signal from a separate, coarser process-level metric instead (e.g. periodic RSS, Resident Set Size, sampling).

Edge cases

• An exception inside func: the finally block still records and logs the partial timing before the exception propagates, so a slow-then-failing call still shows up in the data instead of disappearing silently.
• Reentrant/recursive calls to the decorated function, on the SAME thread, are handled by using RLock specifically: a plain Lock would deadlock the moment a sampled call recursed into itself, since the thread would block waiting to re-acquire a lock it's still holding. With RLock, the reported peak for an outer call can still be diluted by an inner call resetting the trace when both are sampled; for recursive functions, tracing at the outermost call only would need extra bookkeeping (e.g. a thread-local recursion-depth guard that only starts/stops tracing at depth 0).
• Concurrent calls on DIFFERENT threads: this is the case that matters most for a decorator marketed as "safe in production," since a live service under load runs the decorated function on many threads at once. See the lock above; without it, this class of bug produces confidently-wrong numbers rather than a crash, exactly the kind of silent failure a profiling tool must not have.

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.

What each tells you, and where it falls short

• Metrics are aggregated numeric time series, like request rate, error rate, or p99 latency. They tell you that something is wrong and roughly when and which service, cheaply, at scale. They fall short at telling you why: a metric cannot show you what a single slow request actually did, and slicing by too many dimensions gets expensive or impossible.
• Logs are per-event text records with context around a specific moment. They tell you what happened at a point in time: an error, a state change, an unusual input. They fall short when you do not already know where to look: without a shared identifier tying log lines across services together, you cannot reconstruct one request's full journey, and high-volume services often sample or drop logs under load.
• Distributed traces are a per-request tree of timed spans across every service hop that request touched. They tell you exactly which hop dominated a specific slow request's total time. They fall short at explaining why that hop was slow internally: a trace span shows "80 milliseconds in the inventory service," not which function inside that service ate the time, and traces are usually sampled, so the exact slow request you care about may not have one.

Combining them with a flame graph or CPU profile

A flame graph (a visualization where each function is a horizontal bar, width proportional to time spent, stacked by call depth) or a CPU profile shows you why a specific piece of code was slow, at the function level, but only within one process, and only if you already know which process to look at.

A realistic combination: a p99 latency alarm on the checkout endpoint (metric) tells you when and which endpoint. Pulling a trace for a slow request in that window shows 800 of 900 milliseconds was spent in a call to the inventory service, which narrows it to which hop. Logs from the inventory service in that same window show no errors, ruling out a failure path. A CPU profile taken on the inventory service during that window then shows a wide bar under a JSON-parsing function, the why, at the code level. Each tool narrowed the search space for the next one; none of them alone would have found the root cause as fast.