Profile Before You Optimise: A Five-Minute Habit

Every experienced developer has a story about the optimisation that took a day and made the system slower. It usually starts the same way: someone reads the code, spots something that looks expensive, and fixes it without measuring.

Measure before you change anything

Before touching a line, answer three questions with numbers, not feelings:

• What is the baseline? Write down the current duration, query count or memory peak.
• Where does the time actually go? A profiler or a query log, not intuition.
• What would “fixed” look like? A target number makes it obvious when to stop.

The five-minute loop

This works in almost any stack, and it is short enough to do every time:

# 1. Capture a baseline (repeat 3 times, keep the median)
time ./run-the-thing.sh

# 2. Find the hot path
#    PHP:   xdebug or a sampling profiler
#    SQL:   SHOW FULL PROCESSLIST; and the slow query log
#    Node:  node --prof app.js && node --prof-process isolate-*.log

# 3. Change ONE thing
# 4. Re-measure with the exact same command

The single-change rule is what makes the loop trustworthy. If you change three things and the number improves, you have learned nothing about which one mattered — and you will not know which one to keep when the next refactor comes.

The usual suspects, in order

• Database round trips inside a loop. One query per row is almost always the answer, and it is usually fixable with a join or a single IN (...) query.
• Serialisation on the hot path. Reading a 2 MB JSON file per request, or decoding something you already had in memory.
• Network chatter. A hundred small API calls where one batched call would do.
• Real algorithms. An O(n²) loop only matters when n grows — which is exactly when it is hardest to fix later.

Write the number down

Put the before and after figures in the pull request description. It takes ten seconds, it justifies the change to any reviewer, and it stops the same “optimisation” from being reverted and re-applied six months later.

If you cannot measure it, you cannot claim you improved it — you can only claim you changed it.

Sampling or instrumenting: two profilers, two answers

Two families of profiler answer different questions, and picking the wrong one wastes an afternoon.

• Instrumenting profilers (Xdebug, XHProf) hook every function entry and exit, giving exact call counts. They also distort: Xdebug commonly multiplies request time by 3 to 20, so anything waiting on a socket behaves nothing like production.
• Sampling profilers (perf, SPX or Excimer for PHP, node --cpu-prof) interrupt the process a few hundred times per second and record the stack they find. Overhead is typically 1–3%, so they are safe against real traffic.

Sample rate sets the resolution. At 99 Hz you collect about one sample per 10 ms of work, so a function costing 4 ms per request usually never appears. Sampling answers “where did the 1.4 seconds go?”; it cannot answer “how many times did this query run?”. For counting, use a query logger.

Capture a flame graph and read it correctly

perf record -F 99 -g -p 12345 -- sleep 30
perf script | stackcollapse-perf.pl | flamegraph.pl > cpu.svg

node --cpu-prof --cpu-prof-dir=./prof app.js

Three rules make it readable:

• The horizontal axis is proportion of time, not chronological order. A frame twice as wide spent twice as much CPU.
• The vertical axis is stack depth. A wide frame near the bottom — main, a router — only means everything above it ran underneath it.
• Look for the deepest wide frame: that is where time is spent with nothing below it left to blame.

When one function appears as fifty thin slivers across the graph, it is called in a loop, and the total width of its slivers is the number that matters. A sorted “top functions” list hides that.

Measure database time separately from application time

Most requests run on two clocks: SQL time and time in your own code. Log them separately or you optimise the wrong half.

// Wrap the connection once, not every call site.
$start = microtime(true);
$rows  = $pdo->query($sql)->fetchAll();
$log[] = sprintf('%7.1f ms  %s', (microtime(true) - $start) * 1000, $sql);

Frameworks expose the hook already: DB::listen() in Laravel, connection.queries in Django, an ActiveSupport::Notifications subscriber in Rails. Emit three numbers per request — wall time, query count, total query milliseconds. If a page takes 1 400 ms and its queries total 310 ms, the database is not your problem, whatever the slow query log says.

Cache hit ratios belong on the same dashboard, because a low one looks exactly like slow code. In SHOW GLOBAL STATUS, compare Innodb_buffer_pool_read_requests with Innodb_buffer_pool_reads: below roughly 99%, the pool is undersized. An OPcache hit rate under 99% means PHP is recompiling files on most requests.

Profiling production without becoming the incident

• Fix the budget first: under 3% extra CPU and under 2% extra latency, or you stop.
• Profile one instance, or one request in a thousand — never every worker.
• Never enable Xdebug in production. It changes timing by an order of magnitude and can exhaust memory on requests that were previously fine.
• Scrub what you log: query logs carry bind parameters, and those carry passwords and personal data.

If profiling production is forbidden, replay instead: capture a real request — path, session, parameters — and run it against a copy of the data. That is enough to choose where to look next, not enough to claim an improvement.

When the obvious suspect was innocent

A page sits at p95 1.40 s. The slow query log shows a 400 ms query underneath it, so that query is rewritten twice and the page lands at 1.28 s — noise. Proper measurement said something else:

The flame graph explained the missing second: roughly 700 ms sat in one call to preg_replace inside a Markdown renderer, run once per article on a page showing 24 articles. Caching rendered HTML against (article_id, updated_at) removed it. The suspected query was 310 ms of a 1 400 ms request — real, but sixth on the list.

The lesson generalises: the slow query log sorts by the duration of one execution, not by impact. A 40 ms query run 400 times per page costs more than a 400 ms query run once.