Skip to content

Commit b71ab35

Browse files
hazefullyhazefully
committed
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.
1 parent cf64ec3 commit b71ab35

File tree

11 files changed

+202
-16
lines changed

11 files changed

+202
-16
lines changed

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

Lines changed: 46 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -26,6 +26,7 @@
2626
import com.apple.foundationdb.record.RecordStoreState;
2727
import com.apple.foundationdb.record.logging.KeyValueLogMessage;
2828
import com.apple.foundationdb.record.logging.LogMessageKeys;
29+
import com.apple.foundationdb.record.provider.common.StoreTimer;
2930
import com.apple.foundationdb.record.query.IndexQueryabilityFilter;
3031
import com.apple.foundationdb.record.query.ParameterRelationshipGraph;
3132
import com.apple.foundationdb.record.query.RecordQuery;
@@ -55,6 +56,7 @@
5556
import org.slf4j.LoggerFactory;
5657

5758
import javax.annotation.Nonnull;
59+
import javax.annotation.Nullable;
5860
import java.util.ArrayDeque;
5961
import java.util.Collection;
6062
import java.util.Deque;
@@ -212,6 +214,8 @@ public class CascadesPlanner implements QueryPlanner {
212214
private final RecordMetaData metaData;
213215
@Nonnull
214216
private final RecordStoreState recordStoreState;
217+
@Nullable
218+
private final StoreTimer storeTimer;
215219
@Nonnull
216220
private Reference currentRoot;
217221
@Nonnull
@@ -228,9 +232,14 @@ public class CascadesPlanner implements QueryPlanner {
228232
private int maxQueueSize;
229233

230234
public CascadesPlanner(@Nonnull RecordMetaData metaData, @Nonnull RecordStoreState recordStoreState) {
235+
this(metaData, recordStoreState, null);
236+
}
237+
238+
public CascadesPlanner(@Nonnull RecordMetaData metaData, @Nonnull RecordStoreState recordStoreState, @Nullable StoreTimer storeTimer) {
231239
this.configuration = RecordQueryPlannerConfiguration.builder().build();
232240
this.metaData = metaData;
233241
this.recordStoreState = recordStoreState;
242+
this.storeTimer = storeTimer;
234243
// Placeholders until we get a query.
235244
this.currentRoot = Reference.empty();
236245
this.planContext = PlanContext.emptyContext();
@@ -524,6 +533,41 @@ public interface Task {
524533
Debugger.Event toTaskEvent(Location location);
525534
}
526535

536+
private class FinalizePlannerPhase implements Task {
537+
@Nonnull
538+
private final PlannerPhase plannerPhase;
539+
private final long phaseStartTime;
540+
541+
public FinalizePlannerPhase(@Nonnull final PlannerPhase plannerPhase, long phaseStartTime) {
542+
this.plannerPhase = plannerPhase;
543+
this.phaseStartTime = phaseStartTime;
544+
}
545+
546+
@Override
547+
@Nonnull
548+
public PlannerPhase getPlannerPhase() {
549+
return plannerPhase;
550+
}
551+
552+
@Override
553+
public void execute() {
554+
if (storeTimer != null) {
555+
storeTimer.record(plannerPhase.getPhaseCompletionTimerEvent(), System.nanoTime() - phaseStartTime);
556+
}
557+
}
558+
559+
@Override
560+
@Nonnull
561+
public Debugger.Event toTaskEvent(final Location location) {
562+
return new Debugger.FinalizePlannerPhaseEvent(plannerPhase, currentRoot, taskStack, location);
563+
}
564+
565+
@Override
566+
public String toString() {
567+
return "FinalizePlannerPhase(" + plannerPhase.name() + ")";
568+
}
569+
}
570+
527571
/**
528572
* Globally initiate a new planner phase.
529573
* Simplified push/execute overview:
@@ -552,10 +596,12 @@ public PlannerPhase getPlannerPhase() {
552596

553597
@Override
554598
public void execute() {
599+
var phaseStartTime = System.nanoTime();
555600
if (plannerPhase.hasNextPhase()) {
556601
// if there is another phase push it first so it gets executed at the very end
557602
taskStack.push(new InitiatePlannerPhase(plannerPhase.getNextPhase()));
558603
}
604+
taskStack.push(new FinalizePlannerPhase(plannerPhase, phaseStartTime));
559605
taskStack.push(new OptimizeGroup(plannerPhase, currentRoot));
560606
taskStack.push(new ExploreGroup(plannerPhase, currentRoot));
561607
}

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

Lines changed: 14 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -35,8 +35,8 @@
3535
*/
3636
public enum PlannerPhase {
3737
// note that the phase are declared in a counterintuitive inverse way since a phase has to specify the next phase
38-
PLANNING(PlanningRuleSet.getDefault(), PlannerStage.PLANNED, PlanningCostModel::new),
39-
REWRITING(RewritingRuleSet.getDefault(), PlannerStage.CANONICAL, RewritingCostModel::new, PLANNING);
38+
PLANNING(PlanningRuleSet.getDefault(), PlannerStage.PLANNED, PlanningCostModel::new, PlannerTimerEvents.PLANNING_PHASE_COMPLETE),
39+
REWRITING(RewritingRuleSet.getDefault(), PlannerStage.CANONICAL, RewritingCostModel::new, PlannerTimerEvents.REWRITING_PHASE_COMPLETE, PLANNING);
4040

4141
@Nonnull
4242
private final CascadesRuleSet ruleSet;
@@ -46,21 +46,26 @@ public enum PlannerPhase {
4646
private final Function<RecordQueryPlannerConfiguration, CascadesCostModel> costModelCreator;
4747
@Nullable
4848
private final PlannerPhase nextPhase;
49+
@Nonnull
50+
private final PlannerTimerEvents phaseCompletionTimerEvent;
4951

5052
PlannerPhase(@Nonnull final CascadesRuleSet ruleSet,
5153
@Nonnull final PlannerStage targetStage,
52-
@Nonnull final Function<RecordQueryPlannerConfiguration, CascadesCostModel> costModelCreator) {
53-
this(ruleSet, targetStage, costModelCreator, null);
54+
@Nonnull final Function<RecordQueryPlannerConfiguration, CascadesCostModel> costModelCreator,
55+
@Nonnull final PlannerTimerEvents phaseCompletionTimerEvent) {
56+
this(ruleSet, targetStage, costModelCreator, phaseCompletionTimerEvent, null);
5457
}
5558

5659
PlannerPhase(@Nonnull final CascadesRuleSet ruleSet,
5760
@Nonnull final PlannerStage targetStage,
5861
@Nonnull final Function<RecordQueryPlannerConfiguration, CascadesCostModel> costModelCreator,
62+
@Nonnull final PlannerTimerEvents phaseCompletionTimerEvent,
5963
@Nullable final PlannerPhase nextPhase) {
6064
this.ruleSet = ruleSet;
6165
this.targetStage = targetStage;
6266
this.costModelCreator = costModelCreator;
6367
this.nextPhase = nextPhase;
68+
this.phaseCompletionTimerEvent = phaseCompletionTimerEvent;
6469
}
6570

6671
@Nonnull
@@ -87,6 +92,11 @@ public boolean hasNextPhase() {
8792
return nextPhase != null;
8893
}
8994

95+
@Nonnull
96+
public PlannerTimerEvents getPhaseCompletionTimerEvent() {
97+
return phaseCompletionTimerEvent;
98+
}
99+
90100
@Nonnull
91101
public PPlannerPhase toProto() {
92102
switch (this) {

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

Lines changed: 49 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,49 @@
1+
/*
2+
* PlannerTimerEvents.java
3+
*
4+
* This source file is part of the FoundationDB open source project
5+
*
6+
* Copyright 2015-2025 Apple Inc. and the FoundationDB project authors
7+
*
8+
* Licensed under the Apache License, Version 2.0 (the "License");
9+
* you may not use this file except in compliance with the License.
10+
* You may obtain a copy of the License at
11+
*
12+
* http://www.apache.org/licenses/LICENSE-2.0
13+
*
14+
* Unless required by applicable law or agreed to in writing, software
15+
* distributed under the License is distributed on an "AS IS" BASIS,
16+
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
17+
* See the License for the specific language governing permissions and
18+
* limitations under the License.
19+
*/
20+
21+
package com.apple.foundationdb.record.query.plan.cascades;
22+
23+
import com.apple.foundationdb.record.provider.common.StoreTimer;
24+
25+
import javax.annotation.Nonnull;
26+
27+
public enum PlannerTimerEvents implements StoreTimer.Event {
28+
REWRITING_PHASE_COMPLETE("complete the rewriting phase of the planner"),
29+
PLANNING_PHASE_COMPLETE("complete the planning phase of the planner");
30+
31+
private final String title;
32+
private final String logKey;
33+
34+
PlannerTimerEvents(String title) {
35+
this.title = title;
36+
this.logKey = StoreTimer.Event.super.logKey();
37+
}
38+
39+
@Override
40+
public String title() {
41+
return title;
42+
}
43+
44+
@Override
45+
@Nonnull
46+
public String logKey() {
47+
return this.logKey;
48+
}
49+
}

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

Lines changed: 39 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -36,6 +36,7 @@
3636
import com.apple.foundationdb.record.query.plan.cascades.debug.eventprotos.PExecutingTaskEvent;
3737
import com.apple.foundationdb.record.query.plan.cascades.debug.eventprotos.PExploreExpressionEvent;
3838
import com.apple.foundationdb.record.query.plan.cascades.debug.eventprotos.PExploreGroupEvent;
39+
import com.apple.foundationdb.record.query.plan.cascades.debug.eventprotos.PFinalizePlannerPhaseEvent;
3940
import com.apple.foundationdb.record.query.plan.cascades.debug.eventprotos.PInitiatePlannerPhaseEvent;
4041
import com.apple.foundationdb.record.query.plan.cascades.debug.eventprotos.PInsertIntoMemoEvent;
4142
import com.apple.foundationdb.record.query.plan.cascades.debug.eventprotos.PMatchPartition;
@@ -260,7 +261,8 @@ enum Shorthand {
260261
TRANSFORM,
261262
INSERT_INTO_MEMO,
262263
TRANSLATE_CORRELATIONS,
263-
INITPHASE
264+
INITPHASE,
265+
FINALIZEPHASE
264266
}
265267

266268
/**
@@ -529,6 +531,42 @@ public PEvent.Builder toEventBuilder() {
529531
}
530532
}
531533

534+
class FinalizePlannerPhaseEvent extends AbstractEventWithState {
535+
public FinalizePlannerPhaseEvent(@Nonnull final PlannerPhase plannerPhase,
536+
@Nonnull final Reference rootReference,
537+
@Nonnull final Deque<Task> taskStack,
538+
@Nonnull final Location location) {
539+
super(plannerPhase, rootReference, taskStack, location);
540+
}
541+
542+
@Override
543+
@Nonnull
544+
public String getDescription() {
545+
return "finalizing planner phase " + getPlannerPhase().name();
546+
}
547+
548+
@Override
549+
@Nonnull
550+
public Shorthand getShorthand() {
551+
return Shorthand.FINALIZEPHASE;
552+
}
553+
554+
@Nonnull
555+
@Override
556+
public PFinalizePlannerPhaseEvent toProto() {
557+
return PFinalizePlannerPhaseEvent.newBuilder()
558+
.setSuper(toAbstractEventWithStateProto())
559+
.build();
560+
}
561+
562+
@Nonnull
563+
@Override
564+
public PEvent.Builder toEventBuilder() {
565+
return PEvent.newBuilder()
566+
.setFinalizePlannerPhaseEvent(toProto());
567+
}
568+
}
569+
532570
/**
533571
* Events of this class are generated every time the planner executes a task.
534572
*/

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

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -41,6 +41,7 @@ message PEvent {
4141
PInsertIntoMemoEvent insert_into_memo_event = 11;
4242
PTranslateCorrelationsEvent translate_correlations_event = 12;
4343
PInitiatePlannerPhaseEvent initiate_planner_phase_event = 13;
44+
PFinalizePlannerPhaseEvent finalize_planner_phase_event = 14;
4445
}
4546
}
4647

@@ -105,6 +106,10 @@ message PInitiatePlannerPhaseEvent {
105106
optional PAbstractEventWithState super = 1;
106107
}
107108

109+
message PFinalizePlannerPhaseEvent {
110+
optional PAbstractEventWithState super = 1;
111+
}
112+
108113
message PInsertIntoMemoEvent {
109114
optional string location = 1;
110115
optional PRegisteredRelationalExpression expression = 2;

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

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -168,7 +168,7 @@ public QueryPlanner planner(@Nonnull BenchmarkTimer timer, boolean cascades) {
168168
final RecordMetaData recordMetaData = recordStoreBuilder.getMetaDataProvider().getRecordMetaData();
169169
final RecordStoreState recordStoreState = new RecordStoreState(null, null);
170170
if (cascades) {
171-
return new CascadesPlanner(recordMetaData, recordStoreState);
171+
return new CascadesPlanner(recordMetaData, recordStoreState, timer.getTimer());
172172
} else {
173173
return new RecordQueryPlanner(recordMetaData, recordStoreState, timer.getTimer());
174174
}

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

Lines changed: 14 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -20,12 +20,15 @@
2020

2121
package com.apple.foundationdb.relational.api.metrics;
2222

23+
import com.apple.foundationdb.record.provider.common.StoreTimer;
2324
import com.apple.foundationdb.relational.api.exceptions.ErrorCode;
2425
import com.apple.foundationdb.relational.api.exceptions.RelationalException;
2526
import com.apple.foundationdb.relational.util.Supplier;
2627

2728
import javax.annotation.Nonnull;
29+
import javax.annotation.Nullable;
2830
import java.util.Locale;
31+
import java.util.Optional;
2932

3033
/**
3134
* 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) {
9699
* */
97100
default void flush() {
98101
}
102+
103+
/**
104+
* Return an instance of {@link com.apple.foundationdb.record.provider.common.StoreTimer} that corresponds to
105+
* this metric collector, if possible.
106+
*
107+
* @return an instance of {@link com.apple.foundationdb.record.provider.common.StoreTimer} or an empty {@link Optional}
108+
*/
109+
@Nullable
110+
default StoreTimer getRecordLayerStoreTimer() {
111+
return null;
112+
}
99113
}

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

Lines changed: 4 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -31,8 +31,6 @@
3131
import com.apple.foundationdb.relational.util.Assert;
3232
import com.apple.foundationdb.relational.util.Supplier;
3333

34-
import com.google.common.annotations.VisibleForTesting;
35-
3634
import javax.annotation.Nonnull;
3735
import javax.annotation.Nullable;
3836
import java.util.Objects;
@@ -98,12 +96,11 @@ public boolean hasCounter(@Nonnull RelationalMetric.RelationalCount count) {
9896

9997
@Nullable
10098
private StoreTimer.Counter getCounter(@Nonnull RelationalMetric.RelationalCount count) {
101-
return getUnderlyingStoreTimer().getCounter(count);
99+
return Objects.requireNonNull(getRecordLayerStoreTimer()).getCounter(count);
102100
}
103101

104-
@Nonnull
105-
@VisibleForTesting
106-
public StoreTimer getUnderlyingStoreTimer() {
107-
return Objects.requireNonNull(context.getTimer());
102+
@Nullable
103+
public StoreTimer getRecordLayerStoreTimer() {
104+
return context.getTimer();
108105
}
109106
}

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

Lines changed: 5 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -126,7 +126,7 @@ public Plan<?> getPlan(@Nonnull final String query) throws RelationalException {
126126
exception = e;
127127
throw e;
128128
} finally {
129-
RelationalLoggingUtil.publishPlanGenerationLogs(logger, message, plan, exception, totalTimeMicros(), options);
129+
RelationalLoggingUtil.publishPlanGenerationLogs(logger, message, plan, exception, planContext.getMetricsCollector().getRecordLayerStoreTimer(), totalTimeMicros(), options);
130130
}
131131
return plan;
132132
}
@@ -390,7 +390,10 @@ private static boolean shouldNotCache(@Nonnull final Set<AstNormalizer.Normaliza
390390
private static CascadesPlanner createPlanner(@Nonnull final RecordMetaData metaData,
391391
@Nonnull final RecordStoreState recordStoreState,
392392
@Nonnull final PlanContext planContext) {
393-
final var planner = new CascadesPlanner(metaData, recordStoreState);
393+
final var planner = new CascadesPlanner(
394+
metaData,
395+
recordStoreState,
396+
planContext.getMetricsCollector().getRecordLayerStoreTimer());
394397
planner.setConfiguration(planContext.getRecordQueryPlannerConfiguration());
395398
return planner;
396399
}

‎fdb-relational-core/src/main/java/com/apple/foundationdb/relational/util/RelationalLoggingUtil.java

Lines changed: 14 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -23,6 +23,8 @@
2323
import com.apple.foundationdb.annotation.API;
2424

2525
import com.apple.foundationdb.record.logging.KeyValueLogMessage;
26+
import com.apple.foundationdb.record.provider.common.StoreTimer;
27+
import com.apple.foundationdb.record.query.plan.cascades.PlannerTimerEvents;
2628
import com.apple.foundationdb.relational.api.Options;
2729
import com.apple.foundationdb.relational.api.exceptions.RelationalException;
2830
import com.apple.foundationdb.relational.recordlayer.query.OptionsUtils;
@@ -32,13 +34,24 @@
3234
import org.apache.logging.log4j.Logger;
3335

3436
import javax.annotation.Nullable;
37+
import java.util.Optional;
38+
import java.util.concurrent.TimeUnit;
3539

3640
@API(API.Status.EXPERIMENTAL)
3741
public class RelationalLoggingUtil {
3842
public static void publishPlanGenerationLogs(Logger logger, KeyValueLogMessage message, @Nullable Plan<?> plan,
39-
@Nullable RelationalException e, long totalTime, Options options) {
43+
@Nullable RelationalException e, @Nullable StoreTimer storeTimer,
44+
long totalTime, Options options) {
4045
final boolean logQuery = options.getOption(Options.Name.LOG_QUERY);
4146
final boolean isSlow = totalTime > (long) options.getOption(Options.Name.LOG_SLOW_QUERY_THRESHOLD_MICROS);
47+
48+
if (storeTimer != null) {
49+
Optional.ofNullable(storeTimer.getCounter(PlannerTimerEvents.REWRITING_PHASE_COMPLETE)).ifPresent(
50+
(c) -> message.addKeyAndValue("plannerRewritingPhaseTimeMicros", TimeUnit.NANOSECONDS.toMicros(c.getTimeNanos())));
51+
Optional.ofNullable(storeTimer.getCounter(PlannerTimerEvents.PLANNING_PHASE_COMPLETE)).ifPresent(
52+
(c) -> message.addKeyAndValue("plannerPlanningPhaseTimeMicros", TimeUnit.NANOSECONDS.toMicros(c.getTimeNanos())));
53+
}
54+
4255
message.addKeyAndValue("totalPlanTimeMicros", totalTime);
4356
if (plan != null) {
4457
if (plan instanceof QueryPlan.PhysicalQueryPlan) {

0 commit comments

Comments
 (0)