Vector utilization metric emits negative values after upgrade to v0.49.0

[andrepbento]

A note for the community

• Please vote on this issue by adding a 👍 reaction to the original issue to help the community and maintainers prioritize this request
• If you are interested in working on this issue or have submitted a pull request, please leave a comment

Problem

After upgrading Vector from v0.39.0 to v0.49.0, we observed that the vector.utilization metric is emitting negative values in Datadog. This is unexpected because the metric should always be within the range of 0 to 1. The previous version (v0.39.0) did not exhibit this issue.

Investigation:

• Vector v0.49.0 was released on August 12th, 2025.
• Reviewing the commit history for the utilization.rs file, a significant change was made on July 2nd, 2025: commit link.
• We are not sure if this change may have introduced the negative values in the vector.utilization metric.

Additional notes:

• We would appreciate any insights or confirmation if others have encountered this problem.

Configuration

Version

v0.49.0

Debug Output

Example Data

No response

Additional Context

No response

References

No response

[pront]

This line immediately stands out:

https://github.com/vectordotdev/vector/blob/master/src/utilization.rs#L134

let utilization = 1.0 - wait_ratio; // no guarantee that `wait_ratio` is between 0 and 1

P.S. This module currently has no tests :(

[pront]

PR #22070 (cc @esensar) might have broken an invariant or maybe it just exposed a bug in the previous implementation.

LLM generated PR that might offer some ideas: #24064

[thomasqueirozb]

Hi @andrepbento thanks for the report. We believe the issue is with the commit you originally mentioned. While we investigate the root cause I have created a PR which reverts the commit (#24066). I cut a custom release from that PR which you can find either in the workflow run (scroll all the way down) or in the tagged packages (look for the ones tagged with 0.51.0.custom.cffbf20). We'd appreciate if you could either deploy this custom build and report back to us if you still see this issue. In the meantime, you can use v0.48.0 in prod. Thanks!

[esensar]

PR #22070 (cc @esensar) might have broken an invariant or maybe it just exposed a bug in the previous implementation.

LLM generated PR that might offer some ideas: #24064

I think this is caused by possibly delayed messages (such a scenario was not possible before, because there was no central component handling these messages, each component reported its own metrics). I also looked at that LLM PR and it seems to have reached the same conclusion, but I am not sure if that fix is the right way to do it. I like the tests added though 😄

Here is a simple test reproducing it

    #[test]
    fn test_negative_utilization() {
        let mut timer = Timer::new(gauge!("test"), "test".into());

        timer.report();

        // Late message for start wait
        timer.start_wait(Instant::now() - Duration::from_secs(1));

        timer.report();
        assert!(timer.ewma.average().unwrap_or(f64::NAN) > 0.0);
    }

I will create a PR with a fix focused on this issues, it is not that much different from that LLM PR, but it is a bit more focused on the actual issue - I wouldn't do the clamping everywhere, because we might hide some other issues that way.

[sebinsunny]

@esensar I believe PR #22070 is also causing debug log spam during configuration reloads. The logs show repeated messages such as Couldn't send utilization start wait message. component_id=ComponentKey { id: "clickhouse" } error="Closed(..)" and Couldn't send utilization stop wait message. This does not occur in 0.46 — config reloads work there(both) — but Vector is spamming these messages(v0.49,v0.50). I think the bug affects all sinks with disk buffers or long batch timeouts, not just ClickHouse. Will the fix prevent this log spam?

When config reload happens (reload_config_and_respawn):

1. Components are marked for reload → Old sink components start shutting down
2. Utilization task keeps running → The global utilization emitter task continues
3. Utilization channels CLOSE FIRST → Components lose their utilization sender channels
4. Components still polling → Old components are still waiting for batch timeout/disk flush
5. Continuous errors → Every poll attempt generates Closed(..) errors

2025-10-25T08:46:24.898245Z DEBUG sink{component_kind="sink" component_id=clickhouse component_type=clickhouse}: vector::utilization: Couldn't send utilization start wait message. component_id=ComponentKey { id: "clickhouse" } error="Closed(..)"
2025-10-25T08:46:24.898283Z DEBUG sink{component_kind="sink" component_id=clickhouse component_type=clickhouse}: vector::utilization: Couldn't send utilization stop wait message. component_id=ComponentKey { id: "clickhouse" } error="Closed(..)"
2025-10-25T08:46:24.898302Z DEBUG sink{component_kind="sink" component_id=clickhouse component_type=clickhouse}: vector::utilization: Couldn't send utilization start wait message. component_id=ComponentKey { id: "clickhouse" } error="Closed(..)"
2025-10-25T08:46:24.898332Z DEBUG sink{component_kind="sink" component_id=clickhouse component_type=clickhouse}: vector::utilization: Couldn't send utilization start wait message. component_id=ComponentKey { id: "clickhouse" } error="Closed(..)"
2025-10-25T08:46:24.898352Z DEBUG sink{component_kind="sink" component_id=clickhouse component_type=clickhouse}: vector::utilization: Couldn't send utilization stop wait message. component_id=ComponentKey { id: "clickhouse" } error="Closed(..)"
2025-10-25T08:46:24.898376Z DEBUG sink{component_kind="sink" component_id=clickhouse component_type=clickhouse}: vector::utilization: Couldn't send utilization start wait message. component_id=ComponentKey { id: "clickhouse" } error="Closed(..)"
2025-10-25T08:46:25.417998Z DEBUG sink{component_kind="sink" component_id=clickhouse component_type=clickhouse}: vector::utilization: Couldn't send utilization start wait message. component_id=ComponentKey { id: "clickhouse" } error="Closed(..)"
2025-10-25T08:46:25.418034Z DEBUG sink{component_kind="sink" component_id=clickhouse component_type=clickhouse}: vector::utilization: Couldn't send utilization stop wait message. component_id=ComponentKey { id: "clickhouse" } error="Closed(..)"
2025-10-25T08:46:25.418047Z DEBUG sink{component_kind="sink" component_id=clickhouse component_type=clickhouse}: vector::utilization: Couldn't send utilization start wait message. component_id=ComponentKey { id: "clickhouse" } error="Closed(..)"
2025-10-25T08:46:25.418256Z DEBUG sink{component_kind="sink" component_id=clickhouse component_type=clickhouse}: vector::utilization: Couldn't send utilization start wait message. component_id=ComponentKey { id: "clickhouse" } error="Closed(..)"
2025-10-25T08:46:25.418269Z DEBUG sink{component_kind="sink" component_id=clickhouse component_type=clickhouse}: vector::utilization: Couldn't send utilization stop wait message. component_id=ComponentKey { id: "clickhouse" } error="Closed(..)"
2025-10-25T08:46:25.418276Z DEBUG sink{component_kind="sink" component_id=clickhouse component_type=clickhouse}: vector::utilization: Couldn't send utilization start wait message. component_id=ComponentKey { id: "clickhouse" } error="Closed(..)"
2025-10-25T08:46:25.418628Z DEBUG sink{component_kind="sink" component_id=clickhouse component_type=clickhouse}: vector::utilization: Couldn't send utilization start wait message. component_id=ComponentKey { id: "clickhouse" } error="Closed(..)"
2025-10-25T08:46:25.418669Z DEBUG sink{component_kind="sink" component_id=clickhouse component_type=clickhouse}: vector::utilization: Couldn't send utilization stop wait message. component_id=ComponentKey { id: "clickhouse" } error="Closed(..)"
2025-10-25T08:46:25.418711Z DEBUG sink{component_kind="sink" component_id=clickhouse component_type=clickhouse}: vector::utilization: Couldn't send utilization start wait message. component_id=ComponentKey { id: "clickhouse" } error="Closed(..)"
2025-10-25T08:46:25.942396Z DEBUG sink{component_kind="sink" component_id=clickhouse component_type=clickhouse}: vector::utilization: Couldn't send utilization start wait message. component_id=ComponentKey { id: "clickhouse" } error="Closed(..)"
2025-10-25T08:46:25.942439Z DEBUG sink{component_kind="sink" component_id=clickhouse component_type=clickhouse}: vector::utilization: Couldn't send utilization stop wait message. component_id=ComponentKey { id: "clickhouse" } error="Closed(..)"
2025-10-25T08:46:25.942495Z DEBUG sink{component_kind="sink" component_id=clickhouse component_type=clickhouse}: vector::utilization: Couldn't send utilization start wait message. component_id=ComponentKey { id: "clickhouse" } error="Closed(..)"

[sebinsunny]

I tested with https://packages.timber.io/vector/custom/0.51.0.custom.cffbf20/vector-0.51.0.custom.cffbf20-1.x86_64.rpm, and I don't see the spamming log after a config reload.

[esensar]

@esensar I believe PR #22070 is also causing debug log spam during configuration reloads. The logs show repeated messages such as Couldn't send utilization start wait message. component_id=ComponentKey { id: "clickhouse" } error="Closed(..)" and Couldn't send utilization stop wait message. This does not occur in 0.46 — config reloads work there(both) — but Vector is spamming these messages(v0.49,v0.50). I think the bug affects all sinks with disk buffers or long batch timeouts, not just ClickHouse. Will the fix prevent this log spam?

I don't think it will. That is a separate issue that I think I need to handle. The reason it didn't appear before is that the component worked differently before and didn't rely on these messages.

This was set at debug level, since it isn't that important if some component misses a message, but this spam is definitely an issue 😄

EDIT: I think this might be more than spam. I think any new components after reload lose their utilization emitter, because a new one is built for them, but then discarded.