Rust Web Server with Axum 0.8: Profiling and Performance

Episode 42, the last episode of the Rust Backend series, where we built the backend of a blog step by step. After episode 41 our blog API does everything we planned. But is it fast? Today we measure, find the slow part, fix it, and measure again. Never guess. All the code below is the final, tested code from the video, ready to copy.

• New to Rust? Start with the beginner series.
• The full backend series playlist is here.

We continue in the same blog_api project from episode 41, with the 50,000 posts we added in episode 40. Tools: oha (cargo install oha) and perf (sudo apt install linux-tools-generic).

1. The rule

First measure, then change one thing, then measure again. Without numbers, every speed-up is a guess.

2. A load test with oha

oha sends many requests at once and reports the results. 50 connections for 10 seconds, on the posts list sorted by title:

cargo run
oha -c 50 -z 10s --no-tui 'http://localhost:8080/posts?sort=title' | grep -E 'Success|Requests/sec|99.00%'

About 300 requests per second, and the slowest 1% take about 260 ms. But cargo run is a debug build.

3. Release builds

The first and easiest step: --release. The compiler optimizes everything; building takes longer.

cargo run --release
oha -c 50 -z 10s --no-tui 'http://localhost:8080/posts?sort=title' | grep -E 'Success|Requests/sec|99.00%'

About 650 requests per second: twice as many, without changing a line of code. Never measure a debug build.

4. Where does the time go? perf

perf samples the running program hundreds of times per second and counts which functions were running. We put load on it in the background, and record six seconds:

oha -c 50 -z 12s --no-tui 'http://localhost:8080/posts?sort=title' > /dev/null &
perf record -e cpu-clock:u -F 499 -g -p $(pgrep -x blog_api) -o /tmp/perf.data -- sleep 6
perf report --stdio -i /tmp/perf.data | head -40

Almost all of the time is inside SQLite: sqlite3VdbeExec, sqlite3BtreeNext (walking through the rows of the table, one by one), and countStep. Our own Rust code is hardly visible.

5. EXPLAIN QUERY PLAN

Let's ask SQLite how it runs our queries:

sqlite3 blog.db "EXPLAIN QUERY PLAN SELECT * FROM posts WHERE deleted_at IS NULL ORDER BY title LIMIT 10"; sqlite3 blog.db "EXPLAIN QUERY PLAN SELECT COUNT(*) FROM posts WHERE deleted_at IS NULL"

QUERY PLAN
|--SCAN posts
`--USE TEMP B-TREE FOR ORDER BY

SCAN posts and USE TEMP B-TREE FOR ORDER BY: it reads all 50,000 posts and sorts them, for every request, just to return 10. The count query scans the whole table too.

6. An index for sorting

An index on title keeps the posts sorted already. A partial index, only for posts that are not deleted, because that is what every query asks for:

sqlx migrate add index_posts_title

CREATE INDEX posts_title ON posts(title) WHERE deleted_at IS NULL;

sqlx migrate run
sqlite3 blog.db "EXPLAIN QUERY PLAN SELECT * FROM posts WHERE deleted_at IS NULL ORDER BY title LIMIT 10"; sqlite3 blog.db "EXPLAIN QUERY PLAN SELECT COUNT(*) FROM posts WHERE deleted_at IS NULL"

Now: SCAN posts USING INDEX posts_title. No more sorting: SQLite walks the index in order and stops after 10 rows. Even the count uses the (smaller) index.

7. Measure again

cargo run --release
oha -c 50 -z 10s --no-tui 'http://localhost:8080/posts?sort=title' | grep -E 'Success|Requests/sec|99.00%'

About 2,900 requests per second: more than four times the release build before, and the slowest 1% went from about 124 ms to about 25 ms. One line of SQL, and we know it works, because we measured.

(Your numbers will differ with your machine; the ratios are what matter.)

8. Slow on purpose

One more test, on login:

oha -n 40 -c 10 --no-tui -m POST -H 'content-type: application/json' -d '{"email":"ana@example.com","password":"hunter2hunter2"}' http://localhost:8080/login | grep -E 'Requests/sec|\[[0-9]{3}\]'

Login is slow on purpose: argon2 protects passwords (episode 17). And hammering it, almost every answer (36 of 40) is 429 Too Many Requests: the rate limit from episode 23 protects it. Here, slow is a feature.

Other things worth knowing, but only after measuring: a database pool size that matches the load, less cloning of big values, and caching (episode 28).

9. That's the series

From "hello world" in episode 1 to a tested, documented, monitored blog API in Docker, plus a look inside macros, futures and unsafe. Every episode's code is in this blog, in the Rust Backend with Axum folder. Thank you for following all 42 episodes!

The final code

migrations/0011_index_posts_title.sql

-- Add migration script here
CREATE INDEX posts_title ON posts(title) WHERE deleted_at IS NULL;

Recap

• Measure, change one thing, measure again
• oha for load tests; always measure a --release build
• perf record / perf report show where the CPU time goes
• EXPLAIN QUERY PLAN: SCAN plus USE TEMP B-TREE means a full scan and a sort
• An index on the sort column (partial, WHERE deleted_at IS NULL) removed the sort: over 4x faster
• Slow can be right: argon2 and the rate limit protect login

That was the last episode of the Rust Backend series. Watch the whole series on YouTube.