Single intensive task seemingly blocks other axum requests

[wanton stream]

Heya, trying to debug what's going on here.

I have a web API using axum that provides aggregation of stats stored in a database. Because the aggregation needs to be fast, and the data is small enough to fit into ram, it's designed in a way where it periodically grabs all relevant rows from postgres, partially aggregates it, then swaps out a mutex with the current live copy. I use sqlx to talk to the database. The application looks roughly like this (pseudocode):

struct Context {
    pool: sqlx::PgPool,
    data: RwLock<Vec<MyData>>,
}

fn update_endless(context: Arc<Context>) {
    loop {
        reload_rows(context).await;
        tokio::time::sleep(Duration::from_secs(10 * 60)).await;
    }
}

fn reload_rows(context: Arc<Context>) {
    let mut stream =
        sqlx::query!("SELECT ...").fetch(&context.pool);

    let mut new_data = vec![];
    while let Some(row) = stream.next().await {
        // not shown here: a zstd decompress and a serde deserialization
        // not the cheapest operations in the world, but not horribly expensive either
    }

    *context.data.write().await = new_data;
}

#[tokio::main]
async fn main() -> Result<()> {
    let context = Arc::new(Context { ... });
    tokio::spawn(update_endless(context.clone()));

    let listener = ...;
    let app = axum::Router::new()
        .route("/api/", ...)
        .with_state(context.clone());
    axum::serve(app, listener).await?;

    Ok(())
}

This runs on a remote server with 6 cores that's not the most efficient in the world but not underpowered by any definition. Postgres runs locally. Even when a row reload is ongoing, CPU usage across the entire machine does not exceed ~40%.

When deploying this to users, I received reports that occasionally requests that would end up querying this service could stall for seconds or even minutes. I observed this behavior myself, with the stalling behavior always coinciding with a row reload.

(cont in thread)

I went ahead and enabled console integration to see what's going on, then deployed it to production again. The same behavior was immediately visible again.

This is what the console view looks like when a stats update is ongoing, while at the same time I'm trying to make a request in the background. Other than the task with ID 15 climbing in Busy usage, no new tasks appear. In the meantime, my HTTP request is completely stalled. Axum is not serving it.

Eventually (but crucially: while refreshing is still ongoing!), tokio and/or axum finally decide to respond. You see a quick flash of terminated tasks and the HTTP request has resolved itself. Afterwards, it's back to image #1, with new http requests stalling again.

This is what the actual task responsible for refreshing looks like. While a fetch from the database is ongoing, the thread is entirely busy (only Busy time climbs, Idle does not climb at all). Once fetching is finished, Idle climbs while Busy stays as-is.

Beyond the investigations with console, I also added logging across the application to ensure that I'm not accidentally blocking inside the request handlers. This doesn't seem to be the case: none of my checks for long-held mutexes etc get triggered. I've got a build queued up that contains a static route (i.e. just returns a &'static str) and will check if that route stalls at well. Update: yes, even a static route stalls.

[proud anvil]

A few things to try:

1. Add a yield_now() to your loop with zstd/serde.
2. Perform the zstd/serde logic within spawn_blocking.

[wanton stream]

I'll do that now, but in the meantime I'm curious why that would improve the situation here? Isn't updating inherently a task that can only consume at most one thread at a time? I don't see how a single overloaded task could cause other threads to no longer be able to be scheduled

(I might just be naive in how tokio does its scheduling work here of course)

(and is the stream await not already yielding back to the executor? or is the stream able to immediately wake if e.g. psql loads batches at a time)

[proud anvil]

There is a possibility that the thread has responsibility for checking the IO driver and isn't doing it. In that case, other threads might not find out that there's a new IO event. This can only happen if all other tasks are IDLE.

[wanton stream]

here's a small recording of the task window, note that chrome sits on refreshing for a good while even though the handler for this route is async { "Hello, World" }

All other tasks are indeed idle. If I understand correctly, what's going on is something like:

1. sqlx implements streaming by batching n rows at a time
2. for let some = ...await only yields back to scheduler if n more rows need to be fetched
3. body of the loop is relatively expensive and never yields
4. eventually, n rows get handled, scheduler of that thread finally regains execution, pumps events, pending requests get to run
5. at some point, new rows are ready, updating task gets scheduled again, starves off io polling for n more expensive operations?

[proud anvil]

that sounds correct, yes

[wanton stream]

Seems like a yield is enough to get requests unblocked now, but I'll leave this running for a while to see if p90 improves across a longer time.

Any particular preference for one of these over the other?

And I need to brush up on my async concepts again. I was assuming the stream .await would be enough to yield to scheduler. I guess it makes sense that yielding is avoided if the future can immediately resolve

[proud anvil]

Yielding at .await points are not guaranteed if the operation can complete immediately.

Tokio has logic to force yields after 128 consecutive awaits that did not yield, but 128 is a lot in your case.