Performance Profiling - Finding Bottlenecks

By the end of this lesson, you will be able to...

• Turn a latency symptom into a resource question that a profile can answer.

• Choose CPU, waiting, allocation, or lock evidence without treating them as interchangeable.

• Run a before-and-after profiling loop that changes one plausible bottleneck and checks the user result.

Idea in one sentence: A profile is useful when it tests where a resource goes for the slow workload, not when it merely points at code that looks suspicious.

Core Insight

For Atlas Shop, the CDN work from the previous lesson has reduced cache-miss bursts. A remaining GET /home cache miss is still slow: its p99 is 600 ms during the campaign. The on-call engineer sees a database span of 40 ms and a service CPU average of 48%. The dashboard does not say what the application spent the other time doing.

The tempting explanation is “the database is slow.” It is reasonable when the database span dominates the request. Here it does not: tuning an already-small 40 ms slice cannot explain a 600 ms tail. The team needs evidence from inside the process before choosing a subsystem to optimize.

Profiling is that evidence. It samples or records execution cost across many comparable runs and answers a narrower question: where did CPU, allocation, waiting, or lock time accumulate? It does not replace a latency metric or a trace. Those identify the affected request and its user impact; the profile helps locate the resource-consuming work behind that symptom.

The Production Symptom: A Slow Miss After Caching Is Fixed

Atlas labels the request group before collecting anything:

route: /home
cache_state: miss
language: en
campaign: active
response: 200

That label is part of the investigation, not decoration. Mixing cache hits, errors, and ordinary traffic into one profile could make a cheap path look dominant merely because it is common.

During a representative ten-minute slice, the team observes these illustrative values:

Metrics narrow where to look. A trace shows the path of one request. Neither is a profile. The next question is not “which tool is fashionable?” It is “which resource could account for the missing time?”

The Initial Model: Start With the Most Suspicious Dependency

The database is a common cause of a slow endpoint, so checking its span is a good first move. This model works when query or connection time is a large part of the same request class. In that case, an index, a query plan change, or a connection-pool limit may be the next investigation.

It breaks when the observed dependency time is small. A 40 ms database span does not prove the database is perfect, but it makes it a poor first explanation for 600 ms requests. The remaining time might be CPU work, allocation and garbage-collection pressure, a shared lock, queueing, or an external call that the trace has not attributed clearly.

Do not infer the answer from average CPU either. Fleet average CPU can be moderate while a subset of requests does expensive local work. Conversely, a high p99 with a quiet CPU profile may mean the process is waiting, not computing.

The correction is to form a resource hypothesis. “This response probably burns CPU while materializing a large catalog document” is testable. “The service feels slow” is not.

Choose the Profile That Can Disprove the Hypothesis

In plain English, a profile groups many executions by some resource. The technical name depends on the runtime and collector, but the investigation questions are stable.

This is a teaching model, not a promise that every language exposes every profile type in the same way. For example, Python's cProfile is deterministic: it reports call counts and time statistics for a program, while statistical profiling samples where time is spent. The Python documentation also warns that a profiler is not a benchmark because profiling changes execution overhead. Python profiler documentation. The right collector and its overhead are part of the operational choice.

Atlas has a concrete CPU hypothesis: the cache-miss handler builds a much larger response than the client needs. A CPU profile over the labelled slow workload is therefore a reasonable first test. If it is quiet, the team will change the question rather than force a CPU conclusion.

Investigation Path: From a Profile to a Small Change

The team captures a CPU profile for the same route, cache state, and campaign conditions. The following sample counts are synthetic, but the interpretation is the one that matters:

Inclusive cost includes work below a frame. Self cost belongs to the frame itself. This distinction prevents a common bad fix: selecting the widest visible leaf without asking why that leaf receives so much work. Python's profile reports similarly distinguish internal time from cumulative time; the latter includes subfunction time. Python profiler statistics.

The trace and profile now agree on a stronger explanation:

cache miss
  -> query a compact catalog set (about 40 ms)
  -> materialize every variant row
  -> build a large intermediate object
  -> encode JSON
  -> send a homepage that uses only a subset of those rows

The database was not ignored. It was measured and deprioritized for this incident. The intervention is also narrow: build only the fields and variant rows that this public homepage needs. It is not “rewrite JSON” or “optimize everything in the handler.”

Before release, Atlas checks that the smaller representation still includes the price, availability, and language-specific text promised by the page. Performance work can accidentally become a correctness regression when it removes data without naming the contract.

Verify the Change With the Same Question

