Axum 0.7.1 uses the CPU more intensively

[dayvejones]

Hello!

I updated axum from version 0.6.20 to 0.7.1.

According to my metrics, the load on the CPU has increased significantly, although the load on the application has remained the same (300-500 rps). The values, of course, are not too large, but the contrast before and after the update is very noticeable. The load on RAM did not increase or increased slightly. Response latency have not changed either.

My application is a simple service wrapper over a Postgres database (tokio-postgres + bb8).

All my dependencies:

[dependencies]
axum = "0.7.1"
bb8 = "0.8.1"
bb8-postgres = "0.8.1"
tokio = { version = "1.34.0", features = ["macros", "rt-multi-thread"] }
tokio-postgres = { version = "0.7.10", features = ["with-chrono-0_4"] }
serde = { version = "1.0.193", features = ["derive"] }
serde_json = "1.0.108"
config = { version = "0.13.4", default-features = false, features = ["toml"] }
utoipa = { version = "4.1.0", features = ["axum_extras", "chrono", "preserve_path_order"] }
utoipa-swagger-ui = { version = "5.0.0", features = ["axum"] }
chrono = { version = "0.4.31", default-features = false, features = ["serde"] }
metrics = { version ="0.21.1", default-features = false }
metrics-exporter-prometheus = { version ="0.12.1", default-features = false }
tracing = { version ="0.1.40", default-features = false }
tracing-subscriber = { version = "0.3.18", features = ["env-filter"] }
tower-http = { version = "0.5.0", features = ["trace"] }

[profile.release]
strip = true  # Automatically strip symbols from the binary.
opt-level = "z"
lto = true
codegen-units = 1

I use docker image with Alpine 3.18.4
Rust version: 1.74.0
Build command: cargo build --target x86_64-unknown-linux-musl --release

I would be grateful if you could share information about how upgrading Axum version affected your CPU load metrics. Thanks!

[davidpdrsn]

Huh that's very surprising. I honestly have no clue what could be causing this but would be very curious to find out.

Are you able to do more investigation? With the data you've provided here is hard to really say much. Can you run a sampling profiler or something to figure out where the CPU is spending its time?

[dayvejones]

Hello!

I made another experiment (this time on large resources) on a virtual machine with 16 gigabytes of RAM, 8 cores, SSD, OS - Debian 4.19.235-1. Without using docker. The Postgres database is deployed on the current machine (max_connections = 4096).

I made 2 simple examples with the following difference:

1. axum 0.6.20 + tower-http 0.4.4

2. axum 0.7.1 + tower-http 0.5.0

sample axum 0.6.20

//cargo.toml
[package]
name = "test_proj_axum06"
version = "0.1.0"
edition = "2021"
publish = false

[dependencies]
axum = "0.6.20"
bb8 = "0.8.1"
bb8-postgres = "0.8.1"
tokio = { version = "1.34.0", features = ["macros", "rt-multi-thread"] }
tokio-postgres = { version = "0.7.10", features = ["with-chrono-0_4"] }
tracing = { version ="0.1.40", default-features = false }
tracing-subscriber = { version = "0.3.18", features = ["env-filter"] }
metrics = { version ="0.21.1", default-features = false }
metrics-exporter-prometheus = { version ="0.12.1", default-features = false }
tower-http = { version = "0.4.4", features = ["trace"] }

[profile.release]
strip = true  # Automatically strip symbols from the binary.
opt-level = "z"
lto = true
codegen-units = 1

// src\main.rs
use std::{net::SocketAddr, time::Instant, future::ready};

use axum::{
    async_trait,
    extract::{FromRef, FromRequestParts, State, MatchedPath},
    http::{request::Parts, StatusCode, Request},
    routing::get,
    Router, middleware::{Next, self}, response::Response,
};
use bb8::{Pool, PooledConnection};
use bb8_postgres::PostgresConnectionManager;
use metrics_exporter_prometheus::{PrometheusHandle, PrometheusBuilder, Matcher};
use tokio_postgres::NoTls;
use tracing_subscriber::{layer::SubscriberExt, filter, util::SubscriberInitExt};
use tower_http::trace::TraceLayer;

