Better timing?

Signed-off-by: Adam Gutglick <[email protected]>

Author: AdamGS

benchmarks/ddb-bench/src/lib.rs

@@ -4,6 +4,8 @@
 //! DuckDB context for benchmarks.
 
 use std::path::PathBuf;
+use std::time::Duration;
+use std::time::Instant;
 
 use anyhow::Result;
 use tracing::trace;
@@ -32,14 +34,14 @@ impl DuckDBObject {
 }
 
 /// DuckDB context for benchmarks.
-pub struct DuckDBCtx {
+pub struct DuckClient {
     pub db: Database,
     pub connection: Connection,
     pub db_path: Option<PathBuf>,
     pub threads: Option<usize>,
 }
 
-impl DuckDBCtx {
+impl DuckClient {
     /// Create a new DuckDB context with a database at `{data_url}/{format}/duckdb.db`.
     pub fn new(
         data_url: &Url,
@@ -135,17 +137,21 @@ impl DuckDBCtx {
     }
 
     /// Execute DuckDB queries for benchmarks using the internal connection.
-    /// Returns the row count.
-    pub fn execute_query(&self, query: &str) -> Result<usize> {
+    /// Returns `(row_count, optional_timing)` where `optional_timing` is the query's
+    /// internal execution time if available.
+    pub fn execute_query(&self, query: &str) -> Result<(usize, Option<Duration>)> {
         trace!("execute duckdb query: {query}");
+        let time_instant = Instant::now();
         let result = self.connection.query(query)?;
-        Ok(usize::try_from(result.row_count()).vortex_expect("row count overflow"))
+        let query_time = time_instant.elapsed();
+
+        let row_count = usize::try_from(result.row_count()).vortex_expect("row count overflow");
+
+        // TODO: Extract DuckDB's internal timing from profiling info if available
+        Ok((row_count, Some(query_time)))
     }
 
     /// Register tables for benchmarks using the internal connection.
-    ///
-    /// Uses `benchmark.table_specs()` to get table names and `benchmark.pattern()`
-    /// to get file glob patterns.
     pub fn register_tables<B: Benchmark + ?Sized>(
         &self,
         benchmark: &B,
@@ -198,8 +204,8 @@ impl DuckDBCtx {
         }
 
         trace!("Executing table registration commands: {commands}");
-        // Ignore the row count result from registration commands
-        let _ = self.execute_query(&commands)?;
+
+        self.execute_query(&commands)?;
 
         Ok(())
     }

benchmarks/ddb-bench/src/main.rs

@@ -7,7 +7,7 @@ use std::path::PathBuf;
 
 use clap::Parser;
 use clap::value_parser;
-use ddb_bench::DuckDBCtx;
+use ddb_bench::DuckClient;
 use vortex_bench::BenchmarkArg;
 use vortex_bench::CompactionStrategy;
 use vortex_bench::Engine;
@@ -120,7 +120,7 @@ async fn main() -> anyhow::Result<()> {
         &filtered_queries,
         args.iterations,
         |format| {
-            let ctx = DuckDBCtx::new(
+            let ctx = DuckClient::new(
                 benchmark.data_url(),
                 format,
                 args.delete_duckdb_database,

benchmarks/ddb-bench/src/validation.rs

@@ -8,7 +8,7 @@ use std::fs;
 use std::path::Path;
 use std::path::PathBuf;
 
-use ddb_bench::DuckDBCtx;
+use ddb_bench::DuckClient;
 use similar::ChangeTag;
 use similar::TextDiff;
 use vortex_bench::Format;
@@ -44,8 +44,8 @@ pub fn verify_duckdb_tpch_results(
     }
     fs::create_dir(&tmp_dir)?;
 
-    let duckdb_ctx = DuckDBCtx::new_in_memory()?;
-    duckdb_ctx.register_tables(benchmark, Format::OnDiskVortex)?;
+    let duckdb = DuckClient::new_in_memory()?;
+    duckdb.register_tables(benchmark, Format::OnDiskVortex)?;
 
     let mut query_files = fs::read_dir(query_dir)?
         .filter_map(Result::ok)
@@ -76,8 +76,8 @@ pub fn verify_duckdb_tpch_results(
         let write_csv =
             format!("COPY {query_name}_result TO '{csv_actual}' (HEADER, DELIMITER '|');",);
 
-        duckdb_ctx.execute_query(&create_table)?;
-        duckdb_ctx.execute_query(&write_csv)?;
+        duckdb.execute_query(&create_table)?;
+        duckdb.execute_query(&write_csv)?;
 
         let csv_expected = Path::new(env!("CARGO_MANIFEST_DIR")).join(format!(
             "../../vortex-bench/tpch/results/duckdb/{query_name}.csv"

benchmarks/df-bench/src/main.rs

@@ -3,6 +3,7 @@
 
 use std::path::PathBuf;
 use std::sync::Arc;
+use std::time::Instant;
 
 use clap::Parser;
 use clap::value_parser;
@@ -155,9 +156,11 @@ async fn main() -> anyhow::Result<()> {
             },
             |session, _query_idx, query| {
                 Box::pin(async move {
+                    let timer = Instant::now();
                     let (batches, plan) = execute_query(session, query).await?;
+                    let time = timer.elapsed();
                     let row_count = batches.iter().map(|batch| batch.num_rows()).sum::<usize>();
-                    anyhow::Ok((row_count, plan))
+                    anyhow::Ok((row_count, Some(time), plan))
                 })
             },
         )

benchmarks/lance-bench/src/main.rs

@@ -3,6 +3,7 @@
 
 use std::path::PathBuf;
 use std::sync::Arc;
+use std::time::Instant;
 
 use clap::Parser;
 use clap::value_parser;
@@ -109,9 +110,11 @@ async fn main() -> anyhow::Result<()> {
             },
             |session, _query_idx, query| {
                 Box::pin(async move {
+                    let timer = Instant::now();
                     let (batches, plan) = execute_query(session, query).await?;
+                    let time = timer.elapsed();
                     let row_count = batches.iter().map(|batch| batch.num_rows()).sum::<usize>();
-                    anyhow::Ok((row_count, plan))
+                    anyhow::Ok((row_count, Some(time), plan))
                 })
             },
         )

vortex-bench/src/runner.rs

@@ -107,7 +107,10 @@ impl SqlBenchmarkRunner {
     /// Run a synchronous query benchmark.
     ///
     /// Executes the query function `iterations` times, collecting timing information.
-    /// The function should return `(row_count, result)` where `row_count` is used for validation.
+    /// The function should return `(row_count, optional_timing, result)` where:
+    /// - `row_count` is used for validation
+    /// - `optional_timing` can be `Some(Duration)` if the callback wants to report its own timing
+    ///   (e.g., DuckDB's internal timing), or `None` to use external wall-clock measurement
     ///
     /// This handles:
     /// - Memory tracking (start/end)
@@ -123,7 +126,7 @@ impl SqlBenchmarkRunner {
         mut f: F,
     ) -> T
     where
-        F: FnMut() -> (usize, T),
+        F: FnMut() -> (usize, Option<Duration>, T),
     {
         self.start_query();
 
@@ -132,8 +135,9 @@ impl SqlBenchmarkRunner {
 
         for _ in 0..iterations {
             let start = Instant::now();
-            let (row_count, iter_result) = f();
-            runs.push(start.elapsed());
+            let (row_count, timing, iter_result) = f();
+            let elapsed = timing.unwrap_or_else(|| start.elapsed());
+            runs.push(elapsed);
 
             if result.is_none() {
                 result = Some((row_count, iter_result));
@@ -149,7 +153,10 @@ impl SqlBenchmarkRunner {
     /// Run an asynchronous query benchmark.
     ///
     /// Executes the async query function `iterations` times, collecting timing information.
-    /// The function should return `(row_count, result)` where `row_count` is used for validation.
+    /// The function should return `(row_count, optional_timing, result)` where:
+    /// - `row_count` is used for validation
+    /// - `optional_timing` can be `Some(Duration)` if the callback wants to report its own timing
+    ///   (e.g., DuckDB's internal timing), or `None` to use external wall-clock measurement
     ///
     /// This handles:
     /// - Memory tracking (start/end)
@@ -166,7 +173,7 @@ impl SqlBenchmarkRunner {
     ) -> T
     where
         F: FnMut() -> Fut,
-        Fut: Future<Output = (usize, T)>,
+        Fut: Future<Output = (usize, Option<Duration>, T)>,
     {
         self.start_query();
 
@@ -175,8 +182,9 @@ impl SqlBenchmarkRunner {
 
         for _ in 0..iterations {
             let start = Instant::now();
-            let (row_count, iter_result) = f().await;
-            runs.push(start.elapsed());
+            let (row_count, timing, iter_result) = f().await;
+            let elapsed = timing.unwrap_or_else(|| start.elapsed());
+            runs.push(elapsed);
 
             if result.is_none() {
                 result = Some((row_count, iter_result));
@@ -306,7 +314,8 @@ impl SqlBenchmarkRunner {
     /// 2. Iterates over all queries, calling `execute` for each
     ///
     /// The `execute` callback receives the context, query index, and query string,
-    /// and should return the row count.
+    /// and should return `(row_count, optional_timing)` where `optional_timing` can be
+    /// `Some(Duration)` if the callback wants to report its own timing.
     pub fn run_all<Ctx, S, E>(
         &mut self,
         queries: &[(usize, String)],
@@ -316,19 +325,19 @@ impl SqlBenchmarkRunner {
     ) -> anyhow::Result<()>
     where
         S: FnMut(Format) -> anyhow::Result<Ctx>,
-        E: FnMut(&mut Ctx, usize, &str) -> anyhow::Result<usize>,
+        E: FnMut(&mut Ctx, usize, &str) -> anyhow::Result<(usize, Option<Duration>)>,
     {
         for format in self.formats.clone() {
             let mut ctx = setup(format)?;
 
             for (query_idx, query) in queries.iter() {
                 let query_idx = *query_idx;
                 self.run_query(query_idx, format, iterations, || {
-                    let row_count =
+                    let (row_count, timing) =
                         execute(&mut ctx, query_idx, query.as_str()).unwrap_or_else(|err| {
                             vortex_panic!("query {query_idx} failed: {err}");
                         });
-                    (row_count, ())
+                    (row_count, timing, ())
                 });
             }
         }
@@ -343,7 +352,9 @@ impl SqlBenchmarkRunner {
     /// 2. Iterates over all queries, calling `execute` for each
     ///
     /// The `execute` callback receives the context, query index, and query string,
-    /// and should return `(row_count, result)`. Use `Box::pin(async move { ... })` in the closure.
+    /// and should return `(row_count, optional_timing, result)` where `optional_timing` can be
+    /// `Some(Duration)` if the callback wants to report its own timing.
+    /// Use `Box::pin(async move { ... })` in the closure.
     pub async fn run_all_async<Ctx, S, SFut, E, T>(
         &mut self,
         queries: &[(usize, String)],
@@ -358,7 +369,7 @@ impl SqlBenchmarkRunner {
             &'c Ctx,
             usize,
             &'c str,
-        ) -> Pin<Box<dyn Future<Output = anyhow::Result<(usize, T)>> + 'c>>,
+        ) -> Pin<Box<dyn Future<Output = anyhow::Result<(usize, Option<Duration>, T)>> + 'c>>,
     {
         for format in self.formats.clone() {
             let ctx = setup(format).await?;
@@ -373,12 +384,13 @@ impl SqlBenchmarkRunner {
 
                 for _ in 0..iterations {
                     let start = Instant::now();
-                    let (row_count, iter_result) = execute(&ctx, query_idx, query.as_str())
+                    let (row_count, timing, iter_result) = execute(&ctx, query_idx, query.as_str())
                         .await
                         .unwrap_or_else(|err| {
                             vortex_panic!("query {query_idx} failed: {err}");
                         });
-                    runs.push(start.elapsed());
+                    let elapsed = timing.unwrap_or_else(|| start.elapsed());
+                    runs.push(elapsed);
 
                     if result.is_none() {
                         result = Some((row_count, iter_result));