Profiling a Slow Rust Endpoint From Flamegraph to Fix

"The search endpoint feels slow" is not a diagnosis, and the usual response to it, guessing at a cause and rewriting the code you suspect, fixes the wrong thing more often than not. This guide walks the loop that does not guess: make the slowness reproducible, record where the CPU goes, read the recording, change exactly one thing, and prove the change with the same measurement.

Everything here was run on Rust 1.99 with edition 2024 and Axum 0.8. The two micro-measurements, a regex compiled on every call and a response built from clones, are complete programs with their real output. The profiling commands are the ones you run on your own service, and the guide is explicit about what each profile can and cannot tell you.

Step 1: reproduce it with a number

Profile nothing until you can trigger the slowness on demand and write down how bad it is. A flamegraph of a service that is mostly idle shows an idle service. Pick the one route, put a steady load on it from another machine, and record the baseline latency percentiles and throughput. The method for doing that without fooling yourself is in load testing a Rust service; the short version is a fixed arrival rate, a warm-up minute, and p50, p95 and p99 rather than an average.

oha -z 60s -q 800 --no-tui "http://10.0.0.12:3000/search?q=rust"

Write the p95 and the requests per second on a line in your notes. Every later step is compared to that line. A change that you cannot show on that line did not help, however clean the diff looks.

Step 2: build something a profiler can read

A profiler samples the instruction pointer many times a second and maps each address to a function. For that to work on an optimized build, two things must be true: the binary must keep its symbol names, and the profiler must be able to walk the stack. A default release build gives you the speed but strips the line information, and omits frame pointers on some platforms, so frames come out as hex addresses or truncated stacks.

Fix both in Cargo.toml without giving up optimization:

[profile.release]
debug = "line-tables-only"

line-tables-only keeps function names and source lines and adds no runtime cost, only a larger binary. It does not change what the optimizer does, so the profile you read matches the build you ship. Do not profile a debug build. A debug build is dominated by checks and unoptimized iterator chains that disappear in release, and you would spend an afternoon optimizing code that is not slow.

For stack walking, compile with frame pointers when your profiler uses them:

RUSTFLAGS="-C force-frame-pointers=yes" cargo build --release

On Linux, perf can also unwind with DWARF (--call-graph dwarf), which needs no special flag but produces much larger recordings. Frame pointers are cheaper and more reliable for a service you intend to profile repeatedly.

Step 3: record while the load runs

Start the load from step 1, then record the service while it is running. On Linux, cargo flamegraph wraps perf:

cargo install flamegraph
cargo flamegraph --release --bin api --freq 997 -o search.svg

On macOS, samply is the smoother choice and opens an interactive profile in your browser:

cargo install samply
samply record ./target/release/api

Record for thirty to sixty seconds. A frequency of 997 samples per second (a prime, so it does not align with a periodic 1 ms or 10 ms timer inside your program) gives 30,000 or so samples in that window, enough to resolve anything above about a tenth of a percent. Stop the recording, stop the load, and open the result.

Step 4: read the flamegraph correctly

A flamegraph stacks functions by call depth. The x axis is not time; it is the share of samples, with callees stacked above their callers. A wide box means that function, plus everything it called, appeared in many samples. A wide box with nothing on top of it means the time was spent in that function's own code.

Read it in this order:

1. Find the widest boxes at the top of stacks, called plateaus. Those are the leaves where the CPU is actually executing.
2. For each, read downward to see who called it and whether that caller is yours. A plateau inside a library is usually a symptom of how your code calls the library.
3. Ignore anything under about two percent until the big boxes are gone.

What a CPU profile cannot show matters as much as what it can. It samples threads that are running on a core. A request waiting for a database reply, a lock, or a downstream HTTP call is not running, so it does not appear. If the endpoint is slow because it waits, the flamegraph will look healthy and mostly empty, and the right tool is tracing, covered below.

Step 5: the usual suspects, measured

In a typical JSON endpoint, the same handful of mistakes account for most of the CPU. Here are two of them, each with a runnable measurement, so you can see the size of the effect instead of taking it on faith.

Compiling a regex on every request

This looks innocent in a handler:

async fn search(Query(q): Query<SearchQuery>) -> Json<Vec<Item>> {
    let slug = Regex::new(r"^[a-z0-9]+(?:-[a-z0-9]+)*$").unwrap();
    if !slug.is_match(&q.category) {
        return Json(vec![]);
    }
    // ...
}

