Rust mongodb/actix-web deps upgrade causing very high latency

[asaf]

Experiencing major request/response latency after upgrading a couple rust libraries.

On a very fast actix-web/mongodb service, I upgraded versions of a couple of the libraries.

Major ones are actix-web 3.3.2 (from 2.0.0) and mongodb rust driver to 1.2.0 (from 0.9.2)

A lot of code was updated to swap mongodb 0.9.2's synchronous API with 1.2.0's async API. On the upgraded service, the requests complete successfully but have very high latency.

On 2.0.0/0.9.2, requests are super fast, like less than 50ms

After upgrade, requests take upwards of 4 seconds, some longer.

On 3.3.2/1.2.0, I notice the service is spawning many more mongo db connections compared to previously. Not sure if that's related.

Any ideas?

[alice]

Since the completion times are so large, one possible cause is that you may be blocking the thread.

[kornel]

In case it's caused by some sync code blocking async threads, I've dignosed such issues this way.

1. Implement a wrapper for futures that complains when something is slow:

use std::task::Poll;
use std::pin::Pin;
use std::future::Future;

pub struct NonBlock<F> {
    future: F,
    label: &'static str,
}

impl<F: Future> NonBlock<F> {
    #[inline]
    pub fn new(label: &'static str, future: F) -> Self {
        Self { future, label }
    }
}

impl<F: Future> Future for NonBlock<F> {
    type Output = F::Output;
    fn poll(self: Pin<&mut Self>, ctx: &mut std::task::Context<'_>) -> Poll<Self::Output> {
        let start = std::time::Instant::now();
        let label = self.label;
        let projected = unsafe { self.map_unchecked_mut(|s| &mut s.future) };
        let res = projected.poll(ctx);
        let elapsed = start.elapsed().as_secs();
        if elapsed >= 1 {
            eprintln!("blocking poll: {} took {}s", label, elapsed);
        }
        res
    }
}

2. Wrap all expr.await with NonBlock::new("label", expr).await.

Then run the code, and it will print which future is blocking.