Unusual pause outside of handler

[yatesco]

SOLVED It is a Tokio problem/misunderstanding/me butchering all that is good and holy in Tokio!

TLDR: Hi there - how would I go about nailing down timings outside of my handler in mode?

I have a handler that completes within 1ms, however, Chrome shows it takes ~300ms (all localhost):

When I look at where Chrome is waiting, it is pretty much all in "waiting to download":

The response is a few KB of JSON, which is returned by:

    let json = serde_json::to_string_pretty(...);
    let result = Response::builder()
        .status(StatusCode::OK)
        .header(header::CONTENT_TYPE, "application/json")
        .body(json)
        .unwrap();

I don't have anything "funky" going on, but I do have:

• a TypedHeader
• about 7 extensions that all expose Arc<Mutex<SomeThing>>

To my mind, the performance is about 299ms too long :-). Any idea where I should start looking for these extra milliseconds?

Thanks!

*EDIT: I have other handlers where axum is no more than 1 or 2 ms overhead, and others which are also 100s of miliseconds more than the handler
*EDIT: it exhibits the sae performance in both RELEASE and DEBUG

[davidpdrsn]

Can you reproduce this using hyper directly without axum?

[yatesco]

Not tried. I'll have a go and get back to you

[yatesco]

Never mind - it is some bizarre Tokio interaction which I don't understand:

• I stripped out everything from the handler and just returning string
• I stripped out everything from the routing so no extensions and just that one handler mapped
• If I run the database check loop in a separate spawned task then I get the 300ms
• If I disable the database check loop in the separate spawned task then the request takes 5ms

I'm using the rt-multi-thread feature so I would expect Tokio to use threads... I need to debug/read a bit around Tokio.

[yatesco]

Just another note: sometimes the request comes back in under a few milliseconds, which I'd expect, but mostly it is ~250-300ms, even for the same content.