Introduce new timers for the different phases of the Cascades planner

This commit introduces new StoreTimer.Events that record how long each phase (rewriting, planning)
of the Cascades planner take. To achieve this, the Relational layer passes the instance of StoreTimer
within the current transaction to the Cascades planner upon creation, which it makes use of by recording
the time a phase took using a new Cascades task, `FinalizePlannerPhase`, which simply calls record on the
StoreTimer instance (if it is not `null`) with the total time the planner phase took. The
`FinalizePlannerPhase` task is schedueled to be executed by the `InitiatePlannerPhase` task, ensuring that
it is the last task that is run for that phase.

In addition, the logs for queries (which happen if debug logging is enabled or if a query is too slow) is enhanced
to include the durations for the two planner phases.

Author: hazefully

fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/CascadesPlanner.java

@@ -26,6 +26,7 @@
 import com.apple.foundationdb.record.RecordStoreState;
 import com.apple.foundationdb.record.logging.KeyValueLogMessage;
 import com.apple.foundationdb.record.logging.LogMessageKeys;
+import com.apple.foundationdb.record.provider.common.StoreTimer;
 import com.apple.foundationdb.record.query.IndexQueryabilityFilter;
 import com.apple.foundationdb.record.query.ParameterRelationshipGraph;
 import com.apple.foundationdb.record.query.RecordQuery;
@@ -55,6 +56,7 @@
 import org.slf4j.LoggerFactory;
 
 import javax.annotation.Nonnull;
+import javax.annotation.Nullable;
 import java.util.ArrayDeque;
 import java.util.Collection;
 import java.util.Deque;
