From 6185861e1a9824a516be2a9b2880552c0bb5d5d7 Mon Sep 17 00:00:00 2001 From: Feilong Liu Date: Wed, 25 Mar 2026 16:15:02 -0700 Subject: [PATCH] [Presto] Add runtime stats for uncaptured metastore and planning operations Adds runtime metrics to capture previously untracked wall time during query planning, helping decompose the gap between ANALYZE_TIME_NANOS wall time and CPU time. - Add verbose_planner_runtime_stats_enabled session property - Add GET_TABLE_STATISTICS_TIME_NANOS timing in MetadataManager - Add CHECK_ACCESS_PERMISSIONS_TIME_NANOS timing in SqlQueryExecution - Add GET_MATERIALIZED_VIEW_STATUS_TIME_NANOS timing in StatementAnalyzer - Add GET_COLUMN_HANDLE_TIME_NANOS and GET_TABLE_HANDLE_TIME_NANOS timing in StatementAnalyzer - Wire isVerbosePlannerRuntimeStatsEnabled into Optimizer, IterativeOptimizer, ApplyConnectorOptimization, HistoryBasedPlanStatisticsCalculator, and CachingPlanCanonicalInfoProvider Differential Revision: D98045070 --- .../presto/common/RuntimeMetricName.java | 2 ++ .../presto/SystemSessionProperties.java | 11 ++++++++ .../HistoryBasedPlanStatisticsCalculator.java | 3 ++- .../presto/execution/SqlQueryExecution.java | 8 +++++- .../presto/metadata/MetadataManager.java | 5 +++- .../com/facebook/presto/sql/Optimizer.java | 2 +- .../sql/analyzer/StatementAnalyzer.java | 26 ++++++++++++++----- .../CachingPlanCanonicalInfoProvider.java | 3 ++- .../planner/iterative/IterativeOptimizer.java | 3 ++- .../ApplyConnectorOptimization.java | 2 +- 10 files changed, 52 insertions(+), 13 deletions(-) diff --git a/presto-common/src/main/java/com/facebook/presto/common/RuntimeMetricName.java b/presto-common/src/main/java/com/facebook/presto/common/RuntimeMetricName.java index 28513cca567df..07caed607265a 100644 --- a/presto-common/src/main/java/com/facebook/presto/common/RuntimeMetricName.java +++ b/presto-common/src/main/java/com/facebook/presto/common/RuntimeMetricName.java @@ -40,6 +40,7 @@ private RuntimeMetricName() public static final String GET_COLUMN_METADATA_TIME_NANOS = "getColumnMetadataTimeNanos"; public static final String GET_PARTITIONS_BY_NAMES_TIME_NANOS = "getPartitionsByNamesTimeNanos"; public static final String GET_TABLE_TIME_NANOS = "getTableTimeNanos"; + public static final String GET_TABLE_STATISTICS_TIME_NANOS = "getTableStatisticsTimeNanos"; public static final String GET_SPLITS_TIME_NANOS = "getSplitsTimeNanos"; // CPU time taken to schedule a given stage public static final String SCHEDULER_CPU_TIME_NANOS = "schedulerCpuTimeNanos"; @@ -92,4 +93,5 @@ private RuntimeMetricName() public static final String METASTORE_ALTER_PARTITIONS_TIME_NANOS = "metastoreAlterPartitionsTimeNanos"; public static final String METASTORE_UPDATE_PARTITION_STATISTICS_TIME_NANOS = "metastoreUpdatePartitionStatisticsTimeNanos"; public static final String METASTORE_UPDATE_TABLE_STATISTICS_TIME_NANOS = "metastoreUpdateTableStatisticsTimeNanos"; + public static final String CHECK_ACCESS_PERMISSIONS_TIME_NANOS = "checkAccessPermissionsTimeNanos"; } diff --git a/presto-main-base/src/main/java/com/facebook/presto/SystemSessionProperties.java b/presto-main-base/src/main/java/com/facebook/presto/SystemSessionProperties.java index 3723bc8e99017..ad5634b2d863c 100644 --- a/presto-main-base/src/main/java/com/facebook/presto/SystemSessionProperties.java +++ b/presto-main-base/src/main/java/com/facebook/presto/SystemSessionProperties.java @@ -270,6 +270,7 @@ public final class SystemSessionProperties public static final String EXCEEDED_MEMORY_LIMIT_HEAP_DUMP_FILE_DIRECTORY = "exceeded_memory_limit_heap_dump_file_directory"; public static final String DISTRIBUTED_TRACING_MODE = "distributed_tracing_mode"; public static final String VERBOSE_RUNTIME_STATS_ENABLED = "verbose_runtime_stats_enabled"; + public static final String VERBOSE_PLANNER_RUNTIME_STATS_ENABLED = "verbose_planner_runtime_stats_enabled"; public static final String OPTIMIZERS_TO_ENABLE_VERBOSE_RUNTIME_STATS = "optimizers_to_enable_verbose_runtime_stats"; public static final String VERBOSE_OPTIMIZER_INFO_ENABLED = "verbose_optimizer_info_enabled"; public static final String VERBOSE_OPTIMIZER_RESULTS = "verbose_optimizer_results"; @@ -1493,6 +1494,11 @@ public SystemSessionProperties( "Enable logging all runtime stats", featuresConfig.isVerboseRuntimeStatsEnabled(), false), + booleanProperty( + VERBOSE_PLANNER_RUNTIME_STATS_ENABLED, + "Enable verbose runtime stats for analyzer, logical planner, and optimizer phases only", + false, + false), stringProperty( OPTIMIZERS_TO_ENABLE_VERBOSE_RUNTIME_STATS, "Optimizers to enable verbose runtime stats", @@ -3156,6 +3162,11 @@ public static boolean isVerboseRuntimeStatsEnabled(Session session) return session.getSystemProperty(VERBOSE_RUNTIME_STATS_ENABLED, Boolean.class); } + public static boolean isVerbosePlannerRuntimeStatsEnabled(Session session) + { + return session.getSystemProperty(VERBOSE_PLANNER_RUNTIME_STATS_ENABLED, Boolean.class); + } + public static String getOptimizersToEnableVerboseRuntimeStats(Session session) { return session.getSystemProperty(OPTIMIZERS_TO_ENABLE_VERBOSE_RUNTIME_STATS, String.class); diff --git a/presto-main-base/src/main/java/com/facebook/presto/cost/HistoryBasedPlanStatisticsCalculator.java b/presto-main-base/src/main/java/com/facebook/presto/cost/HistoryBasedPlanStatisticsCalculator.java index a903dd9dce459..928af8d0f8a26 100644 --- a/presto-main-base/src/main/java/com/facebook/presto/cost/HistoryBasedPlanStatisticsCalculator.java +++ b/presto-main-base/src/main/java/com/facebook/presto/cost/HistoryBasedPlanStatisticsCalculator.java @@ -39,6 +39,7 @@ import static com.facebook.presto.SystemSessionProperties.estimateSizeUsingVariablesForHBO; import static com.facebook.presto.SystemSessionProperties.getHistoryBasedOptimizerTimeoutLimit; import static com.facebook.presto.SystemSessionProperties.getHistoryInputTableStatisticsMatchingThreshold; +import static com.facebook.presto.SystemSessionProperties.isVerbosePlannerRuntimeStatsEnabled; import static com.facebook.presto.SystemSessionProperties.isVerboseRuntimeStatsEnabled; import static com.facebook.presto.SystemSessionProperties.useHistoryBasedPlanStatisticsEnabled; import static com.facebook.presto.common.RuntimeMetricName.HISTORY_OPTIMIZER_QUERY_REGISTRATION_GET_PLAN_NODE_HASHES; @@ -94,7 +95,7 @@ public boolean registerPlan(PlanNode root, Session session, long startTimeInNano } ImmutableList.Builder planNodesWithHash = ImmutableList.builder(); Iterable planNodeIterable = forTree(PlanNode::getSources).depthFirstPreOrder(root); - boolean enableVerboseRuntimeStats = isVerboseRuntimeStatsEnabled(session) || enableVerboseHistoryBasedOptimizerRuntimeStats(session); + boolean enableVerboseRuntimeStats = isVerboseRuntimeStatsEnabled(session) || isVerbosePlannerRuntimeStatsEnabled(session) || enableVerboseHistoryBasedOptimizerRuntimeStats(session); long profileStartTime = 0; for (PlanNode plan : planNodeIterable) { if (checkTimeOut(startTimeInNano, timeoutInMilliseconds)) { diff --git a/presto-main-base/src/main/java/com/facebook/presto/execution/SqlQueryExecution.java b/presto-main-base/src/main/java/com/facebook/presto/execution/SqlQueryExecution.java index dfbfc86ae0f54..312e54e698bb4 100644 --- a/presto-main-base/src/main/java/com/facebook/presto/execution/SqlQueryExecution.java +++ b/presto-main-base/src/main/java/com/facebook/presto/execution/SqlQueryExecution.java @@ -87,6 +87,7 @@ import static com.facebook.presto.SystemSessionProperties.isLogInvokedFunctionNamesEnabled; import static com.facebook.presto.SystemSessionProperties.isSpoolingOutputBufferEnabled; import static com.facebook.presto.common.RuntimeMetricName.ANALYZE_TIME_NANOS; +import static com.facebook.presto.common.RuntimeMetricName.CHECK_ACCESS_PERMISSIONS_TIME_NANOS; import static com.facebook.presto.common.RuntimeMetricName.CREATE_SCHEDULER_TIME_NANOS; import static com.facebook.presto.common.RuntimeMetricName.FRAGMENT_PLAN_TIME_NANOS; import static com.facebook.presto.common.RuntimeMetricName.GET_CANONICAL_INFO_TIME_NANOS; @@ -223,7 +224,12 @@ private SqlQueryExecution( stateMachine.setExpandedQuery(queryAnalysis.getExpandedQuery()); stateMachine.beginColumnAccessPermissionChecking(); - checkAccessPermissions(queryAnalysis.getAccessControlReferences(), queryAnalysis.getViewDefinitionReferences(), query, getSession().getPreparedStatements(), getSession().getIdentity(), accessControl, getSession().getAccessControlContext()); + getSession().getRuntimeStats().recordWallAndCpuTime( + CHECK_ACCESS_PERMISSIONS_TIME_NANOS, + () -> { + checkAccessPermissions(queryAnalysis.getAccessControlReferences(), queryAnalysis.getViewDefinitionReferences(), query, getSession().getPreparedStatements(), getSession().getIdentity(), accessControl, getSession().getAccessControlContext()); + return null; + }); stateMachine.endColumnAccessPermissionChecking(); // when the query finishes cache the final query info, and clear the reference to the output stage diff --git a/presto-main-base/src/main/java/com/facebook/presto/metadata/MetadataManager.java b/presto-main-base/src/main/java/com/facebook/presto/metadata/MetadataManager.java index 3628f915b47e3..3d8e1ca08b784 100644 --- a/presto-main-base/src/main/java/com/facebook/presto/metadata/MetadataManager.java +++ b/presto-main-base/src/main/java/com/facebook/presto/metadata/MetadataManager.java @@ -118,6 +118,7 @@ import static com.facebook.presto.common.RuntimeMetricName.GET_IDENTIFIER_NORMALIZATION_TIME_NANOS; import static com.facebook.presto.common.RuntimeMetricName.GET_LAYOUT_TIME_NANOS; import static com.facebook.presto.common.RuntimeMetricName.GET_MATERIALIZED_VIEW_STATUS_TIME_NANOS; +import static com.facebook.presto.common.RuntimeMetricName.GET_TABLE_STATISTICS_TIME_NANOS; import static com.facebook.presto.common.RuntimeUnit.NANO; import static com.facebook.presto.common.function.OperatorType.BETWEEN; import static com.facebook.presto.common.function.OperatorType.EQUAL; @@ -587,7 +588,9 @@ public TableStatistics getTableStatistics(Session session, TableHandle tableHand try { ConnectorId connectorId = tableHandle.getConnectorId(); ConnectorMetadata metadata = getMetadata(session, connectorId); - return metadata.getTableStatistics(session.toConnectorSession(connectorId), tableHandle.getConnectorHandle(), tableHandle.getLayout(), columnHandles, constraint); + return session.getRuntimeStats().recordWallTime( + GET_TABLE_STATISTICS_TIME_NANOS, + () -> metadata.getTableStatistics(session.toConnectorSession(connectorId), tableHandle.getConnectorHandle(), tableHandle.getLayout(), columnHandles, constraint)); } catch (RuntimeException e) { if (isIgnoreStatsCalculatorFailures(session)) { diff --git a/presto-main-base/src/main/java/com/facebook/presto/sql/Optimizer.java b/presto-main-base/src/main/java/com/facebook/presto/sql/Optimizer.java index 7a0337b134c3a..137ab9b17250a 100644 --- a/presto-main-base/src/main/java/com/facebook/presto/sql/Optimizer.java +++ b/presto-main-base/src/main/java/com/facebook/presto/sql/Optimizer.java @@ -104,7 +104,7 @@ public Plan validateAndOptimizePlan(PlanNode root, PlanStage stage) { validateIntermediatePlanWithRuntimeStats(root); - boolean enableVerboseRuntimeStats = SystemSessionProperties.isVerboseRuntimeStatsEnabled(session); + boolean enableVerboseRuntimeStats = SystemSessionProperties.isVerboseRuntimeStatsEnabled(session) || SystemSessionProperties.isVerbosePlannerRuntimeStatsEnabled(session); if (stage.ordinal() >= OPTIMIZED.ordinal()) { for (PlanOptimizer optimizer : planOptimizers) { if (Thread.currentThread().isInterrupted()) { diff --git a/presto-main-base/src/main/java/com/facebook/presto/sql/analyzer/StatementAnalyzer.java b/presto-main-base/src/main/java/com/facebook/presto/sql/analyzer/StatementAnalyzer.java index b54fcbb0df9e5..1ef66567edfbd 100644 --- a/presto-main-base/src/main/java/com/facebook/presto/sql/analyzer/StatementAnalyzer.java +++ b/presto-main-base/src/main/java/com/facebook/presto/sql/analyzer/StatementAnalyzer.java @@ -17,6 +17,7 @@ import com.facebook.presto.Session; import com.facebook.presto.SystemSessionProperties; import com.facebook.presto.common.QualifiedObjectName; +import com.facebook.presto.common.RuntimeMetricName; import com.facebook.presto.common.SourceColumn; import com.facebook.presto.common.Subfield; import com.facebook.presto.common.function.OperatorType; @@ -745,7 +746,9 @@ protected Scope visitAnalyze(Analyze node, Optional scope) // user must have read and insert permission in order to analyze stats of a table Multimap tableColumnMap = ImmutableMultimap.builder() - .putAll(tableName, metadataResolver.getColumnHandles(tableHandle).keySet().stream().map(column -> new Subfield(column, ImmutableList.of())).collect(toImmutableSet())) + .putAll(tableName, session.getRuntimeStats().recordWallTime( + RuntimeMetricName.GET_COLUMN_HANDLE_TIME_NANOS, + () -> metadataResolver.getColumnHandles(tableHandle)).keySet().stream().map(column -> new Subfield(column, ImmutableList.of())).collect(toImmutableSet())) .build(); analysis.addTableColumnAndSubfieldReferences(accessControl, session.getIdentity(), session.getTransactionId(), session.getAccessControlContext(), tableColumnMap, tableColumnMap); analysis.addAccessControlCheckForTable(TABLE_INSERT, new AccessControlInfoForTable(accessControl, session.getIdentity(), session.getTransactionId(), session.getAccessControlContext(), tableName)); @@ -944,7 +947,9 @@ private Map analyzeAutoRefreshMaterializedView( RefreshMaterializedView node, QualifiedObjectName viewName) { - MaterializedViewStatus viewStatus = metadataResolver.getMaterializedViewStatus(viewName, TupleDomain.all()); + MaterializedViewStatus viewStatus = session.getRuntimeStats().recordWallTime( + RuntimeMetricName.GET_MATERIALIZED_VIEW_STATUS_TIME_NANOS, + () -> metadataResolver.getMaterializedViewStatus(viewName, TupleDomain.all())); Map missingPartitionsPerTable = viewStatus.getPartitionsFromBaseTables(); @@ -1172,8 +1177,12 @@ protected Scope visitCreateVectorIndex(CreateVectorIndex node, Optional s Scope tableScope = analyzer.analyze(sourceTable, scope); // Validate that specified columns exist in the source table - TableHandle sourceTableHandle = metadataResolver.getTableHandle(sourceTableName).get(); - Map sourceColumns = metadataResolver.getColumnHandles(sourceTableHandle); + TableHandle sourceTableHandle = session.getRuntimeStats().recordWallTime( + RuntimeMetricName.GET_TABLE_HANDLE_TIME_NANOS, + () -> metadataResolver.getTableHandle(sourceTableName)).get(); + Map sourceColumns = session.getRuntimeStats().recordWallTime( + RuntimeMetricName.GET_COLUMN_HANDLE_TIME_NANOS, + () -> metadataResolver.getColumnHandles(sourceTableHandle)); for (Identifier column : node.getColumns()) { if (!sourceColumns.containsKey(column.getValue())) { throw new SemanticException(MISSING_COLUMN, column, "Column '%s' does not exist in source table '%s'", column.getValue(), sourceTableName); @@ -2710,7 +2719,9 @@ private MaterializedViewStatus getMaterializedViewStatus(QualifiedObjectName mat Optional materializedViewDefinition = getMaterializedViewDefinition(session, metadataResolver, analysis.getMetadataHandle(), materializedViewName); if (!materializedViewDefinition.isPresent()) { log.warn("Materialized view definition not present as expected when fetching materialized view status"); - return metadataResolver.getMaterializedViewStatus(materializedViewName, baseQueryDomain); + return session.getRuntimeStats().recordWallTime( + RuntimeMetricName.GET_MATERIALIZED_VIEW_STATUS_TIME_NANOS, + () -> metadataResolver.getMaterializedViewStatus(materializedViewName, TupleDomain.all())); } Scope sourceScope = getScopeFromTable(table, scope); @@ -2780,7 +2791,10 @@ private MaterializedViewStatus getMaterializedViewStatus(QualifiedObjectName mat } } - return metadataResolver.getMaterializedViewStatus(materializedViewName, baseQueryDomain); + TupleDomain finalBaseQueryDomain = baseQueryDomain; + return session.getRuntimeStats().recordWallTime( + RuntimeMetricName.GET_MATERIALIZED_VIEW_STATUS_TIME_NANOS, + () -> metadataResolver.getMaterializedViewStatus(materializedViewName, finalBaseQueryDomain)); } @Override diff --git a/presto-main-base/src/main/java/com/facebook/presto/sql/planner/CachingPlanCanonicalInfoProvider.java b/presto-main-base/src/main/java/com/facebook/presto/sql/planner/CachingPlanCanonicalInfoProvider.java index 54a6a15113f3f..e1568162cd686 100644 --- a/presto-main-base/src/main/java/com/facebook/presto/sql/planner/CachingPlanCanonicalInfoProvider.java +++ b/presto-main-base/src/main/java/com/facebook/presto/sql/planner/CachingPlanCanonicalInfoProvider.java @@ -38,6 +38,7 @@ import static com.facebook.presto.SystemSessionProperties.enableVerboseHistoryBasedOptimizerRuntimeStats; import static com.facebook.presto.SystemSessionProperties.getHistoryBasedOptimizerTimeoutLimit; +import static com.facebook.presto.SystemSessionProperties.isVerbosePlannerRuntimeStatsEnabled; import static com.facebook.presto.SystemSessionProperties.isVerboseRuntimeStatsEnabled; import static com.facebook.presto.SystemSessionProperties.logQueryPlansUsedInHistoryBasedOptimizer; import static com.facebook.presto.common.RuntimeUnit.NANO; @@ -79,7 +80,7 @@ private Optional loadValue(Session session, CacheKey key, long startTimeInNano = System.nanoTime(); long profileStartTime = 0; long timeoutInMilliseconds = getHistoryBasedOptimizerTimeoutLimit(session).toMillis(); - boolean enableVerboseRuntimeStats = isVerboseRuntimeStatsEnabled(session) || enableVerboseHistoryBasedOptimizerRuntimeStats(session); + boolean enableVerboseRuntimeStats = isVerboseRuntimeStatsEnabled(session) || isVerbosePlannerRuntimeStatsEnabled(session) || enableVerboseHistoryBasedOptimizerRuntimeStats(session); Map cache = historyBasedStatisticsCacheManager.getCanonicalInfoCache(session.getQueryId()); PlanNodeCanonicalInfo result = cache.get(key); if (result != null || cacheOnly) { diff --git a/presto-main-base/src/main/java/com/facebook/presto/sql/planner/iterative/IterativeOptimizer.java b/presto-main-base/src/main/java/com/facebook/presto/sql/planner/iterative/IterativeOptimizer.java index 7798d019181ee..635a4225c51c9 100644 --- a/presto-main-base/src/main/java/com/facebook/presto/sql/planner/iterative/IterativeOptimizer.java +++ b/presto-main-base/src/main/java/com/facebook/presto/sql/planner/iterative/IterativeOptimizer.java @@ -50,6 +50,7 @@ import static com.facebook.presto.SystemSessionProperties.getOptimizersToEnableVerboseRuntimeStats; import static com.facebook.presto.SystemSessionProperties.isVerboseOptimizerInfoEnabled; +import static com.facebook.presto.SystemSessionProperties.isVerbosePlannerRuntimeStatsEnabled; import static com.facebook.presto.SystemSessionProperties.isVerboseRuntimeStatsEnabled; import static com.facebook.presto.common.RuntimeUnit.NANO; import static com.facebook.presto.spi.StandardErrorCode.OPTIMIZER_TIMEOUT; @@ -242,7 +243,7 @@ private Rule.Result transform(PlanNode node, Rule rule, Matcher matcher, throw e; } stats.record(rule, duration, !result.isEmpty()); - if (isVerboseRuntimeStatsEnabled(context.session) || trackOptimizerRuntime(context.session, rule)) { + if (isVerboseRuntimeStatsEnabled(context.session) || isVerbosePlannerRuntimeStatsEnabled(context.session) || trackOptimizerRuntime(context.session, rule)) { context.session.getRuntimeStats().addMetricValue(String.format("rule%sTimeNanos", getNameOfOptimizerRule(rule)), NANO, duration); } diff --git a/presto-main-base/src/main/java/com/facebook/presto/sql/planner/optimizations/ApplyConnectorOptimization.java b/presto-main-base/src/main/java/com/facebook/presto/sql/planner/optimizations/ApplyConnectorOptimization.java index e4fa7e25736db..f118e1648abd3 100644 --- a/presto-main-base/src/main/java/com/facebook/presto/sql/planner/optimizations/ApplyConnectorOptimization.java +++ b/presto-main-base/src/main/java/com/facebook/presto/sql/planner/optimizations/ApplyConnectorOptimization.java @@ -124,7 +124,7 @@ public PlanOptimizerResult optimize(PlanNode plan, Session session, TypeProvider requireNonNull(variableAllocator, "variableAllocator is null"); requireNonNull(idAllocator, "idAllocator is null"); - boolean enableVerboseRuntimeStats = SystemSessionProperties.isVerboseRuntimeStatsEnabled(session); + boolean enableVerboseRuntimeStats = SystemSessionProperties.isVerboseRuntimeStatsEnabled(session) || SystemSessionProperties.isVerbosePlannerRuntimeStatsEnabled(session); Map> connectorOptimizers = connectorOptimizersSupplier.get(); if (connectorOptimizers.isEmpty()) { return PlanOptimizerResult.optimizerResult(plan, false);