I have a sync method 'write' that calls a sync method 'flush', that performs a blocking io operation using io_uring, that takes around 20 microseconds to complete. These writes only occur once every second, so this is working fine even under high pressure.
async axum handler --> sync write -> sync flush

Now I want the method 'flush' to be executed on a tokio blocking thread. For that, now the sync 'write' becomes async, and I've created two new methods: 'flush' and 'execute_flush':
async axum handler --> async write -> async flush :: spawn(sync execute_flush)

1. 'flush': now it's async and prepare the thread spawn to call the sync method 'execute_flush', that performs the blocking io operation.

async fn flush(buf_idx: usize, iouring_config: &IOUringOneConfig, first_dir: u8) -> Result<WriteResult, IOUringError> {
    let iouring_config_clone = iouring_config.clone();
    let handle = task::spawn_blocking(move || { execute_flush(buf_idx, &iouring_config_clone, first_dir) });
    handle.await.unwrap_or_else(|err| Err(IOUringError::FailedToSpawnFlushThread(err)))
}

2. 'execute-flush': method that performs the blocking 'flush'.

fn execute_flush(buf_idx: usize, iouring_config: &IOUringOneConfig, first_dir: u8) -> Result<WriteResult, IOUringError> {
	// This method performs the flush, this would the equivalent to the 'sync' flush method when everything was sync.
}

After making this change, the first call to async write -> async flush -> spawn(sync execute_flush) finishes correctly, but immediately all axum threads become busy. No panic, the app is still there, but it's not accepting incoming requests. Server cpu is 100% idle.

╭Tasks (90) ▶ Running (9) ⏸ Idle (78)────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────╮
│   Warn  ID  State  Name  Total  Busy▵  Sched  Idle   Polls Kind     Location                                  Fields                                                                       │
│⚠ 1    17 ▶             1m37s    43s    42s    12s 33167 task     <cargo>/axum-0.8.4/src/serve/mod.rs:389:5 size.bytes=1912 target=tokio::task                                              │
│⚠ 1    19 ▶             1m37s    43s    42s    12s 33126 task     <cargo>/axum-0.8.4/src/serve/mod.rs:389:5 size.bytes=1912 target=tokio::task                                              │
│⚠ 1    59 ▶             1m34s    43s    42s    10s 30472 task     <cargo>/axum-0.8.4/src/serve/mod.rs:389:5 size.bytes=1912 target=tokio::task                                              │
│⚠ 1    65 ▶             1m34s    43s    42s    10s 30528 task     <cargo>/axum-0.8.4/src/serve/mod.rs:389:5 size.bytes=1912 target=tokio::task                                              │
│⚠ 1    85 ▶               55s    42s    42s    0ns 5998  task     <cargo>/axum-0.8.4/src/serve/mod.rs:389:5 size.bytes=1912 target=tokio::task                                              │
│⚠ 1    99 ▶               55s    42s    42s    0ns 6000  task     <cargo>/axum-0.8.4/src/serve/mod.rs:389:5 size.bytes=1912 target=tokio::task                                              │
│⚠ 1   104 ▶               55s    42s    42s    0ns 6006  task     <cargo>/axum-0.8.4/src/serve/mod.rs:389:5 size.bytes=1912 target=tokio::task                                              │
│⚠ 1    87 ▶               55s    42s    42s    0ns 6000  task     <cargo>/axum-0.8.4/src/serve/mod.rs:389:5 size.bytes=1912 target=tokio::task                                              │
│⚠ 1    20 ⏸             1m37s     1s  376ms  1m35s 33084 task     <cargo>/axum-0.8.4/src/serve/mod.rs:389:5 size.bytes=1912 target=tokio::task

Checking one of the busy tasks:
╭Task─────────────────────────────────────────────────────────────────────────────────────────╮╭Waker────────────────────────────────────────────────────────────────────────────────────────╮
│ID: 44 ⏫                                                                                    ││Current wakers: 3 (clones: 33113, drops: 33110)                                              │
│Target: tokio::task                                                                          ││Woken: 33111 times, last woken: 2m50s ago                                                    │
│Location: <cargo>/axum-0.8.4/src/serve/mod.rs:389:5                                          ││Self Wakes: 16555 times (49%)                                                                │
│Total Time: 3m46s                                                                            ││                                                                                             │
│Busy: 1.24s (0.55%)                                                                          ││                                                                                             │
│Scheduled: 2m51s (75.61%)                                                                    ││                                                                                             │
│Idle: 53.95s (23.84%)                                                                        ││                                                                                             │
│                                                                                             ││                                                                                             │

In axum v0.8.4 the code around that location (axum-0.8.4/src/serve/mod.rs:389:5) lives in the Serve::run method, inside its endless request loop.
Roughly, line 389 seems to correspond to the .await on the server future.

No idea what's going on, I've been working with rust just for the last 4 months but this issue is out of my scope.
I did not paste more information because I'm not sure if the above is enough, or what kind of info I should provide.
Any clue about what's going on will be really appreciated.

2 posts - 2 participants

Read full topic