Building a Regex parses the pattern, compiles it to an automaton and allocates its caches. Matching against the result is cheap by comparison, so the fix is to build it once. The program below measures both against the same inputs with a release build:

use std::hint::black_box;
use std::sync::LazyLock;
use std::time::Instant;

use regex::Regex;

static SLUG: LazyLock<Regex> = LazyLock::new(|| Regex::new(r"^[a-z0-9]+(?:-[a-z0-9]+)*$").unwrap());

// What the slow handler did: compile on every call.
fn is_slug_slow(s: &str) -> bool {
    Regex::new(r"^[a-z0-9]+(?:-[a-z0-9]+)*$").unwrap().is_match(s)
}

fn is_slug_fast(s: &str) -> bool {
    SLUG.is_match(s)
}

fn time(label: &str, n: u32, f: impl Fn(&str) -> bool) {
    let start = Instant::now();
    let mut hits = 0;
    for i in 0..n {
        let input = if i % 2 == 0 { "rust-ownership-explained" } else { "Not A Slug" };
        if f(black_box(input)) {
            hits += 1;
        }
    }
    let per_call = start.elapsed() / n;
    println!("{label:<22} {n:>7} calls, {per_call:>9.2?} per call, {hits} matches");
}

fn main() {
    time("compile every call", 20_000, is_slug_slow);
    time("compile once", 20_000, is_slug_fast);
}

compile every call       20000 calls,   12.29µs per call, 10000 matches
compile once             20000 calls,   26.00ns per call, 10000 matches

About 470 times slower per call, on a pattern this small. At 800 requests per second that is roughly 10 ms of CPU every second, which sounds minor until the pattern is large, or the handler compiles three of them, or the service runs on a shared core. In a real flamegraph this shows up as a wide regex_automata plateau under your handler, and its width is exactly how much of your CPU goes there. The fix is std::sync::LazyLock, stable since Rust 1.80, which initializes on first use and is shared by every thread:

use std::sync::LazyLock;
use regex::Regex;

static SLUG: LazyLock<Regex> =
    LazyLock::new(|| Regex::new(r"^[a-z0-9]+(?:-[a-z0-9]+)*$").unwrap());

The unwrap is acceptable here because the pattern is a literal that you test once; a bad literal fails the first request, loudly, and a unit test that calls SLUG.is_match("x") catches it before deploy.

Cloning into the response type

The second suspect is copying data that you only needed to read. A handler loads rows, then builds a response struct with owned String fields by cloning each one. A counting allocator turns "this allocates a lot" into a number. This program replaces the global allocator with a thin wrapper that increments a counter, then serializes 100 rows two ways.

use std::alloc::{GlobalAlloc, Layout, System};
use std::sync::atomic::{AtomicUsize, Ordering};

use serde::Serialize;

struct Counting;
static ALLOCS: AtomicUsize = AtomicUsize::new(0);

unsafe impl GlobalAlloc for Counting {
    unsafe fn alloc(&self, layout: Layout) -> *mut u8 {
        ALLOCS.fetch_add(1, Ordering::Relaxed);
        unsafe { System.alloc(layout) }
    }
    unsafe fn dealloc(&self, ptr: *mut u8, layout: Layout) {
        unsafe { System.dealloc(ptr, layout) }
    }
}

#[global_allocator]
static A: Counting = Counting;

struct Row {
    id: i64,
    name: String,
    category: String,
}

#[derive(Serialize)]
struct OwnedItem {
    id: i64,
    name: String,
    category: String,
}

#[derive(Serialize)]
struct BorrowedItem<'a> {
    id: i64,
    name: &'a str,
    category: &'a str,
}

fn allocations<R>(f: impl FnOnce() -> R) -> (R, usize) {
    let before = ALLOCS.load(Ordering::Relaxed);
    let out = f();
    (out, ALLOCS.load(Ordering::Relaxed) - before)
}

fn main() {
    let rows: Vec<Row> = (0..100)
        .map(|i| Row { id: i, name: format!("item {i}"), category: "tools".to_string() })
        .collect();

    let (_, cloned) = allocations(|| {
        let items: Vec<OwnedItem> = rows
            .iter()
            .map(|r| OwnedItem { id: r.id, name: r.name.clone(), category: r.category.clone() })
            .collect();
        serde_json::to_vec(&items).unwrap()
    });

    let (_, borrowed) = allocations(|| {
        let items: Vec<BorrowedItem> = rows
            .iter()
            .map(|r| BorrowedItem { id: r.id, name: &r.name, category: &r.category })
            .collect();
        serde_json::to_vec(&items).unwrap()
    });

    println!("cloning rows into the response: {cloned} allocations");
    println!("borrowing from the rows:        {borrowed} allocations");
}

