problem & non-solution: cargo hakari enables tokio/tracing feature

cargo check --tests -p utils
cargo check --tests -p utils  --features tracing-based-debugging
RUSTFLAGS="--cfg tokio_unstable" cargo check --tests -p utils --features tracing-based-debugging

Cargo.lock

@@ -1323,6 +1323,45 @@ dependencies = [
  "crossbeam-utils",
 ]
 
+[[package]]
+name = "console-api"
+version = "0.8.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "8030735ecb0d128428b64cd379809817e620a40e5001c54465b99ec5feec2857"
+dependencies = [
+ "futures-core",
+ "prost",
+ "prost-types",
+ "tonic",
+ "tracing-core",
+]
+
+[[package]]
+name = "console-subscriber"
+version = "0.4.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "6539aa9c6a4cd31f4b1c040f860a1eac9aa80e7df6b05d506a6e7179936d6a01"
+dependencies = [
+ "console-api",
+ "crossbeam-channel",
+ "crossbeam-utils",
+ "futures-task",
+ "hdrhistogram",
+ "humantime",
+ "hyper-util",
+ "prost",
+ "prost-types",
+ "serde",
+ "serde_json",
+ "thread_local",
+ "tokio",
+ "tokio-stream",
+ "tonic",
+ "tracing",
+ "tracing-core",
+ "tracing-subscriber",
+]
+
 [[package]]
 name = "const-oid"
 version = "0.9.6"
@@ -3513,6 +3552,16 @@ dependencies = [
  "winapi",
 ]
 
+[[package]]
+name = "nu-ansi-term"
+version = "0.46.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "77a8165726e8236064dbb45459242600304b42a5ea24ee2948e18e023bf7ba84"
+dependencies = [
+ "overload",
+ "winapi",
+]
+
 [[package]]
 name = "num"
 version = "0.4.1"
@@ -3808,6 +3857,12 @@ version = "0.5.1"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "4030760ffd992bef45b0ae3f10ce1aba99e33464c90d14dd7c039884963ddc7a"
 
+[[package]]
+name = "overload"
+version = "0.1.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "b15813163c1d831bf4a13c3610c05c0d03b39feb07f7e09fa234dac9b15aaf39"
+
 [[package]]
 name = "p256"
 version = "0.11.1"
@@ -6636,6 +6691,7 @@ dependencies = [
  "signal-hook-registry",
  "socket2",
  "tokio-macros",
+ "tracing",
  "windows-sys 0.48.0",
 ]
 
@@ -6967,6 +7023,17 @@ dependencies = [
  "syn 2.0.90",
 ]
 
+[[package]]
+name = "tracing-chrome"
+version = "0.7.2"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "bf0a738ed5d6450a9fb96e86a23ad808de2b727fd1394585da5cdd6788ffe724"
+dependencies = [
+ "serde_json",
+ "tracing-core",
+ "tracing-subscriber",
+]
+
 [[package]]
 name = "tracing-core"
 version = "0.1.33"
@@ -6987,6 +7054,17 @@ dependencies = [
  "tracing-subscriber",
 ]
 
+[[package]]
+name = "tracing-flame"
+version = "0.2.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "0bae117ee14789185e129aaee5d93750abe67fdc5a9a62650452bfe4e122a3a9"
+dependencies = [
+ "lazy_static",
+ "tracing",
+ "tracing-subscriber",
+]
+
 [[package]]
 name = "tracing-log"
 version = "0.2.0"
