diff --git a/src/common/enum_util.cpp b/src/common/enum_util.cpp index d41361ae4aa2..3a1f01d8a260 100644 --- a/src/common/enum_util.cpp +++ b/src/common/enum_util.cpp @@ -3367,7 +3367,9 @@ const StringUtil::EnumStringLiteral *GetMetricTypeValues() { { static_cast(MetricType::OPTIMIZER_ROW_NUMBER_REWRITER), "OPTIMIZER_ROW_NUMBER_REWRITER" }, { static_cast(MetricType::OPTIMIZER_PARTITIONED_EXECUTION), "OPTIMIZER_PARTITIONED_EXECUTION" }, { static_cast(MetricType::ALL_OPTIMIZERS), "ALL_OPTIMIZERS" }, + { static_cast(MetricType::CLEANUP), "CLEANUP" }, { static_cast(MetricType::CUMULATIVE_OPTIMIZER_TIMING), "CUMULATIVE_OPTIMIZER_TIMING" }, + { static_cast(MetricType::EXECUTOR_INITIALIZE), "EXECUTOR_INITIALIZE" }, { static_cast(MetricType::PARSER), "PARSER" }, { static_cast(MetricType::PHYSICAL_PLANNER), "PHYSICAL_PLANNER" }, { static_cast(MetricType::PHYSICAL_PLANNER_COLUMN_BINDING), "PHYSICAL_PLANNER_COLUMN_BINDING" }, @@ -3381,12 +3383,12 @@ const StringUtil::EnumStringLiteral *GetMetricTypeValues() { template<> const char* EnumUtil::ToChars(MetricType value) { - return StringUtil::EnumToString(GetMetricTypeValues(), 72, "MetricType", static_cast(value)); + return StringUtil::EnumToString(GetMetricTypeValues(), 74, "MetricType", static_cast(value)); } template<> MetricType EnumUtil::FromString(const char *value) { - return static_cast(StringUtil::StringToEnum(GetMetricTypeValues(), 72, "MetricType", value)); + return static_cast(StringUtil::StringToEnum(GetMetricTypeValues(), 74, "MetricType", value)); } const StringUtil::EnumStringLiteral *GetMonotonicityValues() { diff --git a/src/common/enums/metric_type.cpp b/src/common/enums/metric_type.cpp index 493ecf3fdbfa..e5cf39852fa1 100644 --- a/src/common/enums/metric_type.cpp +++ b/src/common/enums/metric_type.cpp @@ -13,11 +13,13 @@ profiler_settings_t MetricsUtils::GetAllMetrics() { MetricType::ATTACH_REPLAY_WAL_LATENCY, MetricType::BLOCKED_THREAD_TIME, MetricType::CHECKPOINT_LATENCY, + MetricType::CLEANUP, MetricType::COMMIT_LOCAL_STORAGE_LATENCY, MetricType::CPU_TIME, MetricType::CUMULATIVE_CARDINALITY, MetricType::CUMULATIVE_OPTIMIZER_TIMING, MetricType::CUMULATIVE_ROWS_SCANNED, + MetricType::EXECUTOR_INITIALIZE, MetricType::EXTRA_INFO, MetricType::LATENCY, MetricType::OPERATOR_CARDINALITY, @@ -317,7 +319,9 @@ OptimizerType MetricsUtils::GetOptimizerTypeByMetric(MetricType type) { profiler_settings_t MetricsUtils::GetPhaseTimingMetrics() { return { MetricType::ALL_OPTIMIZERS, + MetricType::CLEANUP, MetricType::CUMULATIVE_OPTIMIZER_TIMING, + MetricType::EXECUTOR_INITIALIZE, MetricType::PARSER, MetricType::PHYSICAL_PLANNER, MetricType::PHYSICAL_PLANNER_COLUMN_BINDING, @@ -331,7 +335,9 @@ profiler_settings_t MetricsUtils::GetPhaseTimingMetrics() { bool MetricsUtils::IsPhaseTimingMetric(MetricType type) { switch(type) { case MetricType::ALL_OPTIMIZERS: + case MetricType::CLEANUP: case MetricType::CUMULATIVE_OPTIMIZER_TIMING: + case MetricType::EXECUTOR_INITIALIZE: case MetricType::PARSER: case MetricType::PHYSICAL_PLANNER: case MetricType::PHYSICAL_PLANNER_COLUMN_BINDING: @@ -352,8 +358,10 @@ profiler_settings_t MetricsUtils::GetRootScopeMetrics() { MetricType::ATTACH_REPLAY_WAL_LATENCY, MetricType::BLOCKED_THREAD_TIME, MetricType::CHECKPOINT_LATENCY, + MetricType::CLEANUP, MetricType::COMMIT_LOCAL_STORAGE_LATENCY, MetricType::CUMULATIVE_OPTIMIZER_TIMING, + MetricType::EXECUTOR_INITIALIZE, MetricType::LATENCY, MetricType::OPTIMIZER_AGGREGATE_FUNCTION_REWRITER, MetricType::OPTIMIZER_BUILD_SIDE_PROBE_SIDE, @@ -416,8 +424,10 @@ bool MetricsUtils::IsRootScopeMetric(MetricType type) { case MetricType::ATTACH_REPLAY_WAL_LATENCY: case MetricType::BLOCKED_THREAD_TIME: case MetricType::CHECKPOINT_LATENCY: + case MetricType::CLEANUP: case MetricType::COMMIT_LOCAL_STORAGE_LATENCY: case MetricType::CUMULATIVE_OPTIMIZER_TIMING: + case MetricType::EXECUTOR_INITIALIZE: case MetricType::LATENCY: case MetricType::OPTIMIZER_AGGREGATE_FUNCTION_REWRITER: case MetricType::OPTIMIZER_BUILD_SIDE_PROBE_SIDE: diff --git a/src/common/enums/metric_type.json b/src/common/enums/metric_type.json index 8db09b41d729..a3d83bb89131 100644 --- a/src/common/enums/metric_type.json +++ b/src/common/enums/metric_type.json @@ -292,6 +292,22 @@ "type": "double", "unit": "milliseconds", "query_root": true + }, + { + "name": "EXECUTOR_INITIALIZE", + "enum_value": 101, + "description": "The time spent initializing the executor, building pipelines and scheduling tasks.", + "type": "double", + "unit": "milliseconds", + "query_root": true + }, + { + "name": "CLEANUP", + "enum_value": 102, + "description": "The time spent in post-execution cleanup including transaction commit and thread relaunch.", + "type": "double", + "unit": "milliseconds", + "query_root": true } ] }, diff --git a/src/include/duckdb/common/enums/metric_type.hpp b/src/include/duckdb/common/enums/metric_type.hpp index bef89e7c06d4..e797677bf589 100644 --- a/src/include/duckdb/common/enums/metric_type.hpp +++ b/src/include/duckdb/common/enums/metric_type.hpp @@ -100,7 +100,9 @@ enum class MetricType : uint8_t { OPTIMIZER_PARTITIONED_EXECUTION = 62, // PhaseTiming metrics ALL_OPTIMIZERS = 18, + CLEANUP = 102, CUMULATIVE_OPTIMIZER_TIMING = 19, + EXECUTOR_INITIALIZE = 101, PARSER = 99, PHYSICAL_PLANNER = 22, PHYSICAL_PLANNER_COLUMN_BINDING = 23, diff --git a/src/main/client_context.cpp b/src/main/client_context.cpp index 1846dff71856..13dd9891dfa0 100644 --- a/src/main/client_context.cpp +++ b/src/main/client_context.cpp @@ -398,8 +398,11 @@ unique_ptr ClientContext::FetchResultInternal(ClientContextLock &lo D_ASSERT(executor.HasResultCollector()); // we have a result collector - fetch the result directly from the result collector result = executor.GetResult(); + auto &profiler = QueryProfiler::Get(*this); if (!create_stream_result) { + profiler.StartPhase(MetricType::CLEANUP); CleanupInternal(lock, result.get(), false); + profiler.EndPhase(); } else { active_query->SetOpenResult(*result); } @@ -633,7 +636,10 @@ ClientContext::PendingPreparedStatementInternal(ClientContextLock &lock, // Get the result collector and initialize the executor. auto collector = get_collector(*this, statement_data); D_ASSERT(collector->type == PhysicalOperatorType::RESULT_COLLECTOR); + auto &profiler = QueryProfiler::Get(*this); + profiler.StartPhase(MetricType::EXECUTOR_INITIALIZE); executor.Initialize(std::move(collector)); + profiler.EndPhase(); auto types = executor.GetTypes(); D_ASSERT(types == statement_data.types); diff --git a/src/main/profiling_utils.cpp b/src/main/profiling_utils.cpp index 341ce3c2b54e..ce4cf209e22d 100644 --- a/src/main/profiling_utils.cpp +++ b/src/main/profiling_utils.cpp @@ -57,9 +57,11 @@ void ProfilingUtils::SetMetricToDefault(profiler_metrics_t &metrics, const Metri case MetricType::ATTACH_REPLAY_WAL_LATENCY: case MetricType::BLOCKED_THREAD_TIME: case MetricType::CHECKPOINT_LATENCY: + case MetricType::CLEANUP: case MetricType::COMMIT_LOCAL_STORAGE_LATENCY: case MetricType::CPU_TIME: case MetricType::CUMULATIVE_OPTIMIZER_TIMING: + case MetricType::EXECUTOR_INITIALIZE: case MetricType::LATENCY: case MetricType::OPERATOR_TIMING: case MetricType::OPTIMIZER_AGGREGATE_FUNCTION_REWRITER: @@ -146,9 +148,11 @@ void ProfilingUtils::MetricToJson(duckdb_yyjson::yyjson_mut_doc *doc, duckdb_yyj case MetricType::ATTACH_REPLAY_WAL_LATENCY: case MetricType::BLOCKED_THREAD_TIME: case MetricType::CHECKPOINT_LATENCY: + case MetricType::CLEANUP: case MetricType::COMMIT_LOCAL_STORAGE_LATENCY: case MetricType::CPU_TIME: case MetricType::CUMULATIVE_OPTIMIZER_TIMING: + case MetricType::EXECUTOR_INITIALIZE: case MetricType::LATENCY: case MetricType::OPERATOR_TIMING: case MetricType::OPTIMIZER_AGGREGATE_FUNCTION_REWRITER: diff --git a/test/sql/pragma/profiling/test_all_profiling_settings.test b/test/sql/pragma/profiling/test_all_profiling_settings.test index dc1dd2ec887f..04f7a50a87c3 100644 --- a/test/sql/pragma/profiling/test_all_profiling_settings.test +++ b/test/sql/pragma/profiling/test_all_profiling_settings.test @@ -34,11 +34,13 @@ SELECT unnest(res) FROM ( "ATTACH_REPLAY_WAL_LATENCY": "true" "BLOCKED_THREAD_TIME": "true" "CHECKPOINT_LATENCY": "true" +"CLEANUP": "true" "COMMIT_LOCAL_STORAGE_LATENCY": "true" "CPU_TIME": "true" "CUMULATIVE_CARDINALITY": "true" "CUMULATIVE_OPTIMIZER_TIMING": "true" "CUMULATIVE_ROWS_SCANNED": "true" +"EXECUTOR_INITIALIZE": "true" "EXTRA_INFO": "true" "LATENCY": "true" "OPERATOR_CARDINALITY": "true" diff --git a/test/sql/pragma/profiling/test_custom_profiling_using_groups.test b/test/sql/pragma/profiling/test_custom_profiling_using_groups.test index 84a72b1fd5f1..5a928177d21d 100644 --- a/test/sql/pragma/profiling/test_custom_profiling_using_groups.test +++ b/test/sql/pragma/profiling/test_custom_profiling_using_groups.test @@ -34,11 +34,13 @@ SELECT unnest(res) FROM ( "ATTACH_REPLAY_WAL_LATENCY": "true" "BLOCKED_THREAD_TIME": "true" "CHECKPOINT_LATENCY": "true" +"CLEANUP": "true" "COMMIT_LOCAL_STORAGE_LATENCY": "true" "CPU_TIME": "true" "CUMULATIVE_CARDINALITY": "true" "CUMULATIVE_OPTIMIZER_TIMING": "true" "CUMULATIVE_ROWS_SCANNED": "true" +"EXECUTOR_INITIALIZE": "true" "EXTRA_INFO": "true" "LATENCY": "true" "OPERATOR_CARDINALITY": "true" @@ -111,11 +113,13 @@ SELECT ALL_OPTIMIZERS, ATTACH_REPLAY_WAL_LATENCY, BLOCKED_THREAD_TIME, CHECKPOINT_LATENCY, + CLEANUP, COMMIT_LOCAL_STORAGE_LATENCY, CPU_TIME, CUMULATIVE_CARDINALITY, CUMULATIVE_OPTIMIZER_TIMING, CUMULATIVE_ROWS_SCANNED, + EXECUTOR_INITIALIZE, EXTRA_INFO, LATENCY, OPTIMIZER_AGGREGATE_FUNCTION_REWRITER, @@ -548,7 +552,9 @@ SELECT unnest(res) FROM ( ) ORDER BY ALL; ---- "ALL_OPTIMIZERS": "true" +"CLEANUP": "true" "CUMULATIVE_OPTIMIZER_TIMING": "true" +"EXECUTOR_INITIALIZE": "true" "OPTIMIZER_AGGREGATE_FUNCTION_REWRITER": "true" "OPTIMIZER_BUILD_SIDE_PROBE_SIDE": "true" "OPTIMIZER_COLUMN_LIFETIME": "true" @@ -599,7 +605,9 @@ CREATE OR REPLACE TABLE metrics_output AS SELECT * FROM '{TEST_DIR}/profiling_ou statement ok SELECT ALL_OPTIMIZERS, + CLEANUP, CUMULATIVE_OPTIMIZER_TIMING, + EXECUTOR_INITIALIZE, OPTIMIZER_AGGREGATE_FUNCTION_REWRITER, OPTIMIZER_BUILD_SIDE_PROBE_SIDE, OPTIMIZER_COLUMN_LIFETIME, @@ -870,8 +878,10 @@ SELECT unnest(res) FROM ( "ATTACH_REPLAY_WAL_LATENCY": "true" "BLOCKED_THREAD_TIME": "true" "CHECKPOINT_LATENCY": "true" +"CLEANUP": "true" "COMMIT_LOCAL_STORAGE_LATENCY": "true" "CUMULATIVE_OPTIMIZER_TIMING": "true" +"EXECUTOR_INITIALIZE": "true" "OPTIMIZER_AGGREGATE_FUNCTION_REWRITER": "true" "OPTIMIZER_BUILD_SIDE_PROBE_SIDE": "true" "OPTIMIZER_COLUMN_LIFETIME": "true" @@ -934,8 +944,10 @@ SELECT ALL_OPTIMIZERS, ATTACH_REPLAY_WAL_LATENCY, BLOCKED_THREAD_TIME, CHECKPOINT_LATENCY, + CLEANUP, COMMIT_LOCAL_STORAGE_LATENCY, CUMULATIVE_OPTIMIZER_TIMING, + EXECUTOR_INITIALIZE, OPTIMIZER_AGGREGATE_FUNCTION_REWRITER, OPTIMIZER_BUILD_SIDE_PROBE_SIDE, OPTIMIZER_COLUMN_LIFETIME,