Is a large volume of resources normal when viewed in tokio-console?

[chipsenkbeil]

I have multiple long-lived server processes that leverage tokio for async operations. They make regular use of tokio::time::sleep, and I've recently encountered moments where the server hangs. I'm trying to diagnose the problem and tried leveraging tokio-rs/tracing to identify bottlenecks or other issues.

A couple of the frequently-displayed timer resources are sleep-based timeouts and pauses between loops.

Using sleep to avoid CPU throttling

loop {
    // Do stuff that may exit the loop one day

    // Wait before next iteration of processing
    tokio::time::sleep(...).await;
}

Using sleep in a tokio::select! while waiting on a TCP connection

loop {
    // Determine if our server is ready to read or write to a connection
    let ready = tokio::select! {
        // Check if we are shutting down the server
        cb = shutdown_rx.recv() => {
            debug!("Client got shutdown signal, so exiting event loop");
            let cb = cb.expect("Impossible: shutdown channel closed!");
            let _ = cb.send(Ok(()));
            watcher_tx.send_replace(ConnectionState::Disconnected);
            break Ok(());
        }

        // Checking if we've reached a period of no activity and try to reconnect
        _ = tokio::time::sleep(silence_time_remaining) => {
            silence_needs_reconnect!();
        }

        // Checking if our TCP socket is ready to do something
        result = connection.ready(Interest::READABLE | Interest::WRITABLE) => {
            match result {
                Ok(result) => result,
                Err(x) => {
                    error!("Failed to examine ready state: {x}");
                    needs_reconnect = true;
                    watcher_tx.send_replace(ConnectionState::Reconnecting);
                    continue;
                }
            }
        }
    };

    // Do stuff
}

[hds]

By the look of your console output, all but one of the resources on the screen have terminated (they're grayed out).

This is normal, sleep resources are not "reused", each time you call sleep, a new resource is created. The terminated resources you see are kept in the console for some time so you can still see them (6 seconds by default).

[chipsenkbeil]

That's just the highlight color from having it selected. There's a darker color for those that are no longer active.

And when using the default of 6s, these are sticking around much longer. I end up with over 200,000 resources in 4 hours with the console ui refreshing very slowly.

Is this a tracing issue, or is something I'm doing causing a problem?

[hds]

OK, it was hard to tell which state those resources were in. They shouldnt' stick around for so long. In fact we have a few examples in the console-subscriber crate which make use of sleep (although not in inside a select statement I think) and the resources end and expire as expected.

I have a few questions.

• Does the "Total" column time keep going up? (it should if those resources are still active)
• Can you show me an example of the resource detail screen for one of these timers?
  • Is the detail screen showing increasing busy/idle time?
  • is the detail screen showing any async ops? If so, are they attached to the tasks you would expect them to be?
• To confirm, the hanging problem was occuring before enabling the tracing feature in tokio, correct?
• What does the task view look like? Are there many tasks there?

Given that you were experiencing hanging in your application before enabling tracing (assuming that is the case), then it seems more likely that there is some logic error there rather than this being an error in tokio tracing or in the console. I don't mean that we don't expect to find errors in those other places, just that you already had some error before using them.

[chipsenkbeil]

@hds hey, thanks for the response! I actually do think these sleep calls are supposed to be completed, but they aren't going away. I took two screenshots of sleep resource details: some have async ops and others do not, and they're mixed throughout.

Details

Is the total not the number reflected next to resources? If so, where can I find the total? In the first screenshot I showed, you can see over 200k resource total in parentheses. I also recorded a video of the console running for 1 hour where it has reached 40k, but interestingly if you close and reopen the console then it drops to 17k and starts climbing again.

Only for some of the details do I see busy & idle whereas others I see nothing.

There's absolutely some logic error I have somewhere causing the server to hang, so not denying that! :) Was trying to use tracing to figure out where it was locking up, but the large volume of sleep resources taking over makes it difficult to figure things out.

Quirk where it works? (Macbook Pro M1)

This issue is showing up on my Macbook Air M1 running MacOS 12.6 and compiled with Rustc 1.69.0.

When I built and tested this on a Macbook Pro M1 running MacOS 13.3.1 and compiled with Rustc 1.70.0, it actually looks like the sleep resource isn't shooting up like crazy. However, if you look closely, you can see sleeps are still persisting in the mailbox.rs. These sleeps are 100ms or less, so they shouldn't be persisting past ~6 seconds!

tokio-console-pro-m1.mp4

Screenshots of resource view (Macbook Air M1)

Screenshots of task view (Macbook Air M1)

Video of resources (Macbook Air M1)

tokio-console.mp4

Video of tasks & resources (Macbook Air M1)

tokio-console-2.mp4