perf: Add runtime stats for uncaptured metastore and planning operations

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";
 }

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);

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<PlanNodeWithHash> planNodesWithHash = ImmutableList.builder();
         Iterable<PlanNode> 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)) {

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

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)) {

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()) {

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> scope)
 
             // user must have read and insert permission in order to analyze stats of a table
             Multimap<QualifiedObjectName, Subfield> tableColumnMap = ImmutableMultimap.<QualifiedObjectName, Subfield>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<SchemaTableName, Expression> 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<SchemaTableName, MaterializedViewStatus.MaterializedDataPredicates> missingPartitionsPerTable =
                     viewStatus.getPartitionsFromBaseTables();
 
@@ -1172,8 +1177,12 @@ protected Scope visitCreateVectorIndex(CreateVectorIndex node, Optional<Scope> s
             Scope tableScope = analyzer.analyze(sourceTable, scope);
 
             // Validate that specified columns exist in the source table
-            TableHandle sourceTableHandle = metadataResolver.getTableHandle(sourceTableName).get();
-            Map<String, ColumnHandle> sourceColumns = metadataResolver.getColumnHandles(sourceTableHandle);
+            TableHandle sourceTableHandle = session.getRuntimeStats().recordWallTime(
+                    RuntimeMetricName.GET_TABLE_HANDLE_TIME_NANOS,
+                    () -> metadataResolver.getTableHandle(sourceTableName)).get();
+            Map<String, ColumnHandle> 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> 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<String> finalBaseQueryDomain = baseQueryDomain;
+            return session.getRuntimeStats().recordWallTime(
+                    RuntimeMetricName.GET_MATERIALIZED_VIEW_STATUS_TIME_NANOS,
+                    () -> metadataResolver.getMaterializedViewStatus(materializedViewName, finalBaseQueryDomain));
         }
 
         @Override

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<PlanNodeCanonicalInfo> 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<CacheKey, PlanNodeCanonicalInfo> cache = historyBasedStatisticsCacheManager.getCanonicalInfoCache(session.getQueryId());
         PlanNodeCanonicalInfo result = cache.get(key);
         if (result != null || cacheOnly) {

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 <T> Rule.Result transform(PlanNode node, Rule<T> 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);
         }
 

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<ConnectorId, Set<ConnectorPlanOptimizer>> connectorOptimizers = connectorOptimizersSupplier.get();
         if (connectorOptimizers.isEmpty()) {
             return PlanOptimizerResult.optimizerResult(plan, false);