Use perfetto tracing (#4250)

This backend generates actual Perfetto protobufs, and so we get events
showing up on the correct threads!!

See 
<img width="1245" height="1044" alt="Screenshot 2025-08-15 at 10 33 14"
src="https://github.com/user-attachments/assets/ad9cfcd6-5ca5-4db7-9265-a44c5fb8e978"
/>

Vs the old chrome:
<img width="1486" height="1278" alt="Screenshot 2025-08-15 at 10 33 20"
src="https://github.com/user-attachments/assets/48e5545b-eb86-42ed-8a9d-a39f9d7ae845"
/>

---------

Signed-off-by: Nicholas Gates <[email protected]>

Author: gatesn

Cargo.lock

@@ -177,7 +177,7 @@ tokio-stream = "0.1.17"
 tpchgen = { git = "https://github.com/clflushopt/tpchgen-rs.git", rev = "d849ff430cd52250f6891ed4d5e3adad77bb2698" }
 tpchgen-arrow = { git = "https://github.com/clflushopt/tpchgen-rs.git", rev = "d849ff430cd52250f6891ed4d5e3adad77bb2698" }
 tracing = { version = "0.1.41" }
-tracing-chrome = "0.7.2"
+tracing-perfetto = "0.1.5"
 tracing-subscriber = "0.3.19"
 url = "2.5.4"
 uuid = { version = "1.17", features = ["js"] }

Cargo.toml

@@ -63,7 +63,7 @@ tokio-stream = { workspace = true }
 tpchgen = { workspace = true }
 tpchgen-arrow = { workspace = true }
 tracing = { workspace = true }
-tracing-chrome = { workspace = true }
+tracing-perfetto = { workspace = true }
 tracing-subscriber = { workspace = true, features = [
     "env-filter",
     "tracing-log",
@@ -79,6 +79,3 @@ vortex = { workspace = true, features = [
 vortex-datafusion = { workspace = true }
 vortex-duckdb = { workspace = true }
 xshell = { workspace = true }
-
-[features]
-tracing = ["vortex-datafusion/tracing"]

bench-vortex/Cargo.toml

@@ -17,9 +17,7 @@ use crate::engines::{EngineCtx, benchmark_datafusion_query};
 use crate::measurements::{MemoryMeasurement, QueryMeasurement};
 use crate::memory::BenchmarkMemoryTracker;
 use crate::metrics::{MetricsSetExt, export_plan_spans};
-use crate::query_bench::{
-    filter_queries, print_memory_usage, print_results, setup_logging_and_tracing,
-};
+use crate::query_bench::{filter_queries, print_memory_usage, print_results};
 use crate::utils::{new_tokio_runtime, url_scheme_to_storage};
 use crate::{Engine, Format, Target, df, vortex_panic};
 
@@ -28,7 +26,6 @@ pub struct DriverConfig {
     pub targets: Vec<Target>,
     pub iterations: usize,
     pub threads: Option<usize>,
-    pub verbose: bool,
     pub display_format: DisplayFormat,
     pub disable_datafusion_cache: bool,
     pub delete_duckdb_database: bool,
@@ -44,11 +41,6 @@ pub struct DriverConfig {
 
 /// Run a benchmark using the provided implementation and configuration
 pub fn run_benchmark<B: Benchmark>(benchmark: B, config: DriverConfig) -> Result<()> {
-    let _trace_guard = setup_logging_and_tracing(
-        config.verbose,
-        &format!("{}.trace.json", benchmark.dataset_name()),
-    )?;
-
     // Generate data for each target (idempotent)
     for target in &config.targets {
         benchmark.generate_data(target)?;

bench-vortex/src/benchmark_driver.rs

@@ -14,7 +14,7 @@ use bench_vortex::display::{DisplayFormat, print_measurements_json, render_table
 use bench_vortex::public_bi::PBI_DATASETS;
 use bench_vortex::public_bi::PBIDataset::{Arade, Bimbo, CMSprovider, Euro2016, Food, HashTags};
 use bench_vortex::utils::new_tokio_runtime;
-use bench_vortex::{Engine, Format, Target, default_env_filter, setup_logger};
+use bench_vortex::{Engine, Format, Target, setup_logging_and_tracing};
 use clap::Parser;
 use indicatif::ProgressBar;
 use itertools::Itertools;
@@ -40,13 +40,14 @@ struct Args {
     display_format: DisplayFormat,
     #[arg(short)]
     output_path: Option<PathBuf>,
+    #[arg(long)]
+    tracing: bool,
 }
 
 fn main() -> anyhow::Result<()> {
     let args = Args::parse();
 
-    let filter = default_env_filter(args.verbose);
-    setup_logger(filter);
+    setup_logging_and_tracing(args.verbose, args.tracing)?;
 
     let runtime = new_tokio_runtime(args.threads);
 

bench-vortex/src/bin/compress.rs

@@ -12,7 +12,7 @@ use bench_vortex::metrics::MetricsSetExt;
 use bench_vortex::public_bi::{FileType, PBI_DATASETS, PBIDataset};
 use bench_vortex::utils::constants::STORAGE_NVME;
 use bench_vortex::utils::new_tokio_runtime;
-use bench_vortex::{BenchmarkDataset, Format, Target, default_env_filter, df};
+use bench_vortex::{BenchmarkDataset, Format, Target, df, setup_logging_and_tracing};
 use clap::{Parser, value_parser};
 use indicatif::ProgressBar;
 use itertools::Itertools;
@@ -51,43 +51,14 @@ struct Args {
     queries: Option<Vec<usize>>,
     #[arg(short)]
     output_path: Option<PathBuf>,
+    #[arg(long)]
+    tracing: bool,
 }
 
 fn main() -> anyhow::Result<()> {
     let args = Args::parse();
 
-    // Capture `RUST_LOG` configuration
-    let filter = default_env_filter(args.verbose);
-
-    #[cfg(not(feature = "tracing"))]
-    bench_vortex::setup_logger(filter);
-
-    // We need the guard to live to the end of the function, so can't create it in the if-block
-    #[cfg(feature = "tracing")]
-    let _trace_guard = {
-        use std::io::IsTerminal;
-
-        use tracing_subscriber::prelude::*;
-
-        let (layer, _guard) = tracing_chrome::ChromeLayerBuilder::new()
-            .include_args(true)
-            .trace_style(tracing_chrome::TraceStyle::Async)
-            .file("public_bi.trace.json")
-            .build();
-
-        let fmt_layer = tracing_subscriber::fmt::layer()
-            .with_writer(std::io::stderr)
-            .with_level(true)
-            .with_line_number(true)
-            .with_ansi(std::io::stderr().is_terminal());
-
-        tracing_subscriber::registry()
-            .with(filter)
-            .with(layer)
-            .with(fmt_layer)
-            .init();
-        _guard
-    };
+    setup_logging_and_tracing(args.verbose, args.tracing)?;
 
     let runtime = new_tokio_runtime(args.threads);
 

bench-vortex/src/bin/public_bi.rs

@@ -3,12 +3,12 @@
 
 use std::path::PathBuf;
 
-use bench_vortex::Target;
 use bench_vortex::benchmark_driver::{DriverConfig, run_benchmark};
 use bench_vortex::clickbench::{ClickBenchBenchmark, Flavor};
 use bench_vortex::display::DisplayFormat;
 use bench_vortex::tpcds::TpcDsBenchmark;
 use bench_vortex::tpch::tpch_benchmark::TpcHBenchmark;
+use bench_vortex::{Target, setup_logging_and_tracing};
 use clap::{Parser, Subcommand, value_parser};
 
 #[derive(Parser, Debug)]
@@ -45,6 +45,9 @@ struct CommonArgs {
     #[arg(short, long)]
     verbose: bool,
 
+    #[arg(long)]
+    tracing: bool,
+
     #[arg(long)]
     export_spans: bool,
 
@@ -170,7 +173,6 @@ fn validate_scale_factor(val: &str) -> Result<String, String> {
 
 fn main() -> anyhow::Result<()> {
     let args = Args::parse();
-
     match args.command {
         Commands::ClickBench(clickbench_args) => run_clickbench(clickbench_args),
         Commands::TpcH(tpch_args) => run_tpch(tpch_args),
@@ -179,6 +181,8 @@ fn main() -> anyhow::Result<()> {
 }
 
 fn run_clickbench(args: ClickBenchArgs) -> anyhow::Result<()> {
+    setup_logging_and_tracing(args.common.verbose, args.common.tracing)?;
+
     // Create benchmark instance
     let benchmark = ClickBenchBenchmark::new(
         args.flavor,
@@ -191,7 +195,6 @@ fn run_clickbench(args: ClickBenchArgs) -> anyhow::Result<()> {
         targets: args.targets,
         iterations: args.common.iterations,
         threads: args.common.threads,
-        verbose: args.common.verbose,
         display_format: args.common.display_format,
         disable_datafusion_cache: args.common.disable_datafusion_cache,
         delete_duckdb_database: args.common.delete_duckdb_database,
@@ -211,6 +214,8 @@ fn run_clickbench(args: ClickBenchArgs) -> anyhow::Result<()> {
 }
 
 fn run_tpch(args: TpcHArgs) -> anyhow::Result<()> {
+    setup_logging_and_tracing(args.common.verbose, args.common.tracing)?;
+
     // Create benchmark instance
     let benchmark = TpcHBenchmark::new(args.scale_factor, args.common.use_remote_data_dir)?;
 
@@ -219,7 +224,6 @@ fn run_tpch(args: TpcHArgs) -> anyhow::Result<()> {
         targets: args.targets,
         iterations: args.common.iterations,
         threads: args.common.threads,
-        verbose: args.common.verbose,
         display_format: args.common.display_format,
         disable_datafusion_cache: args.common.disable_datafusion_cache,
         delete_duckdb_database: args.common.delete_duckdb_database,
@@ -240,6 +244,8 @@ fn run_tpch(args: TpcHArgs) -> anyhow::Result<()> {
 }
 
 fn run_tpcds(args: TpcDSArgs) -> anyhow::Result<()> {
+    setup_logging_and_tracing(args.common.verbose, args.common.tracing)?;
+
     // Create benchmark instance
     let benchmark = TpcDsBenchmark::new(args.scale_factor, args.common.use_remote_data_dir)?;
 
@@ -248,7 +254,6 @@ fn run_tpcds(args: TpcDSArgs) -> anyhow::Result<()> {
         targets: args.targets,
         iterations: args.common.iterations,
         threads: args.common.threads,
-        verbose: args.common.verbose,
         display_format: args.common.display_format,
         disable_datafusion_cache: args.common.disable_datafusion_cache,
         delete_duckdb_database: args.common.delete_duckdb_database,

bench-vortex/src/bin/query_bench.rs

@@ -12,7 +12,7 @@ use bench_vortex::measurements::TimingMeasurement;
 use bench_vortex::random_access::take::{take_parquet, take_vortex_tokio};
 use bench_vortex::utils::constants::STORAGE_NVME;
 use bench_vortex::utils::new_tokio_runtime;
-use bench_vortex::{Engine, Format, Target, default_env_filter, setup_logger};
+use bench_vortex::{Engine, Format, Target, setup_logging_and_tracing};
 use clap::Parser;
 use indicatif::ProgressBar;
 use itertools::Itertools;
@@ -34,6 +34,8 @@ struct Args {
     formats: Vec<Format>,
     #[arg(short, long)]
     verbose: bool,
+    #[arg(long)]
+    tracing: bool,
     #[arg(short, long, default_value_t, value_enum)]
     display_format: DisplayFormat,
     #[arg(short)]
@@ -42,6 +44,9 @@ struct Args {
 
 fn main() -> anyhow::Result<()> {
     let args = Args::parse();
+
+    setup_logging_and_tracing(args.verbose, args.tracing)?;
+
     let runtime = new_tokio_runtime(args.threads);
 
     let indices = buffer![10u64, 11, 12, 13, 100_000, 3_000_000];
@@ -50,7 +55,6 @@ fn main() -> anyhow::Result<()> {
         args.iterations,
         args.formats,
         args.display_format,
-        args.verbose,
         indices,
         &args.output_path,
     )
@@ -61,14 +65,9 @@ fn random_access(
     iterations: usize,
     formats: Vec<Format>,
     display_format: DisplayFormat,
-    verbose: bool,
     indices: Buffer<u64>,
     output_path: &Option<PathBuf>,
 ) -> anyhow::Result<()> {
-    // Capture `RUST_LOG` configuration
-    let filter = default_env_filter(verbose);
-    setup_logger(filter);
-
     let targets = formats
         .iter()
         .map(|f| Target::new(Engine::Vortex, *f))