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 75737c4108..559cb73d5f 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 @@ -383,16 +383,65 @@ public QueryPlanResult planGraph(@Nonnull final Supplier referenceSup Debugger.getDebuggerMaybe() .flatMap(Debugger::getStatsMaps).orElse(null)) .build()); + } catch (UnableToPlanException e) { + if (logger.isErrorEnabled()) { + final var logBuilder = KeyValueLogMessage.build("Unable to plan query", + "recordMetadata", metaData.toProto().toString(), + "parameterValues", evaluationContext.getBindings().toString(), + "indexStates", recordStoreState.getIndexStates().toString(), + "dataStoreInfo", recordStoreState.getStoreHeader().toString(), + "taskCount", taskCount, + "maxQueueSize", maxQueueSize, + "plannerConfiguration", configuration.toString()); + + // Add match candidates info if present + if (e.getMatchCandidatesInfo() != null) { + logBuilder.addKeyAndValue("matchCandidatesInfo", e.getMatchCandidatesInfo()); + } + + logger.error(logBuilder.toString(), e); + } + throw e; } finally { Debugger.withDebugger(Debugger::onDone); } } + /** + * Builds a detailed string representation of match candidates for diagnostic purposes. + * This includes the candidate type, name, record types, uniqueness, and column size. + * + * @param matchCandidates the collection of match candidates to describe + * @return a formatted string describing all match candidates + */ + @Nonnull + static String buildMatchCandidatesInfo(@Nonnull final Collection matchCandidates) { + final var matchCandidatesBuilder = new StringBuilder("Match Candidates:\n"); + if (matchCandidates.isEmpty()) { + matchCandidatesBuilder.append(" (none)"); + } else { + for (final var candidate : matchCandidates) { + matchCandidatesBuilder.append(String.format(" - Type: %s, Name: %s, RecordTypes: [%s], Unique: %s, ColumnSize: %d%n", + candidate.getClass().getSimpleName(), + candidate.getName(), + String.join(", ", candidate.getQueriedRecordTypeNames()), + candidate.isUnique(), + candidate.getColumnSize())); + } + } + return matchCandidatesBuilder.toString(); + } + private RecordQueryPlan resultOrFail() { final Set finalExpressions = currentRoot.getFinalExpressions(); Verify.verify(finalExpressions.size() <= 1, "more than one variant present"); if (finalExpressions.isEmpty()) { - throw new UnableToPlanException("Cascades planner could not plan query"); + // Build match candidates info + final var matchCandidates = planContext.getMatchCandidates(); + final var matchCandidatesInfo = buildMatchCandidatesInfo(matchCandidates); + + throw new UnableToPlanException("Cascades planner could not plan query") + .withMatchCandidatesInfo(matchCandidatesInfo); } final RelationalExpression singleRoot = Iterables.getOnlyElement(finalExpressions); diff --git a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/UnableToPlanException.java b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/UnableToPlanException.java index 46813e09a2..bd4c8f830f 100644 --- a/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/UnableToPlanException.java +++ b/fdb-record-layer-core/src/main/java/com/apple/foundationdb/record/query/plan/cascades/UnableToPlanException.java @@ -33,7 +33,30 @@ public class UnableToPlanException extends RecordCoreException { private static final long serialVersionUID = -640771754012134420L; + @Nullable + private String matchCandidatesInfo; + public UnableToPlanException(@Nonnull String msg, @Nullable Object ... keyValues) { super(msg, keyValues); } + + /** + * Set match candidates information to be included when logging this exception. + * @param matchCandidatesInfo String representation of match candidates + * @return this exception for chaining + */ + @Nonnull + public UnableToPlanException withMatchCandidatesInfo(@Nullable String matchCandidatesInfo) { + this.matchCandidatesInfo = matchCandidatesInfo; + return this; + } + + /** + * Get the match candidates information associated with this exception. + * @return match candidates info string, or null if not set + */ + @Nullable + public String getMatchCandidatesInfo() { + return matchCandidatesInfo; + } } diff --git a/fdb-record-layer-core/src/test/java/com/apple/foundationdb/record/query/plan/cascades/UnableToPlanExceptionTest.java b/fdb-record-layer-core/src/test/java/com/apple/foundationdb/record/query/plan/cascades/UnableToPlanExceptionTest.java new file mode 100644 index 0000000000..bcce4245ec --- /dev/null +++ b/fdb-record-layer-core/src/test/java/com/apple/foundationdb/record/query/plan/cascades/UnableToPlanExceptionTest.java @@ -0,0 +1,59 @@ +/* + * UnableToPlanExceptionTest.java + * + * This source file is part of the FoundationDB open source project + * + * Copyright 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 org.junit.jupiter.api.Test; + +import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertNull; +import static org.junit.jupiter.api.Assertions.assertSame; + +/** + * Tests for {@link UnableToPlanException}. + */ +public class UnableToPlanExceptionTest { + @Test + public void testWithMatchCandidatesInfo() { + final UnableToPlanException exception = new UnableToPlanException("Test message"); + final String matchCandidatesInfo = "Match Candidates:\n - candidate1\n - candidate2"; + + final UnableToPlanException result = exception.withMatchCandidatesInfo(matchCandidatesInfo); + + // Verify it returns the same instance (fluent API) + assertSame(exception, result); + + // Verify the match candidates info was set + assertEquals(matchCandidatesInfo, exception.getMatchCandidatesInfo()); + } + + @Test + public void testWithNullValue() { + final UnableToPlanException exception = new UnableToPlanException("Test message"); + + // Set to non-null value first + exception.withMatchCandidatesInfo("match"); + assertEquals("match", exception.getMatchCandidatesInfo()); + + // Now set to null + exception.withMatchCandidatesInfo(null); + assertNull(exception.getMatchCandidatesInfo()); + } +} 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 d5adc8953c..c17a623a59 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 @@ -33,6 +33,7 @@ import com.apple.foundationdb.record.query.plan.cascades.CascadesPlanner; import com.apple.foundationdb.record.query.plan.cascades.SemanticException; import com.apple.foundationdb.record.query.plan.cascades.StableSelectorCostModel; +import com.apple.foundationdb.record.query.plan.cascades.UnableToPlanException; import com.apple.foundationdb.record.query.plan.cascades.typing.TypeRepository; import com.apple.foundationdb.record.query.plan.plans.RecordQueryPlan; import com.apple.foundationdb.record.query.plan.serialization.DefaultPlanSerializationRegistry; @@ -239,6 +240,25 @@ private Plan generatePhysicalPlanForCompilableStatement(@Nonnull AstNormalize planContext.getConstantActionFactory(), planContext.getDbUri(), caseSensitive) .generateLogicalPlan(ast.getParseTree())); return maybePlan.optimize(planner, planContext, currentPlanHashMode); + } catch (UnableToPlanException e) { + // Log plan cache information when planning fails + cache.ifPresent(relationalPlanCache -> logPlanCacheOnFailure(relationalPlanCache, logger)); + + // Log connection options information when planning fails + if (logger.isErrorEnabled()) { + final var optionsBuilder = new StringBuilder("Connection Options:\n"); + for (final var entry : options.entries()) { + final var key = entry.getKey(); + final var value = entry.getValue(); + optionsBuilder.append(String.format(" %s = %s%n", + key, + value != null ? value.toString() : "null")); + } + logger.error(KeyValueLogMessage.of("Connection options when unable to plan", + "connectionOptions", optionsBuilder.toString())); + } + + throw e; } catch (MetaDataException mde) { // we need a better way for translating error codes between record layer and Relational SQL error codes throw new RelationalException(mde.getMessage(), ErrorCode.SYNTAX_OR_ACCESS_VIOLATION, mde).toUncheckedWrappedException(); @@ -371,6 +391,44 @@ public Options getOptions() { return options; } + /** + * Logs the plan cache state when unable to plan a query. + * This method collects tertiary cache statistics and logs them for debugging purposes. + * + * @param cache The optional plan cache + * @param logger The logger instance + */ + static void logPlanCacheOnFailure(@Nonnull final RelationalPlanCache cache, + @Nonnull final Logger logger) { + if (logger.isErrorEnabled()) { + final var cacheStats = cache.getStats(); + final var allPrimaryKeys = cacheStats.getAllKeys(); + final var cacheInfoBuilder = new StringBuilder("Plan Cache Tertiary Layer:\n"); + + for (final var primaryKey : allPrimaryKeys) { + final var secondaryKeys = cacheStats.getAllSecondaryKeys(primaryKey); + for (final var secondaryKey : secondaryKeys) { + final var tertiaryMappings = cacheStats.getAllTertiaryMappings(primaryKey, secondaryKey); + if (!tertiaryMappings.isEmpty()) { + cacheInfoBuilder.append(String.format(" [%s][%s]: %d entries%n", primaryKey, secondaryKey, tertiaryMappings.size())); + for (final var entry : tertiaryMappings.entrySet()) { + cacheInfoBuilder.append(String.format(" - %s%n", entry.getKey().toString())); + } + } + } + } + + cacheInfoBuilder.append(String.format("Cache Stats: size=%d, hits=%d, misses=%d", + cacheStats.numEntries(), cacheStats.numHits(), cacheStats.numMisses())); + + logger.error(KeyValueLogMessage.of("Plan cache state when unable to plan", + "planCacheTertiaryLayer", cacheInfoBuilder.toString(), + "planCachePrimarySize", cacheStats.numEntries(), + "planCachePrimaryHits", cacheStats.numHits(), + "planCachePrimaryMisses", cacheStats.numMisses())); + } + } + /** * Determines whether the query should be looked up and, if not found, cached in the plan cache. Currently, we take * this decision is taken statically, in the future we should combine with other combine it with environmental diff --git a/fdb-relational-core/src/main/java/com/apple/foundationdb/relational/recordlayer/query/cache/MultiStageCache.java b/fdb-relational-core/src/main/java/com/apple/foundationdb/relational/recordlayer/query/cache/MultiStageCache.java index fe6f3b5798..803ac5c5b5 100644 --- a/fdb-relational-core/src/main/java/com/apple/foundationdb/relational/recordlayer/query/cache/MultiStageCache.java +++ b/fdb-relational-core/src/main/java/com/apple/foundationdb/relational/recordlayer/query/cache/MultiStageCache.java @@ -21,6 +21,7 @@ package com.apple.foundationdb.relational.recordlayer.query.cache; import com.apple.foundationdb.annotation.API; +import com.apple.foundationdb.record.logging.KeyValueLogMessage; import com.apple.foundationdb.record.util.pair.NonnullPair; import com.apple.foundationdb.relational.api.exceptions.ErrorCode; import com.apple.foundationdb.relational.api.metrics.RelationalMetric; @@ -30,6 +31,8 @@ import com.github.benmanes.caffeine.cache.RemovalListener; import com.google.common.annotations.VisibleForTesting; import com.google.common.base.Ticker; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; import javax.annotation.Nonnull; import javax.annotation.Nullable; @@ -92,6 +95,9 @@ @API(API.Status.EXPERIMENTAL) public class MultiStageCache extends AbstractCache { + @Nonnull + private static final Logger logger = LoggerFactory.getLogger(MultiStageCache.class); + @Nonnull private final Cache>> mainCache; @@ -167,7 +173,14 @@ public V reduce(@Nonnull final K key, final var secondaryCacheBuilder = Caffeine.newBuilder() .maximumSize(secondarySize) .recordStats() - .removalListener((RemovalListener>) (k, v, i) -> { + .removalListener((RemovalListener>) (k, v, cause) -> { + if (logger.isDebugEnabled()) { + logger.debug(KeyValueLogMessage.of("Plan cache secondary entry evicted", + "primaryKey", key, + "secondaryKey", k, + "cause", cause.toString(), + "remainingEntries", v != null ? v.estimatedSize() : 0)); + } final var value = mainCache.getIfPresent(key); if (value != null && value.asMap().isEmpty()) { mainCache.invalidate(key); // best effort @@ -190,7 +203,15 @@ public V reduce(@Nonnull final K key, final var tertiaryCacheBuilder = Caffeine.newBuilder() .maximumSize(tertiarySize) .recordStats() - .removalListener((RemovalListener) (k, v, i) -> { + .removalListener((RemovalListener) (k, v, cause) -> { + if (logger.isDebugEnabled()) { + logger.debug(KeyValueLogMessage.of("Plan cache tertiary entry evicted", + "primaryKey", key, + "secondaryKey", secondaryKey, + "tertiaryKey", k, + "cause", cause.toString(), + "valueType", v != null ? v.getClass().getSimpleName() : "null")); + } final var value = secondaryCache.getIfPresent(secondaryKey); if (value != null && value.asMap().isEmpty()) { secondaryCache.invalidate(secondaryKey); // best effort diff --git a/fdb-relational-core/src/test/java/com/apple/foundationdb/relational/recordlayer/query/PlanGeneratorCacheLoggingTest.java b/fdb-relational-core/src/test/java/com/apple/foundationdb/relational/recordlayer/query/PlanGeneratorCacheLoggingTest.java new file mode 100644 index 0000000000..f4a9752f72 --- /dev/null +++ b/fdb-relational-core/src/test/java/com/apple/foundationdb/relational/recordlayer/query/PlanGeneratorCacheLoggingTest.java @@ -0,0 +1,196 @@ +/* + * PlanGeneratorCacheLoggingTest.java + * + * This source file is part of the FoundationDB open source project + * + * Copyright 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.relational.recordlayer.query; + +import com.apple.foundationdb.record.EvaluationContext; +import com.apple.foundationdb.record.query.plan.QueryPlanConstraint; +import com.apple.foundationdb.record.query.plan.cascades.CascadesPlanner; +import com.apple.foundationdb.record.util.pair.NonnullPair; +import com.apple.foundationdb.relational.recordlayer.query.cache.PhysicalPlanEquivalence; +import com.apple.foundationdb.relational.recordlayer.query.cache.QueryCacheKey; +import com.apple.foundationdb.relational.recordlayer.query.cache.RelationalPlanCache; +import org.apache.logging.log4j.Level; +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.core.LogEvent; +import org.apache.logging.log4j.core.appender.AbstractAppender; +import org.apache.logging.log4j.core.config.Property; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Test; + +import javax.annotation.Nonnull; +import java.util.ArrayList; +import java.util.List; + +import static org.junit.jupiter.api.Assertions.assertFalse; +import static org.junit.jupiter.api.Assertions.assertTrue; + +/** + * Tests for {@link PlanGenerator#logPlanCacheOnFailure(RelationalPlanCache, org.apache.logging.log4j.Logger)}. + */ +public class PlanGeneratorCacheLoggingTest { + + private TestAppender testAppender; + private org.apache.logging.log4j.core.Logger logger; + + @BeforeEach + public void setup() { + testAppender = new TestAppender("TestAppender"); + testAppender.start(); + logger = (org.apache.logging.log4j.core.Logger) LogManager.getLogger(PlanGenerator.class); + logger.addAppender(testAppender); + logger.setLevel(Level.ERROR); + } + + @AfterEach + public void tearDown() { + logger.removeAppender(testAppender); + testAppender.stop(); + } + + @Test + public void testColdCacheScenario() { + // Create a cache with no entries (cold cache) + final RelationalPlanCache cache = RelationalPlanCache.buildWithDefaults(); + + // Log the cache state + PlanGenerator.logPlanCacheOnFailure(cache, logger); + + // Should log even with empty cache + assertFalse(testAppender.getEvents().isEmpty(), + "Should log even when cache is empty"); + + final LogEvent event = testAppender.getEvents().get(0); + final String message = event.getMessage().getFormattedMessage(); + + // Verify it contains cache stats showing empty cache + assertTrue(message.contains("Plan cache state when unable to plan"), + "Message should indicate plan cache state"); + assertTrue(message.contains("size=0") || message.contains("planCachePrimarySize"), + "Should show cache size of 0 for cold cache"); + } + + @Test + public void testWarmCacheScenario() { + // Create a cache and populate it with some entries + final RelationalPlanCache cache = RelationalPlanCache.buildWithDefaults(); + + // Add a mock plan entry to warm up the cache + final String schemaName = "testSchema"; + final var queryCacheKey = QueryCacheKey.of( + "SELECT * FROM test", + PlannerConfiguration.ofAllAvailableIndexes(), + "testDbPath", + 123456, + 1, + 0); + final var planEquivalence = PhysicalPlanEquivalence.of(EvaluationContext.empty()); + + // Create a simple mock plan + final Plan mockPlan = new Plan("SELECT * FROM test") { + @Override + public boolean isUpdatePlan() { + return false; + } + + @Override + public Plan optimize(@Nonnull CascadesPlanner planner, @Nonnull PlanContext planContext, + @Nonnull com.apple.foundationdb.record.PlanHashable.PlanHashMode currentPlanHashMode) { + return this; + } + + @Override + protected String executeInternal(@Nonnull ExecutionContext c) { + return "mock result"; + } + + @Override + @Nonnull + public QueryPlanConstraint getConstraint() { + return QueryPlanConstraint.noConstraint(); + } + + @Override + @Nonnull + public Plan withExecutionContext(@Nonnull QueryExecutionContext queryExecutionContext) { + return this; + } + + @Override + @Nonnull + public String explain() { + return "Mock Plan"; + } + }; + + // Populate cache + cache.reduce( + schemaName, + queryCacheKey, + planEquivalence, + () -> { + // Return plan with constraint + return NonnullPair.of(PhysicalPlanEquivalence.of(QueryPlanConstraint.noConstraint()), mockPlan); + }, + plan -> plan, + stream -> stream.findFirst().orElse(null), + event -> { } + ); + + // Log the cache state + PlanGenerator.logPlanCacheOnFailure(cache, logger); + + // Should log with cache content + assertFalse(testAppender.getEvents().isEmpty(), + "Should log when cache has entries"); + + final LogEvent event = testAppender.getEvents().get(0); + final String message = event.getMessage().getFormattedMessage(); + + // Verify it contains cache information + assertTrue(message.contains("Plan cache state when unable to plan"), + "Message should indicate plan cache state"); + assertTrue(message.contains(schemaName), + "Should show schema name from cache"); + assertTrue(message.contains("entries") || message.contains("planCachePrimarySize"), + "Should show cache has entries"); + } + + /** + * Custom Log4j2 appender for capturing log events in tests. + */ + private static class TestAppender extends AbstractAppender { + private final List events = new ArrayList<>(); + + protected TestAppender(String name) { + super(name, null, null, true, Property.EMPTY_ARRAY); + } + + @Override + public void append(LogEvent event) { + events.add(event.toImmutable()); + } + + public List getEvents() { + return events; + } + } +}