@@ -7033,6 +7111,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "e8189decb5ac0fa7bc8b96b7cb9b2701d60d48805aca84a238004d665fcc4008"
 dependencies = [
  "matchers",
+ "nu-ansi-term",
  "once_cell",
  "regex",
  "serde",
@@ -7242,6 +7321,7 @@ dependencies = [
  "camino",
  "camino-tempfile",
  "chrono",
+ "console-subscriber",
  "const_format",
  "criterion",
  "diatomic-waker",
@@ -7283,7 +7363,9 @@ dependencies = [
  "tokio-util",
  "toml_edit",
  "tracing",
+ "tracing-chrome",
  "tracing-error",
+ "tracing-flame",
  "tracing-subscriber",
  "url",
  "uuid",
@@ -7797,6 +7879,7 @@ dependencies = [
  "chrono",
  "clap",
  "clap_builder",
+ "crossbeam-utils",
  "crypto-bigint 0.5.5",
  "der 0.7.8",
  "deranged",
@@ -7813,6 +7896,7 @@ dependencies = [
  "getrandom 0.2.11",
  "half",
  "hashbrown 0.14.5",
+ "hdrhistogram",
  "hex",
  "hmac",
  "hyper 0.14.30",
@@ -7870,6 +7954,7 @@ dependencies = [
  "tower",
  "tracing",
  "tracing-core",
+ "tracing-subscriber",
  "url",
  "zerocopy",
  "zeroize",

compute_tools/src/bin/fast_import.rs

@@ -69,7 +69,7 @@ enum EncryptionSecret {
 
 #[tokio::main]
 pub(crate) async fn main() -> anyhow::Result<()> {
-    utils::logging::init(
+    let _guard = utils::logging::init(
         utils::logging::LogFormat::Plain,
         utils::logging::TracingErrorLayerEnablement::EnableWithRustLogFilter,
         utils::logging::Output::Stdout,

libs/desim/tests/reliable_copy_test.rs

@@ -154,7 +154,7 @@ mod reliable_copy_test {
     /// Run test simulations.
     #[test]
     fn sim_example_reliable_copy() {
-        utils::logging::init(
+        let _guard = utils::logging::init(
             utils::logging::LogFormat::Test,
             utils::logging::TracingErrorLayerEnablement::Disabled,
             utils::logging::Output::Stdout,

libs/remote_storage/tests/common/mod.rs

@@ -13,7 +13,7 @@ use tokio::task::JoinSet;
 use tokio_util::sync::CancellationToken;
 use tracing::{debug, error, info};
 
-static LOGGING_DONE: OnceCell<()> = OnceCell::new();
+static LOGGING_DONE: OnceCell<utils::logging::FlushGuard> = OnceCell::new();
 
 pub(crate) fn upload_stream(
     content: std::borrow::Cow<'static, [u8]>,
@@ -210,6 +210,6 @@ pub(crate) fn ensure_logging_ready() {
             utils::logging::TracingErrorLayerEnablement::Disabled,
             utils::logging::Output::Stdout,
         )
-        .expect("logging init failed");
+        .expect("logging init failed")
     });
 }

libs/utils/Cargo.toml

@@ -10,6 +10,10 @@ default = []
 # which adds some runtime cost to run tests on outage conditions
 testing = ["fail/failpoints"]
 
+# Enables debugging functionality that's based on the `tracing` crate,
+# e.g., tokio-console or tracing-chrome.
+tracing-based-debugging = [ "console-subscriber", "tracing-chrome", "tracing-flame", "tokio/tracing" ]
+
 [dependencies]
 arc-swap.workspace = true
 sentry.workspace = true
@@ -20,6 +24,7 @@ bincode.workspace = true
 bytes.workspace = true
 camino.workspace = true
 chrono.workspace = true
+console-subscriber = { version = "0.4.1", optional = true }
 diatomic-waker.workspace = true
 flate2.workspace = true
 git-version.workspace = true
@@ -47,7 +52,9 @@ tokio-tar.workspace = true
 tokio-util.workspace = true
 toml_edit = { workspace = true, features = ["serde"] }
 tracing.workspace = true
+tracing-chrome = { version = "0.7.2", optional = true }
 tracing-error.workspace = true
+tracing-flame = { version = "0.2.0", optional = true }
 tracing-subscriber = { workspace = true, features = ["json", "registry"] }
 rand.workspace = true
 scopeguard.workspace = true
@@ -78,6 +85,9 @@ camino-tempfile.workspace = true
 serde_assert.workspace = true
 tokio = { workspace = true, features = ["test-util"] }
 
+[lints.rust]
+unexpected_cfgs = { level = "warn", check-cfg = ['cfg(tokio_unstable)'] }
+
 [[bench]]
 name = "benchmarks"
 harness = false

libs/utils/src/logging.rs

@@ -1,3 +1,10 @@
+#[cfg(feature = "tracing-based-debugging")]
+use std::{
+    io::BufWriter,
+    num::NonZeroUsize,
+    sync::{Arc, Mutex},
+};
+
 use std::str::FromStr;
 
 use anyhow::Context;
@@ -98,11 +105,44 @@ pub enum Output {
     Stderr,
 }
 
+/// Keep alive and drop it before the program terminates.
+#[allow(dead_code)] // We need to store the `Arc<>` for drop semantics.
+#[must_use]
+#[cfg(feature = "tracing-based-debugging")]
+pub struct FlushGuard(Arc<Mutex<FlushGuardInner>>);
+
+#[cfg(feature = "tracing-based-debugging")]
+struct FlushGuardInner {
+    _tracing_chrome_layer: Option<tracing_chrome::FlushGuard>,
+    _tracing_flame_layer: Option<tracing_flame::FlushGuard<BufWriter<std::fs::File>>>,
+}
+
+#[cfg(not(feature = "tracing-based-debugging"))]
+pub struct FlushGuard;
+
+/// Initialize the global tracing subscriber.
+///
+/// # Tracing-Based Debugging
+///
+/// If feature `tracing-based-debugging` is enabled, this function will add support
+/// for runtime enablement of various tracing-based debugging tools.
+///
+/// The feature is disabled by default to avoid compile time bloat.
+///
+/// For example, to use the `tracing-chrome` crate to debug pageserver:
+///
+/// 1. Enable the feature by adding `tracing-based-debugging` to the `features` list in
+///    the pageserver crate's `Cargo.toml`.
+/// 2. Build pageserver.
+/// 3. Launch pageserver with env var `NEON_UTILS_LOGGING_ENABLE_TRACING_CHROME=1`.
+/// 4. Cleanly shut down pageserver.
+/// 5. Follow instructions of the `tracing-chrome` crate to post-process and visualize
+///    the trace files.
 pub fn init(
     log_format: LogFormat,
     tracing_error_layer_enablement: TracingErrorLayerEnablement,
     output: Output,
-) -> anyhow::Result<()> {
+) -> anyhow::Result<FlushGuard> {
     // We fall back to printing all spans at info-level or above if
     // the RUST_LOG environment variable is not set.
     let rust_log_env_filter = || {
@@ -113,7 +153,9 @@ pub fn init(
     // NB: the order of the with() calls does not matter.
     // See https://docs.rs/tracing-subscriber/0.3.16/tracing_subscriber/layer/index.html#per-layer-filtering
     use tracing_subscriber::prelude::*;
+
     let r = tracing_subscriber::registry();
+
     let r = r.with({
         let log_layer = tracing_subscriber::fmt::layer()
             .with_target(false)
@@ -131,17 +173,95 @@ pub fn init(
         };
         log_layer.with_filter(rust_log_env_filter())
     });
+
     let r = r.with(
         TracingEventCountLayer(&TRACING_EVENT_COUNT_METRIC).with_filter(rust_log_env_filter()),
     );
-    match tracing_error_layer_enablement {
-        TracingErrorLayerEnablement::EnableWithRustLogFilter => r
-            .with(tracing_error::ErrorLayer::default().with_filter(rust_log_env_filter()))
-            .init(),
-        TracingErrorLayerEnablement::Disabled => r.init(),
-    }
 
-    Ok(())
+    let r = r.with(match tracing_error_layer_enablement {
+        TracingErrorLayerEnablement::EnableWithRustLogFilter => {
+            Some(tracing_error::ErrorLayer::default().with_filter(rust_log_env_filter()))
+        }
+        TracingErrorLayerEnablement::Disabled => None,
+    });
+
+    #[cfg(feature = "tracing-based-debugging")]
+    let (r, guard) = {
+        let tracing_chrome_layer_flush_guard;
+        let r = r.with(
+            if crate::env::var("NEON_UTILS_LOGGING_ENABLE_TRACING_CHROME").unwrap_or(false) {
+                let (layer, guard) = tracing_chrome::ChromeLayerBuilder::new()
+                    .trace_style(tracing_chrome::TraceStyle::Async)
+                    .build();
+                tracing_chrome_layer_flush_guard = Some(guard);
+                Some(layer.with_filter(rust_log_env_filter()))
+            } else {
+                tracing_chrome_layer_flush_guard = None;
+                None
+            },
+        );
+
+        let tracing_flame_flush_guard;
+        let r = r.with(
+            if crate::env::var("NEON_UTILS_LOGGING_ENABLE_TRACING_FLAME").unwrap_or(false) {
+                let (layer, guard) =
+                    tracing_flame::FlameLayer::with_file("./tracing.folded").unwrap();
+                let layer = layer
+                    .with_empty_samples(false)
+                    .with_module_path(false)
+                    .with_file_and_line(false)
+                    .with_threads_collapsed(true);
+                tracing_flame_flush_guard = Some(guard);
+                Some(layer.with_filter(rust_log_env_filter()))
+            } else {
+                tracing_flame_flush_guard = None;
+                None
+            },
+        );
+
+        let r = {
+            let varname = "NEON_UTILS_LOGGING_ENABLE_TOKIO_CONSOLE";
+            let console_subscriber_config: Option<NonZeroUsize> = crate::env::var(varname);
+            #[cfg(tokio_unstable)]
+            {
+                r.with(match console_subscriber_config {
+                    Some(n) => {
+                        use console_subscriber::ConsoleLayer;
+                        Some(
+                            console_subscriber::Builder::default()
+                                .event_buffer_capacity(
+                                    n.get() * ConsoleLayer::DEFAULT_EVENT_BUFFER_CAPACITY,
+                                )
+                                .client_buffer_capacity(
+                                    n.get() * ConsoleLayer::DEFAULT_CLIENT_BUFFER_CAPACITY,
+                                )
+                                .spawn(),
+                        )
+                    }
+                    None => None,
+                })
+            }
+            #[cfg(not(tokio_unstable))]
+            if console_subscriber_config.is_some() {
+                panic!("recompile with --cfg tokio_unstable to enable {varname}");
+            } else {
+                r
+            }
+        };
+        (
+            r,
+            FlushGuard(Arc::new(Mutex::new(FlushGuardInner {
+                _tracing_chrome_layer: tracing_chrome_layer_flush_guard,
+                _tracing_flame_layer: tracing_flame_flush_guard,
+            }))),
+        )
+    };
+    #[cfg(not(feature = "tracing-based-debugging"))]
+    let (r, guard) = (r, FlushGuard);
+
+    r.init();
+
+    Ok(guard)
 }
 
 /// Disable the default rust panic hook by using `set_hook`.

pageserver/compaction/tests/tests.rs

@@ -3,7 +3,7 @@ use pageserver_compaction::interface::CompactionLayer;
 use pageserver_compaction::simulator::MockTimeline;
 use utils::logging;
 
-static LOG_HANDLE: OnceCell<()> = OnceCell::new();
+static LOG_HANDLE: OnceCell<logging::FlushGuard> = OnceCell::new();
 
 pub(crate) fn setup_logging() {
     LOG_HANDLE.get_or_init(|| {

pageserver/ctl/src/main.rs

@@ -115,7 +115,7 @@ struct AnalyzeLayerMapCmd {
 
 #[tokio::main]
 async fn main() -> anyhow::Result<()> {
-    logging::init(
+    let _guard = logging::init(
         LogFormat::Plain,
         TracingErrorLayerEnablement::EnableWithRustLogFilter,
         logging::Output::Stdout,

pageserver/pagebench/src/main.rs

@@ -32,7 +32,7 @@ enum Args {
 }
 
 fn main() {
-    logging::init(
+    let _guard = logging::init(
         logging::LogFormat::Plain,
         logging::TracingErrorLayerEnablement::Disabled,
         logging::Output::Stderr,

pageserver/src/bin/pageserver.rs

@@ -114,7 +114,7 @@ fn main() -> anyhow::Result<()> {
     } else {
         TracingErrorLayerEnablement::Disabled
     };
-    logging::init(
+    let _guard = logging::init(
         conf.log_format,
         tracing_error_layer_enablement,
         logging::Output::Stdout,

pageserver/src/tenant.rs

@@ -5562,7 +5562,7 @@ pub(crate) mod harness {
         pub deletion_queue: MockDeletionQueue,
     }
 
-    static LOG_HANDLE: OnceCell<()> = OnceCell::new();
+    static LOG_HANDLE: OnceCell<logging::FlushGuard> = OnceCell::new();
 
     pub(crate) fn setup_logging() {
         LOG_HANDLE.get_or_init(|| {

safekeeper/src/bin/safekeeper.rs

@@ -256,7 +256,7 @@ async fn main() -> anyhow::Result<()> {
     // 1. init logging
     // 2. tracing panic hook
     // 3. sentry
-    logging::init(
+    let _guard = logging::init(
         LogFormat::from_config(&args.log_format)?,
         logging::TracingErrorLayerEnablement::Disabled,
         logging::Output::Stdout,

storage_broker/src/bin/storage_broker.rs

@@ -636,7 +636,7 @@ async fn main() -> Result<(), Box<dyn std::error::Error>> {
     // 1. init logging
     // 2. tracing panic hook
     // 3. sentry
-    logging::init(
+    let _guard = logging::init(
         LogFormat::from_config(&args.log_format)?,
         logging::TracingErrorLayerEnablement::Disabled,
         logging::Output::Stdout,

storage_controller/src/main.rs

@@ -188,7 +188,7 @@ impl Secrets {
 }
 
 fn main() -> anyhow::Result<()> {
-    logging::init(
+    let _guard = logging::init(
         LogFormat::Plain,
         logging::TracingErrorLayerEnablement::Disabled,
         logging::Output::Stdout,
@@ -221,6 +221,12 @@ fn main() -> anyhow::Result<()> {
 async fn async_main() -> anyhow::Result<()> {
     let launch_ts = Box::leak(Box::new(LaunchTimestamp::generate()));
 
+    let _guard = logging::init(
+        LogFormat::Plain,
+        logging::TracingErrorLayerEnablement::Disabled,
+        logging::Output::Stdout,
+    )?;
+
     preinitialize_metrics();
 
     let args = Cli::parse();

workspace_hack/Cargo.toml

@@ -27,6 +27,7 @@ camino = { version = "1", default-features = false, features = ["serde1"] }
 chrono = { version = "0.4", default-features = false, features = ["clock", "serde", "wasmbind"] }
 clap = { version = "4", features = ["derive", "env", "string"] }
 clap_builder = { version = "4", default-features = false, features = ["color", "env", "help", "std", "string", "suggestions", "usage"] }
+crossbeam-utils = { version = "0.8" }
 crypto-bigint = { version = "0.5", features = ["generic-array", "zeroize"] }
 der = { version = "0.7", default-features = false, features = ["oid", "pem", "std"] }
 deranged = { version = "0.3", default-features = false, features = ["powerfmt", "serde", "std"] }
@@ -42,6 +43,7 @@ generic-array = { version = "0.14", default-features = false, features = ["more_
 getrandom = { version = "0.2", default-features = false, features = ["std"] }
 half = { version = "2", default-features = false, features = ["num-traits"] }
 hashbrown = { version = "0.14", features = ["raw"] }
+hdrhistogram = { version = "7" }
 hex = { version = "0.4", features = ["serde"] }
 hmac = { version = "0.12", default-features = false, features = ["reset"] }
 hyper-582f2526e08bb6a0 = { package = "hyper", version = "0.14", features = ["full"] }
@@ -85,7 +87,7 @@ sync_wrapper = { version = "0.1", default-features = false, features = ["futures
 tikv-jemalloc-ctl = { version = "0.6", features = ["stats", "use_std"] }
 tikv-jemalloc-sys = { version = "0.6", features = ["profiling", "stats", "unprefixed_malloc_on_supported_platforms"] }
 time = { version = "0.3", features = ["macros", "serde-well-known"] }
-tokio = { version = "1", features = ["full", "test-util"] }
+tokio = { version = "1", features = ["full", "test-util", "tracing"] }
 tokio-rustls = { version = "0.26", default-features = false, features = ["logging", "ring", "tls12"] }
 tokio-stream = { version = "0.1", features = ["net"] }
 tokio-util = { version = "0.7", features = ["codec", "compat", "io", "rt"] }
@@ -94,6 +96,7 @@ tonic = { version = "0.12", features = ["tls-roots"] }
 tower = { version = "0.4", default-features = false, features = ["balance", "buffer", "limit", "log", "util"] }
 tracing = { version = "0.1", features = ["log"] }
 tracing-core = { version = "0.1" }
+tracing-subscriber = { version = "0.3", features = ["env-filter", "json"] }
 url = { version = "2", features = ["serde"] }
 zerocopy = { version = "0.7", features = ["derive", "simd"] }
 zeroize = { version = "1", features = ["derive", "serde"] }