From 12b5817799845aa3f75a147fb9015c23f349d9c4 Mon Sep 17 00:00:00 2001 From: Hazem Zaghloul Date: Tue, 29 Jul 2025 18:34:11 +0100 Subject: [PATCH 1/9] 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. --- .../query/plan/cascades/CascadesPlanner.java | 46 +++++++++++++++++ .../query/plan/cascades/PlannerPhase.java | 18 +++++-- .../plan/cascades/PlannerTimerEvents.java | 49 +++++++++++++++++++ .../query/plan/cascades/debug/Debugger.java | 40 ++++++++++++++- .../src/main/proto/planner_debugger.proto | 5 ++ .../benchmark/BenchmarkRecordStore.java | 2 +- .../api/metrics/MetricCollector.java | 14 ++++++ .../metric/RecordLayerMetricCollector.java | 12 ++--- .../recordlayer/query/PlanGenerator.java | 7 ++- .../util/RelationalLoggingUtil.java | 15 +++++- .../recordlayer/QueryLoggingTest.java | 11 +++++ 11 files changed, 203 insertions(+), 16 deletions(-) create mode 100644 fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/PlannerTimerEvents.java diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/CascadesPlanner.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/CascadesPlanner.java index fb9f7b51a0..1100205c9f 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/CascadesPlanner.java +++ b/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)); } diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/PlannerPhase.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/PlannerPhase.java index 0389239812..7c5e366851 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/PlannerPhase.java +++ b/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 costModelCreator; @Nullable private final PlannerPhase nextPhase; + @Nonnull + private final PlannerTimerEvents phaseCompletionTimerEvent; PlannerPhase(@Nonnull final CascadesRuleSet ruleSet, @Nonnull final PlannerStage targetStage, - @Nonnull final Function costModelCreator) { - this(ruleSet, targetStage, costModelCreator, null); + @Nonnull final Function costModelCreator, + @Nonnull final PlannerTimerEvents phaseCompletionTimerEvent) { + this(ruleSet, targetStage, costModelCreator, phaseCompletionTimerEvent, null); } PlannerPhase(@Nonnull final CascadesRuleSet ruleSet, @Nonnull final PlannerStage targetStage, @Nonnull final Function 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) { diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/PlannerTimerEvents.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/PlannerTimerEvents.java new file mode 100644 index 0000000000..8e2dbf3f37 --- /dev/null +++ b/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; + } +} diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/Debugger.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/Debugger.java index 5ec77a5df2..9cf417f3e1 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/Debugger.java +++ b/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 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. */ diff --git a/fdb-record-layer-core/src/main/proto/planner_debugger.proto b/fdb-record-layer-core/src/main/proto/planner_debugger.proto index 223221f338..4d6fc8a234 100644 --- a/fdb-record-layer-core/src/main/proto/planner_debugger.proto +++ b/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; diff --git a/fdb-record-layer-jmh/src/jmh/java/com/apple/foundationdb/record/benchmark/BenchmarkRecordStore.java b/fdb-record-layer-jmh/src/jmh/java/com/apple/foundationdb/record/benchmark/BenchmarkRecordStore.java index b201deb4c3..6c7e4af89e 100644 --- a/fdb-record-layer-jmh/src/jmh/java/com/apple/foundationdb/record/benchmark/BenchmarkRecordStore.java +++ b/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()); } diff --git a/fdb-relational-core/src/main/java/com/apple/foundationdb/relational/api/metrics/MetricCollector.java b/fdb-relational-core/src/main/java/com/apple/foundationdb/relational/api/metrics/MetricCollector.java index 26bf94d5dc..42ce4ae991 100644 --- a/fdb-relational-core/src/main/java/com/apple/foundationdb/relational/api/metrics/MetricCollector.java +++ b/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; + } } diff --git a/fdb-relational-core/src/main/java/com/apple/foundationdb/relational/recordlayer/metric/RecordLayerMetricCollector.java b/fdb-relational-core/src/main/java/com/apple/foundationdb/relational/recordlayer/metric/RecordLayerMetricCollector.java index 051ee46ef2..8877181deb 100644 --- a/fdb-relational-core/src/main/java/com/apple/foundationdb/relational/recordlayer/metric/RecordLayerMetricCollector.java +++ b/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(); } } diff --git a/fdb-relational-core/src/main/java/com/apple/foundationdb/relational/recordlayer/query/PlanGenerator.java b/fdb-relational-core/src/main/java/com/apple/foundationdb/relational/recordlayer/query/PlanGenerator.java index 141b2d4053..187dd07dfb 100644 --- a/fdb-relational-core/src/main/java/com/apple/foundationdb/relational/recordlayer/query/PlanGenerator.java +++ b/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 plan, - @Nullable RelationalException e, long totalTime, Options options) { + @Nullable RelationalException e, @Nullable StoreTimer storeTimer, + long totalTime, Options options) { final boolean logQuery = options.getOption(Options.Name.LOG_QUERY); final boolean isSlow = totalTime > (long) options.getOption(Options.Name.LOG_SLOW_QUERY_THRESHOLD_MICROS); + + if (storeTimer != null) { + Optional.ofNullable(storeTimer.getCounter(PlannerTimerEvents.REWRITING_PHASE_COMPLETE)).ifPresent( + (c) -> message.addKeyAndValue("plannerRewritingPhaseTimeMicros", TimeUnit.NANOSECONDS.toMicros(c.getTimeNanos()))); + Optional.ofNullable(storeTimer.getCounter(PlannerTimerEvents.PLANNING_PHASE_COMPLETE)).ifPresent( + (c) -> message.addKeyAndValue("plannerPlanningPhaseTimeMicros", TimeUnit.NANOSECONDS.toMicros(c.getTimeNanos()))); + } + message.addKeyAndValue("totalPlanTimeMicros", totalTime); if (plan != null) { if (plan instanceof QueryPlan.PhysicalQueryPlan) { diff --git a/fdb-relational-core/src/test/java/com/apple/foundationdb/relational/recordlayer/QueryLoggingTest.java b/fdb-relational-core/src/test/java/com/apple/foundationdb/relational/recordlayer/QueryLoggingTest.java index 00f82ff89d..d73a23f74c 100644 --- a/fdb-relational-core/src/test/java/com/apple/foundationdb/relational/recordlayer/QueryLoggingTest.java +++ b/fdb-relational-core/src/test/java/com/apple/foundationdb/relational/recordlayer/QueryLoggingTest.java @@ -359,6 +359,17 @@ void testLogPlanHash() throws Exception { Assertions.assertThat(logAppender.getLastLogEventMessage()).contains("planHash=\"-1179946538\""); } + @Test + void testLogQueryLogsPlanningDurations() throws Exception { + try (final RelationalResultSet resultSet = statement.executeQuery("SELECT * FROM RESTAURANT where rest_no = 34 OPTIONS (LOG QUERY)")) { + resultSet.next(); + } + Assertions.assertThat(logAppender.getLastLogEventMessage()).containsPattern("plannerRewritingPhaseTimeMicros=\"\\d+\""); + Assertions.assertThat(logAppender.getLastLogEventMessage()).containsPattern("plannerPlanningPhaseTimeMicros=\"\\d+\""); + Assertions.assertThat(logAppender.getLastLogEventMessage()).containsPattern("totalPlanTimeMicros=\"\\d+\""); + + } + @Test void testLogException() { Assert.assertThrows(Exception.class, () -> statement.executeQuery("SELECT * FROM REST where rest_no = 0 OPTIONS (LOG QUERY)")); From 260e2b122b77731db97456a4b17b547a7cbcd54f Mon Sep 17 00:00:00 2001 From: Hazem Zaghloul Date: Thu, 7 Aug 2025 15:28:29 +0100 Subject: [PATCH 2/9] Revert "Introduce new timers for the different phases of the Cascades planner" This reverts commit 7e8cc8e68ab977deb73b5fe8a87aa835bd599a20. --- .../query/plan/cascades/CascadesPlanner.java | 46 ----------------- .../query/plan/cascades/PlannerPhase.java | 18 ++----- .../plan/cascades/PlannerTimerEvents.java | 49 ------------------- .../query/plan/cascades/debug/Debugger.java | 40 +-------------- .../src/main/proto/planner_debugger.proto | 5 -- .../benchmark/BenchmarkRecordStore.java | 2 +- .../api/metrics/MetricCollector.java | 14 ------ .../metric/RecordLayerMetricCollector.java | 12 +++-- .../recordlayer/query/PlanGenerator.java | 7 +-- .../util/RelationalLoggingUtil.java | 15 +----- .../recordlayer/QueryLoggingTest.java | 11 ----- 11 files changed, 16 insertions(+), 203 deletions(-) delete mode 100644 fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/PlannerTimerEvents.java diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/CascadesPlanner.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/CascadesPlanner.java index 1100205c9f..fb9f7b51a0 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/CascadesPlanner.java +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/CascadesPlanner.java @@ -26,7 +26,6 @@ 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; @@ -56,7 +55,6 @@ import org.slf4j.LoggerFactory; import javax.annotation.Nonnull; -import javax.annotation.Nullable; import java.util.ArrayDeque; import java.util.Collection; import java.util.Deque; @@ -214,8 +212,6 @@ public class CascadesPlanner implements QueryPlanner { private final RecordMetaData metaData; @Nonnull private final RecordStoreState recordStoreState; - @Nullable - private final StoreTimer storeTimer; @Nonnull private Reference currentRoot; @Nonnull @@ -232,14 +228,9 @@ 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(); @@ -533,41 +524,6 @@ 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: @@ -596,12 +552,10 @@ 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)); } diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/PlannerPhase.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/PlannerPhase.java index 7c5e366851..0389239812 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/PlannerPhase.java +++ b/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, PlannerTimerEvents.PLANNING_PHASE_COMPLETE), - REWRITING(RewritingRuleSet.getDefault(), PlannerStage.CANONICAL, RewritingCostModel::new, PlannerTimerEvents.REWRITING_PHASE_COMPLETE, PLANNING); + PLANNING(PlanningRuleSet.getDefault(), PlannerStage.PLANNED, PlanningCostModel::new), + REWRITING(RewritingRuleSet.getDefault(), PlannerStage.CANONICAL, RewritingCostModel::new, PLANNING); @Nonnull private final CascadesRuleSet ruleSet; @@ -46,26 +46,21 @@ public enum PlannerPhase { private final Function costModelCreator; @Nullable private final PlannerPhase nextPhase; - @Nonnull - private final PlannerTimerEvents phaseCompletionTimerEvent; PlannerPhase(@Nonnull final CascadesRuleSet ruleSet, @Nonnull final PlannerStage targetStage, - @Nonnull final Function costModelCreator, - @Nonnull final PlannerTimerEvents phaseCompletionTimerEvent) { - this(ruleSet, targetStage, costModelCreator, phaseCompletionTimerEvent, null); + @Nonnull final Function costModelCreator) { + this(ruleSet, targetStage, costModelCreator, null); } PlannerPhase(@Nonnull final CascadesRuleSet ruleSet, @Nonnull final PlannerStage targetStage, @Nonnull final Function 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 @@ -92,11 +87,6 @@ public boolean hasNextPhase() { return nextPhase != null; } - @Nonnull - public PlannerTimerEvents getPhaseCompletionTimerEvent() { - return phaseCompletionTimerEvent; - } - @Nonnull public PPlannerPhase toProto() { switch (this) { diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/PlannerTimerEvents.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/PlannerTimerEvents.java deleted file mode 100644 index 8e2dbf3f37..0000000000 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/PlannerTimerEvents.java +++ /dev/null @@ -1,49 +0,0 @@ -/* - * 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; - } -} diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/Debugger.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/Debugger.java index 9cf417f3e1..5ec77a5df2 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/Debugger.java +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/Debugger.java @@ -36,7 +36,6 @@ 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; @@ -261,8 +260,7 @@ enum Shorthand { TRANSFORM, INSERT_INTO_MEMO, TRANSLATE_CORRELATIONS, - INITPHASE, - FINALIZEPHASE + INITPHASE } /** @@ -531,42 +529,6 @@ public PEvent.Builder toEventBuilder() { } } - class FinalizePlannerPhaseEvent extends AbstractEventWithState { - public FinalizePlannerPhaseEvent(@Nonnull final PlannerPhase plannerPhase, - @Nonnull final Reference rootReference, - @Nonnull final Deque 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. */ diff --git a/fdb-record-layer-core/src/main/proto/planner_debugger.proto b/fdb-record-layer-core/src/main/proto/planner_debugger.proto index 4d6fc8a234..223221f338 100644 --- a/fdb-record-layer-core/src/main/proto/planner_debugger.proto +++ b/fdb-record-layer-core/src/main/proto/planner_debugger.proto @@ -41,7 +41,6 @@ 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; } } @@ -106,10 +105,6 @@ message PInitiatePlannerPhaseEvent { optional PAbstractEventWithState super = 1; } -message PFinalizePlannerPhaseEvent { - optional PAbstractEventWithState super = 1; -} - message PInsertIntoMemoEvent { optional string location = 1; optional PRegisteredRelationalExpression expression = 2; diff --git a/fdb-record-layer-jmh/src/jmh/java/com/apple/foundationdb/record/benchmark/BenchmarkRecordStore.java b/fdb-record-layer-jmh/src/jmh/java/com/apple/foundationdb/record/benchmark/BenchmarkRecordStore.java index 6c7e4af89e..b201deb4c3 100644 --- a/fdb-record-layer-jmh/src/jmh/java/com/apple/foundationdb/record/benchmark/BenchmarkRecordStore.java +++ b/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, timer.getTimer()); + return new CascadesPlanner(recordMetaData, recordStoreState); } else { return new RecordQueryPlanner(recordMetaData, recordStoreState, timer.getTimer()); } diff --git a/fdb-relational-core/src/main/java/com/apple/foundationdb/relational/api/metrics/MetricCollector.java b/fdb-relational-core/src/main/java/com/apple/foundationdb/relational/api/metrics/MetricCollector.java index 42ce4ae991..26bf94d5dc 100644 --- a/fdb-relational-core/src/main/java/com/apple/foundationdb/relational/api/metrics/MetricCollector.java +++ b/fdb-relational-core/src/main/java/com/apple/foundationdb/relational/api/metrics/MetricCollector.java @@ -20,15 +20,12 @@ 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 @@ -99,15 +96,4 @@ 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; - } } diff --git a/fdb-relational-core/src/main/java/com/apple/foundationdb/relational/recordlayer/metric/RecordLayerMetricCollector.java b/fdb-relational-core/src/main/java/com/apple/foundationdb/relational/recordlayer/metric/RecordLayerMetricCollector.java index 8877181deb..051ee46ef2 100644 --- a/fdb-relational-core/src/main/java/com/apple/foundationdb/relational/recordlayer/metric/RecordLayerMetricCollector.java +++ b/fdb-relational-core/src/main/java/com/apple/foundationdb/relational/recordlayer/metric/RecordLayerMetricCollector.java @@ -31,6 +31,8 @@ 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; @@ -96,12 +98,12 @@ public boolean hasCounter(@Nonnull RelationalMetric.RelationalCount count) { @Nullable private StoreTimer.Counter getCounter(@Nonnull RelationalMetric.RelationalCount count) { - return Objects.requireNonNull(getRecordLayerStoreTimer()).getCounter(count); + return getUnderlyingStoreTimer().getCounter(count); } - @Override - @Nullable - public StoreTimer getRecordLayerStoreTimer() { - return context.getTimer(); + @Nonnull + @VisibleForTesting + public StoreTimer getUnderlyingStoreTimer() { + return Objects.requireNonNull(context.getTimer()); } } diff --git a/fdb-relational-core/src/main/java/com/apple/foundationdb/relational/recordlayer/query/PlanGenerator.java b/fdb-relational-core/src/main/java/com/apple/foundationdb/relational/recordlayer/query/PlanGenerator.java index 187dd07dfb..141b2d4053 100644 --- a/fdb-relational-core/src/main/java/com/apple/foundationdb/relational/recordlayer/query/PlanGenerator.java +++ b/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, planContext.getMetricsCollector().getRecordLayerStoreTimer(), totalTimeMicros(), options); + RelationalLoggingUtil.publishPlanGenerationLogs(logger, message, plan, exception, totalTimeMicros(), options); } return plan; } @@ -390,10 +390,7 @@ private static boolean shouldNotCache(@Nonnull final Set plan, - @Nullable RelationalException e, @Nullable StoreTimer storeTimer, - long totalTime, Options options) { + @Nullable RelationalException e, long totalTime, Options options) { final boolean logQuery = options.getOption(Options.Name.LOG_QUERY); final boolean isSlow = totalTime > (long) options.getOption(Options.Name.LOG_SLOW_QUERY_THRESHOLD_MICROS); - - if (storeTimer != null) { - Optional.ofNullable(storeTimer.getCounter(PlannerTimerEvents.REWRITING_PHASE_COMPLETE)).ifPresent( - (c) -> message.addKeyAndValue("plannerRewritingPhaseTimeMicros", TimeUnit.NANOSECONDS.toMicros(c.getTimeNanos()))); - Optional.ofNullable(storeTimer.getCounter(PlannerTimerEvents.PLANNING_PHASE_COMPLETE)).ifPresent( - (c) -> message.addKeyAndValue("plannerPlanningPhaseTimeMicros", TimeUnit.NANOSECONDS.toMicros(c.getTimeNanos()))); - } - message.addKeyAndValue("totalPlanTimeMicros", totalTime); if (plan != null) { if (plan instanceof QueryPlan.PhysicalQueryPlan) { diff --git a/fdb-relational-core/src/test/java/com/apple/foundationdb/relational/recordlayer/QueryLoggingTest.java b/fdb-relational-core/src/test/java/com/apple/foundationdb/relational/recordlayer/QueryLoggingTest.java index d73a23f74c..00f82ff89d 100644 --- a/fdb-relational-core/src/test/java/com/apple/foundationdb/relational/recordlayer/QueryLoggingTest.java +++ b/fdb-relational-core/src/test/java/com/apple/foundationdb/relational/recordlayer/QueryLoggingTest.java @@ -359,17 +359,6 @@ void testLogPlanHash() throws Exception { Assertions.assertThat(logAppender.getLastLogEventMessage()).contains("planHash=\"-1179946538\""); } - @Test - void testLogQueryLogsPlanningDurations() throws Exception { - try (final RelationalResultSet resultSet = statement.executeQuery("SELECT * FROM RESTAURANT where rest_no = 34 OPTIONS (LOG QUERY)")) { - resultSet.next(); - } - Assertions.assertThat(logAppender.getLastLogEventMessage()).containsPattern("plannerRewritingPhaseTimeMicros=\"\\d+\""); - Assertions.assertThat(logAppender.getLastLogEventMessage()).containsPattern("plannerPlanningPhaseTimeMicros=\"\\d+\""); - Assertions.assertThat(logAppender.getLastLogEventMessage()).containsPattern("totalPlanTimeMicros=\"\\d+\""); - - } - @Test void testLogException() { Assert.assertThrows(Exception.class, () -> statement.executeQuery("SELECT * FROM REST where rest_no = 0 OPTIONS (LOG QUERY)")); From 2582ff810487c91af9c1be06ff48746a8098eb99 Mon Sep 17 00:00:00 2001 From: Hazem Zaghloul Date: Thu, 7 Aug 2025 17:26:17 +0100 Subject: [PATCH 3/9] Split the Cascades Debugger interface around stats and symbols This commit splits the com.apple.foundationdb.record.query.plan.cascades.debug.Debugger interface into two separate interfaces (StatsDebugger and SymbolDebugger) which both extend the base Debugger interface, in order to ensure that operations related to recording Debugger events (with the purpose of calculating stats based on the profiling of these events) make use of the StatsDebugger interface, and operations related to keeping a registry of all Symbols used within the planner for purposes of associating them with friendly names make use of the SymbolDebugger interface. In addition to splitting the Debugger interface, the State class is also split into two classes, one that keeps of the Debugger events and stats around them (EventState) and one that keeps track of the current Symbols seen during planning (SymbolTables). --- .../query/plan/cascades/CascadesPlanner.java | 27 +-- .../query/plan/cascades/CascadesRuleCall.java | 21 +-- .../plan/cascades/CorrelationIdentifier.java | 7 +- .../PrimaryAccessExpansionVisitor.java | 4 +- .../query/plan/cascades/Quantifier.java | 4 +- .../record/query/plan/cascades/Reference.java | 18 +- .../query/plan/cascades/References.java | 5 +- .../cascades/ValueIndexExpansionVisitor.java | 4 +- .../WindowedIndexExpansionVisitor.java | 4 +- .../query/plan/cascades/debug/Debugger.java | 66 +------ .../debug/DebuggerWithSymbolTables.java | 73 ++++---- .../debug/{State.java => EventState.java} | 152 ++-------------- .../plan/cascades/debug/StatsDebugger.java | 51 ++++++ .../plan/cascades/debug/SymbolDebugger.java | 95 ++++++++++ .../plan/cascades/debug/SymbolTables.java | 169 ++++++++++++++++++ .../cascades/explain/PlannerGraphVisitor.java | 6 +- .../rules/ImplementNestedLoopJoinRule.java | 3 +- .../query/plan/cascades/debug/Commands.java | 18 +- .../plan/cascades/debug/PlannerRepl.java | 69 +++---- 19 files changed, 475 insertions(+), 321 deletions(-) rename fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/{State.java => EventState.java} (71%) create mode 100644 fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/StatsDebugger.java create mode 100644 fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/SymbolDebugger.java create mode 100644 fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/SymbolTables.java diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/CascadesPlanner.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/CascadesPlanner.java index fb9f7b51a0..9ba4796fa2 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/CascadesPlanner.java +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/CascadesPlanner.java @@ -41,6 +41,7 @@ import com.apple.foundationdb.record.query.plan.cascades.debug.Debugger; import com.apple.foundationdb.record.query.plan.cascades.debug.Debugger.Location; import com.apple.foundationdb.record.query.plan.cascades.debug.RestartException; +import com.apple.foundationdb.record.query.plan.cascades.debug.StatsDebugger; import com.apple.foundationdb.record.query.plan.cascades.explain.ExplainPlanVisitor; import com.apple.foundationdb.record.query.plan.cascades.explain.PlannerGraphVisitor; import com.apple.foundationdb.record.query.plan.cascades.expressions.RelationalExpression; @@ -331,7 +332,7 @@ public QueryPlanResult planQuery(@Nonnull final RecordQuery query, .put(QueryPlanInfoKeys.MAX_TASK_QUEUE_SIZE, maxQueueSize) .put(QueryPlanInfoKeys.CONSTRAINTS, constraints) .put(QueryPlanInfoKeys.STATS_MAPS, - Debugger.getDebuggerMaybe().flatMap(Debugger::getStatsMaps) + StatsDebugger.getDebuggerMaybe().flatMap(StatsDebugger::getStatsMaps) .orElse(null)) .build(); return new QueryPlanResult(plan, info); @@ -375,8 +376,8 @@ public QueryPlanResult planGraph(@Nonnull final Supplier referenceSup QueryPlanInfo.newBuilder() .put(QueryPlanInfoKeys.CONSTRAINTS, constraints) .put(QueryPlanInfoKeys.STATS_MAPS, - Debugger.getDebuggerMaybe() - .flatMap(Debugger::getStatsMaps).orElse(null)) + StatsDebugger.getDebuggerMaybe().flatMap(StatsDebugger::getStatsMaps) + .orElse(null)) .build()); } finally { Debugger.withDebugger(Debugger::onDone); @@ -425,7 +426,7 @@ private void planPartial(@Nonnull final Supplier referenceSupplier, } taskCount++; - Debugger.withDebugger(debugger -> debugger.onEvent( + StatsDebugger.withDebugger(debugger -> debugger.onEvent( new Debugger.ExecutingTaskEvent(currentRoot, taskStack, Location.BEGIN, Objects.requireNonNull(taskStack.peek())))); Task nextTask = taskStack.pop(); @@ -434,7 +435,7 @@ private void planPartial(@Nonnull final Supplier referenceSupplier, logger.trace(KeyValueLogMessage.of("executing task", "nextTask", nextTask.toString())); } - Debugger.withDebugger(debugger -> debugger.onEvent(nextTask.toTaskEvent(Location.BEGIN))); + StatsDebugger.withDebugger(debugger -> debugger.onEvent(nextTask.toTaskEvent(Location.BEGIN))); try { nextTask.execute(); Debugger.sanityCheck(() -> { @@ -454,7 +455,7 @@ private void planPartial(@Nonnull final Supplier referenceSupplier, }); } finally { - Debugger.withDebugger(debugger -> debugger.onEvent(nextTask.toTaskEvent(Location.END))); + StatsDebugger.withDebugger(debugger -> debugger.onEvent(nextTask.toTaskEvent(Location.END))); } if (logger.isTraceEnabled()) { @@ -469,7 +470,7 @@ private void planPartial(@Nonnull final Supplier referenceSupplier, .addLogInfo(LogMessageKeys.TASK_QUEUE_SIZE, taskStack.size()); } } finally { - Debugger.withDebugger(debugger -> debugger.onEvent( + StatsDebugger.withDebugger(debugger -> debugger.onEvent( new Debugger.ExecutingTaskEvent(currentRoot, taskStack, Location.END, nextTask))); } } catch (final RestartException restartException) { @@ -1006,14 +1007,14 @@ public void execute() { } // we notify the debugger (if installed) that the transform task is succeeding and // about begin and end of the rule call event - Debugger.withDebugger(debugger -> debugger.onEvent(toTaskEvent(Location.MATCH_PRE))); - Debugger.withDebugger(debugger -> + StatsDebugger.withDebugger(debugger -> debugger.onEvent(toTaskEvent(Location.MATCH_PRE))); + StatsDebugger.withDebugger(debugger -> debugger.onEvent(new Debugger.TransformRuleCallEvent(plannerPhase, currentRoot, taskStack, Location.BEGIN, group, getBindable(), rule, ruleCall))); try { executeRuleCall(ruleCall); } finally { - Debugger.withDebugger(debugger -> + StatsDebugger.withDebugger(debugger -> debugger.onEvent(new Debugger.TransformRuleCallEvent(plannerPhase, currentRoot, taskStack, Location.END, group, getBindable(), rule, ruleCall))); } @@ -1033,21 +1034,21 @@ protected void executeRuleCall(@Nonnull CascadesRuleCall ruleCall) { // Handle produced artifacts (through yield...() calls) // for (final PartialMatch newPartialMatch : ruleCall.getNewPartialMatches()) { - Debugger.withDebugger(debugger -> + StatsDebugger.withDebugger(debugger -> debugger.onEvent(new Debugger.TransformRuleCallEvent(plannerPhase, currentRoot, taskStack, Location.YIELD, group, getBindable(), rule, ruleCall))); taskStack.push(new AdjustMatch(getPlannerPhase(), getGroup(), getExpression(), newPartialMatch)); } for (final RelationalExpression newExpression : ruleCall.getNewFinalExpressions()) { - Debugger.withDebugger(debugger -> + StatsDebugger.withDebugger(debugger -> debugger.onEvent(new Debugger.TransformRuleCallEvent(plannerPhase, currentRoot, taskStack, Location.YIELD, group, getBindable(), rule, ruleCall))); exploreExpressionAndOptimizeInputs(plannerPhase, getGroup(), newExpression, true); } for (final RelationalExpression newExpression : ruleCall.getNewExploratoryExpressions()) { - Debugger.withDebugger(debugger -> + StatsDebugger.withDebugger(debugger -> debugger.onEvent(new Debugger.TransformRuleCallEvent(plannerPhase, currentRoot, taskStack, Location.YIELD, group, getBindable(), rule, ruleCall))); exploreExpression(plannerPhase, group, newExpression, true); diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/CascadesRuleCall.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/CascadesRuleCall.java index d79081a5cb..ced46a3a10 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/CascadesRuleCall.java +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/CascadesRuleCall.java @@ -27,6 +27,7 @@ import com.apple.foundationdb.record.query.plan.cascades.Quantifiers.AliasResolver; import com.apple.foundationdb.record.query.plan.cascades.debug.Debugger; import com.apple.foundationdb.record.query.plan.cascades.debug.Debugger.InsertIntoMemoEvent; +import com.apple.foundationdb.record.query.plan.cascades.debug.StatsDebugger; import com.apple.foundationdb.record.query.plan.cascades.expressions.RelationalExpression; import com.apple.foundationdb.record.query.plan.cascades.matching.structure.PlannerBindings; import com.apple.foundationdb.record.query.plan.plans.RecordQueryPlan; @@ -185,7 +186,7 @@ public void pushConstraint(@Nonnull final Reference reference, @Override public void emitEvent(@Nonnull final Debugger.Location location) { Verify.verify(location != Debugger.Location.BEGIN && location != Debugger.Location.END); - Debugger.withDebugger(debugger -> + StatsDebugger.withDebugger(debugger -> debugger.onEvent( new Debugger.TransformRuleCallEvent(plannerPhase, root, taskStack, location, root, bindings.get(rule.getMatcher()), rule, this))); @@ -295,7 +296,7 @@ public EvaluationContext getEvaluationContext() { @Nonnull private Reference addNewReference(@Nonnull final Reference newRef) { for (RelationalExpression expression : newRef.getAllMemberExpressions()) { - Debugger.withDebugger(debugger -> debugger.onEvent(InsertIntoMemoEvent.newExp(expression))); + StatsDebugger.withDebugger(debugger -> debugger.onEvent(InsertIntoMemoEvent.newExp(expression))); traversal.addExpression(newRef, expression); } newReferences.add(newRef); @@ -352,7 +353,7 @@ public Reference memoizeExploratoryExpressions(@Nonnull final Collection debugger.onEvent(InsertIntoMemoEvent.begin())); + StatsDebugger.withDebugger(debugger -> debugger.onEvent(InsertIntoMemoEvent.begin())); try { Preconditions.checkArgument(expressions.stream().noneMatch(expression -> expression instanceof RecordQueryPlan)); @@ -412,7 +413,7 @@ public Reference memoizeExploratoryExpressions(@Nonnull final Collection - Debugger.withDebugger(debugger -> + StatsDebugger.withDebugger(debugger -> debugger.onEvent(InsertIntoMemoEvent.reusedExpWithReferences(expr, existingRefs)))); Verify.verify(existingReference != this.root); return existingReference; @@ -421,7 +422,7 @@ public Reference memoizeExploratoryExpressions(@Nonnull final Collection debugger.onEvent(InsertIntoMemoEvent.end())); + StatsDebugger.withDebugger(debugger -> debugger.onEvent(InsertIntoMemoEvent.end())); } } @@ -436,7 +437,7 @@ private boolean isEligibleForReuse(@Nonnull Set requiredC @Nonnull private Reference memoizeLeafExpressions(@Nonnull final Collection expressions) { - Debugger.withDebugger(debugger -> debugger.onEvent(InsertIntoMemoEvent.begin())); + StatsDebugger.withDebugger(debugger -> debugger.onEvent(InsertIntoMemoEvent.begin())); try { Preconditions.checkArgument(expressions.stream() .allMatch(expression -> !(expression instanceof RecordQueryPlan) && expression.getQuantifiers().isEmpty())); @@ -450,7 +451,7 @@ private Reference memoizeLeafExpressions(@Nonnull final Collection debugger.onEvent(InsertIntoMemoEvent.reusedExp(expression))); + StatsDebugger.withDebugger(debugger -> debugger.onEvent(InsertIntoMemoEvent.reusedExp(expression))); } return leafRef; } @@ -458,7 +459,7 @@ private Reference memoizeLeafExpressions(@Nonnull final Collection debugger.onEvent(InsertIntoMemoEvent.end())); + StatsDebugger.withDebugger(debugger -> debugger.onEvent(InsertIntoMemoEvent.end())); } } @@ -534,14 +535,14 @@ private Reference memoizeExpressionsExactly(@Nonnull final Collection, Set, Reference> referenceCreator) { final var allExpressions = Iterables.concat(exploratoryExpressions, finalExpressions); - Debugger.withDebugger(debugger -> allExpressions.forEach( + StatsDebugger.withDebugger(debugger -> allExpressions.forEach( expression -> debugger.onEvent(InsertIntoMemoEvent.begin()))); try { final var exploratoryExpressionSet = new LinkedIdentitySet<>(exploratoryExpressions); final var finalExpressionSet = new LinkedIdentitySet<>(finalExpressions); return addNewReference(referenceCreator.apply(exploratoryExpressionSet, finalExpressionSet)); } finally { - Debugger.withDebugger(debugger -> allExpressions.forEach( + StatsDebugger.withDebugger(debugger -> allExpressions.forEach( expression -> debugger.onEvent(InsertIntoMemoEvent.end()))); } } diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/CorrelationIdentifier.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/CorrelationIdentifier.java index 72dc45bcb8..498fd7d426 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/CorrelationIdentifier.java +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/CorrelationIdentifier.java @@ -22,6 +22,7 @@ import com.apple.foundationdb.annotation.API; import com.apple.foundationdb.record.query.plan.cascades.debug.Debugger; +import com.apple.foundationdb.record.query.plan.cascades.debug.SymbolDebugger; import com.apple.foundationdb.record.util.ProtoUtils; import com.google.common.collect.ImmutableSet; @@ -88,10 +89,10 @@ public static CorrelationIdentifier uniqueID(@Nonnull final Class clazz) { @Nonnull public static CorrelationIdentifier uniqueID(@Nonnull final Class clazz, @Nonnull final String prefix) { final CorrelationIdentifier id = - Debugger.getIndexOptional(clazz) + SymbolDebugger.getIndexOptional(clazz) .map(i -> CorrelationIdentifier.of(prefix + i)) .orElseGet(() -> new CorrelationIdentifier(ProtoUtils.uniqueName(prefix))); - Debugger.updateIndex(clazz, i -> i + 1); + SymbolDebugger.updateIndex(clazz, i -> i + 1); return id; } @@ -106,7 +107,7 @@ public static CorrelationIdentifier uniqueID(@Nonnull final Class clazz, @Non */ @Nonnull public static CorrelationIdentifier uniqueSingletonID(@Nonnull final UUID singleton, @Nonnull final String prefix) { - return Debugger.getOrRegisterSingleton(singleton) + return SymbolDebugger.getOrRegisterSingleton(singleton) .map(index -> new CorrelationIdentifier(prefix + index)) .orElseGet(() -> new CorrelationIdentifier(singleton.toString())); } diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/PrimaryAccessExpansionVisitor.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/PrimaryAccessExpansionVisitor.java index cd1bfe193e..82c820ed15 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/PrimaryAccessExpansionVisitor.java +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/PrimaryAccessExpansionVisitor.java @@ -23,7 +23,7 @@ import com.apple.foundationdb.annotation.SpotBugsSuppressWarnings; import com.apple.foundationdb.record.metadata.RecordType; import com.apple.foundationdb.record.metadata.expressions.KeyExpression; -import com.apple.foundationdb.record.query.plan.cascades.debug.Debugger; +import com.apple.foundationdb.record.query.plan.cascades.debug.SymbolDebugger; import com.apple.foundationdb.record.query.plan.cascades.expressions.MatchableSortExpression; import com.apple.foundationdb.record.query.plan.cascades.predicates.PredicateWithValueAndRanges; import com.google.common.collect.ImmutableList; @@ -58,7 +58,7 @@ public PrimaryScanMatchCandidate expand(@Nonnull final Supplier 0); + SymbolDebugger.updateIndex(PredicateWithValueAndRanges.class, old -> 0); final var baseQuantifier = baseQuantifierSupplier.get(); diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/Quantifier.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/Quantifier.java index d40fdee0bd..4e259f891b 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/Quantifier.java +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/Quantifier.java @@ -25,7 +25,7 @@ import com.apple.foundationdb.record.PlanSerializable; import com.apple.foundationdb.record.PlanSerializationContext; import com.apple.foundationdb.record.planprotos.PPhysicalQuantifier; -import com.apple.foundationdb.record.query.plan.cascades.debug.Debugger; +import com.apple.foundationdb.record.query.plan.cascades.debug.SymbolDebugger; import com.apple.foundationdb.record.query.plan.cascades.expressions.RelationalExpression; import com.apple.foundationdb.record.query.plan.cascades.typing.Type; import com.apple.foundationdb.record.query.plan.cascades.typing.Type.Record.Field; @@ -625,7 +625,7 @@ protected Quantifier(@Nonnull final CorrelationIdentifier alias) { this.flowedColumnsSupplier = Suppliers.memoize(this::computeFlowedColumns); this.flowedValuesSupplier = Suppliers.memoize(this::computeFlowedValues); // Call debugger hook for this new quantifier. - Debugger.registerQuantifier(this); + SymbolDebugger.registerQuantifier(this); } @Nonnull diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/Reference.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/Reference.java index d8ede8046a..b897e2fbfa 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/Reference.java +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/Reference.java @@ -25,6 +25,8 @@ import com.apple.foundationdb.record.query.plan.HeuristicPlanner; import com.apple.foundationdb.record.query.plan.cascades.debug.Debugger; import com.apple.foundationdb.record.query.plan.cascades.debug.Debugger.InsertIntoMemoEvent; +import com.apple.foundationdb.record.query.plan.cascades.debug.StatsDebugger; +import com.apple.foundationdb.record.query.plan.cascades.debug.SymbolDebugger; import com.apple.foundationdb.record.query.plan.cascades.explain.PlannerGraphVisitor; import com.apple.foundationdb.record.query.plan.cascades.expressions.RelationalExpression; import com.apple.foundationdb.record.query.plan.cascades.expressions.RelationalExpressionWithChildren; @@ -179,7 +181,7 @@ private Reference(@Nonnull final PlannerStage plannerStage, finalExpressions.forEach(finalExpression -> propertiesMap.add(finalExpression)); this.allMembersView = exploratoryMembers.concatExpressions(finalMembers); // Call debugger hook for this new reference. - Debugger.registerReference(this); + SymbolDebugger.registerReference(this); } @Nonnull @@ -325,10 +327,10 @@ public boolean insertFinalExpression(@Nonnull final RelationalExpression newValu private boolean insert(@Nonnull final RelationalExpression newExpression, final boolean isFinal, @Nullable final Map, ?> precomputedPropertiesMap) { - Debugger.withDebugger(debugger -> debugger.onEvent(InsertIntoMemoEvent.begin())); + StatsDebugger.withDebugger(debugger -> debugger.onEvent(InsertIntoMemoEvent.begin())); try { final boolean containsInMemo = containsInMemo(newExpression, isFinal); - Debugger.withDebugger(debugger -> { + StatsDebugger.withDebugger(debugger -> { if (containsInMemo) { debugger.onEvent(InsertIntoMemoEvent.reusedExpWithReferences(newExpression, ImmutableList.of(this))); } else { @@ -341,7 +343,7 @@ private boolean insert(@Nonnull final RelationalExpression newExpression, } return false; } finally { - Debugger.withDebugger(debugger -> debugger.onEvent(InsertIntoMemoEvent.end())); + StatsDebugger.withDebugger(debugger -> debugger.onEvent(InsertIntoMemoEvent.end())); } } @@ -359,7 +361,7 @@ private void insertUnchecked(@Nonnull final RelationalExpression newExpression, final boolean isFinal, @Nullable final Map, ?> precomputedPropertiesMap) { // Call debugger hook to potentially register this new expression. - Debugger.registerExpression(newExpression); + SymbolDebugger.registerExpression(newExpression); Debugger.sanityCheck(() -> Verify.verify(getTotalMembersSize() == 0 || getResultType().equals(newExpression.getResultType()))); @@ -627,7 +629,7 @@ public U acceptVisitor(@Nonnull SimpleExpressionVisitor simpleExpressionV @Override public String toString() { - return Debugger.mapDebugger(debugger -> debugger.nameForObject(this) + "[" + + return SymbolDebugger.mapDebugger(debugger -> debugger.nameForObject(this) + "[" + getAllMemberExpressions().stream() .map(debugger::nameForObject) .collect(Collectors.joining(",")) + "]") @@ -856,8 +858,8 @@ public static Reference of(@Nonnull final PlannerStage plannerStage, @Nonnull final Collection exploratoryExpressions, @Nonnull final Collection finalExpressions) { // Call debugger hook to potentially register this new expression. - exploratoryExpressions.forEach(Debugger::registerExpression); - finalExpressions.forEach(Debugger::registerExpression); + exploratoryExpressions.forEach(SymbolDebugger::registerExpression); + finalExpressions.forEach(SymbolDebugger::registerExpression); return new Reference(plannerStage, new LinkedIdentitySet<>(exploratoryExpressions), new LinkedIdentitySet<>(finalExpressions)); diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/References.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/References.java index d2ed48195e..df5f632d42 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/References.java +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/References.java @@ -23,6 +23,7 @@ import com.apple.foundationdb.record.RecordCoreException; import com.apple.foundationdb.record.query.combinatorics.TopologicalSort; import com.apple.foundationdb.record.query.plan.cascades.debug.Debugger; +import com.apple.foundationdb.record.query.plan.cascades.debug.StatsDebugger; import com.apple.foundationdb.record.query.plan.cascades.expressions.RelationalExpression; import com.apple.foundationdb.record.query.plan.cascades.expressions.RelationalExpressionWithChildren; import com.apple.foundationdb.record.query.plan.cascades.values.translation.TranslationMap; @@ -187,14 +188,14 @@ private static void rebaseGraph(@Nonnull final Memoizer memoizer, @Nonnull final } else { translatedExpression = expression.translateCorrelations(translationMap, shouldSimplifyValues, translatedQuantifiers); - Debugger.withDebugger(debugger -> debugger.onEvent( + StatsDebugger.withDebugger(debugger -> debugger.onEvent( new Debugger.TranslateCorrelationsEvent(translatedExpression, Debugger.Location.COUNT))); allMembersSame = false; } } else { translatedExpression = expression.translateCorrelations(translationMap, shouldSimplifyValues, translatedQuantifiers); - Debugger.withDebugger(debugger -> debugger.onEvent( + StatsDebugger.withDebugger(debugger -> debugger.onEvent( new Debugger.TranslateCorrelationsEvent(translatedExpression, Debugger.Location.COUNT))); allMembersSame = false; } diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/ValueIndexExpansionVisitor.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/ValueIndexExpansionVisitor.java index 48361388c5..0d1ff32998 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/ValueIndexExpansionVisitor.java +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/ValueIndexExpansionVisitor.java @@ -27,7 +27,7 @@ import com.apple.foundationdb.record.metadata.expressions.GroupingKeyExpression; import com.apple.foundationdb.record.metadata.expressions.KeyExpression; import com.apple.foundationdb.record.metadata.expressions.KeyWithValueExpression; -import com.apple.foundationdb.record.query.plan.cascades.debug.Debugger; +import com.apple.foundationdb.record.query.plan.cascades.debug.SymbolDebugger; import com.apple.foundationdb.record.query.plan.cascades.expressions.MatchableSortExpression; import com.apple.foundationdb.record.query.plan.cascades.predicates.Placeholder; import com.apple.foundationdb.record.query.plan.cascades.predicates.PredicateWithValueAndRanges; @@ -86,7 +86,7 @@ public ValueIndexExpansionVisitor(@Nonnull Index index, @Nonnull Collection baseQuantifierSupplier, @Nullable final KeyExpression primaryKey, final boolean isReverse) { - Debugger.updateIndex(PredicateWithValueAndRanges.class, old -> 0); + SymbolDebugger.updateIndex(PredicateWithValueAndRanges.class, old -> 0); final var baseQuantifier = baseQuantifierSupplier.get(); final var allExpansionsBuilder = ImmutableList.builder(); diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/WindowedIndexExpansionVisitor.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/WindowedIndexExpansionVisitor.java index 6c3ab093ca..9fe928f324 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/WindowedIndexExpansionVisitor.java +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/WindowedIndexExpansionVisitor.java @@ -26,7 +26,7 @@ import com.apple.foundationdb.record.metadata.expressions.GroupingKeyExpression; import com.apple.foundationdb.record.metadata.expressions.KeyExpression; import com.apple.foundationdb.record.query.expressions.Comparisons; -import com.apple.foundationdb.record.query.plan.cascades.debug.Debugger; +import com.apple.foundationdb.record.query.plan.cascades.debug.SymbolDebugger; import com.apple.foundationdb.record.query.plan.cascades.expressions.MatchableSortExpression; import com.apple.foundationdb.record.query.plan.cascades.expressions.SelectExpression; import com.apple.foundationdb.record.query.plan.cascades.predicates.Placeholder; @@ -98,7 +98,7 @@ public MatchCandidate expand(@Nonnull final Supplier baseQua var rootExpression = index.getRootExpression(); Verify.verify(rootExpression instanceof GroupingKeyExpression); - Debugger.updateIndex(PredicateWithValueAndRanges.class, old -> 0); + SymbolDebugger.updateIndex(PredicateWithValueAndRanges.class, old -> 0); final var allExpansionsBuilder = ImmutableList.builder(); final var baseQuantifier = baseQuantifierSupplier.get(); diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/Debugger.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/Debugger.java index 5ec77a5df2..45f43881fc 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/Debugger.java +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/Debugger.java @@ -27,7 +27,6 @@ import com.apple.foundationdb.record.query.plan.cascades.PartialMatch; import com.apple.foundationdb.record.query.plan.cascades.PlanContext; import com.apple.foundationdb.record.query.plan.cascades.PlannerPhase; -import com.apple.foundationdb.record.query.plan.cascades.Quantifier; import com.apple.foundationdb.record.query.plan.cascades.Reference; import com.apple.foundationdb.record.query.plan.cascades.debug.eventprotos.PAbstractEventWithState; import com.apple.foundationdb.record.query.plan.cascades.debug.eventprotos.PAdjustMatchEvent; @@ -50,7 +49,6 @@ import com.apple.foundationdb.record.query.plan.cascades.expressions.RelationalExpression; import com.google.common.base.Verify; import com.google.common.collect.ImmutableList; -import com.google.errorprone.annotations.CanIgnoreReturnValue; import com.google.protobuf.Message; import javax.annotation.Nonnull; @@ -61,7 +59,6 @@ import java.util.Optional; import java.util.function.Consumer; import java.util.function.Function; -import java.util.function.IntUnaryOperator; /** *

@@ -162,11 +159,7 @@ static void sanityCheck(@Nonnull final Runnable runnable) { */ @Nonnull static Optional mapDebugger(@Nonnull final Function function) { - final Debugger debugger = getDebugger(); - if (debugger != null) { - return Optional.ofNullable(function.apply(debugger)); - } - return Optional.empty(); + return getDebuggerMaybe().map(function); } static void install() { @@ -181,56 +174,13 @@ static void show(@Nonnull final Reference ref) { withDebugger(debugger -> debugger.onShow(ref)); } - static Optional getIndexOptional(Class clazz) { - return mapDebugger(debugger -> debugger.onGetIndex(clazz)); - } - - @Nonnull - @CanIgnoreReturnValue - static Optional updateIndex(Class clazz, IntUnaryOperator updateFn) { - return mapDebugger(debugger -> debugger.onUpdateIndex(clazz, updateFn)); - } - - static void registerExpression(RelationalExpression expression) { - withDebugger(debugger -> debugger.onRegisterExpression(expression)); - } - - static void registerReference(Reference reference) { - withDebugger(debugger -> debugger.onRegisterReference(reference)); - } - - static void registerQuantifier(Quantifier quantifier) { - withDebugger(debugger -> debugger.onRegisterQuantifier(quantifier)); - } - - static Optional getOrRegisterSingleton(Object singleton) { - return mapDebugger(debugger -> debugger.onGetOrRegisterSingleton(singleton)); - } - - @Nullable - String nameForObject(@Nonnull Object object); - @Nullable PlanContext getPlanContext(); boolean isSane(); - void onEvent(Event event); - void onDone(); - int onGetIndex(@Nonnull Class clazz); - - int onUpdateIndex(@Nonnull Class clazz, @Nonnull IntUnaryOperator updateFn); - - void onRegisterExpression(@Nonnull RelationalExpression expression); - - void onRegisterReference(@Nonnull Reference reference); - - void onRegisterQuantifier(@Nonnull Quantifier quantifier); - - int onGetOrRegisterSingleton(@Nonnull Object singleton); - void onInstall(); void onSetup(); @@ -239,12 +189,6 @@ static Optional getOrRegisterSingleton(Object singleton) { void onQuery(String queryAsString, PlanContext planContext); - @SuppressWarnings("unused") // only used by debugger - String showStats(); - - @Nonnull - Optional getStatsMaps(); - /** * Shorthands to identify a kind of event. */ @@ -325,7 +269,7 @@ default PEvent toEventProto() { @Nonnull static PRegisteredRelationalExpression toExpressionProto(@Nonnull final RelationalExpression expression) { return PRegisteredRelationalExpression.newBuilder() - .setName(Debugger.mapDebugger(debugger -> debugger.nameForObject(expression)).orElseThrow()) + .setName(SymbolDebugger.mapDebugger(debugger -> debugger.nameForObject(expression)).orElseThrow()) .setSemanticHashCode(expression.semanticHashCode()) .build(); } @@ -333,7 +277,7 @@ static PRegisteredRelationalExpression toExpressionProto(@Nonnull final Relation @Nonnull static PRegisteredReference toReferenceProto(@Nonnull final Reference reference) { final var builder = PRegisteredReference.newBuilder() - .setName(Debugger.mapDebugger(debugger -> debugger.nameForObject(reference)).orElseThrow()); + .setName(SymbolDebugger.mapDebugger(debugger -> debugger.nameForObject(reference)).orElseThrow()); for (final var member : reference.getAllMemberExpressions()) { builder.addExpressions(toExpressionProto(member)); } @@ -1024,13 +968,13 @@ private InsertIntoMemoEvent(@Nonnull final Location location, @Nullable final RelationalExpression expression, @Nonnull final Collection reusedExpressionReferences) { if (expression != null) { - Debugger.registerExpression(expression); + SymbolDebugger.registerExpression(expression); } this.expression = expression; this.location = location; this.reusedExpressionReferences = ImmutableList.copyOf(reusedExpressionReferences); // Call debugger hook to potentially register this new reference. - this.reusedExpressionReferences.forEach(Debugger::registerReference); + this.reusedExpressionReferences.forEach(SymbolDebugger::registerReference); } @Override diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/DebuggerWithSymbolTables.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/DebuggerWithSymbolTables.java index a8f2bb8264..fd143746b0 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/DebuggerWithSymbolTables.java +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/DebuggerWithSymbolTables.java @@ -64,13 +64,15 @@ * while debugging. */ @SuppressWarnings("PMD.SystemPrintln") -public class DebuggerWithSymbolTables implements Debugger { +public class DebuggerWithSymbolTables implements SymbolDebugger, StatsDebugger { private static final Logger logger = LoggerFactory.getLogger(DebuggerWithSymbolTables.class); private final boolean isSane; private final boolean isRecordEvents; private final Iterable prerecordedEventProtoIterable; - private final Deque stateStack; + private final Deque eventStateStack; + private final Deque symbolTablesStack; + @Nullable private String queryAsString; @Nullable @@ -84,14 +86,20 @@ private DebuggerWithSymbolTables(final boolean isSane, final boolean isRecordEve this.isRecordEvents = isRecordEvents; this.prerecordedEventProtoIterable = prerecordedEventsFileName == null ? null : eventProtosFromFile(prerecordedEventsFileName); - this.stateStack = new ArrayDeque<>(); + this.eventStateStack = new ArrayDeque<>(); + this.symbolTablesStack = new ArrayDeque<>(); this.planContext = null; this.singletonToIndexMap = Maps.newHashMap(); } @Nonnull - State getCurrentState() { - return Objects.requireNonNull(stateStack.peek()); + EventState getCurrentEventState() { + return Objects.requireNonNull(eventStateStack.peek()); + } + + @Nonnull + SymbolTables getCurrentSymbolState() { + return Objects.requireNonNull(symbolTablesStack.peek()); } @Nullable @@ -111,27 +119,27 @@ public boolean isSane() { @Override public int onGetIndex(@Nonnull final Class clazz) { - return getCurrentState().getIndex(clazz); + return getCurrentSymbolState().getIndex(clazz); } @Override public int onUpdateIndex(@Nonnull final Class clazz, @Nonnull final IntUnaryOperator updateFn) { - return getCurrentState().updateIndex(clazz, updateFn); + return getCurrentSymbolState().updateIndex(clazz, updateFn); } @Override public void onRegisterExpression(@Nonnull final RelationalExpression expression) { - getCurrentState().registerExpression(expression); + getCurrentSymbolState().registerExpression(expression); } @Override public void onRegisterReference(@Nonnull final Reference reference) { - getCurrentState().registerReference(reference); + getCurrentSymbolState().registerReference(reference); } @Override public void onRegisterQuantifier(@Nonnull final Quantifier quantifier) { - getCurrentState().registerQuantifier(quantifier); + getCurrentSymbolState().registerQuantifier(quantifier); } @Override @@ -157,7 +165,8 @@ public void onShow(@Nonnull final Reference ref) { @Override public void onQuery(@Nonnull final String recordQuery, @Nonnull final PlanContext planContext) { - this.stateStack.push(State.copyOf(getCurrentState())); + this.eventStateStack.push(EventState.copyOf(getCurrentEventState())); + this.symbolTablesStack.push(SymbolTables.copyOf(getCurrentSymbolState())); this.queryAsString = recordQuery; this.planContext = planContext; @@ -165,17 +174,20 @@ public void onQuery(@Nonnull final String recordQuery, @Nonnull final PlanContex } void restartState() { - stateStack.pop(); - stateStack.push(State.copyOf(getCurrentState())); + eventStateStack.pop(); + eventStateStack.push(EventState.copyOf(getCurrentEventState())); + + symbolTablesStack.pop(); + symbolTablesStack.push(SymbolTables.copyOf(getCurrentSymbolState())); } @Override @SuppressWarnings("PMD.GuardLogStatement") // false positive public void onEvent(final Event event) { - if ((queryAsString == null) || (planContext == null) || stateStack.isEmpty()) { + if ((queryAsString == null) || (planContext == null) || eventStateStack.isEmpty()) { return; } - getCurrentState().addCurrentEvent(event); + getCurrentEventState().addCurrentEvent(event); if (logger.isTraceEnabled()) { if (event.getLocation() == Location.END && event instanceof TransformRuleCallEvent) { final TransformRuleCallEvent transformRuleCallEvent = (TransformRuleCallEvent)event; @@ -237,7 +249,7 @@ boolean isValidEntityName(@Nonnull final String identifier) { @Nullable @Override public String nameForObject(@Nonnull final Object object) { - final State state = getCurrentState(); + final SymbolTables state = getCurrentSymbolState(); if (object instanceof RelationalExpression) { @Nullable final Integer id = state.getInvertedExpressionsCache().getIfPresent(object); return (id == null) ? null : "exp" + id; @@ -254,8 +266,8 @@ public String nameForObject(@Nonnull final Object object) { @Override public void onDone() { - if (!stateStack.isEmpty() && queryAsString != null) { - final var state = Objects.requireNonNull(stateStack.peek()); + if (!eventStateStack.isEmpty() && queryAsString != null) { + final var state = Objects.requireNonNull(eventStateStack.peek()); if (logger.isInfoEnabled()) { logger.info(KeyValueLogMessage.of("planning done", "query", Objects.requireNonNull(queryAsString).substring(0, Math.min(queryAsString.length(), 30)), @@ -323,28 +335,23 @@ protected PEvent computeNext() { }; } - @Override - public String showStats() { - State currentState = stateStack.peek(); - if (currentState != null) { - return currentState.showStats(); - } - return "no stats"; - } - @Nonnull @Override public Optional getStatsMaps() { - State currentState = stateStack.peek(); - if (currentState != null) { - return Optional.of(currentState.getStatsMaps()); + EventState currentEventState = eventStateStack.peek(); + if (currentEventState != null) { + return Optional.of(currentEventState.getStatsMaps()); } return Optional.empty(); } private void reset() { - this.stateStack.clear(); - this.stateStack.push(State.initial(isRecordEvents, isRecordEvents, prerecordedEventProtoIterable)); + this.eventStateStack.clear(); + this.eventStateStack.push(EventState.initial(isRecordEvents, isRecordEvents, prerecordedEventProtoIterable)); + + this.symbolTablesStack.clear(); + this.symbolTablesStack.push(new SymbolTables()); + this.planContext = null; this.queryAsString = null; } @@ -399,7 +406,7 @@ public static DebuggerWithSymbolTables withPrerecordedEvents(@Nonnull final Stri public static void printForEachExpression(@Nonnull final Reference root) { forEachExpression(root, expression -> { System.out.println("expression: " + - Debugger.mapDebugger(debugger -> debugger.nameForObject(expression)).orElseThrow() + "; " + + SymbolDebugger.mapDebugger(debugger -> debugger.nameForObject(expression)).orElseThrow() + "; " + "hashCodeWithoutChildren: " + expression.hashCodeWithoutChildren() + "explain: " + expression); }); } diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/State.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/EventState.java similarity index 71% rename from fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/State.java rename to fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/EventState.java index a39eb38661..67af117caa 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/State.java +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/EventState.java @@ -23,18 +23,12 @@ import com.apple.foundationdb.record.RecordCoreException; import com.apple.foundationdb.record.logging.KeyValueLogMessage; import com.apple.foundationdb.record.query.plan.cascades.CascadesRule; -import com.apple.foundationdb.record.query.plan.cascades.Quantifier; -import com.apple.foundationdb.record.query.plan.cascades.Reference; import com.apple.foundationdb.record.query.plan.cascades.debug.eventprotos.PEvent; -import com.apple.foundationdb.record.query.plan.cascades.expressions.RelationalExpression; import com.apple.foundationdb.record.util.pair.Pair; import com.google.common.base.Verify; -import com.google.common.cache.Cache; -import com.google.common.cache.CacheBuilder; import com.google.common.collect.ImmutableMap; import com.google.common.collect.Lists; import com.google.common.collect.Maps; -import com.google.errorprone.annotations.CanIgnoreReturnValue; import org.slf4j.Logger; import org.slf4j.LoggerFactory; @@ -48,22 +42,11 @@ import java.util.Map; import java.util.Objects; import java.util.concurrent.TimeUnit; -import java.util.function.IntUnaryOperator; @SuppressWarnings("PMD.SystemPrintln") -public class State { +public class EventState { @Nonnull - private static final Logger logger = LoggerFactory.getLogger(State.class); - - @Nonnull - private final Map, Integer> classToIndexMap; - @Nonnull - private final Cache expressionCache; - @Nonnull private final Cache invertedExpressionsCache; - @Nonnull private final Cache referenceCache; - @Nonnull private final Cache invertedReferenceCache; - @Nonnull private final Cache quantifierCache; - @Nonnull private final Cache invertedQuantifierCache; + private static final Logger logger = LoggerFactory.getLogger(EventState.class); @Nullable private final List events; @Nullable private final List eventProtos; @@ -76,35 +59,16 @@ public class State { @Nonnull private final Deque, EventDurations>> eventProfilingStack; - private int currentTick; - private final long startTs; + protected int currentTick; + protected final long startTs; - public static State initial(final boolean isRecordEvents, final boolean isRecordEventProtos, - @Nullable Iterable prerecordedEventProtoIterable) { - return new State(isRecordEvents, isRecordEventProtos, prerecordedEventProtoIterable); + public static EventState initial(final boolean isRecordEvents, final boolean isRecordEventProtos, + @Nullable Iterable prerecordedEventProtoIterable) { + return new EventState(isRecordEvents, isRecordEventProtos, prerecordedEventProtoIterable); } - public static State copyOf(final State source) { - final Cache copyExpressionCache = CacheBuilder.newBuilder().weakValues().build(); - source.getExpressionCache().asMap().forEach(copyExpressionCache::put); - final Cache copyInvertedExpressionsCache = CacheBuilder.newBuilder().weakKeys().build(); - source.getInvertedExpressionsCache().asMap().forEach(copyInvertedExpressionsCache::put); - final Cache copyReferenceCache = CacheBuilder.newBuilder().weakValues().build(); - source.getReferenceCache().asMap().forEach(copyReferenceCache::put); - final Cache copyInvertedReferenceCache = CacheBuilder.newBuilder().weakKeys().build(); - source.getInvertedReferenceCache().asMap().forEach(copyInvertedReferenceCache::put); - final Cache copyQuantifierCache = CacheBuilder.newBuilder().weakValues().build(); - source.getQuantifierCache().asMap().forEach(copyQuantifierCache::put); - final Cache copyInvertedQuantifierCache = CacheBuilder.newBuilder().weakKeys().build(); - source.getInvertedQuantifierCache().asMap().forEach(copyInvertedQuantifierCache::put); - - return new State(source.getClassToIndexMap(), - copyExpressionCache, - copyInvertedExpressionsCache, - copyReferenceCache, - copyInvertedReferenceCache, - copyQuantifierCache, - copyInvertedQuantifierCache, + public static EventState copyOf(final EventState source) { + return new EventState( source.events == null ? null : Lists.newArrayList(source.events), source.eventProtos == null ? null : Lists.newArrayList(source.eventProtos), source.prerecordedEventProtoIterable, @@ -115,15 +79,9 @@ public static State copyOf(final State source) { source.getStartTs()); } - private State(final boolean isRecordEvents, final boolean isRecordEventProtos, - @Nullable final Iterable prerecordedEventProtoIterable) { - this(Maps.newHashMap(), - CacheBuilder.newBuilder().weakValues().build(), - CacheBuilder.newBuilder().weakKeys().build(), - CacheBuilder.newBuilder().weakValues().build(), - CacheBuilder.newBuilder().weakKeys().build(), - CacheBuilder.newBuilder().weakValues().build(), - CacheBuilder.newBuilder().weakKeys().build(), + protected EventState(final boolean isRecordEvents, final boolean isRecordEventProtos, + @Nullable final Iterable prerecordedEventProtoIterable) { + this( isRecordEventProtos ? Lists.newArrayList() : null, isRecordEvents ? Lists.newArrayList() : null, prerecordedEventProtoIterable, @@ -134,13 +92,7 @@ private State(final boolean isRecordEvents, final boolean isRecordEventProtos, System.nanoTime()); } - private State(@Nonnull final Map, Integer> classToIndexMap, - @Nonnull final Cache expressionCache, - @Nonnull final Cache invertedExpressionsCache, - @Nonnull final Cache referenceCache, - @Nonnull final Cache invertedReferenceCache, - @Nonnull final Cache quantifierCache, - @Nonnull final Cache invertedQuantifierCache, + protected EventState( @Nullable final List events, @Nullable final List eventProtos, @Nullable final Iterable prerecordedEventProtoIterable, @@ -149,13 +101,7 @@ private State(@Nonnull final Map, Integer> classToIndexMap, @Nonnull final Deque, EventDurations>> eventProfilingStack, final int currentTick, final long startTs) { - this.classToIndexMap = Maps.newHashMap(classToIndexMap); - this.expressionCache = expressionCache; - this.invertedExpressionsCache = invertedExpressionsCache; - this.referenceCache = referenceCache; - this.invertedReferenceCache = invertedReferenceCache; - this.quantifierCache = quantifierCache; - this.invertedQuantifierCache = invertedQuantifierCache; + this.events = events; this.eventProtos = eventProtos; this.prerecordedEventProtoIterable = prerecordedEventProtoIterable; @@ -168,41 +114,6 @@ private State(@Nonnull final Map, Integer> classToIndexMap, this.startTs = startTs; } - @Nonnull - private Map, Integer> getClassToIndexMap() { - return classToIndexMap; - } - - @Nonnull - public Cache getExpressionCache() { - return expressionCache; - } - - @Nonnull - public Cache getInvertedExpressionsCache() { - return invertedExpressionsCache; - } - - @Nonnull - public Cache getReferenceCache() { - return referenceCache; - } - - @Nonnull - public Cache getInvertedReferenceCache() { - return invertedReferenceCache; - } - - @Nonnull - public Cache getQuantifierCache() { - return quantifierCache; - } - - @Nonnull - public Cache getInvertedQuantifierCache() { - return invertedQuantifierCache; - } - @Nullable public List getEvents() { return events; @@ -226,41 +137,6 @@ public long getStartTs() { return startTs; } - public int getIndex(final Class clazz) { - return classToIndexMap.getOrDefault(clazz, 0); - } - - @CanIgnoreReturnValue - public int updateIndex(final Class clazz, IntUnaryOperator computeFn) { - return classToIndexMap.compute(clazz, (c, value) -> value == null ? computeFn.applyAsInt(0) : computeFn.applyAsInt(value)); - } - - public void registerExpression(final RelationalExpression expression) { - if (invertedExpressionsCache.getIfPresent(expression) == null) { - final int index = getIndex(RelationalExpression.class); - expressionCache.put(index, expression); - invertedExpressionsCache.put(expression, index); - updateIndex(RelationalExpression.class, i -> i + 1); - } - } - - public void registerReference(final Reference reference) { - if (invertedReferenceCache.getIfPresent(reference) == null) { - final int index = getIndex(Reference.class); - referenceCache.put(index, reference); - invertedReferenceCache.put(reference, index); - updateIndex(Reference.class, i -> i + 1); - } - } - - public void registerQuantifier(final Quantifier quantifier) { - if (invertedQuantifierCache.getIfPresent(quantifier) == null) { - final int index = getIndex(Quantifier.class); - quantifierCache.put(index, quantifier); - invertedQuantifierCache.put(quantifier, index); - updateIndex(Quantifier.class, i -> i + 1); - } - } @SuppressWarnings("unchecked") public void addCurrentEvent(@Nonnull final Debugger.Event event) { diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/StatsDebugger.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/StatsDebugger.java new file mode 100644 index 0000000000..87a8adf397 --- /dev/null +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/StatsDebugger.java @@ -0,0 +1,51 @@ +/* + * StatsDebugger.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.debug; + +import javax.annotation.Nonnull; +import java.util.Optional; +import java.util.function.Consumer; +import java.util.function.Function; + +public interface StatsDebugger extends Debugger { + @Nonnull + static Optional getDebuggerMaybe() { + final var debugger = Debugger.getDebugger(); + if (debugger instanceof StatsDebugger) { + return Optional.of((StatsDebugger)debugger); + } + return Optional.empty(); + } + + static void withDebugger(@Nonnull final Consumer action) { + getDebuggerMaybe().ifPresent(action); + } + + @Nonnull + static Optional mapDebugger(@Nonnull final Function function) { + return getDebuggerMaybe().map(function); + } + + @Nonnull + Optional getStatsMaps(); + + void onEvent(Debugger.Event event); +} diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/SymbolDebugger.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/SymbolDebugger.java new file mode 100644 index 0000000000..fcad8bceb6 --- /dev/null +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/SymbolDebugger.java @@ -0,0 +1,95 @@ +/* + * SymbolDebugger.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.debug; + +import com.apple.foundationdb.record.query.plan.cascades.Quantifier; +import com.apple.foundationdb.record.query.plan.cascades.Reference; +import com.apple.foundationdb.record.query.plan.cascades.expressions.RelationalExpression; +import com.google.errorprone.annotations.CanIgnoreReturnValue; + +import javax.annotation.Nonnull; +import javax.annotation.Nullable; +import java.util.Optional; +import java.util.function.Consumer; +import java.util.function.Function; +import java.util.function.IntUnaryOperator; + +public interface SymbolDebugger extends Debugger { + @Nonnull + static Optional getDebuggerMaybe() { + final var debugger = Debugger.getDebugger(); + if (debugger instanceof SymbolDebugger) { + return Optional.of((SymbolDebugger)debugger); + } + return Optional.empty(); + } + + static void withDebugger(@Nonnull final Consumer action) { + getDebuggerMaybe().ifPresent(action); + } + + + @Nonnull + static Optional mapDebugger(@Nonnull final Function function) { + return getDebuggerMaybe().map(function); + } + + static Optional getIndexOptional(Class clazz) { + return mapDebugger(debugger -> debugger.onGetIndex(clazz)); + } + + @Nonnull + @CanIgnoreReturnValue + static Optional updateIndex(Class clazz, IntUnaryOperator updateFn) { + return mapDebugger(debugger -> debugger.onUpdateIndex(clazz, updateFn)); + } + + static void registerExpression(RelationalExpression expression) { + withDebugger(debugger -> debugger.onRegisterExpression(expression)); + } + + static void registerReference(Reference reference) { + withDebugger(debugger -> debugger.onRegisterReference(reference)); + } + + static void registerQuantifier(Quantifier quantifier) { + withDebugger(debugger -> debugger.onRegisterQuantifier(quantifier)); + } + + static Optional getOrRegisterSingleton(Object singleton) { + return mapDebugger(debugger -> debugger.onGetOrRegisterSingleton(singleton)); + } + + int onGetIndex(@Nonnull Class clazz); + + int onUpdateIndex(@Nonnull Class clazz, @Nonnull IntUnaryOperator updateFn); + + void onRegisterExpression(@Nonnull RelationalExpression expression); + + void onRegisterReference(@Nonnull Reference reference); + + void onRegisterQuantifier(@Nonnull Quantifier quantifier); + + int onGetOrRegisterSingleton(@Nonnull Object singleton); + + @Nullable + String nameForObject(@Nonnull Object object); +} diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/SymbolTables.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/SymbolTables.java new file mode 100644 index 0000000000..60e4e2d850 --- /dev/null +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/SymbolTables.java @@ -0,0 +1,169 @@ +/* + * SymbolState.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.debug; + +import com.apple.foundationdb.record.query.plan.cascades.Quantifier; +import com.apple.foundationdb.record.query.plan.cascades.Reference; +import com.apple.foundationdb.record.query.plan.cascades.expressions.RelationalExpression; +import com.google.common.cache.Cache; +import com.google.common.cache.CacheBuilder; +import com.google.common.collect.Maps; +import com.google.errorprone.annotations.CanIgnoreReturnValue; + + + +import javax.annotation.Nonnull; +import java.util.Map; +import java.util.function.IntUnaryOperator; + +public class SymbolTables { + @Nonnull + private final Map, Integer> classToIndexMap; + @Nonnull + private final Cache expressionCache; + @Nonnull private final Cache invertedExpressionsCache; + @Nonnull private final Cache referenceCache; + @Nonnull private final Cache invertedReferenceCache; + @Nonnull private final Cache quantifierCache; + @Nonnull private final Cache invertedQuantifierCache; + + public static SymbolTables copyOf(final SymbolTables source) { + final Cache copyExpressionCache = CacheBuilder.newBuilder().weakValues().build(); + source.getExpressionCache().asMap().forEach(copyExpressionCache::put); + final Cache copyInvertedExpressionsCache = CacheBuilder.newBuilder().weakKeys().build(); + source.getInvertedExpressionsCache().asMap().forEach(copyInvertedExpressionsCache::put); + final Cache copyReferenceCache = CacheBuilder.newBuilder().weakValues().build(); + source.getReferenceCache().asMap().forEach(copyReferenceCache::put); + final Cache copyInvertedReferenceCache = CacheBuilder.newBuilder().weakKeys().build(); + source.getInvertedReferenceCache().asMap().forEach(copyInvertedReferenceCache::put); + final Cache copyQuantifierCache = CacheBuilder.newBuilder().weakValues().build(); + source.getQuantifierCache().asMap().forEach(copyQuantifierCache::put); + final Cache copyInvertedQuantifierCache = CacheBuilder.newBuilder().weakKeys().build(); + source.getInvertedQuantifierCache().asMap().forEach(copyInvertedQuantifierCache::put); + + return new SymbolTables(source.getClassToIndexMap(), + copyExpressionCache, + copyInvertedExpressionsCache, + copyReferenceCache, + copyInvertedReferenceCache, + copyQuantifierCache, + copyInvertedQuantifierCache); + } + + public SymbolTables() { + classToIndexMap = Maps.newHashMap(); + expressionCache = CacheBuilder.newBuilder().weakValues().build(); + invertedExpressionsCache = CacheBuilder.newBuilder().weakKeys().build(); + referenceCache = CacheBuilder.newBuilder().weakValues().build(); + invertedReferenceCache = CacheBuilder.newBuilder().weakKeys().build(); + quantifierCache = CacheBuilder.newBuilder().weakValues().build(); + invertedQuantifierCache = CacheBuilder.newBuilder().weakKeys().build(); + } + + private SymbolTables(@Nonnull final Map, Integer> classToIndexMap, + @Nonnull final Cache expressionCache, + @Nonnull final Cache invertedExpressionsCache, + @Nonnull final Cache referenceCache, + @Nonnull final Cache invertedReferenceCache, + @Nonnull final Cache quantifierCache, + @Nonnull final Cache invertedQuantifierCache) { + this.classToIndexMap = Maps.newHashMap(classToIndexMap); + this.expressionCache = expressionCache; + this.invertedExpressionsCache = invertedExpressionsCache; + this.referenceCache = referenceCache; + this.invertedReferenceCache = invertedReferenceCache; + this.quantifierCache = quantifierCache; + this.invertedQuantifierCache = invertedQuantifierCache; + } + + @Nonnull + private Map, Integer> getClassToIndexMap() { + return classToIndexMap; + } + + @Nonnull + public Cache getExpressionCache() { + return expressionCache; + } + + @Nonnull + public Cache getInvertedExpressionsCache() { + return invertedExpressionsCache; + } + + @Nonnull + public Cache getReferenceCache() { + return referenceCache; + } + + @Nonnull + public Cache getInvertedReferenceCache() { + return invertedReferenceCache; + } + + @Nonnull + public Cache getQuantifierCache() { + return quantifierCache; + } + + @Nonnull + public Cache getInvertedQuantifierCache() { + return invertedQuantifierCache; + } + + + public int getIndex(final Class clazz) { + return classToIndexMap.getOrDefault(clazz, 0); + } + + @CanIgnoreReturnValue + public int updateIndex(final Class clazz, IntUnaryOperator computeFn) { + return classToIndexMap.compute(clazz, (c, value) -> value == null ? computeFn.applyAsInt(0) : computeFn.applyAsInt(value)); + } + + public void registerExpression(final RelationalExpression expression) { + if (invertedExpressionsCache.getIfPresent(expression) == null) { + final int index = getIndex(RelationalExpression.class); + expressionCache.put(index, expression); + invertedExpressionsCache.put(expression, index); + updateIndex(RelationalExpression.class, i -> i + 1); + } + } + + public void registerReference(final Reference reference) { + if (invertedReferenceCache.getIfPresent(reference) == null) { + final int index = getIndex(Reference.class); + referenceCache.put(index, reference); + invertedReferenceCache.put(reference, index); + updateIndex(Reference.class, i -> i + 1); + } + } + + public void registerQuantifier(final Quantifier quantifier) { + if (invertedQuantifierCache.getIfPresent(quantifier) == null) { + final int index = getIndex(Quantifier.class); + quantifierCache.put(index, quantifier); + invertedQuantifierCache.put(quantifier, index); + updateIndex(Quantifier.class, i -> i + 1); + } + } + +} diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/explain/PlannerGraphVisitor.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/explain/PlannerGraphVisitor.java index 721fb3e424..df71082516 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/explain/PlannerGraphVisitor.java +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/explain/PlannerGraphVisitor.java @@ -26,7 +26,7 @@ import com.apple.foundationdb.record.query.plan.cascades.SimpleExpressionVisitor; import com.apple.foundationdb.record.query.plan.cascades.Traversal; import com.apple.foundationdb.record.query.plan.cascades.debug.BrowserHelper; -import com.apple.foundationdb.record.query.plan.cascades.debug.Debugger; +import com.apple.foundationdb.record.query.plan.cascades.debug.SymbolDebugger; import com.apple.foundationdb.record.query.plan.cascades.explain.GraphExporter.Cluster; import com.apple.foundationdb.record.query.plan.cascades.explain.GraphExporter.ComponentIdProvider; import com.apple.foundationdb.record.query.plan.cascades.explain.PlannerGraph.Edge; @@ -323,7 +323,7 @@ private static Collection> clustersForGroups(final Network { - final String label = Debugger.mapDebugger(debugger -> debugger.nameForObject(entry.getKey().getIdentity())) + final String label = SymbolDebugger.mapDebugger(debugger -> debugger.nameForObject(entry.getKey().getIdentity())) .orElse("group"); return new GroupCluster(label, entry.getValue()); }) @@ -509,7 +509,7 @@ public PlannerGraph evaluateAtRef(@Nonnull final Reference ref, @Nonnull List { final Node root = childGraph.getRoot(); final Optional debugNameOptional = - Debugger.mapDebugger(debugger -> { + SymbolDebugger.mapDebugger(debugger -> { if (root instanceof PlannerGraph.WithExpression) { final PlannerGraph.WithExpression withExpression = (PlannerGraph.WithExpression)root; @Nullable final RelationalExpression expression = withExpression.getExpression(); diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/rules/ImplementNestedLoopJoinRule.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/rules/ImplementNestedLoopJoinRule.java index 7d1e65a68e..053dcb621f 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/rules/ImplementNestedLoopJoinRule.java +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/rules/ImplementNestedLoopJoinRule.java @@ -29,6 +29,7 @@ import com.apple.foundationdb.record.query.plan.cascades.Reference; import com.apple.foundationdb.record.query.plan.cascades.RequestedOrderingConstraint; import com.apple.foundationdb.record.query.plan.cascades.debug.Debugger; +import com.apple.foundationdb.record.query.plan.cascades.debug.SymbolDebugger; import com.apple.foundationdb.record.query.plan.cascades.expressions.SelectExpression; import com.apple.foundationdb.record.query.plan.cascades.matching.structure.BindingMatcher; import com.apple.foundationdb.record.query.plan.cascades.predicates.QueryPredicate; @@ -111,7 +112,7 @@ public void onMatch(@Nonnull final ImplementationCascadesRuleCall call) { final var outerPartition = bindings.get(outerPlanPartitionsMatcher); final var innerPartition = bindings.get(innerPlanPartitionsMatcher); - final var joinName = Debugger.mapDebugger(debugger -> debugger.nameForObject(call.getRoot()) + "[" + debugger.nameForObject(selectExpression) + "]: " + outerQuantifier.getAlias() + " ⨝ " + innerQuantifier.getAlias()).orElse("not in debug mode"); + final var joinName = SymbolDebugger.mapDebugger(debugger -> debugger.nameForObject(call.getRoot()) + "[" + debugger.nameForObject(selectExpression) + "]: " + outerQuantifier.getAlias() + " ⨝ " + innerQuantifier.getAlias()).orElse("not in debug mode"); Debugger.withDebugger(debugger -> logger.debug(KeyValueLogMessage.of("attempting join", "joinedTables", joinName, "requestedOrderings", requestedOrderings))); final var fullCorrelationOrder = diff --git a/fdb-record-layer-debugger/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/Commands.java b/fdb-record-layer-debugger/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/Commands.java index 128eb8f900..5abe3864da 100644 --- a/fdb-record-layer-debugger/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/Commands.java +++ b/fdb-record-layer-debugger/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/Commands.java @@ -309,13 +309,13 @@ public static class CurrentCommand implements Command { public boolean executeCommand(@Nonnull final PlannerRepl plannerRepl, @Nonnull final Event event, @Nonnull final ParsedLine parsedLine) { - final State state = plannerRepl.getCurrentState(); - final List events = state.getEvents(); + final EventState eventState = plannerRepl.getCurrentState(); + final List events = eventState.getEvents(); if (events == null) { plannerRepl.printlnError("Configuration mandates to not record events. Please turn on event recording and restart."); return false; } - final Event e = events.get(state.getCurrentTick()); + final Event e = events.get(eventState.getCurrentTick()); plannerRepl.withProcessors(e, processor -> processor.onDetail(plannerRepl, e)); return false; } @@ -341,15 +341,15 @@ public static class EventsCommand implements Command { public boolean executeCommand(@Nonnull final PlannerRepl plannerRepl, @Nonnull final Event event, @Nonnull final ParsedLine parsedLine) { - final State state = plannerRepl.getCurrentState(); - final List events = state.getEvents(); + final EventState eventState = plannerRepl.getCurrentState(); + final List events = eventState.getEvents(); if (events == null) { plannerRepl.printlnError("Configuration mandates to not record events. Please turn on event recording and restart."); return false; } for (int tick = 0; tick < events.size(); tick++) { final Event e = events.get(tick); - if (state.getCurrentTick() == tick) { + if (eventState.getCurrentTick() == tick) { plannerRepl.printHighlighted("==> "); } else { plannerRepl.print(" "); @@ -382,7 +382,7 @@ public static class ExpsCommand implements Command { public boolean executeCommand(@Nonnull final PlannerRepl plannerRepl, @Nonnull final Event event, @Nonnull final ParsedLine parsedLine) { - final State state = plannerRepl.getCurrentState(); + final SymbolTables state = plannerRepl.getCurrentSymbolState(); final Cache expressionCache = state.getExpressionCache(); final List ids = Lists.newArrayList(expressionCache.asMap().keySet()); Collections.sort(ids); @@ -452,7 +452,7 @@ public static class RefsCommand implements Command { public boolean executeCommand(@Nonnull final PlannerRepl plannerRepl, @Nonnull final Event event, @Nonnull final ParsedLine parsedLine) { - final State state = plannerRepl.getCurrentState(); + final SymbolTables state = plannerRepl.getCurrentSymbolState(); final Cache referenceCache = state.getReferenceCache(); final List ids = Lists.newArrayList(referenceCache.asMap().keySet()); Collections.sort(ids); @@ -724,7 +724,7 @@ public static class QunsCommand implements Command { public boolean executeCommand(@Nonnull final PlannerRepl plannerRepl, @Nonnull final Event event, @Nonnull final ParsedLine parsedLine) { - final State state = plannerRepl.getCurrentState(); + final SymbolTables state = plannerRepl.getCurrentSymbolState(); final List ids = Lists.newArrayList(state.getQuantifierCache().asMap().keySet()); Collections.sort(ids); for (Integer id : ids) { diff --git a/fdb-record-layer-debugger/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/PlannerRepl.java b/fdb-record-layer-debugger/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/PlannerRepl.java index 2d52da7453..6df35a0fb7 100644 --- a/fdb-record-layer-debugger/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/PlannerRepl.java +++ b/fdb-record-layer-debugger/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/PlannerRepl.java @@ -69,7 +69,7 @@ /** * Implementation of a debugger as a repl. */ -public class PlannerRepl implements Debugger { +public class PlannerRepl implements StatsDebugger, SymbolDebugger { private static final Logger logger = LoggerFactory.getLogger(PlannerRepl.class); private static final String banner = @@ -92,7 +92,8 @@ public class PlannerRepl implements Debugger { processorsMap = loadProcessors(); } - private final Deque stateStack; + private final Deque eventStateStack; + private final Deque symbolTablesStack; private final BiMap breakPoints; private int currentBreakPointIndex; @@ -117,7 +118,8 @@ public PlannerRepl(@Nonnull final Terminal terminal) { } public PlannerRepl(@Nonnull final Terminal terminal, boolean exitOnQuit) { - this.stateStack = new ArrayDeque<>(); + this.eventStateStack = new ArrayDeque<>(); + this.symbolTablesStack = new ArrayDeque<>(); this.breakPoints = HashBiMap.create(); this.currentBreakPointIndex = 0; this.currentInternalBreakPointIndex = -1; @@ -133,10 +135,15 @@ boolean shouldExitOnQuit() { } @Nonnull - State getCurrentState() { - return Objects.requireNonNull(stateStack.peek()); + SymbolTables getCurrentSymbolState() { + return Objects.requireNonNull(symbolTablesStack.peek()); } + EventState getCurrentState() { + return Objects.requireNonNull(eventStateStack.peek()); + } + + @Nullable @Override public PlanContext getPlanContext() { @@ -151,27 +158,27 @@ public boolean isSane() { @Override public int onGetIndex(@Nonnull final Class clazz) { - return getCurrentState().getIndex(clazz); + return getCurrentSymbolState().getIndex(clazz); } @Override public int onUpdateIndex(@Nonnull final Class clazz, @Nonnull final IntUnaryOperator updateFn) { - return getCurrentState().updateIndex(clazz, updateFn); + return getCurrentSymbolState().updateIndex(clazz, updateFn); } @Override public void onRegisterExpression(@Nonnull final RelationalExpression expression) { - getCurrentState().registerExpression(expression); + getCurrentSymbolState().registerExpression(expression); } @Override public void onRegisterReference(@Nonnull final Reference reference) { - getCurrentState().registerReference(reference); + getCurrentSymbolState().registerReference(reference); } @Override public void onRegisterQuantifier(@Nonnull final Quantifier quantifier) { - getCurrentState().registerQuantifier(quantifier); + getCurrentSymbolState().registerQuantifier(quantifier); } @Override @@ -203,7 +210,9 @@ public void onShow(@Nonnull final Reference ref) { @Override public void onQuery(@Nonnull final String queryAsString, @Nonnull final PlanContext planContext) { - this.stateStack.push(State.copyOf(getCurrentState())); + this.eventStateStack.push(EventState.copyOf(getCurrentState())); + this.symbolTablesStack.push(SymbolTables.copyOf(getCurrentSymbolState())); + this.queryAsString = queryAsString; this.planContext = planContext; @@ -214,8 +223,11 @@ public void onQuery(@Nonnull final String queryAsString, @Nonnull final PlanCont } void restartState() { - stateStack.pop(); - stateStack.push(State.copyOf(getCurrentState())); + eventStateStack.pop(); + eventStateStack.push(EventState.copyOf(getCurrentState())); + + symbolTablesStack.pop(); + symbolTablesStack.push(SymbolTables.copyOf(getCurrentSymbolState())); } void addBreakPoint(final BreakPoint breakPoint) { @@ -255,9 +267,9 @@ public void onEvent(final Event event) { Objects.requireNonNull(queryAsString); Objects.requireNonNull(planContext); - final State state = getCurrentState(); + final EventState eventState = getCurrentState(); - state.addCurrentEvent(event); + eventState.addCurrentEvent(event); final Set satisfiedBreakPoints = computeSatisfiedBreakPoints(event); satisfiedBreakPoints.forEach(breakPoint -> breakPoint.onBreak(this)); @@ -265,7 +277,7 @@ public void onEvent(final Event event) { final boolean stop = !satisfiedBreakPoints.isEmpty(); if (stop) { printKeyValue("paused in", Thread.currentThread().getName() + " at "); - printlnKeyValue("tick", String.valueOf(state.getCurrentTick())); + printlnKeyValue("tick", String.valueOf(eventState.getCurrentTick())); withProcessors(event, processor -> processor.onCallback(this, event)); println(); @@ -332,7 +344,7 @@ boolean processIdentifiers(final String potentialIdentifier, final Consumer expressionConsumer, final Consumer referenceConsumer, final Consumer quantifierConsumer) { - final State state = getCurrentState(); + final SymbolTables state = getCurrentSymbolState(); final String upperCasePotentialIdentifier = potentialIdentifier.toUpperCase(Locale.ROOT); if (upperCasePotentialIdentifier.startsWith("EXP")) { @Nullable final RelationalExpression expression = lookupInCache(state.getExpressionCache(), upperCasePotentialIdentifier, "EXP"); @@ -399,7 +411,7 @@ boolean isValidEntityName(@Nonnull final String identifier) { @Nullable @Override public String nameForObject(@Nonnull final Object object) { - final State state = getCurrentState(); + final SymbolTables state = getCurrentSymbolState(); if (object instanceof RelationalExpression) { @Nullable final Integer id = state.getInvertedExpressionsCache().getIfPresent(object); return (id == null) ? null : "exp" + id; @@ -453,28 +465,21 @@ public void onDone() { reset(); } - @Override - public String showStats() { - State currentState = stateStack.peek(); - if (currentState != null) { - return currentState.showStats(); - } - return "no stats"; - } - @Nonnull @Override public Optional getStatsMaps() { - State currentState = stateStack.peek(); - if (currentState != null) { - return Optional.of(currentState.getStatsMaps()); + EventState currentEventState = eventStateStack.peek(); + if (currentEventState != null) { + return Optional.of(currentEventState.getStatsMaps()); } return Optional.empty(); } private void reset() { - this.stateStack.clear(); - this.stateStack.push(State.initial(true, true, null)); + this.eventStateStack.clear(); + this.eventStateStack.push(EventState.initial(true, true, null)); + this.symbolTablesStack.clear(); + this.symbolTablesStack.push(new SymbolTables()); this.breakPoints.clear(); this.currentBreakPointIndex = 0; this.currentInternalBreakPointIndex = -1; From bdf2e166bf05b9141edbcf72811afd3df9cd4fbd Mon Sep 17 00:00:00 2001 From: Hazem Zaghloul Date: Thu, 7 Aug 2025 17:36:41 +0100 Subject: [PATCH 4/9] Extract showing Debugger stats in the browser to a separate class --- .../query/plan/cascades/debug/EventState.java | 82 ------------ .../plan/cascades/debug/StatsViewer.java | 121 ++++++++++++++++++ 2 files changed, 121 insertions(+), 82 deletions(-) create mode 100644 fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/StatsViewer.java diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/EventState.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/EventState.java index 67af117caa..94cd18e6f9 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/EventState.java +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/EventState.java @@ -252,88 +252,6 @@ StatsMaps getStatsMaps() { return new StatsMaps(eventClassStatsMap, plannerRuleClassStatsMap); } - public String showStats() { - StringBuilder tableBuilder = new StringBuilder(); - tableBuilder.append(""); - tableHeader(tableBuilder, "Event"); - final ImmutableMap eventStatsMap = - eventClassStatsMap.entrySet() - .stream() - .map(entry -> Pair.of(entry.getKey().getSimpleName(), entry.getValue())) - .sorted(Map.Entry.comparingByKey()) - .collect(ImmutableMap.toImmutableMap(Pair::getKey, Pair::getValue)); - tableBody(tableBuilder, eventStatsMap); - tableBuilder.append("
"); - - final String eventProfilingString = tableBuilder.toString(); - - tableBuilder = new StringBuilder(); - tableBuilder.append(""); - tableHeader(tableBuilder, "Planner Rule"); - final ImmutableMap plannerRuleStatsMap = - plannerRuleClassStatsMap.entrySet() - .stream() - .map(entry -> Pair.of(entry.getKey().getSimpleName(), entry.getValue())) - .sorted(Map.Entry.comparingByKey()) - .collect(ImmutableMap.toImmutableMap(Pair::getKey, Pair::getValue)); - tableBody(tableBuilder, plannerRuleStatsMap); - tableBuilder.append("
"); - - final String plannerRuleProfilingString = tableBuilder.toString(); - - return BrowserHelper.browse("/showProfilingReport.html", - ImmutableMap.of("$EVENT_PROFILING", eventProfilingString, - "$PLANNER_RULE_PROFILING", plannerRuleProfilingString)); - } - - private void tableHeader(@Nonnull final StringBuilder stringBuilder, @Nonnull final String category) { - stringBuilder.append(""); - stringBuilder.append(""); - stringBuilder.append("").append(category).append(""); - stringBuilder.append("Location"); - stringBuilder.append("Count"); - stringBuilder.append("Total Time (micros)"); - stringBuilder.append("Average Time (micros)"); - stringBuilder.append("Total Own Time (micros)"); - stringBuilder.append("Average Own Time (micros)"); - stringBuilder.append(""); - stringBuilder.append(""); - } - - private void tableBody(@Nonnull final StringBuilder stringBuilder, @Nonnull final Map statsMap) { - stringBuilder.append(""); - for (final Map.Entry entry : statsMap.entrySet()) { - final MutableStats mutableStats = entry.getValue(); - for (final var locationEntry : mutableStats.getLocationCountMap().entrySet()) { - stringBuilder.append(""); - stringBuilder.append("").append(entry.getKey()).append(""); - if (locationEntry.getKey() == Debugger.Location.BEGIN) { - stringBuilder.append(""); - } else { - stringBuilder.append("").append(locationEntry.getKey().name()).append(""); - } - stringBuilder.append("").append(locationEntry.getValue()).append(""); - if (locationEntry.getKey() == Debugger.Location.BEGIN) { - stringBuilder.append("").append(formatNsInMicros(mutableStats.getTotalTimeInNs())).append(""); - stringBuilder.append("").append(formatNsInMicros(mutableStats.getTotalTimeInNs() / mutableStats.getCount(Debugger.Location.BEGIN))).append(""); - stringBuilder.append("").append(formatNsInMicros(mutableStats.getOwnTimeInNs())).append(""); - stringBuilder.append("").append(formatNsInMicros(mutableStats.getOwnTimeInNs() / mutableStats.getCount(Debugger.Location.BEGIN))).append(""); - } else { - stringBuilder.append(""); - stringBuilder.append(""); - } - stringBuilder.append(""); - } - } - stringBuilder.append(""); - } - - @Nonnull - private String formatNsInMicros(final long ns) { - final long micros = TimeUnit.NANOSECONDS.toMicros(ns); - return String.format(Locale.ROOT, "%,d", micros); - } - private static class MutableStats extends Stats { public MutableStats() { super(Maps.newLinkedHashMap(), 0L, 0L); diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/StatsViewer.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/StatsViewer.java new file mode 100644 index 0000000000..3c6ad206fe --- /dev/null +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/StatsViewer.java @@ -0,0 +1,121 @@ +/* + * StatsViewer.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.debug; + +import com.apple.foundationdb.record.util.pair.Pair; +import com.google.common.collect.ImmutableMap; + +import javax.annotation.Nonnull; +import java.util.Locale; +import java.util.Map; +import java.util.concurrent.TimeUnit; + +/** Only used by debuggers to display stats.*/ +@SuppressWarnings("unused") +public class StatsViewer { + public static String showStats(@Nonnull final StatsDebugger statsDebugger) { + final var statsMaps = statsDebugger.getStatsMaps(); + + if (statsMaps.isEmpty()) { + return "no stats available"; + } + + StringBuilder tableBuilder = new StringBuilder(); + tableBuilder.append(""); + tableHeader(tableBuilder, "Event"); + final ImmutableMap eventStatsMap = + statsMaps.get().getEventClassStatsMap().entrySet() + .stream() + .map(entry -> Pair.of(entry.getKey().getSimpleName(), entry.getValue())) + .sorted(Map.Entry.comparingByKey()) + .collect(ImmutableMap.toImmutableMap(Pair::getKey, Pair::getValue)); + tableBody(tableBuilder, eventStatsMap); + tableBuilder.append("
"); + + final String eventProfilingString = tableBuilder.toString(); + + tableBuilder = new StringBuilder(); + tableBuilder.append(""); + tableHeader(tableBuilder, "Planner Rule"); + final ImmutableMap plannerRuleStatsMap = + statsMaps.get().getPlannerRuleClassStatsMap().entrySet() + .stream() + .map(entry -> Pair.of(entry.getKey().getSimpleName(), entry.getValue())) + .sorted(Map.Entry.comparingByKey()) + .collect(ImmutableMap.toImmutableMap(Pair::getKey, Pair::getValue)); + tableBody(tableBuilder, plannerRuleStatsMap); + tableBuilder.append("
"); + + final String plannerRuleProfilingString = tableBuilder.toString(); + + return BrowserHelper.browse("/showProfilingReport.html", + ImmutableMap.of("$EVENT_PROFILING", eventProfilingString, + "$PLANNER_RULE_PROFILING", plannerRuleProfilingString)); + } + + private static void tableHeader(@Nonnull final StringBuilder stringBuilder, @Nonnull final String category) { + stringBuilder.append(""); + stringBuilder.append(""); + stringBuilder.append("").append(category).append(""); + stringBuilder.append("Location"); + stringBuilder.append("Count"); + stringBuilder.append("Total Time (micros)"); + stringBuilder.append("Average Time (micros)"); + stringBuilder.append("Total Own Time (micros)"); + stringBuilder.append("Average Own Time (micros)"); + stringBuilder.append(""); + stringBuilder.append(""); + } + + private static void tableBody(@Nonnull final StringBuilder stringBuilder, @Nonnull final Map statsMap) { + stringBuilder.append(""); + for (final Map.Entry entry : statsMap.entrySet()) { + final Stats stats = entry.getValue(); + for (final var locationEntry : stats.getLocationCountMap().entrySet()) { + stringBuilder.append(""); + stringBuilder.append("").append(entry.getKey()).append(""); + if (locationEntry.getKey() == Debugger.Location.BEGIN) { + stringBuilder.append(""); + } else { + stringBuilder.append("").append(locationEntry.getKey().name()).append(""); + } + stringBuilder.append("").append(locationEntry.getValue()).append(""); + if (locationEntry.getKey() == Debugger.Location.BEGIN) { + stringBuilder.append("").append(formatNsInMicros(stats.getTotalTimeInNs())).append(""); + stringBuilder.append("").append(formatNsInMicros(stats.getTotalTimeInNs() / stats.getCount(Debugger.Location.BEGIN))).append(""); + stringBuilder.append("").append(formatNsInMicros(stats.getOwnTimeInNs())).append(""); + stringBuilder.append("").append(formatNsInMicros(stats.getOwnTimeInNs() / stats.getCount(Debugger.Location.BEGIN))).append(""); + } else { + stringBuilder.append(""); + stringBuilder.append(""); + } + stringBuilder.append(""); + } + } + stringBuilder.append(""); + } + + @Nonnull + private static String formatNsInMicros(final long ns) { + final long micros = TimeUnit.NANOSECONDS.toMicros(ns); + return String.format(Locale.ROOT, "%,d", micros); + } +} From cf9848b04f555dd5ec9366d31fed3d19f80aa291 Mon Sep 17 00:00:00 2001 From: Hazem Zaghloul Date: Thu, 7 Aug 2025 17:40:57 +0100 Subject: [PATCH 5/9] Group Debugger events by PlannerPhase in stats This commit modifies the EventState class and the StatsMaps that it produces to group Debugger events by the planner phase it was emitted during to enable the ability of getting stats for each planner phase separately. Given that some Debugger events (e.g. InsertIntoMemoEvent) do not store the planner phase they were emitted in (as it not visible to the code that emits them), these events are stored separately and can be retrieved from the StatsMaps (in addition to the ability of retrieving all events, regardless of the planner phase that they were emitted in). --- .../query/plan/cascades/debug/EventState.java | 72 +++++++++++------- .../query/plan/cascades/debug/Stats.java | 12 +++ .../query/plan/cascades/debug/StatsMaps.java | 75 +++++++++++++++++-- .../plan/cascades/debug/StatsViewer.java | 38 +++++++--- 4 files changed, 153 insertions(+), 44 deletions(-) diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/EventState.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/EventState.java index 94cd18e6f9..d75ccf8730 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/EventState.java +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/EventState.java @@ -23,10 +23,10 @@ import com.apple.foundationdb.record.RecordCoreException; import com.apple.foundationdb.record.logging.KeyValueLogMessage; import com.apple.foundationdb.record.query.plan.cascades.CascadesRule; +import com.apple.foundationdb.record.query.plan.cascades.PlannerPhase; import com.apple.foundationdb.record.query.plan.cascades.debug.eventprotos.PEvent; import com.apple.foundationdb.record.util.pair.Pair; import com.google.common.base.Verify; -import com.google.common.collect.ImmutableMap; import com.google.common.collect.Lists; import com.google.common.collect.Maps; import org.slf4j.Logger; @@ -35,29 +35,30 @@ import javax.annotation.Nonnull; import javax.annotation.Nullable; import java.util.ArrayDeque; +import java.util.Collections; import java.util.Deque; import java.util.Iterator; +import java.util.LinkedHashMap; import java.util.List; -import java.util.Locale; import java.util.Map; import java.util.Objects; -import java.util.concurrent.TimeUnit; @SuppressWarnings("PMD.SystemPrintln") public class EventState { @Nonnull private static final Logger logger = LoggerFactory.getLogger(EventState.class); - @Nullable private final List events; - @Nullable private final List eventProtos; - @Nullable private final Iterable prerecordedEventProtoIterable; - @Nullable private Iterator prerecordedEventProtoIterator; + @Nullable protected final List events; + @Nullable protected final List eventProtos; + @Nullable protected final Iterable prerecordedEventProtoIterable; + @Nullable protected Iterator prerecordedEventProtoIterator; - @Nonnull private final Map, MutableStats> eventClassStatsMap; + @Nonnull protected final Map, MutableStats> eventWithoutStateClassStatsMap; + @Nonnull protected final Map, MutableStats>> eventWithStateClassStatsMapByPlannerPhase; - @Nonnull private final Map>, MutableStats> plannerRuleClassStatsMap; + @Nonnull protected final Map>, MutableStats> plannerRuleClassStatsMap; - @Nonnull private final Deque, EventDurations>> eventProfilingStack; + @Nonnull protected final Deque, EventDurations>> eventProfilingStack; protected int currentTick; protected final long startTs; @@ -72,7 +73,8 @@ public static EventState copyOf(final EventState source) { source.events == null ? null : Lists.newArrayList(source.events), source.eventProtos == null ? null : Lists.newArrayList(source.eventProtos), source.prerecordedEventProtoIterable, - Maps.newLinkedHashMap(source.eventClassStatsMap), + Maps.newLinkedHashMap(source.eventWithoutStateClassStatsMap), + Maps.newEnumMap(source.eventWithStateClassStatsMapByPlannerPhase), Maps.newLinkedHashMap(source.plannerRuleClassStatsMap), new ArrayDeque<>(source.eventProfilingStack), source.getCurrentTick(), @@ -86,6 +88,7 @@ protected EventState(final boolean isRecordEvents, final boolean isRecordEventPr isRecordEvents ? Lists.newArrayList() : null, prerecordedEventProtoIterable, Maps.newLinkedHashMap(), + Maps.newEnumMap(PlannerPhase.class), Maps.newLinkedHashMap(), new ArrayDeque<>(), -1, @@ -93,21 +96,23 @@ protected EventState(final boolean isRecordEvents, final boolean isRecordEventPr } protected EventState( - @Nullable final List events, - @Nullable final List eventProtos, - @Nullable final Iterable prerecordedEventProtoIterable, - @Nonnull final Map, MutableStats> eventClassStatsMap, - @Nonnull final Map>, MutableStats> plannerRuleClassStatsMap, - @Nonnull final Deque, EventDurations>> eventProfilingStack, - final int currentTick, - final long startTs) { + @Nullable final List events, + @Nullable final List eventProtos, + @Nullable final Iterable prerecordedEventProtoIterable, + @Nonnull final Map, MutableStats> eventWithoutStateClassStatsMap, + @Nonnull final Map, MutableStats>> eventWithStateClassStatsMapByPlannerPhase, + @Nonnull final Map>, MutableStats> plannerRuleClassStatsMap, + @Nonnull final Deque, EventDurations>> eventProfilingStack, + final int currentTick, + final long startTs) { this.events = events; this.eventProtos = eventProtos; this.prerecordedEventProtoIterable = prerecordedEventProtoIterable; this.prerecordedEventProtoIterator = prerecordedEventProtoIterable == null ? null : prerecordedEventProtoIterable.iterator(); - this.eventClassStatsMap = eventClassStatsMap; + this.eventWithoutStateClassStatsMap = eventWithoutStateClassStatsMap; + this.eventWithStateClassStatsMapByPlannerPhase = eventWithStateClassStatsMapByPlannerPhase; this.plannerRuleClassStatsMap = plannerRuleClassStatsMap; this.eventProfilingStack = eventProfilingStack; this.currentTick = currentTick; @@ -179,7 +184,7 @@ public void addCurrentEvent(@Nonnull final Debugger.Event event) { final long totalTime = currentTsInNs - eventDurations.getStartTsInNs(); final long ownTime = totalTime - eventDurations.getAdjustmentForOwnTimeInNs(); - final MutableStats forEventClass = getEventStatsForEventClass(currentEventClass); + final MutableStats forEventClass = getEventStatsForEvent(event); forEventClass.increaseTotalTimeInNs(totalTime); forEventClass.increaseOwnTimeInNs(ownTime); if (event instanceof Debugger.TransformRuleCallEvent) { @@ -229,8 +234,9 @@ private void verifyCurrentEventProto(final PEvent currentEventProto) { @SuppressWarnings("unchecked") private void updateCounts(@Nonnull final Debugger.Event event) { - final MutableStats forEventClass = getEventStatsForEventClass(event.getClass()); + final MutableStats forEventClass = getEventStatsForEvent(event); forEventClass.increaseCount(event.getLocation(), 1L); + if (event instanceof Debugger.EventWithRule) { final CascadesRule rule = ((Debugger.EventWithRule)event).getRule(); final Class> ruleClass = (Class>)rule.getClass(); @@ -239,17 +245,31 @@ private void updateCounts(@Nonnull final Debugger.Event event) { } } - private MutableStats getEventStatsForEventClass(@Nonnull Class eventClass) { - return eventClassStatsMap.compute(eventClass, (eC, mutableStats) -> mutableStats != null ? mutableStats : new MutableStats()); + private MutableStats getEventStatsForEvent(@Nonnull Debugger.Event event) { + return (event instanceof Debugger.EventWithState) ? + getEventStatsForEventWithStateClassByPlannerPhase((Debugger.EventWithState)event) : + getEventStatsForEventWithoutStateClass(event.getClass()); + } + + private MutableStats getEventStatsForEventWithoutStateClass(@Nonnull Class eventClass) { + return eventWithoutStateClassStatsMap.compute(eventClass, (eC, mutableStats) -> mutableStats != null ? mutableStats : new MutableStats()); + } + + private MutableStats getEventStatsForEventWithStateClassByPlannerPhase(@Nonnull Debugger.EventWithState event) { + return eventWithStateClassStatsMapByPlannerPhase.computeIfAbsent(event.getPlannerPhase(), pP -> new LinkedHashMap<>()) + .computeIfAbsent(event.getClass(), (eC) -> new MutableStats()); } private MutableStats getEventStatsForPlannerRuleClass(@Nonnull Class> plannerRuleClass) { - return plannerRuleClassStatsMap.compute(plannerRuleClass, (eC, mutableStats) -> mutableStats != null ? mutableStats : new MutableStats()); + return plannerRuleClassStatsMap.computeIfAbsent(plannerRuleClass, (eC) -> new MutableStats()); } @Nonnull StatsMaps getStatsMaps() { - return new StatsMaps(eventClassStatsMap, plannerRuleClassStatsMap); + return new StatsMaps( + Collections.unmodifiableMap(eventWithoutStateClassStatsMap), + Collections.unmodifiableMap(eventWithStateClassStatsMapByPlannerPhase), + Collections.unmodifiableMap(plannerRuleClassStatsMap)); } private static class MutableStats extends Stats { diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/Stats.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/Stats.java index 43e7f8a44d..62cd044502 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/Stats.java +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/Stats.java @@ -24,6 +24,8 @@ import javax.annotation.Nonnull; import java.util.Map; +import java.util.Set; +import java.util.stream.Stream; public class Stats { @Nonnull @@ -61,4 +63,14 @@ public long getOwnTimeInNs() { public Stats toImmutable() { return new Stats(ImmutableMap.copyOf(locationCountMap), totalTimeInNs, ownTimeInNs); } + + public static Stats merge(final Stats first, final Stats second) { + return new Stats( + Stream.of(first.getLocationCountMap(), second.getLocationCountMap()) + .map(Map::entrySet) + .flatMap(Set::stream) + .collect(ImmutableMap.toImmutableMap(Map.Entry::getKey, Map.Entry::getValue, Long::sum)), + first.getTotalTimeInNs() + second.getTotalTimeInNs(), + first.getOwnTimeInNs() + second.getOwnTimeInNs()); + } } diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/StatsMaps.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/StatsMaps.java index 3ccae3ad15..84d112b6d2 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/StatsMaps.java +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/StatsMaps.java @@ -21,29 +21,45 @@ package com.apple.foundationdb.record.query.plan.cascades.debug; import com.apple.foundationdb.record.query.plan.cascades.CascadesRule; +import com.apple.foundationdb.record.query.plan.cascades.PlannerPhase; import com.google.common.base.Suppliers; import com.google.common.collect.ImmutableMap; import javax.annotation.Nonnull; +import java.util.LinkedHashMap; import java.util.Map; +import java.util.Optional; import java.util.function.Supplier; public class StatsMaps { @Nonnull - private final Map, ? extends Stats> eventClassStatsMap; + private final Map, ? extends Stats> eventWithoutStateClassStatsMap; + @Nonnull + private final Map, ? extends Stats>> eventWithStateClassStatsByPlannerPhaseMap; @Nonnull private final Map>, ? extends Stats> plannerRuleClassStatsMap; @Nonnull private final Supplier, Stats>> immutableEventClassStatsMapSupplier; @Nonnull + private final Supplier, Stats>> immutableEventWithoutStateClassStatsMapSupplier; + @Nonnull + private final Supplier, Stats>>> immutableEventWithStateClassStatsByPlannerPhaseMapSupplier; + @Nonnull private final Supplier>, Stats>> immutablePlannerRuleClassStatsMapSupplier; - public StatsMaps(@Nonnull final Map, ? extends Stats> eventClassStatsMap, + + public StatsMaps(@Nonnull final Map, ? extends Stats> eventWithoutStateClassStatsMap, + @Nonnull final Map, ? extends Stats>> eventWithStateClassStatsByPlannerPhaseMap, @Nonnull final Map>, ? extends Stats> plannerRuleClassStatsMap) { - this.eventClassStatsMap = eventClassStatsMap; + + this.eventWithoutStateClassStatsMap = eventWithoutStateClassStatsMap; + this.eventWithStateClassStatsByPlannerPhaseMap = eventWithStateClassStatsByPlannerPhaseMap; this.plannerRuleClassStatsMap = plannerRuleClassStatsMap; + this.immutableEventClassStatsMapSupplier = Suppliers.memoize(this::computeImmutableEventClassStatsMap); + this.immutableEventWithoutStateClassStatsMapSupplier = Suppliers.memoize(this::computeImmutableEventWithoutStateClassStatsMap); + this.immutableEventWithStateClassStatsByPlannerPhaseMapSupplier = Suppliers.memoize(this::computeImmutableEventWithStateClassStatsByPlannerPhaseMap); this.immutablePlannerRuleClassStatsMapSupplier = Suppliers.memoize(this::computeImmutablePlannerRuleClassStatsMap); } @@ -58,13 +74,56 @@ public Map>, Stats> getPlannerRuleClassStatsMap( } @Nonnull - private Map, Stats> computeImmutableEventClassStatsMap() { - final var eventClassStatsMapBuilder = + public Map, Stats> getEventWithoutStateClassStatsMap() { + return immutableEventClassStatsMapSupplier.get(); + } + + @Nonnull + public Optional, Stats>> getEventWithStateClassStatsMapByPlannerPhase(@Nonnull PlannerPhase plannerPhase) { + return Optional.ofNullable(immutableEventWithStateClassStatsByPlannerPhaseMapSupplier.get().get(plannerPhase)); + } + + private Map, Stats> computeImmutableEventWithoutStateClassStatsMap() { + final var eventWithoutStateClassStatsMapBuilder = ImmutableMap., Stats>builder(); - for (final var entry : eventClassStatsMap.entrySet()) { - eventClassStatsMapBuilder.put(entry.getKey(), entry.getValue().toImmutable()); + + eventWithoutStateClassStatsMap.forEach( + (eventClass, stats) -> eventWithoutStateClassStatsMapBuilder.put(eventClass, stats.toImmutable()) + ); + + return eventWithoutStateClassStatsMapBuilder.build(); + } + + @Nonnull + private Map, Stats> computeImmutableEventClassStatsMap() { + // Add all events not tied to a specific planner phase first + Map, Stats> result = new LinkedHashMap<>(this.immutableEventWithoutStateClassStatsMapSupplier.get()); + + // Merge the stats all events tied to a specific planner phase with other events + for (final var eventWithStateClassStats : eventWithStateClassStatsByPlannerPhaseMap.values()) { + for (final var eventWithStateClassStatsEntry : eventWithStateClassStats.entrySet()) { + result.merge( + eventWithStateClassStatsEntry.getKey(), + eventWithStateClassStatsEntry.getValue().toImmutable(), + (s1, s2) -> Stats.merge(s1, s2).toImmutable()); + } + } + + return ImmutableMap.copyOf(result); + } + + @Nonnull + private Map, Stats>> computeImmutableEventWithStateClassStatsByPlannerPhaseMap() { + final var eventClassStatsByPlannerPhaseMapBuilder = + ImmutableMap., Stats>>builder(); + for (final var eventClassStatsByPlannerPhaseEntry : eventWithStateClassStatsByPlannerPhaseMap.entrySet()) { + final Map, Stats> eventClassImmutableStats = + eventClassStatsByPlannerPhaseEntry.getValue().entrySet().stream().collect( + ImmutableMap.toImmutableMap(Map.Entry::getKey, e -> e.getValue().toImmutable()) + ); + eventClassStatsByPlannerPhaseMapBuilder.put(eventClassStatsByPlannerPhaseEntry.getKey(), eventClassImmutableStats); } - return eventClassStatsMapBuilder.build(); + return eventClassStatsByPlannerPhaseMapBuilder.build(); } @Nonnull diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/StatsViewer.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/StatsViewer.java index 3c6ad206fe..120f98590f 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/StatsViewer.java +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/StatsViewer.java @@ -20,12 +20,14 @@ package com.apple.foundationdb.record.query.plan.cascades.debug; +import com.apple.foundationdb.record.query.plan.cascades.PlannerPhase; import com.apple.foundationdb.record.util.pair.Pair; import com.google.common.collect.ImmutableMap; import javax.annotation.Nonnull; import java.util.Locale; import java.util.Map; +import java.util.Optional; import java.util.concurrent.TimeUnit; /** Only used by debuggers to display stats.*/ @@ -39,16 +41,32 @@ public static String showStats(@Nonnull final StatsDebugger statsDebugger) { } StringBuilder tableBuilder = new StringBuilder(); - tableBuilder.append(""); - tableHeader(tableBuilder, "Event"); - final ImmutableMap eventStatsMap = - statsMaps.get().getEventClassStatsMap().entrySet() - .stream() - .map(entry -> Pair.of(entry.getKey().getSimpleName(), entry.getValue())) - .sorted(Map.Entry.comparingByKey()) - .collect(ImmutableMap.toImmutableMap(Pair::getKey, Pair::getValue)); - tableBody(tableBuilder, eventStatsMap); - tableBuilder.append("
"); + + final var phaseNameToStatsMap = ImmutableMap.of( + "Rewriting", statsMaps.get().getEventWithStateClassStatsMapByPlannerPhase(PlannerPhase.REWRITING), + "Planning", statsMaps.get().getEventWithStateClassStatsMapByPlannerPhase(PlannerPhase.PLANNING), + "Unspecified", Optional.of(statsMaps.get().getEventWithoutStateClassStatsMap()) + ); + + for (final var phaseNameToStatsMapEntry : phaseNameToStatsMap.entrySet()) { + if (phaseNameToStatsMapEntry.getValue().map(Map::isEmpty).orElse(false)) { + continue; + } + + tableBuilder.append("

").append(phaseNameToStatsMapEntry.getKey()).append(" Phase:

"); + tableBuilder.append(""); + tableHeader(tableBuilder, "Event"); + + final ImmutableMap eventStatsMap = + phaseNameToStatsMapEntry.getValue().get().entrySet() + .stream() + .map(entry -> Pair.of(entry.getKey().getSimpleName(), entry.getValue())) + .sorted(Map.Entry.comparingByKey()) + .collect(ImmutableMap.toImmutableMap(Pair::getKey, Pair::getValue)); + + tableBody(tableBuilder, eventStatsMap); + tableBuilder.append("
"); + } final String eventProfilingString = tableBuilder.toString(); From a9edd0f36ff40c1ca5d472a5d9f61b79d143d401 Mon Sep 17 00:00:00 2001 From: Hazem Zaghloul Date: Thu, 7 Aug 2025 17:52:42 +0100 Subject: [PATCH 6/9] Include planner phase specifc metrics in EXPLAIN result --- .../query/FDBRecordStoreQueryTestBase.java | 23 +++++++++- .../recordlayer/query/QueryPlan.java | 44 +++++++++++++------ .../recordlayer/query/ExplainTests.java | 23 +++++++++- 3 files changed, 73 insertions(+), 17 deletions(-) diff --git a/fdb-record-layer-core/src/test/java/com/apple/foundationdb/record/provider/foundationdb/query/FDBRecordStoreQueryTestBase.java b/fdb-record-layer-core/src/test/java/com/apple/foundationdb/record/provider/foundationdb/query/FDBRecordStoreQueryTestBase.java index 60dc3336c3..16b8efe8c5 100644 --- a/fdb-record-layer-core/src/test/java/com/apple/foundationdb/record/provider/foundationdb/query/FDBRecordStoreQueryTestBase.java +++ b/fdb-record-layer-core/src/test/java/com/apple/foundationdb/record/provider/foundationdb/query/FDBRecordStoreQueryTestBase.java @@ -57,6 +57,7 @@ import com.apple.foundationdb.record.query.plan.RecordQueryPlanner; import com.apple.foundationdb.record.query.plan.cascades.CascadesPlanner; import com.apple.foundationdb.record.query.plan.cascades.CorrelationIdentifier; +import com.apple.foundationdb.record.query.plan.cascades.PlannerPhase; import com.apple.foundationdb.record.query.plan.cascades.Reference; import com.apple.foundationdb.record.query.plan.cascades.debug.Debugger; import com.apple.foundationdb.record.query.plan.cascades.matching.structure.BindingMatcher; @@ -101,6 +102,7 @@ import static org.hamcrest.Matchers.greaterThanOrEqualTo; import static org.hamcrest.Matchers.instanceOf; import static org.hamcrest.Matchers.lessThanOrEqualTo; +import static org.junit.jupiter.api.Assertions.assertEquals; import static org.junit.jupiter.api.Assertions.assertNotNull; import static org.junit.jupiter.api.Assertions.assertTrue; import static org.junit.jupiter.api.Assertions.fail; @@ -664,7 +666,24 @@ protected RecordQueryPlan planGraph(@Nonnull Supplier querySupplier, assertNotNull(statsMaps); final var eventClassStatsMap = statsMaps.getEventClassStatsMap(); assertTrue(eventClassStatsMap.containsKey(Debugger.ExecutingTaskEvent.class)); - assertTrue(eventClassStatsMap.get(Debugger.ExecutingTaskEvent.class).getCount(Debugger.Location.BEGIN) > 0); + + final var eventClassStatsMapForRewriting = statsMaps.getEventWithStateClassStatsMapByPlannerPhase(PlannerPhase.REWRITING); + assertTrue(eventClassStatsMapForRewriting.isPresent()); + assertTrue(eventClassStatsMapForRewriting.get().containsKey(Debugger.ExecutingTaskEvent.class)); + assertTrue(eventClassStatsMapForRewriting.get().get(Debugger.ExecutingTaskEvent.class).getCount(Debugger.Location.BEGIN) > 0); + + final var eventClassStatsMapForPlanning = statsMaps.getEventWithStateClassStatsMapByPlannerPhase(PlannerPhase.PLANNING); + assertTrue(eventClassStatsMapForPlanning.isPresent()); + assertTrue(eventClassStatsMapForPlanning.get().containsKey(Debugger.ExecutingTaskEvent.class)); + + final var totalTasks = eventClassStatsMap.get(Debugger.ExecutingTaskEvent.class).getCount(Debugger.Location.BEGIN); + final var rewritingTasks = eventClassStatsMapForRewriting.get().get(Debugger.ExecutingTaskEvent.class).getCount(Debugger.Location.BEGIN); + final var planningTasks = eventClassStatsMapForPlanning.get().get(Debugger.ExecutingTaskEvent.class).getCount(Debugger.Location.BEGIN); + + assertTrue(totalTasks > 0); + assertTrue(rewritingTasks > 0); + assertTrue(planningTasks > 0); + assertEquals(rewritingTasks + planningTasks, totalTasks); final var plan = planResult.getPlan(); System.out.println("\n" + ExplainPlanVisitor.prettyExplain(plan) + "\n"); @@ -693,7 +712,7 @@ protected static RecordQueryPlan verifySerialization(@Nonnull final RecordQueryP final PlanSerializationContext deserializationContext = new PlanSerializationContext(new DefaultPlanSerializationRegistry(), PlanHashable.CURRENT_FOR_CONTINUATION); final RecordQueryPlan deserializedPlan = RecordQueryPlan.fromRecordQueryPlanProto(deserializationContext, parsedPlanProto); - Assertions.assertEquals(plan.planHash(PlanHashable.CURRENT_FOR_CONTINUATION), deserializedPlan.planHash(PlanHashable.CURRENT_FOR_CONTINUATION)); + assertEquals(plan.planHash(PlanHashable.CURRENT_FOR_CONTINUATION), deserializedPlan.planHash(PlanHashable.CURRENT_FOR_CONTINUATION)); Assertions.assertTrue(plan.structuralEquals(deserializedPlan)); return deserializedPlan; } diff --git a/fdb-relational-core/src/main/java/com/apple/foundationdb/relational/recordlayer/query/QueryPlan.java b/fdb-relational-core/src/main/java/com/apple/foundationdb/relational/recordlayer/query/QueryPlan.java index 47ea0ffa34..a31cb6b380 100644 --- a/fdb-relational-core/src/main/java/com/apple/foundationdb/relational/recordlayer/query/QueryPlan.java +++ b/fdb-relational-core/src/main/java/com/apple/foundationdb/relational/recordlayer/query/QueryPlan.java @@ -33,6 +33,7 @@ import com.apple.foundationdb.record.query.plan.QueryPlanInfoKeys; import com.apple.foundationdb.record.query.plan.QueryPlanResult; import com.apple.foundationdb.record.query.plan.cascades.CascadesPlanner; +import com.apple.foundationdb.record.query.plan.cascades.PlannerPhase; import com.apple.foundationdb.record.query.plan.cascades.Reference; import com.apple.foundationdb.record.query.plan.cascades.debug.Debugger; import com.apple.foundationdb.record.query.plan.cascades.debug.Stats; @@ -88,6 +89,7 @@ import java.sql.Struct; import java.util.ArrayList; import java.util.Collections; + import java.util.List; import java.util.Map; import java.util.Objects; @@ -296,7 +298,11 @@ private RelationalResultSet executeExplain(@Nonnull ContinuationImpl parsedConti DataType.StructType.Field.from("TRANSFORM_YIELD_COUNT", DataType.Primitives.LONG.type(), 4), DataType.StructType.Field.from("INSERT_TIME_NS", DataType.Primitives.LONG.type(), 5), DataType.StructType.Field.from("INSERT_NEW_COUNT", DataType.Primitives.LONG.type(), 6), - DataType.StructType.Field.from("INSERT_REUSED_COUNT", DataType.Primitives.LONG.type(), 7)), + DataType.StructType.Field.from("INSERT_REUSED_COUNT", DataType.Primitives.LONG.type(), 7), + DataType.StructType.Field.from("REWRITING_PHASE_TASK_COUNT", DataType.Primitives.LONG.type(), 8), + DataType.StructType.Field.from("PLANNING_PHASE_TASK_COUNT", DataType.Primitives.LONG.type(), 9), + DataType.StructType.Field.from("REWRITING_PHASE_TASKS_TOTAL_TIME_NS", DataType.Primitives.LONG.type(), 10), + DataType.StructType.Field.from("PLANNING_PHASE_TASKS_TOTAL_TIME_NS", DataType.Primitives.LONG.type(), 11)), true); final var explainStructType = DataType.StructType.from( "EXPLAIN", List.of( @@ -320,25 +326,35 @@ private RelationalResultSet executeExplain(@Nonnull ContinuationImpl parsedConti plannerMetrics = null; } else { final var plannerEventClassStatsMap = plannerStatsMaps.getEventClassStatsMap(); - final var executingTasksStats = + + final var aggregateExecutingTasksStats = Optional.ofNullable(plannerEventClassStatsMap.get(Debugger.ExecutingTaskEvent.class)); - final var transformRuleCallStats = + final var aggregateTransformRuleCallStats = Optional.ofNullable(plannerEventClassStatsMap.get(Debugger.TransformRuleCallEvent.class)); - final var insertIntoMemoStats = + final var aggregateInsertIntoMemoStats = Optional.ofNullable(plannerEventClassStatsMap.get(Debugger.InsertIntoMemoEvent.class)); + final var executingTasksStatsForRewritingPhase = + plannerStatsMaps.getEventWithStateClassStatsMapByPlannerPhase(PlannerPhase.REWRITING) + .map(m -> m.get(Debugger.ExecutingTaskEvent.class)); + final var executingTasksStatsForPlanningPhase = + plannerStatsMaps.getEventWithStateClassStatsMapByPlannerPhase(PlannerPhase.PLANNING) + .map(m -> m.get(Debugger.ExecutingTaskEvent.class)); + plannerMetrics = new ImmutableRowStruct(new ArrayRow( - executingTasksStats.map(s -> s.getCount(Debugger.Location.BEGIN)).orElse(0L), - executingTasksStats.map(Stats::getTotalTimeInNs).orElse(0L), - transformRuleCallStats.map(s -> s.getCount(Debugger.Location.BEGIN)).orElse(0L), - transformRuleCallStats.map(Stats::getOwnTimeInNs).orElse(0L), - transformRuleCallStats.map(s -> s.getCount(Debugger.Location.YIELD)).orElse(0L), - insertIntoMemoStats.map(Stats::getOwnTimeInNs).orElse(0L), - insertIntoMemoStats.map(s -> s.getCount(Debugger.Location.NEW)).orElse(0L), - insertIntoMemoStats.map(s -> s.getCount(Debugger.Location.REUSED)).orElse(0L), - parsedContinuation.getVersion(), - parsedContinuation.getCompiledStatement() == null ? null : parsedContinuation.getCompiledStatement().getPlanSerializationMode() + aggregateExecutingTasksStats.map(s -> s.getCount(Debugger.Location.BEGIN)).orElse(0L), + aggregateExecutingTasksStats.map(Stats::getTotalTimeInNs).orElse(0L), + aggregateTransformRuleCallStats.map(s -> s.getCount(Debugger.Location.BEGIN)).orElse(0L), + aggregateTransformRuleCallStats.map(Stats::getOwnTimeInNs).orElse(0L), + aggregateTransformRuleCallStats.map(s -> s.getCount(Debugger.Location.YIELD)).orElse(0L), + aggregateInsertIntoMemoStats.map(Stats::getOwnTimeInNs).orElse(0L), + aggregateInsertIntoMemoStats.map(s -> s.getCount(Debugger.Location.NEW)).orElse(0L), + aggregateInsertIntoMemoStats.map(s -> s.getCount(Debugger.Location.REUSED)).orElse(0L), + executingTasksStatsForRewritingPhase.map(s -> s.getCount(Debugger.Location.BEGIN)).orElse(0L), + executingTasksStatsForPlanningPhase.map(s -> s.getCount(Debugger.Location.BEGIN)).orElse(0L), + executingTasksStatsForRewritingPhase.map(Stats::getTotalTimeInNs).orElse(0L), + executingTasksStatsForPlanningPhase.map(Stats::getTotalTimeInNs).orElse(0L) ), RelationalStructMetaData.of(plannerMetricsStructType)); } diff --git a/fdb-relational-core/src/test/java/com/apple/foundationdb/relational/recordlayer/query/ExplainTests.java b/fdb-relational-core/src/test/java/com/apple/foundationdb/relational/recordlayer/query/ExplainTests.java index ad1e844c62..bd9b582c97 100644 --- a/fdb-relational-core/src/test/java/com/apple/foundationdb/relational/recordlayer/query/ExplainTests.java +++ b/fdb-relational-core/src/test/java/com/apple/foundationdb/relational/recordlayer/query/ExplainTests.java @@ -40,6 +40,7 @@ import java.net.URI; import java.sql.SQLException; import java.sql.Types; +import java.util.Collections; import java.util.List; public class ExplainTests { @@ -71,6 +72,21 @@ void explainResultSetMetadataTest() throws Exception { final var expectedTypes = List.of(Types.VARCHAR, Types.INTEGER, Types.VARCHAR, Types.VARCHAR, Types.STRUCT, Types.STRUCT); final var expectedContLabels = List.of("EXECUTION_STATE", "VERSION", "PLAN_HASH_MODE"); final var expectedContTypes = List.of(Types.BINARY, Types.INTEGER, Types.VARCHAR); + final var expectedPlannerMetricsLabels = List.of( + "TASK_COUNT", + "TASK_TOTAL_TIME_NS", + "TRANSFORM_COUNT", + "TRANSFORM_TIME_NS", + "TRANSFORM_YIELD_COUNT", + "INSERT_TIME_NS", + "INSERT_NEW_COUNT", + "INSERT_REUSED_COUNT", + "REWRITING_PHASE_TASK_COUNT", + "PLANNING_PHASE_TASK_COUNT", + "REWRITING_PHASE_TASKS_TOTAL_TIME_NS", + "PLANNING_PHASE_TASKS_TOTAL_TIME_NS" + ); + final var expectedPlannerMetricsTypes = Collections.nCopies(expectedPlannerMetricsLabels.size(), Types.BIGINT); try (var ddl = Ddl.builder().database(URI.create("/TEST/QT")).relationalExtension(relationalExtension).schemaTemplate(schemaTemplate).build()) { executeInsert(ddl); try (RelationalPreparedStatement ps = ddl.setSchemaAndGetConnection().prepareStatement("EXPLAIN SELECT * FROM RestaurantComplexRecord")) { @@ -87,7 +103,12 @@ void explainResultSetMetadataTest() throws Exception { org.junit.jupiter.api.Assertions.assertEquals(expectedContLabels.get(i), actualContinuationMetadata.getColumnLabel(i + 1)); org.junit.jupiter.api.Assertions.assertEquals(expectedContTypes.get(i), actualContinuationMetadata.getColumnType(i + 1)); } - + final var actualPlannerMetricsMetadata = actualMetadata.getStructMetaData(6); + org.junit.jupiter.api.Assertions.assertEquals(expectedPlannerMetricsLabels.size(), actualPlannerMetricsMetadata.getColumnCount()); + for (int i = 0; i < expectedPlannerMetricsLabels.size(); i++) { + org.junit.jupiter.api.Assertions.assertEquals(expectedPlannerMetricsLabels.get(i), actualPlannerMetricsMetadata.getColumnLabel(i + 1)); + org.junit.jupiter.api.Assertions.assertEquals(expectedPlannerMetricsTypes.get(i), actualPlannerMetricsMetadata.getColumnType(i + 1)); + } } } } From 2ee4763e6a36b43269d2f7f87bde53730c3465d9 Mon Sep 17 00:00:00 2001 From: Hazem Zaghloul Date: Thu, 7 Aug 2025 17:54:23 +0100 Subject: [PATCH 7/9] Add new lightweight debugger implementation This commit adds a new implmentation of the Cascades Debugger interface, which only keeps track of statstics around debugger events and doesn't support keeping track of symbol tables. This new implementation should be safe to use outside of tests since it should have a minimal impact on the planner's performance. --- .../cascades/debug/LightweightDebugger.java | 136 ++++++++++++++++++ .../command/DebuggerImplementation.java | 2 + .../src/test/java/YamlIntegrationTests.java | 5 + ...ery-with-different-debuggers.metrics.binpb | 14 ++ ...uery-with-different-debuggers.metrics.yaml | 31 ++++ ...mple-query-with-different-debuggers.yamsql | 53 +++++++ 6 files changed, 241 insertions(+) create mode 100644 fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/LightweightDebugger.java create mode 100644 yaml-tests/src/test/resources/simple-query-with-different-debuggers.metrics.binpb create mode 100644 yaml-tests/src/test/resources/simple-query-with-different-debuggers.metrics.yaml create mode 100644 yaml-tests/src/test/resources/simple-query-with-different-debuggers.yamsql diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/LightweightDebugger.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/LightweightDebugger.java new file mode 100644 index 0000000000..2d44518bd3 --- /dev/null +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/LightweightDebugger.java @@ -0,0 +1,136 @@ +/* + * LightweightDebugger.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.debug; + +import com.apple.foundationdb.record.logging.KeyValueLogMessage; +import com.apple.foundationdb.record.query.plan.cascades.PlanContext; +import com.apple.foundationdb.record.query.plan.cascades.Reference; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + +import javax.annotation.Nonnull; +import javax.annotation.Nullable; +import java.util.Objects; +import java.util.Optional; +import java.util.concurrent.TimeUnit; + +/** + * Implementation of a lightweight debugger that only maintains debugging events for calculating {@link Stats} + * (i.e. it implements only the {@link StatsDebugger} interface). + * This debugger is safe for use in production. + */ +public class LightweightDebugger implements StatsDebugger { + private static final Logger logger = LoggerFactory.getLogger(LightweightDebugger.class); + + @Nullable + private EventState currentEventState; + @Nullable + private String queryAsString; + @Nullable + private PlanContext planContext; + + public LightweightDebugger() { + this.currentEventState = null; + this.planContext = null; + } + + @Nonnull + EventState getCurrentEventState() { + return Objects.requireNonNull(currentEventState); + } + + @Nullable + @Override + public PlanContext getPlanContext() { + return planContext; + } + + @Override + public boolean isSane() { + return true; + } + + @Override + public void onInstall() { + // do nothing + } + + @Override + public void onSetup() { + reset(); + } + + @Override + public void onShow(@Nonnull final Reference ref) { + // do nothing + } + + @Override + public void onQuery(@Nonnull final String recordQuery, @Nonnull final PlanContext planContext) { + this.queryAsString = recordQuery; + this.planContext = planContext; + + logQuery(); + } + + @Override + public void onEvent(final Debugger.Event event) { + if ((queryAsString == null) || (planContext == null) || (currentEventState == null)) { + return; + } + getCurrentEventState().addCurrentEvent(event); + } + + @Override + public void onDone() { + if (currentEventState != null && queryAsString != null) { + final var state = Objects.requireNonNull(currentEventState); + if (logger.isDebugEnabled()) { + logger.debug(KeyValueLogMessage.of("planning done", + "query", Objects.requireNonNull(queryAsString).substring(0, Math.min(queryAsString.length(), 30)), + "duration-in-ms", TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - state.getStartTs()), + "ticks", state.getCurrentTick())); + } + } + reset(); + } + + @Nonnull + @Override + public Optional getStatsMaps() { + if (currentEventState != null) { + return Optional.of(currentEventState.getStatsMaps()); + } + return Optional.empty(); + } + + private void reset() { + this.currentEventState = EventState.initial(false, false, null); + this.planContext = null; + this.queryAsString = null; + } + + void logQuery() { + if (logger.isDebugEnabled()) { + logger.debug(KeyValueLogMessage.of("planning started", "query", queryAsString)); + } + } +} diff --git a/yaml-tests/src/main/java/com/apple/foundationdb/relational/yamltests/command/DebuggerImplementation.java b/yaml-tests/src/main/java/com/apple/foundationdb/relational/yamltests/command/DebuggerImplementation.java index f0c3334bce..918e8738fb 100644 --- a/yaml-tests/src/main/java/com/apple/foundationdb/relational/yamltests/command/DebuggerImplementation.java +++ b/yaml-tests/src/main/java/com/apple/foundationdb/relational/yamltests/command/DebuggerImplementation.java @@ -22,6 +22,7 @@ import com.apple.foundationdb.record.query.plan.cascades.debug.Debugger; import com.apple.foundationdb.record.query.plan.cascades.debug.DebuggerWithSymbolTables; +import com.apple.foundationdb.record.query.plan.cascades.debug.LightweightDebugger; import com.apple.foundationdb.record.query.plan.cascades.debug.PlannerRepl; import com.apple.foundationdb.relational.yamltests.YamlExecutionContext; import org.jline.terminal.TerminalBuilder; @@ -31,6 +32,7 @@ import java.util.function.Function; public enum DebuggerImplementation { + LIGHTWEIGHT(context -> new LightweightDebugger()), INSANE(context -> DebuggerWithSymbolTables.withSanityChecks()), SANE(context -> DebuggerWithSymbolTables.withoutSanityChecks()), REPL(context -> { diff --git a/yaml-tests/src/test/java/YamlIntegrationTests.java b/yaml-tests/src/test/java/YamlIntegrationTests.java index 138f9bcc75..c3ebec745c 100644 --- a/yaml-tests/src/test/java/YamlIntegrationTests.java +++ b/yaml-tests/src/test/java/YamlIntegrationTests.java @@ -305,4 +305,9 @@ public void literalExtractionTests(YamlTest.Runner runner) throws Exception { public void caseSensitivityTest(YamlTest.Runner runner) throws Exception { runner.runYamsql("case-sensitivity.yamsql"); } + + @TestTemplate + public void simpleQueryWithDifferentDebuggersTest(YamlTest.Runner runner) throws Exception { + runner.runYamsql("simple-query-with-different-debuggers.yamsql"); + } } diff --git a/yaml-tests/src/test/resources/simple-query-with-different-debuggers.metrics.binpb b/yaml-tests/src/test/resources/simple-query-with-different-debuggers.metrics.binpb new file mode 100644 index 0000000000..ac0ef454d7 --- /dev/null +++ b/yaml-tests/src/test/resources/simple-query-with-different-debuggers.metrics.binpb @@ -0,0 +1,14 @@ + +N +%simple-query-with-different-debuggers%EXPLAIN select * from t1 where id > 1 +"* (0I8@9SCAN(<,>) | FILTER _.ID GREATER_THAN promote(@c8 AS LONG) +digraph G { + fontname=courier; + rankdir=BT; + splines=polyline; + 1 [ label=<
Predicate Filter
WHERE q9bd5c851_f08a_4d97_bc5d_1ae41728b1b7.ID GREATER_THAN promote(@c8 AS LONG)
> color="black" shape="plain" style="solid" fillcolor="black" fontname="courier" fontsize="8" tooltip="RELATION(LONG AS ID, )" ]; + 2 [ label=<
Scan
range: <-∞, ∞>
> color="black" shape="plain" style="solid" fillcolor="black" fontname="courier" fontsize="8" tooltip="RELATION(LONG AS ID, )" ]; + 3 [ label=<
Primary Storage
record types: [T1]
> color="black" shape="plain" style="filled" fillcolor="lightblue" fontname="courier" fontsize="8" tooltip="RELATION(LONG AS ID, )" ]; + 3 -> 2 [ color="gray20" style="solid" fontname="courier" fontsize="8" arrowhead="normal" arrowtail="none" dir="both" ]; + 2 -> 1 [ label=< q9bd5c851_f08a_4d97_bc5d_1ae41728b1b7> label="q9bd5c851_f08a_4d97_bc5d_1ae41728b1b7" color="gray20" style="bold" fontname="courier" fontsize="8" arrowhead="normal" arrowtail="none" dir="both" ]; +} \ No newline at end of file diff --git a/yaml-tests/src/test/resources/simple-query-with-different-debuggers.metrics.yaml b/yaml-tests/src/test/resources/simple-query-with-different-debuggers.metrics.yaml new file mode 100644 index 0000000000..deaa3ecd54 --- /dev/null +++ b/yaml-tests/src/test/resources/simple-query-with-different-debuggers.metrics.yaml @@ -0,0 +1,31 @@ +simple-query-with-different-debuggers: +- query: EXPLAIN select * from t1 where id > 1 + explain: SCAN(<,>) | FILTER _.ID GREATER_THAN promote(@c8 AS LONG) + task_count: 163 + task_total_time_ms: 72 + transform_count: 42 + transform_time_ms: 61 + transform_yield_count: 14 + insert_time_ms: 1 + insert_new_count: 14 + insert_reused_count: 2 +- query: EXPLAIN select * from t1 where id > 1 + explain: SCAN(<,>) | FILTER _.ID GREATER_THAN promote(@c8 AS LONG) + task_count: 163 + task_total_time_ms: 72 + transform_count: 42 + transform_time_ms: 61 + transform_yield_count: 14 + insert_time_ms: 1 + insert_new_count: 14 + insert_reused_count: 2 +- query: EXPLAIN select * from t1 where id > 1 + explain: SCAN(<,>) | FILTER _.ID GREATER_THAN promote(@c8 AS LONG) + task_count: 163 + task_total_time_ms: 72 + transform_count: 42 + transform_time_ms: 61 + transform_yield_count: 14 + insert_time_ms: 1 + insert_new_count: 14 + insert_reused_count: 2 diff --git a/yaml-tests/src/test/resources/simple-query-with-different-debuggers.yamsql b/yaml-tests/src/test/resources/simple-query-with-different-debuggers.yamsql new file mode 100644 index 0000000000..71cc43ecf5 --- /dev/null +++ b/yaml-tests/src/test/resources/simple-query-with-different-debuggers.yamsql @@ -0,0 +1,53 @@ +# +# simple-query-with-different-debuggers.yamsql +# +# This source file is part of the FoundationDB open source project +# +# Copyright 2021-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. + +--- +schema_template: + create table t1(id bigint, col1 string, primary key(id)) +--- +setup: + steps: + - query: INSERT INTO T1 VALUES + (1, 'a'), + (2, 'b'), + (3, 'c') +--- +test_block: + name: simple-query-with-different-debuggers + preset: single_repetition_ordered + tests: + - + - query: select * from t1 where id > 1 + - explain: "SCAN(<,>) | FILTER _.ID GREATER_THAN promote(@c8 AS LONG)" + - debugger: lightweight + - result: [{id: 2, col1: 'b'}, + {id: 3, col1: 'c'}] + - + - query: select * from t1 where id > 1 + - explain: "SCAN(<,>) | FILTER _.ID GREATER_THAN promote(@c8 AS LONG)" + - debugger: sane + - result: [{id: 2, col1: 'b'}, + {id: 3, col1: 'c'}] + - + - query: select * from t1 where id > 1 + - explain: "SCAN(<,>) | FILTER _.ID GREATER_THAN promote(@c8 AS LONG)" + - debugger: insane + - result: [{id: 2, col1: 'b'}, + {id: 3, col1: 'c'}] +... From f35f7aab8b1a909f20d217b332e77b0952475f46 Mon Sep 17 00:00:00 2001 From: Hazem Zaghloul Date: Fri, 8 Aug 2025 18:42:21 +0100 Subject: [PATCH 8/9] Update doc comments --- .../record/query/plan/cascades/debug/Debugger.java | 4 +++- .../cascades/debug/DebuggerWithSymbolTables.java | 3 +++ .../query/plan/cascades/debug/EventState.java | 4 ++++ .../plan/cascades/debug/LightweightDebugger.java | 2 +- .../query/plan/cascades/debug/StatsDebugger.java | 10 ++++++++++ .../query/plan/cascades/debug/StatsViewer.java | 14 +++++++++++++- .../query/plan/cascades/debug/SymbolDebugger.java | 10 ++++++++++ .../query/plan/cascades/debug/SymbolTables.java | 5 +++++ 8 files changed, 49 insertions(+), 3 deletions(-) diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/Debugger.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/Debugger.java index 45f43881fc..2630d4e054 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/Debugger.java +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/Debugger.java @@ -66,13 +66,15 @@ * As the planner is currently single-threaded as per planning of a query, we keep an instance of an implementor of * this class in the thread-local. (per-thread singleton). * The main mean of communication with the debugger is the set of statics defined within this interface. + * There are two interfaces that extend this interface which provides different debugging functionalities, + * see {@link StatsDebugger} and {@link SymbolDebugger} for more details. *

- * Debugging functionality should only be enabled in test cases, never in deployments. *

* In order to enable debugging capabilities, clients should use {@link #setDebugger} which sets a debugger to be used * for the current thread. Once set, the planner starts interacting with the debugger in order to communicate important * state changes, like begin of planning, end of planner, etc. *

+ * Certain debugger implementations should only be enabled in test cases, never in deployments. *

* Clients using the debugger should never hold on/manage/use an instance of a debugger directly. Instead, clients * should use {@link #withDebugger} and {@link #mapDebugger} to invoke methods on the currently installed debugger. diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/DebuggerWithSymbolTables.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/DebuggerWithSymbolTables.java index fd143746b0..9aa067ba80 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/DebuggerWithSymbolTables.java +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/DebuggerWithSymbolTables.java @@ -60,8 +60,11 @@ import static com.apple.foundationdb.record.query.plan.cascades.properties.ReferencesAndDependenciesProperty.referencesAndDependencies; /** + *

* Implementation of a debugger that maintains symbol tables for easier human consumption e.g. in test cases and/or * while debugging. + *

+ * Instances of this debugger should only be enabled in test cases, never in deployments. */ @SuppressWarnings("PMD.SystemPrintln") public class DebuggerWithSymbolTables implements SymbolDebugger, StatsDebugger { diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/EventState.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/EventState.java index d75ccf8730..8f4d75b3c4 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/EventState.java +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/EventState.java @@ -43,6 +43,10 @@ import java.util.Map; import java.util.Objects; +/** + * A class used by different implementations of {@link StatsDebugger} to record {@link Debugger.Event} and produce + * stats (number of events, total time taken by events of a specific type, etc.) for the recorded events. + */ @SuppressWarnings("PMD.SystemPrintln") public class EventState { @Nonnull diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/LightweightDebugger.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/LightweightDebugger.java index 2d44518bd3..ba299a8833 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/LightweightDebugger.java +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/LightweightDebugger.java @@ -35,7 +35,7 @@ /** * Implementation of a lightweight debugger that only maintains debugging events for calculating {@link Stats} * (i.e. it implements only the {@link StatsDebugger} interface). - * This debugger is safe for use in production. + * This debugger is safe for use in deployments. */ public class LightweightDebugger implements StatsDebugger { private static final Logger logger = LoggerFactory.getLogger(LightweightDebugger.class); diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/StatsDebugger.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/StatsDebugger.java index 87a8adf397..96a9199bdf 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/StatsDebugger.java +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/StatsDebugger.java @@ -25,6 +25,16 @@ import java.util.function.Consumer; import java.util.function.Function; +/** + *

+ * This interface extends the {@link Debugger} interface and provides functionality related to + * recording instances of {@link Debugger.Event} and producing statistics based on these events + * in the form of {@link StatsMaps}. + *

+ * Similar to the {@link Debugger} interface, the main mean of communication with the debugger + * for operations related to recording events is the set of statics defined within this interface. + *

+ */ public interface StatsDebugger extends Debugger { @Nonnull static Optional getDebuggerMaybe() { diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/StatsViewer.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/StatsViewer.java index 120f98590f..b3d3d8a68b 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/StatsViewer.java +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/StatsViewer.java @@ -30,7 +30,19 @@ import java.util.Optional; import java.util.concurrent.TimeUnit; -/** Only used by debuggers to display stats.*/ +/** + * A class that can be used to view {@link Stats} for all {@link Debugger.Event} collected by {@link StatsDebugger} + * during planning in a browser. + *

+ * To view the stats, evaluate the following expression in a debugging session at a breakpoint before the Cascades planner + * returns the plan: + * 

+ *     StatsViewer.showStats(StatsDebugger.getDebuggerMaybe().get())
+ *
+ * + * The stats will be displayed in a new window of the system browser. + *

+ */ @SuppressWarnings("unused") public class StatsViewer { public static String showStats(@Nonnull final StatsDebugger statsDebugger) { diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/SymbolDebugger.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/SymbolDebugger.java index fcad8bceb6..7392412e82 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/SymbolDebugger.java +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/SymbolDebugger.java @@ -32,6 +32,16 @@ import java.util.function.Function; import java.util.function.IntUnaryOperator; +/** + *

+ * This interface extends the {@link Debugger} interface and provides functionality related to + * registering different symbols (i.e. objects) during planning and retrieving debugging-friendly + * names for them. + *

+ * Similar to the {@link Debugger} interface, the main mean of communication with the debugger + * for operations related to recording events is the set of statics defined within this interface. + *

+ */ public interface SymbolDebugger extends Debugger { @Nonnull static Optional getDebuggerMaybe() { diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/SymbolTables.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/SymbolTables.java index 60e4e2d850..cdc8c63cac 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/SymbolTables.java +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/SymbolTables.java @@ -34,6 +34,11 @@ import java.util.Map; import java.util.function.IntUnaryOperator; +/** + * A class used by different implementations of {@link SymbolDebugger} to map different types of objects + * during planning ({@link RelationalExpression}, {@link Reference}, {@link Quantifier}) to unique indices, which + * is used to generate debugging-friendly names for these objects. + */ public class SymbolTables { @Nonnull private final Map, Integer> classToIndexMap; From b53e0424ea51d7552b6710594566422947d7799d Mon Sep 17 00:00:00 2001 From: Hazem Zaghloul Date: Fri, 8 Aug 2025 18:43:19 +0100 Subject: [PATCH 9/9] Fix bug in StatsMaps for events without a state --- .../record/query/plan/cascades/debug/LightweightDebugger.java | 2 ++ .../record/query/plan/cascades/debug/StatsMaps.java | 2 +- 2 files changed, 3 insertions(+), 1 deletion(-) diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/LightweightDebugger.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/LightweightDebugger.java index ba299a8833..b387ae1e49 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/LightweightDebugger.java +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/LightweightDebugger.java @@ -85,6 +85,8 @@ public void onShow(@Nonnull final Reference ref) { @Override public void onQuery(@Nonnull final String recordQuery, @Nonnull final PlanContext planContext) { + reset(); + this.queryAsString = recordQuery; this.planContext = planContext; diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/StatsMaps.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/StatsMaps.java index 84d112b6d2..a8a86727d8 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/StatsMaps.java +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/debug/StatsMaps.java @@ -75,7 +75,7 @@ public Map>, Stats> getPlannerRuleClassStatsMap( @Nonnull public Map, Stats> getEventWithoutStateClassStatsMap() { - return immutableEventClassStatsMapSupplier.get(); + return immutableEventWithoutStateClassStatsMapSupplier.get(); } @Nonnull