cloning rows into the response: 208 allocations
borrowing from the rows:        8 allocations

The cloning version makes two allocations per row for the cloned strings plus the vector growth and output buffer. The borrowing version serializes &str slices that point into the rows already in memory and allocates only for the vectors and the output. The change is a lifetime parameter on the response struct, which the compiler checks for you: the response cannot outlive the rows. Allocation count is not the same as time, but it is a good proxy, since each allocation is a lock-free but nonzero cost and each clone is a copy that the allocator later has to free. In a flamegraph, the signature is malloc, free or alloc::string::String::clone widening under the serialization code.

Step 6: change one thing, measure again

After the regex fix, rebuild with the same profile settings, restart, and run the identical load from step 1. Add a line to your notes with the new p95 and requests per second next to the baseline. Then repeat for the next fix, so the notes read as a ledger: baseline, regex compiled once, borrowed instead of cloned, each with its own pair of numbers.

Do one row at a time. If you change the regex, the serializer and the query in one commit and the p95 drops, you do not know which one mattered, and you cannot tell whether the other two made things worse. Profile again after each fix, because removing the widest box redistributes the percentages: a function that was 12 percent of a profile may become 40 percent of a smaller one, and it is then your next target.

Stop when the profile is flat. A flat profile has no plateau above a few percent, and further tuning of individual functions buys little. At that point the remaining wins are structural: cache the response for repeated queries, do less work per request, or add capacity.

When the profile is empty: the endpoint is waiting

If most samples land in kernel functions, the thread parking code of the async runtime, or the profile is simply sparse, the endpoint spends its time waiting. Look at wall-clock time instead, using spans around each await point. With the tracing crate, instrument the stages of the handler:

use tracing::{info_span, Instrument};

async fn search(Query(q): Query<SearchQuery>, State(db): State<PgPool>) -> Result<Json<Vec<Item>>, AppError> {
    let rows = sqlx::query_as::<_, Row>("SELECT id, name, category FROM items WHERE name ILIKE $1 LIMIT 50")
        .bind(format!("%{}%", q.q))
        .fetch_all(&db)
        .instrument(info_span!("db.search"))
        .await?;

    let items = info_span!("map").in_scope(|| rows.into_iter().map(Item::from).collect::<Vec<_>>());
    Ok(Json(items))
}

With a subscriber that records span durations, you see directly that db.search takes 38 ms of a 41 ms request. That is not a Rust problem, it is a query problem, and the next tool is EXPLAIN (ANALYZE, BUFFERS) on that statement. A leading-wildcard ILIKE cannot use a normal B-tree index and scans the table; a trigram index (pg_trgm) or a full-text search column usually turns a 38 ms scan into a sub-millisecond lookup. No amount of Rust optimization would have found that, which is the point of checking whether the time is CPU or waiting before opening a profiler.

Two other waiting patterns are common. Pool starvation looks like requests spending time in acquire before the query starts; the fix is a bigger pool, faster queries, or releasing connections earlier. Blocking the async runtime looks like latency that rises across unrelated endpoints at once, because a synchronous call, a large serde parse or a std::fs read is holding a worker thread. Move CPU-heavy or blocking work onto tokio::task::spawn_blocking.

Suspect three: the N+1 query that no CPU profile will show

The most expensive mistake in a list endpoint is a query inside a loop. It is invisible in a flamegraph because the handler spends its time awaiting the database, not running. The symptom is latency that grows linearly with the number of rows returned and a database log full of identical statements.

// One query for the items, then one more per item for its tags: 1 + N round trips.
let items = sqlx::query_as::<_, Item>("SELECT id, name FROM items LIMIT 50")
    .fetch_all(&db)
    .await?;

let mut out = Vec::with_capacity(items.len());
for item in items {
    let tags: Vec<String> = sqlx::query_scalar("SELECT tag FROM item_tags WHERE item_id = $1")
        .bind(item.id)
        .fetch_all(&db)
        .await?;
    out.push(ItemWithTags { item, tags });
}

With a 1 ms round trip to the database, fifty items cost 51 ms of pure waiting before any real work. The fix fetches the tags for all items in one statement using ANY, then groups them in memory:

