Add RESULT_COLLECTOR profiling metric

src/common/enum_util.cpp

@@ -3367,7 +3367,9 @@ const StringUtil::EnumStringLiteral *GetMetricTypeValues() {
 		{ static_cast<uint32_t>(MetricType::OPTIMIZER_ROW_NUMBER_REWRITER), "OPTIMIZER_ROW_NUMBER_REWRITER" },
 		{ static_cast<uint32_t>(MetricType::OPTIMIZER_PARTITIONED_EXECUTION), "OPTIMIZER_PARTITIONED_EXECUTION" },
 		{ static_cast<uint32_t>(MetricType::ALL_OPTIMIZERS), "ALL_OPTIMIZERS" },
+		{ static_cast<uint32_t>(MetricType::CLEANUP), "CLEANUP" },
 		{ static_cast<uint32_t>(MetricType::CUMULATIVE_OPTIMIZER_TIMING), "CUMULATIVE_OPTIMIZER_TIMING" },
+		{ static_cast<uint32_t>(MetricType::EXECUTOR_INITIALIZE), "EXECUTOR_INITIALIZE" },
 		{ static_cast<uint32_t>(MetricType::PARSER), "PARSER" },
 		{ static_cast<uint32_t>(MetricType::PHYSICAL_PLANNER), "PHYSICAL_PLANNER" },
 		{ static_cast<uint32_t>(MetricType::PHYSICAL_PLANNER_COLUMN_BINDING), "PHYSICAL_PLANNER_COLUMN_BINDING" },
@@ -3381,12 +3383,12 @@ const StringUtil::EnumStringLiteral *GetMetricTypeValues() {
 
 template<>
 const char* EnumUtil::ToChars<MetricType>(MetricType value) {
-	return StringUtil::EnumToString(GetMetricTypeValues(), 72, "MetricType", static_cast<uint32_t>(value));
+	return StringUtil::EnumToString(GetMetricTypeValues(), 74, "MetricType", static_cast<uint32_t>(value));
 }
 
 template<>
 MetricType EnumUtil::FromString<MetricType>(const char *value) {
-	return static_cast<MetricType>(StringUtil::StringToEnum(GetMetricTypeValues(), 72, "MetricType", value));
+	return static_cast<MetricType>(StringUtil::StringToEnum(GetMetricTypeValues(), 74, "MetricType", value));
 }
 
 const StringUtil::EnumStringLiteral *GetMonotonicityValues() {

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:

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
       }
     ]
   },

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,

src/main/client_context.cpp

@@ -398,8 +398,11 @@ unique_ptr<QueryResult> 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);

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:

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"

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,