#[tokio::main]
async fn main() {
    let filter = filter::LevelFilter::ERROR;

    let recorder_handle = setup_metrics_recorder();
    tracing_subscriber::registry()
      .with(filter)
      .init();

    // set up connection pool
    let manager =
        PostgresConnectionManager::new_from_stringlike("postgres://postgres:password@localhost:5432/rs-playground", NoTls)
            .unwrap();
    let pool = Pool::builder().max_size(50).build(manager).await.unwrap();

    // build our application with some routes
    let app = Router::new()
        .route(
            "/",
            get(using_connection_pool_extractor).post(using_connection_extractor),
        )
        .route("/metrics", get(move || ready(recorder_handle.render())))
        .route_layer(middleware::from_fn(move |req, next| {
            track_metrics(req, next)
        }))
        .with_state(pool)
        .layer(TraceLayer::new_for_http());

    let addr = SocketAddr::from(([127, 0, 0, 1], 8866));
    println!("listening on {}", addr);
    axum::Server::bind(&addr)
            .serve(app.into_make_service())
            .await
            .unwrap();
}

type ConnectionPool = Pool<PostgresConnectionManager<NoTls>>;

async fn using_connection_pool_extractor(
    State(pool): State<ConnectionPool>,
) -> Result<String, (StatusCode, String)> {
    let conn = pool.get().await.map_err(internal_error)?;

    let row = conn
        .query_one("select 1 + 1", &[])
        .await
        .map_err(internal_error)?;
    let two: i32 = row.try_get(0).map_err(internal_error)?;

    Ok(two.to_string())
}