use std::collections::HashMap;

let ids: Vec<i64> = items.iter().map(|i| i.id).collect();
let rows: Vec<(i64, String)> =
    sqlx::query_as("SELECT item_id, tag FROM item_tags WHERE item_id = ANY($1)")
        .bind(&ids)
        .fetch_all(&db)
        .await?;

let mut by_item: HashMap<i64, Vec<String>> = HashMap::new();
for (item_id, tag) in rows {
    by_item.entry(item_id).or_default().push(tag);
}

let out: Vec<ItemWithTags> = items
    .into_iter()
    .map(|item| {
        let tags = by_item.remove(&item.id).unwrap_or_default();
        ItemWithTags { item, tags }
    })
    .collect();

Two queries replace fifty-one, and the endpoint's database time no longer depends on the page size. You find this class of bug by counting statements per request, which is one line in the database log (log_min_duration_statement = 0 on a staging Postgres for a minute) or a counter in your tracing layer. If one request produces more than a handful of statements, read the loop.

A worked session, start to finish

Put the pieces together with a concrete complaint: /search has a p95 of 210 ms at 800 requests per second and the target is 100 ms. The investigation order that finds the cause fastest is cheap checks first.

1. Check the error rate and the status distribution from the load run. If there are 503 responses, the service is rejecting load, and latency is the wrong thing to chase.
2. Check CPU while the load runs. If it is under 40 percent across cores, the endpoint is waiting and the CPU profile will mislead you. Go to the spans.
3. If CPU is high, record a flamegraph. Read the top plateaus and match them against the suspects in this guide: regex construction, cloning and allocation, serialization, hashing or compression that should be off the hot path.
4. If spans show the database dominating, count statements, then run EXPLAIN (ANALYZE, BUFFERS) on the slowest one.
5. Fix the biggest finding only. Re-run the load. Write down the numbers.

This order matters because the expensive tools come last. Counting statements takes a minute. Reading CPU takes ten seconds. A flamegraph takes ten minutes. Reaching for the flamegraph first, because it is the tool people associate with performance work, is how an N+1 query survives three optimization passes over the serializer.

Allocation and memory profiles

When the flamegraph shows malloc and free widening, the next question is who allocates. The counting allocator above answers it for a block of code. For a whole service, dhat (the dhat-rs crate in heap-profiling mode) records every allocation site and its size, and writes a file the DHAT viewer opens. It slows the program considerably, so use it on a short, scripted run of the endpoint rather than under production load. The output ranks allocation sites by total bytes and by number of blocks, and the top entries are usually the clones and format! calls you can remove.

Reducing allocations has diminishing returns. Going from 208 to 8 allocations in a response builder is a clear win on a hot path; hunting the last 8 is not. The signal to stop is again the profile: when malloc is under a few percent of samples, you are done with allocation.

Keep a regression guard once you have won

A fix that nothing protects tends to be undone in a refactor six months later. Two cheap guards work. A criterion benchmark for the hot function, run in CI with a threshold, catches a regression in the function itself. A scheduled load test with a p95 threshold in the pipeline catches regressions that come from anywhere. Neither needs to be elaborate: one benchmark for the function you just fixed, and one nightly run against staging, are enough to keep the number you fought for.

Pitfalls that waste an afternoon

• Profiling a debug build, or a release build without symbols, so the graph is addresses or the wrong code.
• Profiling at idle. The recording must overlap the load.
• Trusting inlined frames. The optimizer merges small functions into their callers, so a plateau attributed to your handler may be a helper that was inlined. Mark a suspect #[inline(never)] temporarily to see it separately, and remove the attribute afterward.
• Optimizing a three percent plateau while a 35 percent one sits beside it.
• Comparing runs taken on different instance types, or with a cold cache against a warm one.
• Believing a micro-benchmark over the service. The regex measurement above says how much a mistake costs in isolation; only the load test says how much it cost your service.

When this method does not fit

For a service dominated by database time, the profile is the wrong first step and EXPLAIN is the right one. For a leak or ever-growing memory, a CPU profile tells you nothing, and you want an allocation profile, covered in finding memory leaks in Rust services. For a problem that appears only under production traffic that you cannot reproduce, continuous profiling with a low sampling rate in production, or tracing with sampling, gets you data that a benchmark on your laptop never will. And for a one-off script, a stopwatch around the suspicious block is faster than any of this. The general method for CPU profiling is also written up in profiling Rust programs from flamegraph to a fix.