After changing one response-building boundary, the team repeats the same campaign slice. These are illustrative before-and-after results:

This is a profiling loop, not a screenshot ritual:

1. Define the slow request class and its baseline.
2. State the resource hypothesis.
3. Capture evidence for that resource under comparable conditions.
4. Change one mechanism that the evidence makes plausible.
5. Re-profile and compare the user signal, resource signal, and correctness signal.

Go's profiling walkthrough demonstrates this same discipline: it enables a profile, examines it with pprof, changes a specific source of cost, and measures again. Profiling Go Programs. Continuous profilers can also be correlated with metrics, logs, and traces, which is useful when a short capture misses the incident window. Grafana Pyroscope documentation.

So far, profiling has transformed an attractive database theory into a response-construction hypothesis and then checked that the chosen change affected both CPU cost and p99. It has not proven that a 350 ms p99 meets the product target, nor that every region, cache state, or language behaves the same way.

Trade-offs, Limits, and Signals to Watch

This approach improves the chance of fixing the dominant path. It costs representative traffic selection, collector overhead, storage and access control for profile data, and careful comparison. The trade-off is worth it when a meaningful request class is slow enough that a wrong optimization would cost more than the investigation.

Profiling can still fail in several ways:

• A profile from a warm cache cannot explain a cold-miss incident.
• A CPU profile can be nearly empty while threads wait on a lock or I/O.
• Sampling can miss a rare, short path; deterministic instrumentation can add enough overhead to distort a fragile workload.
• A function with large inclusive cost may be a useful dispatcher, not the source of avoidable work.
• Reducing CPU may not improve p99 if the remaining boundary is queueing, network delay, or a lock.

The boundary signal is disagreement between the hypothesis and the next observation. If encode_json shrinks but latency does not, switch from “more CPU tuning” to the resource that can explain the remaining time. If a lock profile shows one shared cache mutex, the next lesson on flame graphs can make the relevant stack family visible; the following lesson investigates lock contention and I/O wait in more depth.

Check: The p99 of a worker job is 900 ms. Its CPU profile has no wide hot stack, while worker threads spend much of the interval blocked on one mutex. Should the team micro-optimize the most visible CPU function?

Think first, then reveal.

Answer: No. The CPU evidence does not support CPU work as the main cause. Start a lock or blocking investigation, identify the contested path, and preserve the correctness reason for any synchronization before changing it.

Practice: Write a Profiling Runbook Step

An image-processing worker has rising queue lag. One sampled job shows 1.2 seconds of wall time, 90 ms of CPU time, and an external image store span of 80 ms. The service uses a shared in-process metadata map. Engineers want to rewrite the image codec because its source is complex.

Write the next small profiling step. Name the request or job cohort, the resource question, the profile to capture, one signal that would change your mind, and the before-and-after result needed before approving a change.

A good answer should mention:

• a cohort such as image jobs of the same size range and queue state, rather than all worker traffic;
• a waiting or lock hypothesis, because wall time is much larger than observed CPU and store time;
• a lock, mutex, blocking, or off-CPU profile that can reveal time around the shared metadata map;
• a disconfirming signal, such as a profile showing CPU in decoding or a longer external-store span; and
• a repeatable comparison of queue lag, job p95/p99, lock or wait evidence, and output correctness after one bounded change.

Connections

The CDN lesson reduced duplicate origin work but left the expensive miss path to inspect. This lesson supplies the evidence loop for that path. The next lesson turns aggregated profile stacks into flame graphs, so the learner can see where a wide stack begins before choosing a function to change.

Resources

• [DOCS] The Python Profilers — Focus: Distinguish deterministic profile statistics, internal time, cumulative time, and profiling overhead.
• [DOCS] Profiling Go Programs — Focus: Follow a concrete pprof capture, focused change, and repeat measurement.
• [DOCS] Grafana Pyroscope — Focus: Connect continuous profiles with metrics, logs, traces, comparison, and flame-graph views.

Key Takeaways

• Start profiling from a labelled slow workload and a resource question, not from a suspicious-looking function.
• CPU, waiting, allocation, and lock evidence answer different questions; a quiet CPU profile is often a cue to change the profile type.
• Read inclusive cost as a path to investigate and self cost as local work; neither number alone chooses the fix.
• A trustworthy optimization changes one evidence-backed mechanism, then compares user latency, resource cost, and correctness under comparable conditions.
• Profiling locates work inside a process. It does not replace latency metrics, traces, dependency evidence, or a product performance target.