perf: impl tail-based tracing with minitrace (#567)

.github/template/template.yml

@@ -106,6 +106,7 @@ jobs:
         run: |
           cargo clippy --all-targets --features tokio-console -- -D warnings
           cargo clippy --all-targets --features deadlock -- -D warnings
+          cargo clippy --all-targets --features mtrace -- -D warnings
           cargo clippy --all-targets -- -D warnings
       - if: steps.cache.outputs.cache-hit != 'true'
         uses: taiki-e/install-action@cargo-llvm-cov

.github/workflows/main.yml

@@ -112,6 +112,7 @@ jobs:
         run: |
           cargo clippy --all-targets --features tokio-console -- -D warnings
           cargo clippy --all-targets --features deadlock -- -D warnings
+          cargo clippy --all-targets --features mtrace -- -D warnings
           cargo clippy --all-targets -- -D warnings
       - if: steps.cache.outputs.cache-hit != 'true'
         uses: taiki-e/install-action@cargo-llvm-cov

.github/workflows/pull-request.yml

@@ -111,6 +111,7 @@ jobs:
         run: |
           cargo clippy --all-targets --features tokio-console -- -D warnings
           cargo clippy --all-targets --features deadlock -- -D warnings
+          cargo clippy --all-targets --features mtrace -- -D warnings
           cargo clippy --all-targets -- -D warnings
       - if: steps.cache.outputs.cache-hit != 'true'
         uses: taiki-e/install-action@cargo-llvm-cov

.gitignore

@@ -9,4 +9,6 @@ docker-compose.override.yaml
 .tmp
 
 perf.data*
-flamegraph.svg
+flamegraph.svg
+
+trace.txt

Cargo.toml

@@ -28,6 +28,8 @@ test-log = { version = "0.2", default-features = false, features = [
 ] }
 itertools = "0.13"
 metrics = "0.23"
+minitrace = "0.6"
+minitrace-jaeger = "0.6"
 
 [profile.release]
 debug = true

Makefile

@@ -23,6 +23,7 @@ check-all:
 	cargo clippy --all-targets --features tokio-console
 	cargo clippy --all-targets --features trace
 	cargo clippy --all-targets --features sanity
+	cargo clippy --all-targets --features mtrace
 	cargo clippy --all-targets
 
 test:

foyer-bench/Cargo.toml

@@ -21,6 +21,8 @@ hdrhistogram = "7"
 itertools = { workspace = true }
 metrics = { workspace = true }
 metrics-exporter-prometheus = "0.15"
+minitrace = { workspace = true, optional = true }
+minitrace-jaeger = { workspace = true, optional = true }
 opentelemetry = { version = "0.23", optional = true }
 opentelemetry-otlp = { version = "0.16", optional = true }
 opentelemetry-semantic-conventions = { version = "0.15", optional = true }
@@ -54,3 +56,4 @@ trace = [
 strict_assertions = ["foyer/strict_assertions"]
 sanity = ["foyer/sanity"]
 jemalloc = ["tikv-jemallocator"]
+mtrace = ["foyer/mtrace", "minitrace-jaeger", "minitrace"]

foyer-bench/src/main.rs

@@ -19,7 +19,7 @@ mod text;
 use bytesize::MIB;
 use foyer::{
     DirectFsDeviceOptionsBuilder, FifoConfig, FifoPicker, HybridCache, HybridCacheBuilder, InvalidRatioPicker,
-    LfuConfig, LruConfig, RateLimitPicker, RuntimeConfigBuilder, S3FifoConfig,
+    LfuConfig, LruConfig, RateLimitPicker, RuntimeConfigBuilder, S3FifoConfig, TraceConfig,
 };
 use metrics_exporter_prometheus::PrometheusBuilder;
 
@@ -29,7 +29,7 @@ use std::{
     net::SocketAddr,
     ops::{Deref, Range},
     sync::{
-        atomic::{AtomicU64, Ordering},
+        atomic::{AtomicU64, AtomicUsize, Ordering},
         Arc,
     },
     time::{Duration, Instant},
@@ -179,6 +179,22 @@ pub struct Args {
 
     #[arg(long, default_value = "lfu")]
     eviction: String,
+
+    /// Record insert trace threshold. Only effective with "mtrace" feature.
+    #[arg(long, default_value_t = 1000 * 1000 * 1000)]
+    trace_insert_ns: usize,
+    /// Record get trace threshold. Only effective with "mtrace" feature.
+    #[arg(long, default_value_t = 1000 * 1000 * 1000)]
+    trace_get_ns: usize,
+    /// Record obtain trace threshold. Only effective with "mtrace" feature.
+    #[arg(long, default_value_t = 1000 * 1000 * 1000)]
+    trace_obtain_ns: usize,
+    /// Record remove trace threshold. Only effective with "mtrace" feature.
+    #[arg(long, default_value_t = 1000 * 1000 * 1000)]
+    trace_remove_ns: usize,
+    /// Record fetch trace threshold. Only effective with "mtrace" feature.
+    #[arg(long, default_value_t = 1000 * 1000 * 1000)]
+    trace_fetch_ns: usize,
 }
 
 #[derive(Debug)]
@@ -265,12 +281,12 @@ mod arc_bytes {
 }
 
 #[cfg(feature = "tokio-console")]
-fn init_logger() {
+fn setup() {
     console_subscriber::init();
 }
 
 #[cfg(feature = "trace")]
-fn init_logger() {
+fn setup() {
     use opentelemetry_sdk::{
         trace::{BatchConfigBuilder, Config},
         Resource,
@@ -309,8 +325,18 @@ fn init_logger() {
         .init();
 }
 
-#[cfg(not(any(feature = "tokio-console", feature = "trace")))]
-fn init_logger() {
+#[cfg(feature = "mtrace")]
+fn setup() {
+    use minitrace::collector::Config;
+    let reporter = minitrace_jaeger::JaegerReporter::new("127.0.0.1:6831".parse().unwrap(), "foyer-bench").unwrap();
+    minitrace::set_reporter(
+        reporter,
+        Config::default().batch_report_interval(Duration::from_millis(1)),
+    );
+}
+
+#[cfg(not(any(feature = "tokio-console", feature = "trace", feature = "mtrace")))]
+fn setup() {
     use tracing_subscriber::{prelude::*, EnvFilter};
 
     tracing_subscriber::registry()
@@ -323,12 +349,22 @@ fn init_logger() {
         .init();
 }
 
+#[cfg(not(any(feature = "mtrace")))]
+fn teardown() {}
+
+#[cfg(feature = "mtrace")]
+fn teardown() {
+    minitrace::flush();
+}
+
 #[tokio::main]
 async fn main() {
-    init_logger();
+    setup();
 
     #[cfg(all(feature = "jemalloc", not(target_env = "msvc")))]
-    tracing::info!("[foyer bench]: jemalloc is enabled.");
+    {
+        tracing::info!("[foyer bench]: jemalloc is enabled.");
+    }
 
     #[cfg(feature = "deadlock")]
     {
@@ -367,7 +403,16 @@ async fn main() {
 
     create_dir_all(&args.dir).unwrap();
 
+    let trace_config = TraceConfig {
+        record_hybrid_insert_threshold_ns: AtomicUsize::new(args.trace_insert_ns),
+        record_hybrid_get_threshold_ns: AtomicUsize::new(args.trace_get_ns),
+        record_hybrid_obtain_threshold_ns: AtomicUsize::new(args.trace_obtain_ns),
+        record_hybrid_remove_threshold_ns: AtomicUsize::new(args.trace_remove_ns),
+        record_hybrid_fetch_threshold_ns: AtomicUsize::new(args.trace_fetch_ns),
+    };
+
     let builder = HybridCacheBuilder::new()
+        .with_trace_config(trace_config)
         .memory(args.mem * MIB as usize)
         .with_shards(args.shards);
 
@@ -473,6 +518,8 @@ async fn main() {
     handle_signal.abort();
 
     println!("\nTotal:\n{}", analysis);
+
+    teardown();
 }
 
 async fn bench(args: Args, hybrid: HybridCache<u64, Value>, metrics: Metrics, stop_tx: broadcast::Sender<()>) {

foyer-common/src/lib.rs

@@ -45,6 +45,8 @@ pub mod rate;
 pub mod rated_ticket;
 /// A runtime that automatically shutdown itself on drop.
 pub mod runtime;
+/// Trace related components.
+pub mod trace;
 
 /// File system utils.
 #[cfg(any(target_os = "linux", target_os = "macos"))]

foyer-common/src/trace.rs

@@ -0,0 +1,42 @@
+//  Copyright 2024 Foyer Project Authors
+//
+//  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.
+
+use std::sync::atomic::AtomicUsize;
+
+/// Configurations for trace.
+#[derive(Debug)]
+pub struct TraceConfig {
+    /// Threshold for recording the hybrid cache `insert` and `insert_with_context` operation in ns.
+    pub record_hybrid_insert_threshold_ns: AtomicUsize,
+    /// Threshold for recording the hybrid cache `get` operation in ns.
+    pub record_hybrid_get_threshold_ns: AtomicUsize,
+    /// Threshold for recording the hybrid cache `obtain` operation in ns.
+    pub record_hybrid_obtain_threshold_ns: AtomicUsize,
+    /// Threshold for recording the hybrid cache `remove` operation in ns.
+    pub record_hybrid_remove_threshold_ns: AtomicUsize,
+    /// Threshold for recording the hybrid cache `fetch` operation in ns.
+    pub record_hybrid_fetch_threshold_ns: AtomicUsize,
+}
+
+impl Default for TraceConfig {
+    fn default() -> Self {
+        Self {
+            record_hybrid_insert_threshold_ns: AtomicUsize::from(1000 * 1000 * 1000),
+            record_hybrid_get_threshold_ns: AtomicUsize::from(1000 * 1000 * 1000),
+            record_hybrid_obtain_threshold_ns: AtomicUsize::from(1000 * 1000 * 1000),
+            record_hybrid_remove_threshold_ns: AtomicUsize::from(1000 * 1000 * 1000),
+            record_hybrid_fetch_threshold_ns: AtomicUsize::from(1000 * 1000 * 1000),
+        }
+    }
+}

foyer-memory/Cargo.toml

@@ -20,6 +20,7 @@ futures = "0.3"
 hashbrown = "0.14"
 itertools = { workspace = true }
 libc = "0.2"
+minitrace = { workspace = true }
 parking_lot = "0.12"
 serde = { workspace = true }
 tokio = { workspace = true }
@@ -40,6 +41,7 @@ strict_assertions = [
     "foyer-intrusive/strict_assertions",
 ]
 sanity = ["strict_assertions"]
+mtrace = ["minitrace/enable"]
 
 [[bench]]
 name = "bench_hit_ratio"

foyer-memory/src/cache.rs

@@ -501,6 +501,7 @@ where
     S: HashBuilder,
 {
     /// Insert cache entry to the in-memory cache.
+    #[minitrace::trace(short_name = true)]
     pub fn insert(&self, key: K, value: V) -> CacheEntry<K, V, S> {
         match self {
             Cache::Fifo(cache) => cache.insert(key, value).into(),
@@ -511,6 +512,7 @@ where
     }
 
     /// Insert cache entry with cache context to the in-memory cache.
+    #[minitrace::trace(short_name = true)]
     pub fn insert_with_context(&self, key: K, value: V, context: CacheContext) -> CacheEntry<K, V, S> {
         match self {
             Cache::Fifo(cache) => cache.insert_with_context(key, value, context).into(),
@@ -525,6 +527,7 @@ where
     /// The entry will be removed as soon as the returned entry is dropped.
     ///
     /// The entry will become a normal entry after it is accessed.
+    #[minitrace::trace(short_name = true)]
     pub fn deposit(&self, key: K, value: V) -> CacheEntry<K, V, S> {
         match self {
             Cache::Fifo(cache) => cache.deposit(key, value).into(),
@@ -539,6 +542,7 @@ where
     /// The entry will be removed as soon as the returned entry is dropped.
     ///
     /// The entry will become a normal entry after it is accessed.
+    #[minitrace::trace(short_name = true)]
     pub fn deposit_with_context(&self, key: K, value: V, context: CacheContext) -> CacheEntry<K, V, S> {
         match self {
             Cache::Fifo(cache) => cache.deposit_with_context(key, value, context).into(),
@@ -549,6 +553,7 @@ where
     }
 
     /// Remove a cached entry with the given key from the in-memory cache.
+    #[minitrace::trace(short_name = true)]
     pub fn remove<Q>(&self, key: &Q) -> Option<CacheEntry<K, V, S>>
     where
         K: Borrow<Q>,
@@ -563,6 +568,7 @@ where
     }
 
     /// Get cached entry with the given key from the in-memory cache.
+    #[minitrace::trace(short_name = true)]
     pub fn get<Q>(&self, key: &Q) -> Option<CacheEntry<K, V, S>>
     where
         K: Borrow<Q>,
@@ -577,6 +583,7 @@ where
     }
 
     /// Check if the in-memory cache contains a cached entry with the given key.
+    #[minitrace::trace(short_name = true)]
     pub fn contains<Q>(&self, key: &Q) -> bool
     where
         K: Borrow<Q>,
@@ -593,6 +600,7 @@ where
     /// Access the cached entry with the given key but don't return.
     ///
     /// Note: This method can be used to update the cache eviction information and order based on the algorithm.
+    #[minitrace::trace(short_name = true)]
     pub fn touch<Q>(&self, key: &Q) -> bool
     where
         K: Borrow<Q>,
@@ -607,6 +615,7 @@ where
     }
 
     /// Clear the in-memory cache.
+    #[minitrace::trace(short_name = true)]
     pub fn clear(&self) {
         match self {
             Cache::Fifo(cache) => cache.clear(),
@@ -778,6 +787,7 @@ where
     /// Use `fetch` to fetch the cache value from the remote storage on cache miss.
     ///
     /// The concurrent fetch requests will be deduplicated.
+    #[minitrace::trace(short_name = true)]
     pub fn fetch<F, FU, ER>(&self, key: K, fetch: F) -> Fetch<K, V, ER, S>
     where
         F: FnOnce() -> FU,

foyer-memory/src/generic.rs

@@ -46,6 +46,8 @@ use crate::{
     CacheContext,
 };
 
+use minitrace::prelude::*;
+
 // TODO(MrCroxx): Use `trait_alias` after stable.
 /// The weighter for the in-memory cache.
 ///
@@ -748,7 +750,7 @@ where
         }
 
         let cache = self.clone();
-        let future = fetch();
+        let future = fetch().in_span(Span::enter_with_local_parent("spawned"));
         let join = runtime.spawn(async move {
             let (value, context) = match future.await {
                 Ok((value, context)) => (value, context),

foyer-storage/Cargo.toml

@@ -29,6 +29,7 @@ itertools = { workspace = true }
 lazy_static = "1"
 libc = "0.2"
 lz4 = "1.24"
+minitrace = { workspace = true }
 parking_lot = { version = "0.12", features = ["arc_lock"] }
 pin-project = "1"
 rand = "0.8"
@@ -51,3 +52,4 @@ strict_assertions = [
     "foyer-common/strict_assertions",
     "foyer-memory/strict_assertions",
 ]
+mtrace = ["minitrace/enable", "foyer-memory/mtrace"]