diff --git a/crates/client-api/src/lib.rs b/crates/client-api/src/lib.rs
index 7fd6f238128..49fe15bee6d 100644
--- a/crates/client-api/src/lib.rs
+++ b/crates/client-api/src/lib.rs
@@ -137,14 +137,28 @@ impl Host {
     pub async fn exec_sql(
         &self,
         auth: AuthCtx,
-        _database: Database,
+        database: Database,
         confirmed_read: bool,
         body: String,
     ) -> axum::response::Result<Vec<SqlStmtResult<ProductValue>>> {
+        let request_start = std::time::Instant::now();
+        let sql_len = body.len();
+        log::debug!(
+            "sql exec: start database={} caller={} confirmed={confirmed_read} sql_len={sql_len}",
+            database.database_identity,
+            auth.caller()
+        );
+        let start = std::time::Instant::now();
+        log::debug!("sql exec: module lookup start database={}", database.database_identity);
         let module_host = self
             .module()
             .await
             .map_err(|_| (StatusCode::NOT_FOUND, "module not found".to_string()))?;
+        log::debug!(
+            "sql exec: module lookup finished database={} elapsed={:?}",
+            database.database_identity,
+            start.elapsed()
+        );
 
         tracing::info!(sql = body);
         let mut header = vec![];
@@ -154,6 +168,11 @@ impl Host {
         let db = module_host.relational_db().clone();
         let durable_offset = db.durable_tx_offset();
 
+        log::debug!(
+            "sql exec: sql::execute::run start database={} caller={}",
+            database.database_identity,
+            auth.caller()
+        );
         let result = sql::execute::run(
             db,
             body,
@@ -164,9 +183,20 @@ impl Host {
         )
         .await
         .map_err(|e| {
+            log::debug!(
+                "sql exec: sql::execute::run failed database={} elapsed={:?} err={e}",
+                database.database_identity,
+                sql_start.elapsed()
+            );
             log::warn!("{e}");
             (StatusCode::BAD_REQUEST, e.to_string())
         })?;
+        log::debug!(
+            "sql exec: sql::execute::run finished database={} elapsed={:?} rows={}",
+            database.database_identity,
+            sql_start.elapsed(),
+            result.rows.len()
+        );
 
         let total_duration = sql_start.elapsed();
         drop(_guard);
@@ -184,12 +214,68 @@ impl Host {
             total_duration_micros: total_duration.as_micros() as u64,
             stats: SqlStmtStats::from_metrics(&result.metrics),
         }];
+        log::debug!(
+            "sql exec: response prepared database={} stmt_results={} rows={} confirmed={confirmed_read}",
+            database.database_identity,
+            json.len(),
+            json.iter().map(|result| result.rows.len()).sum::<usize>()
+        );
 
         if confirmed_read && let Some(mut durable_offset) = durable_offset {
-            let tx_offset = tx_offset.await.map_err(|_| log_and_500("transaction aborted"))?;
-            durable_offset.wait_for(tx_offset).await.map_err(log_and_500)?;
+            let start = std::time::Instant::now();
+            log::debug!(
+                "sql exec: awaiting transaction offset database={}",
+                database.database_identity
+            );
+            let tx_offset = tx_offset.await.map_err(|_| {
+                log::debug!(
+                    "sql exec: transaction offset await failed database={} elapsed={:?}",
+                    database.database_identity,
+                    start.elapsed()
+                );
+                log_and_500("transaction aborted")
+            })?;
+            log::debug!(
+                "sql exec: transaction offset received database={} tx_offset={} elapsed={:?}",
+                database.database_identity,
+                tx_offset,
+                start.elapsed()
+            );
+
+            let start = std::time::Instant::now();
+            log::debug!(
+                "sql exec: waiting for durable offset database={} tx_offset={}",
+                database.database_identity,
+                tx_offset
+            );
+            durable_offset.wait_for(tx_offset).await.map_err(|err| {
+                log::debug!(
+                    "sql exec: durable offset wait failed database={} tx_offset={} elapsed={:?} err={err}",
+                    database.database_identity,
+                    tx_offset,
+                    start.elapsed()
+                );
+                log_and_500(err)
+            })?;
+            log::debug!(
+                "sql exec: durable offset reached database={} tx_offset={} elapsed={:?}",
+                database.database_identity,
+                tx_offset,
+                start.elapsed()
+            );
+        } else {
+            log::debug!(
+                "sql exec: skipping durable offset wait database={} confirmed={confirmed_read} has_durable_offset={}",
+                database.database_identity,
+                durable_offset.is_some()
+            );
         }
 
+        log::debug!(
+            "sql exec: finished database={} elapsed={:?}",
+            database.database_identity,
+            request_start.elapsed()
+        );
         Ok(json)
     }
 
diff --git a/crates/client-api/src/routes/database.rs b/crates/client-api/src/routes/database.rs
index 862597d289c..36b3dffc969 100644
--- a/crates/client-api/src/routes/database.rs
+++ b/crates/client-api/src/routes/database.rs
@@ -717,22 +717,48 @@ where
 {
     tokio::spawn(async move {
         let connection_id = generate_random_connection_id();
+        let request_start = std::time::Instant::now();
+        log::debug!("sql request {connection_id}: spawned connection lifecycle caller={caller_identity}");
 
         // Run the module's client_connected reducer, if any.
         // If it rejects the connection, bail before executing `fut`
+        let start = std::time::Instant::now();
+        log::debug!("sql request {connection_id}: client_connected start caller={caller_identity}");
         module
             .call_identity_connected(caller_auth, connection_id)
             .await
             .map_err(client_connected_error_to_response)?;
+        log::debug!(
+            "sql request {connection_id}: client_connected finished elapsed={:?}",
+            start.elapsed()
+        );
 
+        let start = std::time::Instant::now();
+        log::debug!("sql request {connection_id}: handler future start caller={caller_identity}");
         let result = fut(module.clone(), caller_identity, connection_id).await;
+        log::debug!(
+            "sql request {connection_id}: handler future finished elapsed={:?} ok={}",
+            start.elapsed(),
+            result.is_ok()
+        );
 
         // Always disconnect, even if authorization or execution failed.
+        let start = std::time::Instant::now();
+        log::debug!("sql request {connection_id}: client_disconnected start caller={caller_identity}");
         module
             .call_identity_disconnected(caller_identity, connection_id)
             .await
             .map_err(client_disconnected_error_to_response)?;
+        log::debug!(
+            "sql request {connection_id}: client_disconnected finished elapsed={:?}",
+            start.elapsed()
+        );
 
+        log::debug!(
+            "sql request {connection_id}: connection lifecycle finished elapsed={:?} ok={}",
+            request_start.elapsed(),
+            result.is_ok()
+        );
         result
     })
     .await
@@ -750,21 +776,65 @@ pub async fn sql_direct<S>(
 where
     S: NodeDelegate + ControlStateDelegate + Authorization + 'static,
 {
+    let confirmed_read = confirmed.unwrap_or(crate::DEFAULT_CONFIRMED_READS);
+    let sql_len = sql.len();
+    log::debug!(
+        "sql request: resolving database name_or_identity={name_or_identity:?} caller={caller_identity} confirmed={confirmed_read} sql_len={sql_len}"
+    );
+    let start = std::time::Instant::now();
     let (host, database) = find_leader_and_database(&worker_ctx, name_or_identity).await?;
-
+    log::debug!(
+        "sql request: resolved database identity={} id={} elapsed={:?}",
+        database.database_identity,
+        database.id,
+        start.elapsed()
+    );
+
+    let start = std::time::Instant::now();
+    log::debug!(
+        "sql request: loading module host database={}",
+        database.database_identity
+    );
     let module = host.module().await.map_err(log_and_500)?;
-    let fut = async move |_module: ModuleHost, caller_identity: Identity, _connection_id: ConnectionId| {
+    log::debug!(
+        "sql request: loaded module host database={} elapsed={:?}",
+        database.database_identity,
+        start.elapsed()
+    );
+    let fut = async move |_module: ModuleHost, caller_identity: Identity, connection_id: ConnectionId| {
+        let start = std::time::Instant::now();
+        log::debug!(
+            "sql request {connection_id}: authorize_sql start caller={caller_identity} database={}",
+            database.database_identity
+        );
         let sql_auth = worker_ctx
             .authorize_sql(caller_identity, database.database_identity)
             .await?;
+        log::debug!(
+            "sql request {connection_id}: authorize_sql finished elapsed={:?}",
+            start.elapsed()
+        );
 
-        host.exec_sql(
-            sql_auth,
-            database,
-            confirmed.unwrap_or(crate::DEFAULT_CONFIRMED_READS),
-            sql,
-        )
-        .await
+        let start = std::time::Instant::now();
+        log::debug!(
+            "sql request {connection_id}: host.exec_sql start database={} confirmed={confirmed_read} sql_len={sql_len}",
+            database.database_identity
+        );
+        host.exec_sql(sql_auth, database, confirmed_read, sql)
+            .await
+            .inspect(|rows| {
+                log::debug!(
+                    "sql request {connection_id}: host.exec_sql finished elapsed={:?} stmt_results={}",
+                    start.elapsed(),
+                    rows.len()
+                );
+            })
+            .inspect_err(|err| {
+                log::debug!(
+                    "sql request {connection_id}: host.exec_sql failed elapsed={:?} err={err:?}",
+                    start.elapsed(),
+                );
+            })
     };
 
     with_connection(module, caller_auth, caller_identity, fut).await
@@ -780,11 +850,27 @@ pub async fn sql<S>(
 where
     S: NodeDelegate + ControlStateDelegate + Authorization + 'static,
 {
+    log::debug!(
+        "sql route: received request caller={} confirmed={:?} sql_len={}",
+        auth.claims.identity,
+        params.confirmed,
+        body.len()
+    );
     let caller_identity = auth.claims.identity;
     let caller_auth: ConnectionAuthCtx = auth.into();
+    let start = std::time::Instant::now();
     let json = sql_direct(worker_ctx, name_or_identity, params, caller_identity, caller_auth, body).await?;
+    log::debug!(
+        "sql route: sql_direct finished caller={caller_identity} elapsed={:?} stmt_results={}",
+        start.elapsed(),
+        json.len()
+    );
 
     let total_duration = json.iter().fold(0, |acc, x| acc + x.total_duration_micros);
+    log::debug!(
+        "sql route: returning response caller={caller_identity} execution_duration_micros={}",
+        total_duration
+    );
 
     Ok((
         TypedHeader(SpacetimeExecutionDurationMicros(Duration::from_micros(total_duration))),
diff --git a/crates/core/src/host/module_host.rs b/crates/core/src/host/module_host.rs
index 8a1bbc6b414..2e938895b0f 100644
--- a/crates/core/src/host/module_host.rs
+++ b/crates/core/src/host/module_host.rs
@@ -1821,6 +1821,10 @@ impl ModuleHost {
     {
         self.guard_closed()?;
         let timer_guard = self.start_call_timer(label);
+        let start = std::time::Instant::now();
+        if label == "call_sql" {
+            log::debug!("module host call_sql: dispatch start");
+        }
 
         scopeguard::defer_on_unwind!({
             log::warn!("module operation {label} panicked");
@@ -1829,21 +1833,42 @@ impl ModuleHost {
 
         Ok(match &*self.inner {
             ModuleHostInner::Wasm(host) => {
+                if label == "call_sql" {
+                    log::debug!("module host call_sql: dispatching to wasm main worker");
+                }
                 let executor = host.executor.clone();
-                executor
+                let result = executor
                     .run_sync_job(move |state| {
                         state.with_instance(move |inst| {
                             drop(timer_guard);
                             wasm(arg, inst)
                         })
                     })
-                    .await
+                    .await;
+                if label == "call_sql" {
+                    log::debug!(
+                        "module host call_sql: wasm main worker finished elapsed={:?}",
+                        start.elapsed()
+                    );
+                }
+                result
             }
             ModuleHostInner::Js(host) => {
+                if label == "call_sql" {
+                    log::debug!("module host call_sql: dispatching to js main worker");
+                }
                 drop(timer_guard);
-                host.main_instance
+                let result = host
+                    .main_instance
                     .with_instance(|inst| async move { js(arg, &inst).await })
-                    .await
+                    .await;
+                if label == "call_sql" {
+                    log::debug!(
+                        "module host call_sql: js main worker finished elapsed={:?}",
+                        start.elapsed()
+                    );
+                }
+                result
             }
         })
     }
@@ -1986,10 +2011,18 @@ impl ModuleHost {
     }
 
     async fn call_sql_command(&self, cmd: SqlCommand) -> Result<SqlCommandResult, DBError> {
-        call_instance!(self, "call_sql", cmd, |cmd, inst| inst.call_sql(cmd), |cmd, inst| inst
+        let start = std::time::Instant::now();
+        log::debug!("module host call_sql: command dispatch start");
+        let result = call_instance!(self, "call_sql", cmd, |cmd, inst| inst.call_sql(cmd), |cmd, inst| inst
             .call_sql(cmd)
             .await,)
-        .map_err(|_| DBError::Other(anyhow::anyhow!("no such module")))
+        .map_err(|_| DBError::Other(anyhow::anyhow!("no such module")));
+        log::debug!(
+            "module host call_sql: command dispatch finished elapsed={:?} ok={}",
+            start.elapsed(),
+            result.is_ok()
+        );
+        result
     }
 
     pub async fn disconnect_client(&self, client_id: ClientActorId) {
@@ -2510,6 +2543,13 @@ impl ModuleHost {
         subs: Option<ModuleSubscriptions>,
         head: &mut Vec<(RawIdentifier, AlgebraicType)>,
     ) -> Result<SqlResult, DBError> {
+        let start = std::time::Instant::now();
+        log::debug!(
+            "module host call_sql: start caller={} sql_len={} subscriptions={}",
+            auth.caller(),
+            sql_text.len(),
+            subs.is_some()
+        );
         let cmd = SqlCommand {
             db,
             sql_text,
@@ -2520,7 +2560,13 @@ impl ModuleHost {
         let res = self.call_sql_command(cmd).await?;
 
         *head = res.head;
-        res.result
+        let result = res.result;
+        log::debug!(
+            "module host call_sql: finished elapsed={:?} ok={}",
+            start.elapsed(),
+            result.is_ok()
+        );
+        result
     }
 
     pub async fn call_procedure(
diff --git a/crates/core/src/sql/execute.rs b/crates/core/src/sql/execute.rs
index 7fe2fe229f8..2e355a39656 100644
--- a/crates/core/src/sql/execute.rs
+++ b/crates/core/src/sql/execute.rs
@@ -57,9 +57,34 @@ pub async fn run(
     module: Option<ModuleHost>,
     head: &mut Vec<(RawIdentifier, AlgebraicType)>,
 ) -> Result<SqlResult, DBError> {
+    let start = std::time::Instant::now();
+    let sql_len = sql_text.len();
+    let caller = auth.caller();
+    let via_module = module.is_some();
+    log::debug!(
+        "sql execute: run start caller={caller} sql_len={sql_len} via_module={via_module} subscriptions={}",
+        subs.is_some()
+    );
     match module {
-        Some(module) => module.call_sql(db, sql_text, auth, subs, head).await,
-        None => run_inner::<crate::host::wasmtime::WasmtimeInstance>(None, db, sql_text, auth, subs, head).map(|x| x.0),
+        Some(module) => {
+            let result = module.call_sql(db, sql_text, auth, subs, head).await;
+            log::debug!(
+                "sql execute: run finished caller={caller} via_module=true elapsed={:?} ok={}",
+                start.elapsed(),
+                result.is_ok()
+            );
+            result
+        }
+        None => {
+            let result =
+                run_inner::<crate::host::wasmtime::WasmtimeInstance>(None, db, sql_text, auth, subs, head).map(|x| x.0);
+            log::debug!(
+                "sql execute: run finished caller={caller} via_module=false elapsed={:?} ok={}",
+                start.elapsed(),
+                result.is_ok()
+            );
+            result
+        }
     }
 }
 
@@ -85,29 +110,60 @@ fn run_inner<I: WasmInstance>(
     subs: Option<ModuleSubscriptions>,
     head: &mut Vec<(RawIdentifier, AlgebraicType)>,
 ) -> Result<(SqlResult, bool), DBError> {
+    let start = std::time::Instant::now();
+    log::debug!(
+        "sql execute: run_inner start caller={} sql_len={} has_instance={} subscriptions={}",
+        auth.caller(),
+        sql_text.len(),
+        instance.is_some(),
+        subs.is_some()
+    );
     // We parse the sql statement in a mutable transaction.
     // If it turns out to be a query, we downgrade the tx.
+    let compile_start = std::time::Instant::now();
+    log::debug!("sql execute: compile start caller={}", auth.caller());
     let (tx, stmt) = db.with_auto_rollback(db.begin_mut_tx(IsolationLevel::Serializable, Workload::Sql), |tx| {
         compile_sql_stmt(&sql_text, &SchemaViewer::new(tx, &auth), &auth)
     })?;
+    log::debug!(
+        "sql execute: compile finished caller={} elapsed={:?}",
+        auth.caller(),
+        compile_start.elapsed()
+    );
 
     let mut metrics = ExecutionMetrics::default();
 
     match stmt {
         Statement::Select(stmt) => {
+            log::debug!("sql execute: statement kind=select caller={}", auth.caller());
             // Materialize views and downgrade to a read-only transaction
+            let materialize_start = std::time::Instant::now();
+            log::debug!("sql execute: materialize views start caller={}", auth.caller());
             let (tx, trapped) = match instance {
                 Some(instance) => ModuleHost::materialize_views(tx, instance, &stmt, auth.caller(), Workload::Sql)?,
                 None => (tx, false),
             };
-
+            log::debug!(
+                "sql execute: materialize views finished caller={} elapsed={:?} trapped={trapped}",
+                auth.caller(),
+                materialize_start.elapsed()
+            );
+
+            let downgrade_start = std::time::Instant::now();
+            log::debug!("sql execute: commit downgrade start caller={}", auth.caller());
             let (tx_data, tx_metrics_mut, tx) = db.commit_tx_downgrade(tx, Workload::Sql);
+            log::debug!(
+                "sql execute: commit downgrade finished caller={} elapsed={:?}",
+                auth.caller(),
+                downgrade_start.elapsed()
+            );
 
             let (tx_offset_send, tx_offset) = oneshot::channel();
             // Release the tx on drop, so that we record metrics
             // and set the transaction offset.
             let mut tx = scopeguard::guard(tx, |tx| {
                 let (offset, tx_metrics_downgrade, reducer) = db.release_tx(tx);
+                log::debug!("sql execute: select tx released offset={offset}");
                 let _ = tx_offset_send.send(offset);
                 db.report_tx_metrics(reducer, Some(tx_data), Some(tx_metrics_mut), Some(tx_metrics_downgrade));
             });
@@ -118,7 +174,11 @@ fn run_inner<I: WasmInstance>(
             });
 
             // Evaluate the query
+            let select_start = std::time::Instant::now();
+            log::debug!("sql execute: select execution start caller={}", auth.caller());
             let rows = execute_select_stmt(&auth, stmt, &DeltaTx::from(&*tx), &mut metrics, |plan| {
+                let row_limit_start = std::time::Instant::now();
+                log::debug!("sql execute: select row limit check start caller={}", auth.caller());
                 check_row_limit(
                     &[&plan],
                     &db,
@@ -126,12 +186,28 @@ fn run_inner<I: WasmInstance>(
                     |plan, tx| plan.plan_iter().map(|plan| estimate_rows_scanned(tx, plan)).sum(),
                     &auth,
                 )?;
+                log::debug!(
+                    "sql execute: select row limit check finished caller={} elapsed={:?}",
+                    auth.caller(),
+                    row_limit_start.elapsed()
+                );
                 Ok(plan)
             })?;
+            log::debug!(
+                "sql execute: select execution finished caller={} elapsed={:?} rows={}",
+                auth.caller(),
+                select_start.elapsed(),
+                rows.len()
+            );
 
             // Update transaction metrics
             tx.metrics.merge(metrics);
 
+            log::debug!(
+                "sql execute: run_inner finished caller={} kind=select elapsed={:?}",
+                auth.caller(),
+                start.elapsed()
+            );
             Ok((
                 SqlResult {
                     tx_offset,
@@ -142,25 +218,42 @@ fn run_inner<I: WasmInstance>(
             ))
         }
         Statement::DML(stmt) => {
+            log::debug!("sql execute: statement kind=dml caller={}", auth.caller());
             // An extra layer of auth is required for DML
             if !auth.has_write_access() {
+                log::debug!("sql execute: dml rejected caller={} reason=unauthorized", auth.caller());
                 return Err(anyhow!("Caller {} is not authorized to run SQL DML statements", auth.caller()).into());
             }
 
             // Evaluate the mutation
+            let dml_start = std::time::Instant::now();
+            log::debug!("sql execute: dml execution start caller={}", auth.caller());
             let (mut tx, _) = db.with_auto_rollback(tx, |tx| execute_dml_stmt(&auth, stmt, tx, &mut metrics))?;
+            log::debug!(
+                "sql execute: dml execution finished caller={} elapsed={:?}",
+                auth.caller(),
+                dml_start.elapsed()
+            );
 
             // Update transaction metrics
             tx.metrics.merge(metrics);
 
             // Update views
+            let views_start = std::time::Instant::now();
+            log::debug!("sql execute: dml view update start caller={}", auth.caller());
             let (result, trapped) = match instance {
                 Some(instance) => ModuleHost::call_views_with_tx(tx, instance, auth.caller()),
                 None => (ViewCallResult::default(tx), false),
             };
+            log::debug!(
+                "sql execute: dml view update finished caller={} elapsed={:?} trapped={trapped}",
+                auth.caller(),
+                views_start.elapsed()
+            );
 
             // Rollback transaction and report metrics if view execution failed
             if let ViewOutcome::Failed(err) = result.outcome {
+                log::debug!("sql execute: dml view update failed caller={}", auth.caller());
                 let (_, metrics, reducer) = db.rollback_mut_tx(result.tx);
                 db.report_mut_tx_metrics(reducer, metrics, None);
                 return Err(DBError::View(spacetimedb_engine::error::ViewError::InternalError(err)));
@@ -171,8 +264,15 @@ fn run_inner<I: WasmInstance>(
             // Commit the tx if there are no deltas to process
             if subs.is_none() {
                 let metrics = tx.metrics;
+                let commit_start = std::time::Instant::now();
+                log::debug!("sql execute: dml commit start caller={}", auth.caller());
                 return db.commit_tx(tx).map(|tx_opt| {
                     let (tx_offset, tx_data, tx_metrics, reducer) = tx_opt.unwrap();
+                    log::debug!(
+                        "sql execute: dml commit finished caller={} elapsed={:?} tx_offset={tx_offset}",
+                        auth.caller(),
+                        commit_start.elapsed()
+                    );
 
                     let (tx_offset_sender, tx_offset_receiver) = oneshot::channel();
                     let _ = tx_offset_sender.send(tx_offset);
@@ -209,7 +309,19 @@ fn run_inner<I: WasmInstance>(
                 request_id: None,
                 timer: None,
             };
+            let broadcast_start = std::time::Instant::now();
+            log::debug!("sql execute: dml commit and broadcast start caller={}", auth.caller());
             let res = commit_and_broadcast_event(&subs.unwrap(), None, event, tx);
+            log::debug!(
+                "sql execute: dml commit and broadcast finished caller={} elapsed={:?}",
+                auth.caller(),
+                broadcast_start.elapsed()
+            );
+            log::debug!(
+                "sql execute: run_inner finished caller={} kind=dml elapsed={:?}",
+                auth.caller(),
+                start.elapsed()
+            );
             Ok((
                 SqlResult {
                     tx_offset: res.tx_offset,
diff --git a/crates/smoketests/src/lib.rs b/crates/smoketests/src/lib.rs
index 1fc9521dade..4d5cf8f9cda 100644
--- a/crates/smoketests/src/lib.rs
+++ b/crates/smoketests/src/lib.rs
@@ -62,7 +62,7 @@ use std::io::{BufRead, BufReader};
 use std::path::{Path, PathBuf};
 use std::process::{Command, Output, Stdio};
 use std::sync::OnceLock;
-use std::time::Instant;
+use std::time::{Duration, Instant};
 use which::which;
 
 /// Returns the remote server URL if running against a remote server.
@@ -1124,6 +1124,61 @@ impl Smoketest {
         output
     }
 
+    /// Runs a spacetime CLI command with a process-level timeout.
+    ///
+    /// Uses --config-path to isolate test config from user config.
+    /// Callers should pass `--server` explicitly when the command needs it.
+    pub fn spacetime_with_timeout(&self, args: &[&str], timeout: Duration) -> Result<String> {
+        let start = Instant::now();
+        let cli_path = self.cli_path();
+        let mut child = Command::new(&cli_path)
+            .arg("--config-path")
+            .arg(&self.config_path)
+            .args(args)
+            .current_dir(self.project_dir.path())
+            .stdout(Stdio::piped())
+            .stderr(Stdio::piped())
+            .spawn()
+            .expect("Failed to spawn spacetime command");
+
+        loop {
+            if child.try_wait().context("Failed to poll spacetime command")?.is_some() {
+                let output = child.wait_with_output().expect("Failed to wait for spacetime command");
+                let cmd_name = args.first().unwrap_or(&"unknown");
+                eprintln!("[TIMING] spacetime {}: {:?}", cmd_name, start.elapsed());
+
+                if !output.status.success() {
+                    bail!(
+                        "spacetime {:?} failed:\nstdout: {}\nstderr: {}",
+                        args,
+                        String::from_utf8_lossy(&output.stdout),
+                        String::from_utf8_lossy(&output.stderr)
+                    );
+                }
+                return Ok(String::from_utf8_lossy(&output.stdout).to_string());
+            }
+
+            let elapsed = start.elapsed();
+            if elapsed >= timeout {
+                let _ = child.kill();
+                let output = child
+                    .wait_with_output()
+                    .expect("Failed to wait for timed out spacetime command");
+                let cmd_name = args.first().unwrap_or(&"unknown");
+                eprintln!("[TIMING] spacetime {} timed out after {:?}", cmd_name, elapsed);
+                bail!(
+                    "spacetime {:?} timed out after {:?}:\nstdout: {}\nstderr: {}",
+                    args,
+                    elapsed,
+                    String::from_utf8_lossy(&output.stdout),
+                    String::from_utf8_lossy(&output.stderr)
+                );
+            }
+
+            std::thread::sleep(Duration::from_millis(25));
+        }
+    }
+
     /// Runs a spacetime CLI command with stdin input.
     ///
     /// Returns the command output. The command is run but not yet asserted.