Performance and profiling

Every engineer has a story about optimizing the wrong thing. A week goes into a parsing loop that turns out to be 2% of request time, while the real problem is 80 sequential database queries. The fix is a habit, not cleverness: measure first, find where the time goes, change one thing, and measure again.

Performance work has its own vocabulary and tools, and you can learn both. This topic covers how to describe latency, how to predict the payoff of a change, how profilers find the expensive code, how to find time spent waiting, and how to benchmark without fooling yourself.

Concepts in this section

Read them in this order.

Putting it together: a slow endpoint

Here is a real kind of investigation, condensed. A GET /api/orders endpoint has a p99 of 1.9 seconds, against a target of 300 ms. Hosts sit at about 15% CPU, so adding servers has not helped.

1. Check the queue with Little's law. Peak traffic is 400 requests per second at 0.45 s each, so about 180 requests are in flight. The fleet has 128 worker slots. Requests queue for a free worker, so the p99 is mostly waiting.
2. Trace one slow request. The trace shows one query for the list, then one query per order for its line items. Each takes about 4 ms, so 100 queries take about 400 ms. Each query is fast alone, which is why no slow-query log flagged it. This is the classic N+1 query.
3. Fix the N+1. Load the line items in one batched query. The p50 falls from 450 ms to about 70 ms. In-flight requests at peak drop to about 28, well under 128, and the p99 falls to about 180 ms.
4. Profile the CPU. Traffic grew, and large responses now dominate CPU. A flame graph shows 68% of CPU in serialization, mostly in a deep copy done before the JSON encoder runs.
5. Predict before you change. Serialization is 70% of a 400 ms request. A faster encoder that is 10 times quicker on this payload gives 1 / (0.30 + 0.70 / 10) ≈ 2.7×, so 400 ms becomes about 148 ms. Benchmark it, ship it, and re-profile.
6. Add a guard. Test the query count per request, run the serializer benchmark in CI, and alert on the endpoint's p99.

This is a sketch of the fix in an ORM. The first version makes one round trip for the list and one more for each order's line items. The second makes two round trips, whatever the list length.

orders = session.query(Order).filter_by(customer_id=cid).limit(100).all()
return [to_dto(o, o.line_items) for o in orders]   # each o.line_items runs a query

orders = (session.query(Order)
          .options(selectinload(Order.line_items))  # one "IN (...)" query
          .filter_by(customer_id=cid).limit(100).all())

The order matters. The first problem was waiting, which a CPU profile could not see. The second problem was CPU, found only after the waiting was gone.

Common mistakes

• Optimizing without a profile. Intuition about what must be slow is often wrong.
• Reporting averages. Show percentiles, and merge histograms before computing them across hosts.
• Reading a CPU graph for a latency problem. Waiting time is invisible to it.
• Changing several things at once. You cannot tell which change helped.
• Skipping the guard. Without a test or alert, the problem returns quietly.

Key takeaways

• Measure, find the biggest share of time, change one thing, and measure again.
• Predict the payoff with Amdahl's law and the concurrency with Little's law before you code.
• Sampling profilers are cheap enough for production. Read width as share of samples.
• Low CPU with high latency means waiting. Use tracing and off-CPU profiles.
• Benchmarks need warmup, consumed results, realistic data and statistics.

Further learning

Brendan Gregg's Linux performance pages cover the USE method and the tools for each resource.

py-spy: sampling profiler for PythonSampling profiler for Python programs. Contribute to benfred/py-spy development by creating an account on GitHub.GitHub