Skip to content

Commit 565a6da

Browse files
alecgrieseralecgrieser
authored
RecordQueryPlanComplexityException now includes only a shortened plan string as a log message key (#3168)
This updates the plan string in the default `RecordQueryPlanComplexityException` to include only the first 1k characters in the plan string. This decreases the total size of the data pushed to the exception for logging. It also updates the `RecordQueryPlanComplexityException` class so that it extends `RecordQueryException` and uses the log message keys now available in order to convey information instead of relying updating the error message with each error. This resolves #3167.
1 parent 889cca7 commit 565a6da

File tree

6 files changed

+152
-26
lines changed

6 files changed

+152
-26
lines changed

‎fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/logging/LogMessageKeys.java

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -278,6 +278,15 @@ public enum LogMessageKeys {
278278
PLAN,
279279
PLAN_HASH,
280280
QUERY,
281+
RULE,
282+
COMPLEXITY,
283+
RULE_MATCHES_COUNT,
284+
TASK_COUNT,
285+
TASK_QUEUE_SIZE,
286+
MAX_COMPLEXITY,
287+
MAX_RULE_MATCHES_COUNT,
288+
MAX_TASK_COUNT,
289+
MAX_TASK_QUEUE_SIZE,
281290

282291
// error
283292
ERROR,

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

Lines changed: 7 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -21,26 +21,26 @@
2121
package com.apple.foundationdb.record.query.plan;
2222

2323
import com.apple.foundationdb.annotation.API;
24+
import com.apple.foundationdb.record.RecordCoreException;
25+
import com.apple.foundationdb.record.logging.LogMessageKeys;
26+
import com.apple.foundationdb.record.query.plan.explain.ExplainLevel;
27+
import com.apple.foundationdb.record.query.plan.explain.ExplainPlanVisitor;
2428
import com.apple.foundationdb.record.query.plan.plans.RecordQueryPlan;
2529

2630
import javax.annotation.Nonnull;
27-
import javax.annotation.Nullable;
2831

2932
/**
3033
* Exception thrown when a query plan is more complex than the configured limit.
3134
*/
3235
@SuppressWarnings("serial")
3336
@API(API.Status.UNSTABLE)
34-
public class RecordQueryPlanComplexityException extends RuntimeException {
37+
public class RecordQueryPlanComplexityException extends RecordCoreException {
3538
public RecordQueryPlanComplexityException(@Nonnull String msg) {
3639
super(msg);
3740
}
3841

39-
public RecordQueryPlanComplexityException(@Nonnull String msg, @Nullable Throwable cause) {
40-
super(msg, cause);
41-
}
42-
4342
public RecordQueryPlanComplexityException(RecordQueryPlan plan) {
44-
this("AttemptedPlan: " + plan.toString());
43+
this("Plan exceeds complexity threshold");
44+
addLogInfo(LogMessageKeys.PLAN, ExplainPlanVisitor.toStringForExternalExplain(plan, ExplainLevel.ALL_DETAILS, 1_000));
4545
}
4646
}

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

Lines changed: 13 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -30,6 +30,7 @@
3030
import com.apple.foundationdb.record.RecordMetaData;
3131
import com.apple.foundationdb.record.RecordStoreState;
3232
import com.apple.foundationdb.record.logging.KeyValueLogMessage;
33+
import com.apple.foundationdb.record.logging.LogMessageKeys;
3334
import com.apple.foundationdb.record.metadata.Index;
3435
import com.apple.foundationdb.record.metadata.IndexOptions;
3536
import com.apple.foundationdb.record.metadata.IndexTypes;
@@ -325,7 +326,9 @@ public RecordQueryPlan plan(@Nonnull RecordQuery query, @Nonnull ParameterRelati
325326
}
326327

327328
if (plan.getComplexity() > configuration.getComplexityThreshold()) {
328-
throw new RecordQueryPlanComplexityException(plan);
329+
throw new RecordQueryPlanComplexityException(plan)
330+
.addLogInfo(LogMessageKeys.COMPLEXITY, plan.getComplexity())
331+
.addLogInfo(LogMessageKeys.MAX_COMPLEXITY, configuration.getComplexityThreshold());
329332
}
330333

331334
if (logger.isTraceEnabled()) {
@@ -1178,7 +1181,9 @@ private ScoredPlan planIntersection(@Nonnull List<ScoredPlan> intersectionCandid
11781181
// after this call.
11791182
final RecordQueryPlan intersectionPlan = RecordQueryIntersectionPlan.from(includedPlans, comparisonKey);
11801183
if (intersectionPlan.getComplexity() > configuration.getComplexityThreshold()) {
1181-
throw new RecordQueryPlanComplexityException(intersectionPlan);
1184+
throw new RecordQueryPlanComplexityException(intersectionPlan)
1185+
.addLogInfo(LogMessageKeys.COMPLEXITY, intersectionPlan.getComplexity())
1186+
.addLogInfo(LogMessageKeys.MAX_COMPLEXITY, configuration.getComplexityThreshold());
11821187
}
11831188
return new ScoredPlan(intersectionPlan, nonSargables, Collections.emptyList(),
11841189
computeSargedComparisons(intersectionPlan), plan1.score, plan1.createsDuplicates,
@@ -1927,7 +1932,9 @@ private ScoredPlan planOrderedUnion(@Nonnull PlanContext planContext, @Nonnull L
19271932
boolean showComparisonKey = !comparisonKey.equals(planContext.commonPrimaryKey);
19281933
final RecordQueryPlan unionPlan = RecordQueryUnionPlan.from(childPlans, comparisonKey, showComparisonKey);
19291934
if (unionPlan.getComplexity() > configuration.getComplexityThreshold()) {
1930-
throw new RecordQueryPlanComplexityException(unionPlan);
1935+
throw new RecordQueryPlanComplexityException(unionPlan)
1936+
.addLogInfo(LogMessageKeys.COMPLEXITY, unionPlan.getComplexity())
1937+
.addLogInfo(LogMessageKeys.MAX_COMPLEXITY, configuration.getComplexityThreshold());
19311938
}
19321939

19331940
// If we don't change this when shouldAttemptFailedInJoinAsOr() is true, then we _always_ pick the union plan,
@@ -1952,7 +1959,9 @@ private ScoredPlan planUnorderedUnion(@Nonnull PlanContext planContext, @Nonnull
19521959
}
19531960
final RecordQueryUnorderedUnionPlan unionPlan = RecordQueryUnorderedUnionPlan.from(childPlans);
19541961
if (unionPlan.getComplexity() > configuration.getComplexityThreshold()) {
1955-
throw new RecordQueryPlanComplexityException(unionPlan);
1962+
throw new RecordQueryPlanComplexityException(unionPlan)
1963+
.addLogInfo(LogMessageKeys.COMPLEXITY, unionPlan.getComplexity())
1964+
.addLogInfo(LogMessageKeys.MAX_COMPLEXITY, configuration.getComplexityThreshold());
19561965
}
19571966
return new ScoredPlan(unionPlan, Collections.emptyList(), Collections.emptyList(), Collections.emptySet(),
19581967
1, true, false, false, includedRankComparisons);

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

Lines changed: 13 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -26,6 +26,7 @@
2626
import com.apple.foundationdb.record.RecordMetaData;
2727
import com.apple.foundationdb.record.RecordStoreState;
2828
import com.apple.foundationdb.record.logging.KeyValueLogMessage;
29+
import com.apple.foundationdb.record.logging.LogMessageKeys;
2930
import com.apple.foundationdb.record.query.IndexQueryabilityFilter;
3031
import com.apple.foundationdb.record.query.ParameterRelationshipGraph;
3132
import com.apple.foundationdb.record.query.RecordQuery;
@@ -401,7 +402,9 @@ private void planPartial(@Nonnull Supplier<Reference> referenceSupplier,
401402
while (!taskStack.isEmpty()) {
402403
try {
403404
if (isTaskTotalCountExceeded(configuration, taskCount)) {
404-
throw new RecordQueryPlanComplexityException("Maximum number of tasks (" + configuration.getMaxTotalTaskCount() + ") was exceeded");
405+
throw new RecordQueryPlanComplexityException("Maximum number of tasks was exceeded")
406+
.addLogInfo(LogMessageKeys.MAX_TASK_COUNT, configuration.getMaxTotalTaskCount())
407+
.addLogInfo(LogMessageKeys.TASK_COUNT, taskCount);
405408
}
406409
taskCount++;
407410

@@ -429,7 +432,9 @@ private void planPartial(@Nonnull Supplier<Reference> referenceSupplier,
429432

430433
maxQueueSize = Math.max(maxQueueSize, taskStack.size());
431434
if (isTaskQueueSizeExceeded(configuration, taskStack.size())) {
432-
throw new RecordQueryPlanComplexityException("Maximum task queue size (" + configuration.getMaxTaskQueueSize() + ") was exceeded");
435+
throw new RecordQueryPlanComplexityException("Maximum task queue size was exceeded")
436+
.addLogInfo(LogMessageKeys.MAX_TASK_QUEUE_SIZE, configuration.getMaxTaskQueueSize())
437+
.addLogInfo(LogMessageKeys.TASK_QUEUE_SIZE, taskStack.size());
433438
}
434439
} finally {
435440
Debugger.withDebugger(debugger -> debugger.onEvent(
@@ -878,8 +883,12 @@ public void execute() {
878883
.bindMatches(getConfiguration(), initialBindings, getBindable())
879884
.map(bindings -> new CascadesRuleCall(getContext(), rule, group, traversal, taskStack, bindings, evaluationContext))
880885
.forEach(ruleCall -> {
881-
if (isMaxNumMatchesPerRuleCallExceeded(configuration, numMatches.incrementAndGet())) {
882-
throw new RecordQueryPlanComplexityException("Maximum number of matches per rule call for " + rule + " of " + configuration.getMaxNumMatchesPerRuleCall() + " has been exceeded.");
886+
int ruleMatchesCount = numMatches.incrementAndGet();
887+
if (isMaxNumMatchesPerRuleCallExceeded(configuration, ruleMatchesCount)) {
888+
throw new RecordQueryPlanComplexityException("Maximum number of matches per rule call has been exceeded")
889+
.addLogInfo(LogMessageKeys.RULE, ruleCall)
890+
.addLogInfo(LogMessageKeys.RULE_MATCHES_COUNT, ruleMatchesCount)
891+
.addLogInfo(LogMessageKeys.MAX_RULE_MATCHES_COUNT, configuration.getMaxNumMatchesPerRuleCall());
883892
}
884893
// we notify the debugger (if installed) that the transform task is succeeding and
885894
// about begin and end of the rule call event

‎fdb-record-layer-core/src/test/java/com/apple/foundationdb/record/provider/foundationdb/query/FDBRecordStoreQueryTest.java

Lines changed: 85 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -34,6 +34,7 @@
3434
import com.apple.foundationdb.record.TestRecordsEnumProto;
3535
import com.apple.foundationdb.record.TestRecordsMultiProto;
3636
import com.apple.foundationdb.record.TestRecordsTupleFieldsProto;
37+
import com.apple.foundationdb.record.logging.LogMessageKeys;
3738
import com.apple.foundationdb.record.metadata.Index;
3839
import com.apple.foundationdb.record.metadata.RecordTypeBuilder;
3940
import com.apple.foundationdb.record.metadata.expressions.TupleFieldsHelper;
@@ -44,6 +45,7 @@
4445
import com.apple.foundationdb.record.query.expressions.Comparisons;
4546
import com.apple.foundationdb.record.query.expressions.Query;
4647
import com.apple.foundationdb.record.query.expressions.QueryComponent;
48+
import com.apple.foundationdb.record.query.plan.QueryPlanner;
4749
import com.apple.foundationdb.record.query.plan.RecordQueryPlanComplexityException;
4850
import com.apple.foundationdb.record.query.plan.RecordQueryPlanner;
4951
import com.apple.foundationdb.record.query.plan.cascades.matching.structure.ListMatcher;
@@ -104,6 +106,11 @@
104106
import static com.apple.foundationdb.record.query.plan.match.PlanMatchers.scan;
105107
import static org.hamcrest.MatcherAssert.assertThat;
106108
import static org.hamcrest.Matchers.containsInAnyOrder;
109+
import static org.hamcrest.Matchers.greaterThan;
110+
import static org.hamcrest.Matchers.hasEntry;
111+
import static org.hamcrest.Matchers.hasKey;
112+
import static org.hamcrest.Matchers.instanceOf;
113+
import static org.hamcrest.Matchers.lessThanOrEqualTo;
107114
import static org.hamcrest.core.StringContains.containsString;
108115
import static org.junit.jupiter.api.Assertions.assertEquals;
109116
import static org.junit.jupiter.api.Assertions.assertFalse;
@@ -897,11 +904,28 @@ void queryExcludeNull() throws Exception {
897904
}
898905
}
899906

907+
/**
908+
* Exercise the default code path for checking the complexity limit. There are special code paths that
909+
* check the limit for unions, unordered unions, and intersections, so they have their own methods.
910+
*
911+
* @throws Exception from setting up the planner
912+
*/
900913
@Test
901-
void queryComplexityLimit() throws Exception {
902-
RecordMetaDataHook hook = complexQuerySetupHook();
903-
complexQuerySetup(hook);
914+
void queryComplexityLimitsForInUnion() throws Exception {
915+
List<Integer> values = IntStream.range(0, RecordQueryPlanner.DEFAULT_COMPLEXITY_THRESHOLD + 10)
916+
.boxed()
917+
.collect(Collectors.toList());
918+
919+
RecordQuery query = RecordQuery.newBuilder()
920+
.setRecordType("MySimpleRecord")
921+
.setFilter(Query.field("num_value_3_indexed").in(values))
922+
.setSort(field("rec_no"))
923+
.build();
924+
queryComplexityLimit(query);
925+
}
904926

927+
@Test
928+
void queryOrderedUnionComplexityLimit() throws Exception {
905929
List<QueryComponent> clauses = Lists.newArrayList(Query.field("num_value_unique").greaterThanOrEquals(-1));
906930

907931
for (int i = 0; i < RecordQueryPlanner.DEFAULT_COMPLEXITY_THRESHOLD + 10; i++) {
@@ -912,8 +936,65 @@ void queryComplexityLimit() throws Exception {
912936
.setRecordType("MySimpleRecord")
913937
.setFilter(Query.or(clauses))
914938
.build();
939+
queryComplexityLimit(query);
940+
}
941+
942+
@Test
943+
void queryUnorderedUnionComplexityLimit() throws Exception {
944+
List<QueryComponent> clauses = List.of(
945+
Query.field("str_value_indexed").startsWith("blah"),
946+
Query.field("num_value_3_indexed").greaterThan(4),
947+
Query.field("num_value_unique").lessThanOrEquals(10)
948+
);
949+
950+
RecordQuery query = RecordQuery.newBuilder()
951+
.setRecordType("MySimpleRecord")
952+
.setFilter(Query.or(clauses))
953+
.build();
954+
queryComplexityLimit(query, 3);
955+
}
956+
957+
@Test
958+
void queryIntersectionComplexityLimit() throws Exception {
959+
List<QueryComponent> clauses = Lists.newArrayList(
960+
Query.field("str_value_indexed").equalsValue("even"),
961+
Query.field("num_value_3_indexed").equalsValue(1),
962+
Query.field("num_value_unique").equalsValue(2)
963+
);
964+
RecordQuery query = RecordQuery.newBuilder()
965+
.setRecordType("MySimpleRecord")
966+
.setFilter(Query.and(clauses))
967+
.build();
968+
queryComplexityLimit(query, 3);
969+
}
970+
971+
private void queryComplexityLimit(RecordQuery query) throws Exception {
972+
queryComplexityLimit(query, RecordQueryPlanner.DEFAULT_COMPLEXITY_THRESHOLD);
973+
}
915974

916-
assertThrows(RecordQueryPlanComplexityException.class, () -> planQuery(query));
975+
private void queryComplexityLimit(RecordQuery query, int complexityLimit) throws Exception {
976+
complexQuerySetup(complexQuerySetupHook());
977+
planner.setConfiguration(planner.getConfiguration().asBuilder()
978+
.setIndexScanPreference(QueryPlanner.IndexScanPreference.PREFER_INDEX)
979+
.setAttemptFailedInJoinAsUnionMaxSize(1000)
980+
.setComplexityThreshold(complexityLimit)
981+
.setDeferFetchAfterInJoinAndInUnion(true)
982+
.setDeferFetchAfterUnionAndIntersection(true)
983+
.setOmitPrimaryKeyInOrderingKeyForInUnion(true)
984+
.setOmitPrimaryKeyInUnionOrderingKey(true)
985+
.build());
986+
987+
RecordQueryPlanComplexityException err = assertThrows(RecordQueryPlanComplexityException.class, () -> planQuery(query));
988+
assertThat(err.getLogInfo(), hasKey(LogMessageKeys.PLAN.toString()));
989+
Object plan = err.getLogInfo().get(LogMessageKeys.PLAN.toString());
990+
assertThat(plan, instanceOf(String.class));
991+
assertThat("Expected plan \"" + plan + "\" to be under size threshold", ((String) plan).length(), lessThanOrEqualTo(1003));
992+
993+
assertThat(err.getLogInfo(), hasEntry(LogMessageKeys.MAX_COMPLEXITY.toString(), complexityLimit));
994+
assertThat(err.getLogInfo(), hasKey(LogMessageKeys.COMPLEXITY.toString()));
995+
Object complexity = err.getLogInfo().get(LogMessageKeys.COMPLEXITY.toString());
996+
assertThat(complexity, instanceOf(Number.class));
997+
assertThat(((Number) complexity).intValue(), greaterThan(complexityLimit));
917998
}
918999

9191000
@Test

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

Lines changed: 25 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -20,6 +20,7 @@
2020

2121
package com.apple.foundationdb.record.query.plan.cascades;
2222

23+
import com.apple.foundationdb.record.logging.LogMessageKeys;
2324
import com.apple.foundationdb.record.metadata.expressions.KeyExpression;
2425
import com.apple.foundationdb.record.provider.foundationdb.query.FDBRecordStoreQueryTestBase;
2526
import com.apple.foundationdb.record.query.RecordQuery;
@@ -37,6 +38,10 @@
3738
import java.util.Collections;
3839
import java.util.List;
3940

41+
import static org.hamcrest.MatcherAssert.assertThat;
42+
import static org.hamcrest.Matchers.hasEntry;
43+
import static org.hamcrest.Matchers.hasKey;
44+
4045
/**
4146
* Test the "plan too complex" settings for the cascades planner.
4247
*/
@@ -46,32 +51,45 @@ public class PlanComplexityExceededTest extends FDBRecordStoreQueryTestBase {
4651
private CascadesPlanner cascadesPlanner;
4752

4853
@BeforeEach
49-
public void setup() throws Exception {
54+
void setup() throws Exception {
5055
setUseCascadesPlanner(true);
5156
RecordMetaDataHook hook = complexQuerySetupHook();
5257
complexQuerySetup(hook);
5358
cascadesPlanner = (CascadesPlanner)planner;
5459
}
5560

5661
@Test
57-
public void testPlanSucceeds() throws Exception {
58-
RecordQueryPlan plan = createPlan("MySimpleRecord", Query.field("num_value_2").equalsValue(1));
62+
void testPlanSucceeds() {
63+
createPlan("MySimpleRecord", Query.field("num_value_2").equalsValue(1));
5964
}
6065

6166
@Test
62-
public void testPlanQueueTooLarge() throws Exception {
67+
void testPlanQueueTooLarge() {
6368
cascadesPlanner.setConfiguration(RecordQueryPlannerConfiguration.builder().setMaxTaskQueueSize(1).build());
64-
Assertions.assertThrows(RecordQueryPlanComplexityException.class,
69+
RecordQueryPlanComplexityException err = Assertions.assertThrows(RecordQueryPlanComplexityException.class,
6570
() -> createPlan("MySimpleRecord", Query.field("num_value_2").equalsValue(1)));
71+
assertThat(err.getLogInfo(), hasEntry(LogMessageKeys.MAX_TASK_QUEUE_SIZE.toString(), 1));
72+
assertThat(err.getLogInfo(), hasKey(LogMessageKeys.TASK_QUEUE_SIZE.toString()));
6673
}
6774

6875
@Test
69-
public void testPlanTooManyTasks() throws Exception {
76+
void testPlanTooManyTasks() {
7077
cascadesPlanner.setConfiguration(RecordQueryPlannerConfiguration.builder().setMaxTotalTaskCount(1).build());
71-
Assertions.assertThrows(RecordQueryPlanComplexityException.class,
78+
RecordQueryPlanComplexityException err = Assertions.assertThrows(RecordQueryPlanComplexityException.class,
7279
() -> createPlan("MySimpleRecord", Query.field("num_value_2").equalsValue(1)));
80+
assertThat(err.getLogInfo(), hasEntry(LogMessageKeys.MAX_TASK_COUNT.toString(), 1));
81+
assertThat(err.getLogInfo(), hasKey(LogMessageKeys.TASK_COUNT.toString()));
7382
}
7483

84+
@Test
85+
void testPlanMatchesRuleCallTooManyTimes() {
86+
cascadesPlanner.setConfiguration(RecordQueryPlannerConfiguration.builder().setMaxNumMatchesPerRuleCall(2).build());
87+
RecordQueryPlanComplexityException err = Assertions.assertThrows(RecordQueryPlanComplexityException.class,
88+
() -> createPlan("MySimpleRecord", Query.field("num_value_2").equalsValue(1)));
89+
assertThat(err.getLogInfo(), hasEntry(LogMessageKeys.MAX_RULE_MATCHES_COUNT.toString(), 2));
90+
assertThat(err.getLogInfo(), hasKey(LogMessageKeys.RULE_MATCHES_COUNT.toString()));
91+
assertThat(err.getLogInfo(), hasKey(LogMessageKeys.RULE.toString()));
92+
}
7593

7694
private RecordQueryPlan createPlan(String recordType, QueryComponent filter) {
7795
return createPlan(recordType, filter, null);

0 commit comments

Comments
 (0)