struct DatabaseConnection(PooledConnection<'static, PostgresConnectionManager<NoTls>>);

#[async_trait]
impl<S> FromRequestParts<S> for DatabaseConnection
where
    ConnectionPool: FromRef<S>,
    S: Send + Sync,
{
    type Rejection = (StatusCode, String);

    async fn from_request_parts(_parts: &mut Parts, state: &S) -> Result<Self, Self::Rejection> {
        let pool = ConnectionPool::from_ref(state);

        let conn = pool.get_owned().await.map_err(internal_error)?;

        Ok(Self(conn))
    }
}

async fn using_connection_extractor(
    DatabaseConnection(conn): DatabaseConnection,
) -> Result<String, (StatusCode, String)> {
    let row = conn
        .query_one("select 1 + 1", &[])
        .await
        .map_err(internal_error)?;
    let two: i32 = row.try_get(0).map_err(internal_error)?;

    Ok(two.to_string())
}

fn internal_error<E>(err: E) -> (StatusCode, String)
where
    E: std::error::Error,
{
    (StatusCode::INTERNAL_SERVER_ERROR, err.to_string())
}

fn setup_metrics_recorder() -> PrometheusHandle {
    const EXPONENTIAL_SECONDS: &[f64] = &[
        0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1.0, 2.5, 5.0, 10.0,
    ];

    PrometheusBuilder::new()
        .set_buckets_for_metric(
            Matcher::Full("http_requests_duration_seconds".to_string()),
            EXPONENTIAL_SECONDS,
        )
        .unwrap()
        .install_recorder()
        .unwrap()
}

async fn track_metrics<B>(req: Request<B>, next: Next<B>) -> Result<Response, StatusCode> {
    let start = Instant::now();
    let path = if let Some(matched_path) = req.extensions().get::<MatchedPath>() {
        matched_path.as_str().to_owned()
    } else {
        req.uri().path().to_owned()
    };
    let method= req.method().clone();

    let client_name = req
        .headers()
        .get("x-client-name")
        .and_then(|header| header.to_str().ok())
        .unwrap_or("anonymous")
        .to_owned();

    let response = next.run(req).await;

    let latency = start.elapsed().as_secs_f64();
    let status = response.status().as_u16().to_string();

    let labels = [
        ("method", method.to_string()),
        ("path", path),
        ("status", status),
        ("client", client_name),
    ];

    metrics::increment_counter!("http_requests_total", &labels);
    metrics::histogram!("http_requests_duration_seconds", latency, &labels);

    return Ok(response);
}

sample axum 0.7.1

//cargo.toml
[package]
name = "test_proj_axum07"
version = "0.1.0"
edition = "2021"
publish = false

[dependencies]
axum = "0.7.1"
bb8 = "0.8.1"
bb8-postgres = "0.8.1"
tokio = { version = "1.34.0", features = ["macros", "rt-multi-thread"] }
tokio-postgres = { version = "0.7.10", features = ["with-chrono-0_4"] }
tracing = { version ="0.1.40", default-features = false }
tracing-subscriber = { version = "0.3.18", features = ["env-filter"] }
metrics = { version ="0.21.1", default-features = false }
metrics-exporter-prometheus = { version ="0.12.1", default-features = false }
tower-http = { version = "0.5.0", features = ["trace"] }

[profile.release]
strip = true  # Automatically strip symbols from the binary.
opt-level = "z"
lto = true
codegen-units = 1

// src\main.rs
use std::{time::Instant, future::ready};

use axum::{
    async_trait,
    routing::{get},
    Router, middleware::{self, Next}, 
    http::{request::Parts, StatusCode},
    response::Response, extract::MatchedPath,
    extract::{FromRef, FromRequestParts, State, Request}
};

use bb8::{Pool, PooledConnection};
use bb8_postgres::PostgresConnectionManager;
use metrics_exporter_prometheus::{PrometheusHandle, PrometheusBuilder, Matcher};
use tokio_postgres::NoTls;
use tracing_subscriber::{layer::SubscriberExt, filter, util::SubscriberInitExt};
use tower_http::trace::TraceLayer;

#[tokio::main]
async fn main() {
    let filter = filter::LevelFilter::ERROR;

    let recorder_handle = setup_metrics_recorder();
    tracing_subscriber::registry()
      .with(filter)
      .init();

    // set up connection pool
    let manager =
        PostgresConnectionManager::new_from_stringlike("postgres://postgres:password@localhost:5432/rs-playground", NoTls)
            .unwrap();
    let pool = Pool::builder().max_size(50).build(manager).await.unwrap();

    // build our application with some routes
    let app = Router::new()
        .route(
            "/",
            get(using_connection_pool_extractor).post(using_connection_extractor),
        )
        .route("/metrics", get(move || ready(recorder_handle.render())))
        .route_layer(middleware::from_fn(move |req, next| {
            track_metrics(req, next)
        }))
        .with_state(pool)
        .layer(TraceLayer::new_for_http());

    // run it
    let listener = tokio::net::TcpListener::bind("127.0.0.1:8865")
        .await
        .unwrap();
    tracing::debug!("listening on {}", listener.local_addr().unwrap());
    axum::serve(listener, app).await.unwrap();
}

type ConnectionPool = Pool<PostgresConnectionManager<NoTls>>;

async fn using_connection_pool_extractor(
    State(pool): State<ConnectionPool>,
) -> Result<String, (StatusCode, String)> {
    let conn = pool.get().await.map_err(internal_error)?;

    let row = conn
        .query_one("select 1 + 1", &[])
        .await
        .map_err(internal_error)?;
    let two: i32 = row.try_get(0).map_err(internal_error)?;

    Ok(two.to_string())
}

struct DatabaseConnection(PooledConnection<'static, PostgresConnectionManager<NoTls>>);

#[async_trait]
impl<S> FromRequestParts<S> for DatabaseConnection
where
    ConnectionPool: FromRef<S>,
    S: Send + Sync,
{
    type Rejection = (StatusCode, String);

    async fn from_request_parts(_parts: &mut Parts, state: &S) -> Result<Self, Self::Rejection> {
        let pool = ConnectionPool::from_ref(state);

        let conn = pool.get_owned().await.map_err(internal_error)?;

        Ok(Self(conn))
    }
}

async fn using_connection_extractor(
    DatabaseConnection(conn): DatabaseConnection,
) -> Result<String, (StatusCode, String)> {
    let row = conn
        .query_one("select 1 + 1", &[])
        .await
        .map_err(internal_error)?;
    let two: i32 = row.try_get(0).map_err(internal_error)?;

    Ok(two.to_string())
}

fn internal_error<E>(err: E) -> (StatusCode, String)
where
    E: std::error::Error,
{
    (StatusCode::INTERNAL_SERVER_ERROR, err.to_string())
}

fn setup_metrics_recorder() -> PrometheusHandle {
    const EXPONENTIAL_SECONDS: &[f64] = &[
        0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1.0, 2.5, 5.0, 10.0,
    ];

    PrometheusBuilder::new()
        .set_buckets_for_metric(
            Matcher::Full("http_requests_duration_seconds".to_string()),
            EXPONENTIAL_SECONDS,
        )
        .unwrap()
        .install_recorder()
        .unwrap()
}

async fn track_metrics(req: Request, next: Next) -> Result<Response, StatusCode> {
    let start = Instant::now();
    let path = if let Some(matched_path) = req.extensions().get::<MatchedPath>() {
        matched_path.as_str().to_owned()
    } else {
        req.uri().path().to_owned()
    };
    let method= req.method().clone();

    let client_name = req
        .headers()
        .get("x-client-name")
        .and_then(|header| header.to_str().ok())
        .unwrap_or("anonymous")
        .to_owned();

    let response = next.run(req).await;

    let latency = start.elapsed().as_secs_f64();
    let status = response.status().as_u16().to_string();

    let labels = [
        ("method", method.to_string()),
        ("path", path),
        ("status", status),
        ("client", client_name),
    ];

    metrics::increment_counter!("http_requests_total", &labels);
    metrics::histogram!("http_requests_duration_seconds", latency, &labels);

    return Ok(response);
}

I installed the wrk utility on my current machine for load testing and launched both versions of the program on different ports
0.7.1 - port: 8865
0.6.20 - port :8866

cargo build --release

result file size for 0.6.20: 1763912 bytes
result file size for 0.7.1: 2370320 bytes ( +30% )

Next, I ran tests with different parameters and got different metrics. Example:

5 times for 0.7.1: wrk -t8 -c200 -d30s http://127.0.0.1:8865

wrk -t8 -c200 -d30s http://127.0.0.1:8865

Running 30s test @ http://127.0.0.1:8865
8 threads and 200 connections
Thread Stats Avg Stdev Max +/- Stdev
Latency 6.21ms 1.68ms 63.70ms 90.46%
Req/Sec 4.06k 328.79 8.28k 71.68%
970941 requests in 30.07s, 108.34MB read
Requests/sec: 32284.52
Transfer/sec: 3.60MB

wrk -t8 -c200 -d30s http://127.0.0.1:8865

Running 30s test @ http://127.0.0.1:8865
8 threads and 200 connections
Thread Stats Avg Stdev Max +/- Stdev
Latency 6.10ms 1.40ms 30.57ms 87.88%
Req/Sec 4.13k 310.18 10.49k 76.53%
987827 requests in 30.08s, 110.22MB read
Requests/sec: 32843.34
Transfer/sec: 3.66MB

wrk -t8 -c200 -d30s http://127.0.0.1:8865

Running 30s test @ http://127.0.0.1:8865
8 threads and 200 connections
Thread Stats Avg Stdev Max +/- Stdev
Latency 6.27ms 1.64ms 57.89ms 90.82%
Req/Sec 4.03k 346.98 7.93k 71.74%
963935 requests in 30.08s, 107.56MB read
Requests/sec: 32042.36
Transfer/sec: 3.58MB

wrk -t8 -c200 -d30s http://127.0.0.1:8865

Running 30s test @ http://127.0.0.1:8865
8 threads and 200 connections
Thread Stats Avg Stdev Max +/- Stdev
Latency 6.07ms 1.21ms 24.68ms 85.01%
Req/Sec 4.14k 292.22 8.27k 76.12%
991100 requests in 30.07s, 110.59MB read
Requests/sec: 32959.00
Transfer/sec: 3.68MB

wrk -t8 -c200 -d30s http://127.0.0.1:8865

Running 30s test @ http://127.0.0.1:8865
8 threads and 200 connections
Thread Stats Avg Stdev Max +/- Stdev
Latency 6.70ms 1.89ms 42.34ms 89.15%
Req/Sec 3.78k 484.53 9.15k 67.17%
903237 requests in 30.09s, 100.78MB read
Requests/sec: 30019.71
Transfer/sec: 3.35MB

5 times for 0.6.20: wrk -t8 -c200 -d30s http://127.0.0.1:8866

wrk -t8 -c200 -d30s http://127.0.0.1:8866

wrk -t8 -c200 -d30s http://127.0.0.1:8866

Running 30s test @ http://127.0.0.1:8866
8 threads and 200 connections
Thread Stats Avg Stdev Max +/- Stdev
Latency 5.93ms 1.56ms 26.35ms 88.13%
Req/Sec 4.25k 372.38 12.73k 77.07%
1017542 requests in 30.10s, 113.54MB read
Requests/sec: 33806.29
Transfer/sec: 3.77MB

wrk -t8 -c200 -d30s http://127.0.0.1:8866

Running 30s test @ http://127.0.0.1:8866
8 threads and 200 connections
Thread Stats Avg Stdev Max +/- Stdev
Latency 6.27ms 1.84ms 58.98ms 88.73%
Req/Sec 4.03k 432.04 7.98k 68.00%
963948 requests in 30.06s, 107.56MB read
Requests/sec: 32071.60
Transfer/sec: 3.58MB

wrk -t8 -c200 -d30s http://127.0.0.1:8866

Running 30s test @ http://127.0.0.1:8866
8 threads and 200 connections
Thread Stats Avg Stdev Max +/- Stdev
Latency 5.98ms 1.61ms 46.66ms 89.06%
Req/Sec 4.22k 325.47 7.29k 68.68%
1008027 requests in 30.06s, 112.48MB read
Requests/sec: 33529.36
Transfer/sec: 3.74MB

wrk -t8 -c200 -d30s http://127.0.0.1:8866

Running 30s test @ http://127.0.0.1:8866
8 threads and 200 connections
Thread Stats Avg Stdev Max +/- Stdev
Latency 6.01ms 1.86ms 46.45ms 91.85%
Req/Sec 4.22k 366.32 6.89k 75.57%
1009549 requests in 30.08s, 112.65MB read
Requests/sec: 33559.06
Transfer/sec: 3.74MB

wrk -t8 -c200 -d30s http://127.0.0.1:8866

Running 30s test @ http://127.0.0.1:8866
8 threads and 200 connections
Thread Stats Avg Stdev Max +/- Stdev
Latency 6.02ms 1.58ms 54.97ms 88.46%
Req/Sec 4.19k 405.40 10.53k 74.62%
1001490 requests in 30.10s, 111.75MB read
Requests/sec: 33273.33
Transfer/sec: 3.71MB

During the tests, the program on axum 0.6.20 used from 3.06 to 3.37 CPU cores, and the program on axum 0.7.1 from 3.2 to 3.6 CPU cores. Also, version 0.6.20 produced more Requests per second ( better on ~3..8 percents).

I repeated this experiment many times to ensure that the results were repeatable. Occasionally the results were similar, but most often the performance of version 0.6.20 was better. Version 0.7.1 never won.

I also changed the parameters for wrk: I increased and decreased the number of threads and connections.
The general trend has always remained the same.

Perhaps someone else would like to test the same program on different versions of axum (hyper and tower-http). It would be interesting.

I'll try to figure out later how to use the sampling profiler to run the program inside a docker image with few resources (for result from first post)

[jplatte]

Re. sampling profilers, flamegraph is an easy to use solution for getting insights into where time is spent inside an executable.

[yanns]

We are also observing more CPU consumption when migrating to axum 0.7
The update to axum 0.7.4 mitigated this a bit, but not on the same level as axum 0.6

[yanns]

@dayvejones on my side, I've noticed this issue because my application is consuming quite large request bodies. Maybe it's less observable with small bodies, a more common pattern? Or people do not care anymore :D

[Aleksbgbg]

@dayvejones @yanns
I happened to be developing an app that needed to consume requests of 100MiB at a time (or larger). I was disheartened at how much slower ingestion was in Axum was than Go, and decided to get to the bottom of it by using a benchmark.

It turns out that using tokio::io::copy (as per the example here) is one of the slowest ways to copy to a file.

Here are the results for various configurations (in order from fastest to slowest):

framework           | method              | block size | result
--------------------------------------------------------------------------------------------------------------------------------------------
frameworkless       | manual              | 64K        | INFO benchmark: 100 sends, average response 132.67ms (total 9.77GiB at 753.77MiB/s)
gin (go)            | io.Copy             | 32K        | INFO benchmark: 100 sends, average response 135.94ms (total 9.77GiB at 735.60MiB/s)
frameworkless-async | manual              | 64K        | INFO benchmark: 100 sends, average response 165.47ms (total 9.77GiB at 604.35MiB/s)
frameworkless       | manual              | 8K         | INFO benchmark: 100 sends, average response 179.49ms (total 9.77GiB at 557.14MiB/s)
axum                | manual              | 64K        | INFO benchmark: 100 sends, average response 276.40ms (total 9.77GiB at 361.79MiB/s)
axum                | tokio::io::copy_buf | 64K        | INFO benchmark: 100 sends, average response 280.43ms (total 9.77GiB at 356.60MiB/s)
frameworkless-async | manual              | 8K         | INFO benchmark: 100 sends, average response 483.65ms (total 9.77GiB at 206.76MiB/s)
actix               | tokio::io::copy     | 8K         | INFO benchmark: 100 sends, average response 559.14ms (total 9.77GiB at 178.85MiB/s)
axum                | tokio::io::copy     | 8K         | INFO benchmark: 100 sends, average response 566.74ms (total 9.77GiB at 176.45MiB/s)
frameworkless-async | tokio::io::copy     | 8K         | INFO benchmark: 100 sends, average response 584.24ms (total 9.77GiB at 171.16MiB/s)

tokio::io::copy is consistently last place, with manual 64K transfers being fastest.

Note that the frameworkless example is neither mutlithreaded nor concurrent, so it has an unfair speed advantage, but apps running on tokio are able to make maximum use of the hardware even if individual requests are a little bit slower.

64K is the max packet size for TCP, and on my kernel this is the biggest size that a single read would return. You could likely make this a little bit faster by buferring multiple reads at once, and writing to a file in big chunks of e.g. 256K or more (you could find the optimum with an exponential search), depending on how much memory you want to sacrifice.

My benchmark is available here: https://gitlab.com/Aleksbgbg/data-ingestion-benchmark; feel free to run these for yourselves on your own systems and test the various configurations.

We could also use this benchmark to check improvements in performance over time. The manual reads in Axum are still slower than the manual reads in frameworkless-async by quite a large margin, which indicates there is probably some overhead in Axum itself.

--

My hardware configuration for reference:
Kernel: Ubuntu 23.10, Linux 6.5
CPU: Ryzen 7 3800X (8C 16T)
Motherboard: Gigabyte B450 AORUS M
Memory: Corsair Vengeance LPX 4x8GB DDR4 3200MHz (16-18-18-36)
Disk: Samsung 850 EVO 500GB

[yanns]

I'm not doing any file IO, but just network read/writes.
AFAIK, tokio::io is not as fast as blocking IO. Some people using rust for databases told me that they avoid async rust because it's too slow for all file IO operations.

[frederikhors]

Some people using rust for databases told me that they avoid async rust because it's too slow for all file IO operations.

Wow, this requires proof. Do they maybe mean "too difficult"?

[yanns]

No no, they've done lots of perf research.
I think that async IO with tokio is slower than the std blocking part is even mentioned https://www.youtube.com/watch?v=o2ob8zkeq2s

[yanns]

I'm still wondering if we can optimize the body extraction even more.
If the request contains information about the size of the body, we could maybe use it, like:

#[async_trait]
impl<S> FromRequest<S> for Bytes
where
    S: Send + Sync,
{
    type Rejection = BytesRejection;

    async fn from_request(req: Request, _: &S) -> Result<Self, Self::Rejection> {
        let body_size = req.size_hint().upper(); // <- added
        let bytes = req
            .into_limited_body()
            .collect()
            .await
            .map_err(FailedToBufferBody::from_err)?
            .to_bytes(body_size); // <- changed

        Ok(bytes)
    }
}

And we would change the signature of to_bytes to have an optional size:

    /// Convert this body into a [`Bytes`].
    pub fn to_bytes(mut self, size_hint: Option<usize>) -> Bytes {
        match size_hint {
            Some(size_hint) => self.bufs.copy_to_bytes(size_hint),
            None => self.bufs.copy_to_bytes(self.bufs.remaining()),
        }
    }

This would allow us avoiding to compute self.bufs.remaining() that has to iterate over all bufs.