refactor(obs): make dial9 telemetry opt-in and actually record events (#4663)

* refactor(obs): make dial9 telemetry opt-in and actually record events The dial9 Tokio-runtime profiler was disabled by default, yet every build paid for it, and enabling it produced trace files with no events in them. Recorded empty traces --------------------- `build_traced_runtime` called `TracedRuntime::builder()...build(..)`, but dial9 only starts recording in `build_and_start*`. `build` still returns a live guard whose `is_enabled()` reports true, and still creates and seals segment files — they just contain a header and no events. It also skipped `with_trace_path`, so the background worker driving the segment pipeline was never spawned. Measured on the new smoke example: 310 bytes of bare segment header, against 5640 bytes for the same workload once recording actually starts. Switch to `with_trace_path(..).build_and_start(..)`. Cost was unconditional ---------------------- `--cfg tokio_unstable` was a global `[build] rustflags` entry and `rustfs-obs` depended on `dial9-tokio-telemetry` unconditionally, so all builds depended on Tokio's non-semver API. Worse, an environment `RUSTFLAGS` replaces (never appends to) the config-file value, so any caller exporting their own RUSTFLAGS silently dropped the flag — the long comment in build.yml was a scar from that. dial9 is now an opt-in feature (`dial9`, plus `dial9-s3` and `dial9-taskdump`), the global rustflag is gone, and `crates/obs/build.rs` fails the compile if the feature is on without the flag. Telemetry builds go through `make build-profiling`. Metrics that could not lie -------------------------- `rustfs_dial9_{events_total,bytes_written_total,rotations_total,cpu_overhead_percent}` were hard-coded to zero — a Counter pinned at 0 reads as "nothing happened". Removed. `rustfs_dial9_enabled` was sourced from the environment, so it read 1 even when the traced runtime failed and the process fell back to a standard runtime; it is replaced by `rustfs_dial9_supported` (compile-time), `rustfs_dial9_configured` (intent) and `rustfs_dial9_active_sessions` (reality). No `writer_healthy` gauge is exported: dial9's `RotatingWriter` can enter its `Finished` state and stop writing, but exposes no way to observe that, so the gauge could only ever be hard-coded to 1. Documented as a known gap instead. Final events were lost ---------------------- The `TelemetryGuard` lived in a `static OnceLock`, which is never dropped, so buffered events were never flushed at exit. `build_tokio_runtime` now returns the guard and `run_process` drops it before any exit path. Also ---- - `disk_usage_bytes` was a `read_dir` + per-file `stat` on the metrics collection path. It is now sampled by a background task into an atomic. - `SAMPLING_RATE`/`S3_BUCKET`/`S3_PREFIX` were parsed, warned about, and discarded. S3 upload is now wired to dial9's `with_s3_uploader` behind `dial9-s3`; `SAMPLING_RATE` has no upstream equivalent and is removed. - Wire `with_task_dumps` (async backtraces of stalled tasks), configurable via `RUSTFS_RUNTIME_DIAL9_TASK_DUMP_{ENABLED,IDLE_THRESHOLD_MS}`. - Split `telemetry/dial9.rs` into `config`/`state`/`enabled`/`disabled`; the stub keeps the public API identical so callers need no `#[cfg]`. - Drop four print-only examples and the manual test bin that exercised the removed `init_session` scaffolding. Verified: cargo check/clippy/test across default, `dial9`, and `dial9-s3`; build.rs correctly rejects `dial9` without `--cfg tokio_unstable`; `make pre-commit` passes. Co-Authored-By: heihutu <heihutu@gmail.com> * docs(obs): document dial9 as an on-demand profiler scripts/run.sh advertised a `SAMPLING_RATE` knob that was never passed to dial9, and claimed "CPU overhead < 5% (with sampling rate 1.0)" and "lower values reduce CPU overhead" on the strength of it. The knob is gone; the guidance built on it had to go too. Replace it with what is actually true: dial9 needs a `make build-profiling` binary, its disk budget evicts oldest-first (so a high poll rate can overwrite the incident you are chasing), and it cannot be toggled without a restart. Add docs/operations/dial9-runtime-profiling.md covering the build variants, an investigation walkthrough, the configuration table, how to read the three supported/configured/active_sessions gauges against each other, and the upstream gap that makes writer death only indirectly observable. Co-Authored-By: heihutu <heihutu@gmail.com> * test(obs): add a dial9 smoke example that proves events are recorded The bug this guards against is invisible to every existing signal: with `build` instead of `build_and_start`, dial9 creates the trace file, seals segments, and reports `TelemetryGuard::is_enabled() == true` — it simply records no events. Only the segment's byte count tells the two apart. Measured on this workload: 5640 bytes when recording, 310 bytes (a bare segment header) when not. The example asserts >= 2048 bytes, and was verified to fail with the `build` call restored. Also correct the comment on the `is_enabled` check in `finish_traced_runtime`. It claimed to catch "recording silently off"; it does not. It only rejects the inert guard a lenient config yields after a build failure. Recording is guaranteed by `build_and_start`, not by that check. Co-Authored-By: heihutu <heihutu@gmail.com> * test(rustfs): accept Unsupported runtime telemetry capability A binary built without the `dial9` feature now reports the runtime-telemetry capability as `Unsupported` rather than `Disabled`. The distinction matters to operators: `Disabled` implies the capability can be switched on by setting an environment variable, which is not true here — telemetry needs a rebuild. Widen the assertion and pin the new semantics: when `dial9::is_supported()` is false, the state must be exactly `Unsupported`. Co-Authored-By: heihutu <heihutu@gmail.com> * fix(obs): drop the dial9-s3 feature, its TLS stack is vulnerable CI's Dependency Review and `cargo deny` both reject the branch: dial9's `worker-s3` feature depends on aws-sdk-s3-transfer-manager 0.1.3, which pins aws-smithy-http-client onto hyper-rustls 0.24 and rustls-webpki 0.101.7. That webpki carries RUSTSEC-2026-0098, -0099 and -0104. 0.1.3 is the latest release of the transfer manager, and 1.2.0 the latest of the smithy client, so there is nothing to upgrade to. Cargo's feature unification can add features but cannot drop a transitive dependency, so it cannot be worked around from here either — the rest of the workspace already resolves to the safe rustls-webpki 0.103 / hyper-rustls 0.27. Remove the `dial9-s3` feature and the `with_s3_uploader` wiring. The two S3 environment variables stay parsed and warned about, now naming the real reason rather than a missing build feature. Trace segments are collected from the output directory instead. Tracked as D9-14 in rustfs/backlog#1157. With this, Cargo.lock is byte-identical to main: the PR no longer touches the dependency graph at all. Also correct the `dial9-taskdump` documentation. It claimed the feature "compiles to a no-op elsewhere"; in fact `tokio/taskdump` raises a `compile_error!` on any target other than linux/{aarch64,x86,x86_64}. Verified by trying to build it on macOS, which is how the claim was found to be wrong. Co-Authored-By: heihutu <heihutu@gmail.com> --------- Co-authored-by: heihutu <heihutu@gmail.com>
2026-08-18 02:33:15 +00:00 · 2026-07-10 18:52:48 +08:00
parent f83f9ada13
commit 00536da80c
30 changed files with 1406 additions and 1197 deletions
@@ -0,0 +1,236 @@
+// Copyright 2024 RustFS Team
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+//! `dial9-tokio-telemetry` integration, compiled when the `dial9` feature is on.
+//!
+//! Captures Tokio runtime-level events (poll start/end, worker park/unpark,
+//! task spawn/terminate) into rotating binary trace segments. This is an
+//! on-demand profiler rather than always-on telemetry: it is disabled by
+//! default and requires a `--cfg tokio_unstable` build.
+
+use super::config::Dial9Config;
+use super::state::{dial9_runtime_state, measure_disk_usage_bytes};
+use super::{EVENT_DIAL9_STATE, LOG_COMPONENT_OBS, LOG_SUBSYSTEM_DIAL9};
+use crate::TelemetryError;
+use dial9_tokio_telemetry::telemetry::{ProcessResourceUsageConfig, RotatingWriter, TaskDumpConfig, TracedRuntime};
+use std::time::Duration;
+use tracing::{info, warn};
+
+pub use dial9_tokio_telemetry::telemetry::TelemetryGuard;
+
+/// How often the background refresher restates trace-file disk usage.
+const DISK_USAGE_REFRESH_INTERVAL: Duration = Duration::from_secs(60);
+
+/// Name recorded in segment metadata so the trace viewer can label workers.
+const RUNTIME_NAME: &str = "rustfs-worker";
+
+/// Owns a live dial9 telemetry session.
+///
+/// Dropping this guard flushes buffered events and seals the active segment.
+/// It must be dropped before the process exits: a guard parked in a `static` is
+/// never dropped, and the final buffered events — usually the interesting ones —
+/// are lost.
+pub struct Dial9SessionGuard {
+    guard: TelemetryGuard,
+    config: Dial9Config,
+}
+
+impl Dial9SessionGuard {
+    /// Whether the underlying telemetry session is recording.
+    pub fn is_active(&self) -> bool {
+        self.guard.is_enabled()
+    }
+
+    /// The configuration this session was built from.
+    pub fn config(&self) -> &Dial9Config {
+        &self.config
+    }
+}
+
+impl std::fmt::Debug for Dial9SessionGuard {
+    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
+        f.debug_struct("Dial9SessionGuard")
+            .field("active", &self.is_active())
+            .field("output_dir", &self.config.output_dir)
+            .finish()
+    }
+}
+
+impl Drop for Dial9SessionGuard {
+    fn drop(&mut self) {
+        dial9_runtime_state().record_runtime_stopped();
+        info!(
+            event = EVENT_DIAL9_STATE,
+            component = LOG_COMPONENT_OBS,
+            subsystem = LOG_SUBSYSTEM_DIAL9,
+            state = "flushed",
+            "dial9 state changed"
+        );
+        // `TelemetryGuard`'s own `Drop` flushes buffered events and seals the
+        // active segment; it runs immediately after this body.
+    }
+}
+
+/// Build a Tokio runtime with dial9 telemetry attached and recording started.
+///
+/// # Errors
+///
+/// Returns an error when dial9 is not enabled, when the output directory cannot
+/// be created, or when the traced runtime fails to build. Callers are expected
+/// to fall back to a standard runtime.
+pub fn build_traced_runtime(
+    builder: tokio::runtime::Builder,
+) -> Result<(tokio::runtime::Runtime, Dial9SessionGuard), TelemetryError> {
+    let config = Dial9Config::from_env();
+    if !config.enabled {
+        return Err(TelemetryError::Io("dial9 telemetry is not enabled".to_string()));
+    }
+
+    std::fs::create_dir_all(&config.output_dir).map_err(|e| {
+        dial9_runtime_state().record_runtime_error(&config);
+        TelemetryError::Io(format!("Failed to create dial9 output directory '{}': {e}", config.output_dir))
+    })?;
+
+    let writer = RotatingWriter::new(config.base_path(), config.max_file_size, config.total_disk_budget()).map_err(|e| {
+        dial9_runtime_state().record_runtime_error(&config);
+        TelemetryError::Io(format!("Failed to create dial9 RotatingWriter: {e}"))
+    })?;
+
+    // `with_trace_path` transitions the builder into the state that spawns the
+    // background worker, which drives the segment pipeline.
+    let traced = TracedRuntime::builder()
+        .with_trace_path(&config.output_dir)
+        .with_task_tracking(true)
+        .with_runtime_name(RUNTIME_NAME)
+        .with_process_resource_usage(ProcessResourceUsageConfig::default());
+
+    let traced = if config.task_dump_enabled {
+        traced.with_task_dumps(
+            TaskDumpConfig::builder()
+                .idle_threshold(config.task_dump_idle_threshold)
+                .build(),
+        )
+    } else {
+        traced
+    };
+
+    // `build_and_start` rather than `build`: `build` returns a live guard that
+    // never records, writing segments that contain only a header.
+    //
+    // No `with_s3_uploader` here: dial9's `worker-s3` feature carries a
+    // vulnerable TLS stack. See the note in `crates/obs/Cargo.toml`.
+    finish_traced_runtime(traced.build_and_start(builder, writer), config)
+}
+
+/// Publish the outcome of a traced-runtime build and start the background
+/// disk-usage refresher.
+fn finish_traced_runtime(
+    started: std::io::Result<(tokio::runtime::Runtime, TelemetryGuard)>,
+    config: Dial9Config,
+) -> Result<(tokio::runtime::Runtime, Dial9SessionGuard), TelemetryError> {
+    let (runtime, guard) = started.map_err(|e| {
+        dial9_runtime_state().record_runtime_error(&config);
+        TelemetryError::Io(format!("Failed to build dial9 TracedRuntime: {e}"))
+    })?;
+
+    // `is_enabled` distinguishes a live guard from the inert one a lenient
+    // config produces after a build failure. It does NOT mean recording has
+    // started — a guard from `build` (rather than `build_and_start`) reports
+    // `true` while writing segments that contain only a header. Recording is
+    // guaranteed by the `build_and_start` call above, not by this check.
+    if !guard.is_enabled() {
+        dial9_runtime_state().record_runtime_error(&config);
+        return Err(TelemetryError::Io("dial9 TracedRuntime built with telemetry disabled".to_string()));
+    }
+
+    dial9_runtime_state().record_runtime_started(&config);
+    runtime.spawn(refresh_disk_usage_loop());
+
+    info!(
+        event = EVENT_DIAL9_STATE,
+        component = LOG_COMPONENT_OBS,
+        subsystem = LOG_SUBSYSTEM_DIAL9,
+        state = "recording",
+        output_dir = %config.output_dir,
+        file_prefix = %config.file_prefix,
+        disk_budget_bytes = config.total_disk_budget(),
+        task_dumps = config.task_dump_enabled,
+        "dial9 state changed"
+    );
+
+    Ok((runtime, Dial9SessionGuard { guard, config }))
+}
+
+/// Periodically restate trace-file disk usage so the metrics collector can read
+/// it from an atomic instead of walking the directory on its own thread.
+async fn refresh_disk_usage_loop() {
+    let mut ticker = tokio::time::interval(DISK_USAGE_REFRESH_INTERVAL);
+    ticker.set_missed_tick_behavior(tokio::time::MissedTickBehavior::Skip);
+
+    loop {
+        ticker.tick().await;
+
+        let Some(location) = dial9_runtime_state().trace_location() else {
+            continue;
+        };
+
+        // `measure_disk_usage_bytes` walks a directory and stats every entry,
+        // so it must stay off the async workers.
+        let measured =
+            tokio::task::spawn_blocking(move || measure_disk_usage_bytes(&location.output_dir, &location.file_prefix)).await;
+
+        match measured {
+            Ok(bytes) => dial9_runtime_state().set_disk_usage_bytes(bytes),
+            Err(e) => warn!(
+                event = EVENT_DIAL9_STATE,
+                component = LOG_COMPONENT_OBS,
+                subsystem = LOG_SUBSYSTEM_DIAL9,
+                result = "disk_usage_refresh_failed",
+                error = %e,
+                "dial9 state changed"
+            ),
+        }
+    }
+}
+
+#[cfg(test)]
+mod tests {
+    use super::super::state::{reset_for_test, runtime_stats_snapshot};
+    use super::*;
+
+    #[test]
+    fn build_traced_runtime_refuses_when_disabled() {
+        reset_for_test();
+        // dial9 is not configured in the unit-test environment, so
+        // `Dial9Config::from_env()` yields a disabled config.
+        let result = build_traced_runtime(tokio::runtime::Builder::new_current_thread());
+        assert!(result.is_err(), "disabled dial9 must not build a traced runtime");
+    }
+
+    #[test]
+    fn recording_session_reports_active_until_stopped() {
+        reset_for_test();
+        let config = Dial9Config {
+            enabled: true,
+            ..Dial9Config::default()
+        };
+
+        dial9_runtime_state().record_runtime_started(&config);
+        assert_eq!(runtime_stats_snapshot().active_sessions, 1);
+
+        // Mirrors what `Dial9SessionGuard::drop` publishes.
+        dial9_runtime_state().record_runtime_stopped();
+        assert_eq!(runtime_stats_snapshot().active_sessions, 0);
+    }
+}