diff --git a/src/adapter/src/coord.rs b/src/adapter/src/coord.rs index 796dc6dc3ddf1..f2e03cfabedaf 100644 --- a/src/adapter/src/coord.rs +++ b/src/adapter/src/coord.rs @@ -540,6 +540,7 @@ pub struct PeekStageFinish { plan_insights_optimizer_trace: Option, insights_ctx: Option>, global_lir_plan: optimize::peek::GlobalLirPlan, + optimization_began_at: EpochMillis, optimization_finished_at: EpochMillis, } @@ -548,6 +549,7 @@ pub struct PeekStageCopyTo { validity: PlanValidity, optimizer: optimize::copy_to::Optimizer, global_lir_plan: optimize::copy_to::GlobalLirPlan, + optimization_began_at: EpochMillis, optimization_finished_at: EpochMillis, source_ids: BTreeSet, } diff --git a/src/adapter/src/coord/sequencer/inner/peek.rs b/src/adapter/src/coord/sequencer/inner/peek.rs index eb2254dd1f263..d5072e0d52485 100644 --- a/src/adapter/src/coord/sequencer/inner/peek.rs +++ b/src/adapter/src/coord/sequencer/inner/peek.rs @@ -590,6 +590,7 @@ impl Coordinator { } }; + let optimization_began_at = now(); let pipeline_result = pipeline(); let optimization_finished_at = now(); @@ -649,6 +650,7 @@ impl Coordinator { finishing: optimizer.finishing().clone(), plan_insights_optimizer_trace: Some(optimizer_trace), global_lir_plan, + optimization_began_at, optimization_finished_at, insights_ctx, }) @@ -665,6 +667,7 @@ impl Coordinator { finishing: optimizer.finishing().clone(), plan_insights_optimizer_trace: None, global_lir_plan, + optimization_began_at, optimization_finished_at, insights_ctx, }), @@ -695,6 +698,7 @@ impl Coordinator { validity, optimizer, global_lir_plan, + optimization_began_at, optimization_finished_at, source_ids, }) @@ -819,11 +823,17 @@ impl Coordinator { finishing, plan_insights_optimizer_trace, global_lir_plan, + optimization_began_at, optimization_finished_at, insights_ctx, }: PeekStageFinish, ) -> Result>, AdapterError> { if let Some(id) = ctx.extra.contents() { + self.record_statement_lifecycle_event( + &id, + &StatementLifecycleEvent::OptimizationBegan, + optimization_began_at, + ); self.record_statement_lifecycle_event( &id, &StatementLifecycleEvent::OptimizationFinished, @@ -997,11 +1007,17 @@ impl Coordinator { validity: _, optimizer, global_lir_plan, + optimization_began_at, optimization_finished_at, source_ids, }: PeekStageCopyTo, ) -> Result>, AdapterError> { if let Some(id) = ctx.extra.contents() { + self.record_statement_lifecycle_event( + &id, + &StatementLifecycleEvent::OptimizationBegan, + optimization_began_at, + ); self.record_statement_lifecycle_event( &id, &StatementLifecycleEvent::OptimizationFinished, diff --git a/src/adapter/src/statement_logging.rs b/src/adapter/src/statement_logging.rs index 0835cd5eddb9f..9f590337b2994 100644 --- a/src/adapter/src/statement_logging.rs +++ b/src/adapter/src/statement_logging.rs @@ -20,6 +20,7 @@ use crate::{AdapterError, ExecuteResponse}; #[derive(Clone, Debug)] pub enum StatementLifecycleEvent { ExecutionBegan, + OptimizationBegan, OptimizationFinished, StorageDependenciesFinished, ComputeDependenciesFinished, @@ -30,6 +31,7 @@ impl StatementLifecycleEvent { pub fn as_str(&self) -> &str { match self { Self::ExecutionBegan => "execution-began", + Self::OptimizationBegan => "optimization-began", Self::OptimizationFinished => "optimization-finished", Self::StorageDependenciesFinished => "storage-dependencies-finished", Self::ComputeDependenciesFinished => "compute-dependencies-finished", diff --git a/test/cluster/statement-logging/statement-logging.td b/test/cluster/statement-logging/statement-logging.td index dfccffc87081d..34e29f2b310b6 100644 --- a/test/cluster/statement-logging/statement-logging.td +++ b/test/cluster/statement-logging/statement-logging.td @@ -168,6 +168,7 @@ COMMIT execution-finished "EXECUTE p('hello world')" compute-dependencies-finished "EXECUTE p('hello world')" execution-began "EXECUTE p('hello world')" execution-finished +"EXECUTE p('hello world')" optimization-began "EXECUTE p('hello world')" optimization-finished "EXECUTE p('hello world')" storage-dependencies-finished "FETCH c" compute-dependencies-finished @@ -177,6 +178,7 @@ COMMIT execution-finished "FETCH c" execution-finished "FETCH c" execution-finished "FETCH c" execution-finished +"FETCH c" optimization-began "FETCH c" optimization-finished "FETCH c" storage-dependencies-finished "INSERT INTO t VALUES (1)" execution-began @@ -186,21 +188,25 @@ COMMIT execution-finished "SELECT 'beginning real test!'" compute-dependencies-finished "SELECT 'beginning real test!'" execution-began "SELECT 'beginning real test!'" execution-finished +"SELECT 'beginning real test!'" optimization-began "SELECT 'beginning real test!'" optimization-finished "SELECT 'beginning real test!'" storage-dependencies-finished "SELECT 'serializable'" compute-dependencies-finished "SELECT 'serializable'" execution-began "SELECT 'serializable'" execution-finished +"SELECT 'serializable'" optimization-began "SELECT 'serializable'" optimization-finished "SELECT 'serializable'" storage-dependencies-finished "SELECT * FROM t" compute-dependencies-finished "SELECT * FROM t" execution-began "SELECT * FROM t" execution-finished +"SELECT * FROM t" optimization-began "SELECT * FROM t" optimization-finished "SELECT * FROM t" storage-dependencies-finished "SELECT count(*) > 0 FROM mz_internal.mz_cluster_replica_metrics" compute-dependencies-finished "SELECT count(*) > 0 FROM mz_internal.mz_cluster_replica_metrics" execution-began "SELECT count(*) > 0 FROM mz_internal.mz_cluster_replica_metrics" execution-finished +"SELECT count(*) > 0 FROM mz_internal.mz_cluster_replica_metrics" optimization-began "SELECT count(*) > 0 FROM mz_internal.mz_cluster_replica_metrics" optimization-finished "SELECT count(*) > 0 FROM mz_internal.mz_cluster_replica_metrics" storage-dependencies-finished "SELECT count(*) FROM t" compute-dependencies-finished @@ -209,6 +215,8 @@ COMMIT execution-finished "SELECT count(*) FROM t" execution-began "SELECT count(*) FROM t" execution-finished "SELECT count(*) FROM t" execution-finished +"SELECT count(*) FROM t" optimization-began +"SELECT count(*) FROM t" optimization-began "SELECT count(*) FROM t" optimization-finished "SELECT count(*) FROM t" optimization-finished "SELECT count(*) FROM t" storage-dependencies-finished @@ -216,6 +224,7 @@ COMMIT execution-finished "SELECT f/0 FROM t" compute-dependencies-finished "SELECT f/0 FROM t" execution-began "SELECT f/0 FROM t" execution-finished +"SELECT f/0 FROM t" optimization-began "SELECT f/0 FROM t" optimization-finished "SELECT f/0 FROM t" storage-dependencies-finished "SET cluster TO c" execution-began