@@ -212,6 +214,8 @@ public class CascadesPlanner implements QueryPlanner {
     private final RecordMetaData metaData;
     @Nonnull
     private final RecordStoreState recordStoreState;
+    @Nullable
+    private final StoreTimer storeTimer;
     @Nonnull
     private Reference currentRoot;
     @Nonnull
@@ -228,9 +232,14 @@ public class CascadesPlanner implements QueryPlanner {
     private int maxQueueSize;
 
     public CascadesPlanner(@Nonnull RecordMetaData metaData, @Nonnull RecordStoreState recordStoreState) {
+        this(metaData, recordStoreState, null);
+    }
+
+    public CascadesPlanner(@Nonnull RecordMetaData metaData, @Nonnull RecordStoreState recordStoreState, @Nullable StoreTimer storeTimer) {
         this.configuration = RecordQueryPlannerConfiguration.builder().build();
         this.metaData = metaData;
         this.recordStoreState = recordStoreState;
+        this.storeTimer = storeTimer;
         // Placeholders until we get a query.
         this.currentRoot = Reference.empty();
         this.planContext = PlanContext.emptyContext();
@@ -524,6 +533,41 @@ public interface Task {
         Debugger.Event toTaskEvent(Location location);
     }
 
+    private class FinalizePlannerPhase implements Task {
+        @Nonnull
+        private final PlannerPhase plannerPhase;
+        private final long phaseStartTime;
+
+        public FinalizePlannerPhase(@Nonnull final PlannerPhase plannerPhase, long phaseStartTime) {
+            this.plannerPhase = plannerPhase;
+            this.phaseStartTime = phaseStartTime;
+        }
+
+        @Override
+        @Nonnull
+        public PlannerPhase getPlannerPhase() {
+            return plannerPhase;
+        }
+
+        @Override
+        public void execute() {
+            if (storeTimer != null) {
+                storeTimer.record(plannerPhase.getPhaseCompletionTimerEvent(), System.nanoTime() - phaseStartTime);
+            }
+        }
+
+        @Override
+        @Nonnull
+        public Debugger.Event toTaskEvent(final Location location) {
+            return new Debugger.FinalizePlannerPhaseEvent(plannerPhase, currentRoot, taskStack, location);
+        }
+
+        @Override
+        public String toString() {
+            return "FinalizePlannerPhase(" + plannerPhase.name() + ")";
+        }
+    }
+
     /**
      * Globally initiate a new planner phase.
      * Simplified push/execute overview:
@@ -552,10 +596,12 @@ public PlannerPhase getPlannerPhase() {
 
         @Override
         public void execute() {
+            var phaseStartTime = System.nanoTime();
             if (plannerPhase.hasNextPhase()) {
                 // if there is another phase push it first so it gets executed at the very end
                 taskStack.push(new InitiatePlannerPhase(plannerPhase.getNextPhase()));
             }
+            taskStack.push(new FinalizePlannerPhase(plannerPhase, phaseStartTime));
             taskStack.push(new OptimizeGroup(plannerPhase, currentRoot));
             taskStack.push(new ExploreGroup(plannerPhase, currentRoot));
         }

fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/PlannerPhase.java

@@ -35,8 +35,8 @@
  */
 public enum PlannerPhase {
     // note that the phase are declared in a counterintuitive inverse way since a phase has to specify the next phase
-    PLANNING(PlanningRuleSet.getDefault(), PlannerStage.PLANNED, PlanningCostModel::new),
-    REWRITING(RewritingRuleSet.getDefault(), PlannerStage.CANONICAL, RewritingCostModel::new, PLANNING);
+    PLANNING(PlanningRuleSet.getDefault(), PlannerStage.PLANNED, PlanningCostModel::new, PlannerTimerEvents.PLANNING_PHASE_COMPLETE),
+    REWRITING(RewritingRuleSet.getDefault(), PlannerStage.CANONICAL, RewritingCostModel::new, PlannerTimerEvents.REWRITING_PHASE_COMPLETE, PLANNING);
 
     @Nonnull
     private final CascadesRuleSet ruleSet;
@@ -46,21 +46,26 @@ public enum PlannerPhase {
     private final Function<RecordQueryPlannerConfiguration, CascadesCostModel> costModelCreator;
     @Nullable
     private final PlannerPhase nextPhase;
+    @Nonnull
+    private final PlannerTimerEvents phaseCompletionTimerEvent;
 
     PlannerPhase(@Nonnull final CascadesRuleSet ruleSet,
                  @Nonnull final PlannerStage targetStage,
-                 @Nonnull final Function<RecordQueryPlannerConfiguration, CascadesCostModel> costModelCreator) {
-        this(ruleSet, targetStage, costModelCreator, null);
+                 @Nonnull final Function<RecordQueryPlannerConfiguration, CascadesCostModel> costModelCreator,
+                 @Nonnull final PlannerTimerEvents phaseCompletionTimerEvent) {
+        this(ruleSet, targetStage, costModelCreator, phaseCompletionTimerEvent, null);
     }
 
     PlannerPhase(@Nonnull final CascadesRuleSet ruleSet,
                  @Nonnull final PlannerStage targetStage,
                  @Nonnull final Function<RecordQueryPlannerConfiguration, CascadesCostModel> costModelCreator,
+                 @Nonnull final PlannerTimerEvents phaseCompletionTimerEvent,
                  @Nullable final PlannerPhase nextPhase) {
         this.ruleSet = ruleSet;
         this.targetStage = targetStage;
         this.costModelCreator = costModelCreator;
         this.nextPhase = nextPhase;
+        this.phaseCompletionTimerEvent = phaseCompletionTimerEvent;
     }
 
     @Nonnull
@@ -87,6 +92,11 @@ public boolean hasNextPhase() {
         return nextPhase != null;
     }
 
+    @Nonnull
+    public PlannerTimerEvents getPhaseCompletionTimerEvent() {
+        return phaseCompletionTimerEvent;
+    }
+
     @Nonnull
     public PPlannerPhase toProto() {
         switch (this) {

fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/PlannerTimerEvents.java

@@ -0,0 +1,49 @@
+/*
+ * PlannerTimerEvents.java
+ *
+ * This source file is part of the FoundationDB open source project
+ *
+ * Copyright 2015-2025 Apple Inc. and the FoundationDB project authors
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package com.apple.foundationdb.record.query.plan.cascades;
+
+import com.apple.foundationdb.record.provider.common.StoreTimer;
+
+import javax.annotation.Nonnull;
+
+public enum PlannerTimerEvents implements StoreTimer.Event {
+    REWRITING_PHASE_COMPLETE("complete the rewriting phase of the planner"),
+    PLANNING_PHASE_COMPLETE("complete the planning phase of the planner");
+
+    private final String title;
+    private final String logKey;
+
+    PlannerTimerEvents(String title) {
+        this.title = title;
+        this.logKey = StoreTimer.Event.super.logKey();
+    }
+
+    @Override
+    public String title() {
+        return title;
+    }
+
+    @Override
+    @Nonnull
+    public String logKey() {
+        return this.logKey;
+    }
+}

fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/Debugger.java

@@ -36,6 +36,7 @@
 import com.apple.foundationdb.record.query.plan.cascades.debug.eventprotos.PExecutingTaskEvent;
 import com.apple.foundationdb.record.query.plan.cascades.debug.eventprotos.PExploreExpressionEvent;
 import com.apple.foundationdb.record.query.plan.cascades.debug.eventprotos.PExploreGroupEvent;
+import com.apple.foundationdb.record.query.plan.cascades.debug.eventprotos.PFinalizePlannerPhaseEvent;
 import com.apple.foundationdb.record.query.plan.cascades.debug.eventprotos.PInitiatePlannerPhaseEvent;
 import com.apple.foundationdb.record.query.plan.cascades.debug.eventprotos.PInsertIntoMemoEvent;
 import com.apple.foundationdb.record.query.plan.cascades.debug.eventprotos.PMatchPartition;
@@ -260,7 +261,8 @@ enum Shorthand {
         TRANSFORM,
         INSERT_INTO_MEMO,
         TRANSLATE_CORRELATIONS,
-        INITPHASE
+        INITPHASE,
+        FINALIZEPHASE
     }
 
     /**
@@ -529,6 +531,42 @@ public PEvent.Builder toEventBuilder() {
         }
     }
 
+    class FinalizePlannerPhaseEvent extends AbstractEventWithState {
+        public FinalizePlannerPhaseEvent(@Nonnull final PlannerPhase plannerPhase,
+                                         @Nonnull final Reference rootReference,
+                                         @Nonnull final Deque<Task> taskStack,
+                                         @Nonnull final Location location) {
+            super(plannerPhase, rootReference, taskStack, location);
+        }
+
+        @Override
+        @Nonnull
+        public String getDescription() {
+            return "finalizing planner phase " + getPlannerPhase().name();
+        }
+
+        @Override
+        @Nonnull
+        public Shorthand getShorthand() {
+            return Shorthand.FINALIZEPHASE;
+        }
+
+        @Nonnull
+        @Override
+        public PFinalizePlannerPhaseEvent toProto() {
+            return PFinalizePlannerPhaseEvent.newBuilder()
+                    .setSuper(toAbstractEventWithStateProto())
+                    .build();
+        }
+
+        @Nonnull
+        @Override
+        public PEvent.Builder toEventBuilder() {
+            return PEvent.newBuilder()
+                    .setFinalizePlannerPhaseEvent(toProto());
+        }
+    }
+
     /**
      * Events of this class are generated every time the planner executes a task.
      */

fdb-record-layer-core/src/main/proto/planner_debugger.proto

@@ -41,6 +41,7 @@ message PEvent {
     PInsertIntoMemoEvent insert_into_memo_event = 11;
     PTranslateCorrelationsEvent translate_correlations_event = 12;
     PInitiatePlannerPhaseEvent initiate_planner_phase_event = 13;
+    PFinalizePlannerPhaseEvent finalize_planner_phase_event = 14;
   }
 }
 
@@ -105,6 +106,10 @@ message PInitiatePlannerPhaseEvent {
   optional PAbstractEventWithState super = 1;
 }
 
+message PFinalizePlannerPhaseEvent {
+  optional PAbstractEventWithState super = 1;
+}
+
 message PInsertIntoMemoEvent {
   optional string location = 1;
   optional PRegisteredRelationalExpression expression = 2;

fdb-record-layer-jmh/src/jmh/java/com/apple/foundationdb/record/benchmark/BenchmarkRecordStore.java

@@ -168,7 +168,7 @@ public QueryPlanner planner(@Nonnull BenchmarkTimer timer, boolean cascades) {
         final RecordMetaData recordMetaData = recordStoreBuilder.getMetaDataProvider().getRecordMetaData();
         final RecordStoreState recordStoreState = new RecordStoreState(null, null);
         if (cascades) {
-            return new CascadesPlanner(recordMetaData, recordStoreState);
+            return new CascadesPlanner(recordMetaData, recordStoreState, timer.getTimer());
         } else {
             return new RecordQueryPlanner(recordMetaData, recordStoreState, timer.getTimer());
         }

fdb-relational-core/src/main/java/com/apple/foundationdb/relational/api/metrics/MetricCollector.java

@@ -20,12 +20,15 @@
 
 package com.apple.foundationdb.relational.api.metrics;
 
+import com.apple.foundationdb.record.provider.common.StoreTimer;
 import com.apple.foundationdb.relational.api.exceptions.ErrorCode;
 import com.apple.foundationdb.relational.api.exceptions.RelationalException;
 import com.apple.foundationdb.relational.util.Supplier;
 
 import javax.annotation.Nonnull;
+import javax.annotation.Nullable;
 import java.util.Locale;
+import java.util.Optional;
 
 /**
  * MetricCollector provides a utility API to register events and counts while performing operations in the Relational
@@ -96,4 +99,15 @@ default boolean hasCounter(@Nonnull RelationalMetric.RelationalCount count) {
      * */
     default void flush() {
     }
+
+    /**
+     * Return an instance of {@link com.apple.foundationdb.record.provider.common.StoreTimer} that corresponds to
+     * this metric collector, if possible.
+     *
+     * @return an instance of {@link com.apple.foundationdb.record.provider.common.StoreTimer} or an empty {@link Optional}
+     */
+    @Nullable
+    default StoreTimer getRecordLayerStoreTimer() {
+        return null;
+    }
 }

fdb-relational-core/src/main/java/com/apple/foundationdb/relational/recordlayer/metric/RecordLayerMetricCollector.java

@@ -31,8 +31,6 @@
 import com.apple.foundationdb.relational.util.Assert;
 import com.apple.foundationdb.relational.util.Supplier;
 
-import com.google.common.annotations.VisibleForTesting;
-
 import javax.annotation.Nonnull;
 import javax.annotation.Nullable;
 import java.util.Objects;
@@ -98,12 +96,12 @@ public boolean hasCounter(@Nonnull RelationalMetric.RelationalCount count) {
 
     @Nullable
     private StoreTimer.Counter getCounter(@Nonnull RelationalMetric.RelationalCount count) {
-        return getUnderlyingStoreTimer().getCounter(count);
+        return Objects.requireNonNull(getRecordLayerStoreTimer()).getCounter(count);
     }
 
-    @Nonnull
-    @VisibleForTesting
-    public StoreTimer getUnderlyingStoreTimer() {
-        return Objects.requireNonNull(context.getTimer());
+    @Override
+    @Nullable
+    public StoreTimer getRecordLayerStoreTimer() {
+        return context.getTimer();
     }
 }

fdb-relational-core/src/main/java/com/apple/foundationdb/relational/recordlayer/query/PlanGenerator.java

@@ -126,7 +126,7 @@ public Plan<?> getPlan(@Nonnull final String query) throws RelationalException {
             exception = e;
             throw e;
         } finally {
-            RelationalLoggingUtil.publishPlanGenerationLogs(logger, message, plan, exception, totalTimeMicros(), options);
+            RelationalLoggingUtil.publishPlanGenerationLogs(logger, message, plan, exception, planContext.getMetricsCollector().getRecordLayerStoreTimer(), totalTimeMicros(), options);
         }
         return plan;
     }
@@ -390,7 +390,10 @@ private static boolean shouldNotCache(@Nonnull final Set<AstNormalizer.Normaliza
     private static CascadesPlanner createPlanner(@Nonnull final RecordMetaData metaData,
                                                  @Nonnull final RecordStoreState recordStoreState,
                                                  @Nonnull final PlanContext planContext) {
-        final var planner = new CascadesPlanner(metaData, recordStoreState);
+        final var planner = new CascadesPlanner(
+                metaData,
+                recordStoreState,
+                planContext.getMetricsCollector().getRecordLayerStoreTimer());
         planner.setConfiguration(planContext.getRecordQueryPlannerConfiguration());
         return planner;
     }