Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

worker_total_busy_duration seems to be calculated incorrectly when using multi-threaded runtime #6129

Closed
aliu opened this issue Nov 3, 2023 · 0 comments · Fixed by #6131
Closed
Labels
A-tokio Area: The main tokio crate C-bug Category: This is a bug. M-metrics Module: tokio/runtime/metrics

Comments

@aliu
Copy link
Contributor

aliu commented Nov 3, 2023

Version

❯ cargo tree | grep tokio
├── tokio v1.29.0
│   ├── tokio-macros v2.1.0 (proc-macro)
└── tokio-metrics v0.1.0
    └── tokio v1.29.0 (*)

Platform
x86_64 Linux

Description
I am using RuntimeMetrics::worker_total_busy_duration to calculate the estimated event load on the tokio runtime (basically the same calculation as busy_ratio in the tokio-metrics crate). Recently, I noticed that there was a change in the reported event load numbers after upgrading tokio, and I was able to narrow it down to #5720 which happened between versions 1.28 and 1.29. Here is a simple example to demonstrate what I am seeing:

use std::time::Duration;

use tokio::runtime::Handle;
use tokio_metrics::RuntimeMonitor;

#[tokio::main(flavor = "multi_thread", worker_threads = 2)]
async fn main() {
    let monitor = RuntimeMonitor::new(&Handle::current());
    std::thread::spawn(|| track_event_load(monitor));

    tokio::spawn(async move {
        loop {
            tokio::time::sleep(Duration::from_millis(100)).await;
        }
    });

    tokio::signal::ctrl_c().await.unwrap();
}

fn track_event_load(monitor: RuntimeMonitor) {
    for interval in monitor.intervals() {
        println!("{}", interval.busy_ratio());
        std::thread::sleep(Duration::from_millis(100));
    }
}

As far as I am aware, this program should be idle for a majority of the time, so the event load should be low. However running the program gives the following numbers:

❯ cargo run --release
0
0.000002697440264061419
1.0110493860183998
2.0225204177870992
3.033462889146423
4.044081159758517
5.054872941776264
6.06575124507064
7.077271165227848
8.08814815824306
9.09991369484245
10.108758659279012
11.110218749233546
12.122804806173969
13.133740007360979
14.143114816648776
15.15440810561376
16.155732167689255
17.16620561286237
18.177692313879106
19.18841098847948
20.198520569079214
21.21058178051834
22.22162817428536
23.232624228992883
24.24083027183287
25.2534032265727
26.26191009135129
27.27588544601849
28.28587580335727
29.2976930104215
30.304969480723297
1.0108201089267066
2.021770179796413
3.022983152446736
4.0332942378842445
5.044964380701878
6.055508896793953
7.066673154183617
8.06688527646335
9.079267982430617
10.089493180144416

I am not too sure why, but for some reason the loop with the tokio::time::sleep call is causing this weird output. This only happens when using a multi-threaded runtime in tokio versions 1.29 and greater. If I use #[tokio::main(flavor = "current_thread")] or tokio 1.28, there is no issue:

❯ cargo run --release
0
0.0000020982167884979592
0.00006034466575184553
0.0000798158286216105
0.00004835816196900927
0.00003717309566581585
0.00003566482129022396
0.000038961367077247215
0.00006323981024580236
0.00003926155233964036
@aliu aliu added A-tokio Area: The main tokio crate C-bug Category: This is a bug. labels Nov 3, 2023
@Darksonn Darksonn added the M-metrics Module: tokio/runtime/metrics label Nov 6, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
A-tokio Area: The main tokio crate C-bug Category: This is a bug. M-metrics Module: tokio/runtime/metrics
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants