This is an automated email from the ASF dual-hosted git repository. rmaucher pushed a commit to branch 9.0.x in repository https://gitbox.apache.org/repos/asf/tomcat.git
commit 09cd65483acf80a4f68cf0c4a1e1b363554d96bc Author: opencode <[email protected]> AuthorDate: Tue Oct 27 18:01:26 2026 +0100 Fix immortal prepare-only entries inverting slow query LRU eviction SlowQueryReport.QueryStats.prepare() only updated prepareCount and prepareTime, leaving lastInvocation at its initial 0. The eviction comparator maps 0 to Long.MAX_VALUE - never invoked counts as the newest possible invocation - so statistics for statements that were prepared but never executed (statement-cache entries discarded un-executed, applications that prepare literals and drop them) sorted last and were therefore evicted last, i.e. never: they occupied maxQueries slots for ever and, once capacity was reached, removeOldest() discarded the statistics of genuinely executed queries before ever touching the prepare-only garbage. Under prepare-heavy churn of distinct SQL the slow query report converged to holding only useless entries. Record preparation as activity on the entry: prepare() now also sets lastInvocation to the current time, so prepared-but-never-executed entries age like any other and are evicted by LRU in the normal order. The fresh-entry protection is unchanged - the eviction check inside getQueryStats() runs while a just-inserted entry still has lastInvocation == 0, and both prepare() and add()/failure() update the timestamp only after getQueryStats() returns - and handleZero() is kept for entries that were created but never touched at all (bug 58489). Single-threaded eviction ordering for executed queries, and therefore the content exposed via getPoolStats() and the SlowQueryReportJmx getSlowQueriesCD() dump (which does no sorting of its own), are unaffected. The JMX field description for lastInvocation was reworded to match the new semantics. Regression coverage in TestSlowQueryEviction: an end-to-end test on a real pool with maxQueries=5 shows that a churn of 20 distinct prepare-only statements used to evict every executed query's statistics while keeping the prepare-only entries (pre-fix the 5-slot map held four prepare-only entries and a single lucky executed query), and a unit test asserts through the JMX composite data that preparing a query now updates its lastInvocation. Both fail before the fix and pass after it; the full module suite runs 264 tests, 0 failures. --- .../jdbc/pool/interceptor/SlowQueryReport.java | 10 ++- .../pool/interceptor/TestSlowQueryEviction.java | 97 ++++++++++++++++++++++ 2 files changed, 104 insertions(+), 3 deletions(-) diff --git a/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/interceptor/SlowQueryReport.java b/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/interceptor/SlowQueryReport.java index 368311b53d..b48d8f02c7 100644 --- a/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/interceptor/SlowQueryReport.java +++ b/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/interceptor/SlowQueryReport.java @@ -406,7 +406,7 @@ public class SlowQueryReport extends AbstractQueryReport { "The number of failures for this query", "The number of times this query was prepared (prepareStatement/prepareCall)", "The total number of milliseconds spent preparing this query", - "The date and time of the last invocation" + "The date and time of the last invocation or preparation" }; static final OpenType<?>[] FIELD_TYPES = new OpenType[] { @@ -541,14 +541,18 @@ public class SlowQueryReport extends AbstractQueryReport { } /** - * Records the time taken to prepare this query. + * Records the time taken to prepare this query. Preparation counts as + * activity on the entry, so the last invocation time that orders the + * statistics for eviction is updated as well: a statement that is + * prepared but never executed must age like any other query instead + * of occupying a statistics slot for ever. * * @param invocationTime the time in milliseconds to prepare the query */ public synchronized void prepare(long invocationTime) { prepareCount++; prepareTime+=invocationTime; - + lastInvocation = System.currentTimeMillis(); } /** diff --git a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestSlowQueryEviction.java b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestSlowQueryEviction.java index 69d6649786..8ba701f989 100644 --- a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestSlowQueryEviction.java +++ b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestSlowQueryEviction.java @@ -17,6 +17,8 @@ package org.apache.tomcat.jdbc.pool.interceptor; import java.sql.Connection; +import java.sql.PreparedStatement; +import java.sql.Statement; import java.util.concurrent.ConcurrentHashMap; import java.util.concurrent.CopyOnWriteArrayList; import java.util.concurrent.CountDownLatch; @@ -25,6 +27,9 @@ import java.util.concurrent.Executors; import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicInteger; +import javax.management.openmbean.CompositeData; +import javax.management.openmbean.CompositeType; + import org.junit.jupiter.api.Assertions; import org.junit.jupiter.api.Test; @@ -180,4 +185,96 @@ class TestSlowQueryEviction extends JdbcPoolBaseTest { "the map must stay near its configured capacity, was " + size); Assertions.assertTrue(size > 0, "the map must still hold statistics, was " + size); } + + /* + * Prepared-but-never-executed statements are ordinary users of a + * statistics slot: the statement cache throws them out un-executed and + * applications prepare literals and discard them. They must therefore + * age like any other entry. Because preparation used to leave + * lastInvocation at zero - which the comparator treats as the newest + * possible invocation - it was picked for eviction last, so a churn of + * distinct prepared SQL pushed the real, executed queries out of the + * report instead of itself. + */ + @Test + void prepareOnlyChurnDoesNotEvictTheExecutedQueries() throws Exception { + DataSource ds = newDataSource(); + ds.getPoolProperties().setJdbcInterceptors( + "org.apache.tomcat.jdbc.pool.interceptor.SlowQueryReport" + + "(maxQueries=5)"); + ds.createPool(); + String poolName = ds.getPoolProperties().getPoolName(); + + int prepared = 20; + int executed = 5; + try (Connection c = ds.getConnection()) { + for (int i = 0; i < prepared; i++) { + try (PreparedStatement ps = c.prepareStatement( + "SELECT 1 /* prepare-only " + i + " */")) { + // never executed, the statement is simply discarded + } + } + ConcurrentHashMap<String,QueryStats> stats = + SlowQueryReport.getPoolStats(poolName); + Assertions.assertTrue(stats.keySet().stream() + .anyMatch(sql -> sql.contains("prepare-only")), + "the prepared statements must have been registered"); + + // The two phases are ordered by real time, and the timestamps + // are millisecond-resolution, so the executed queries must start + // measurably after the last preparation for the eviction order + // below to be strict rather than decided by a comparator tie. + // Wait for the clock to pass the deadline rather than trusting a + // fixed sleep: every preparation timestamp was taken before it. + long prepareDeadline = System.currentTimeMillis(); + while (System.currentTimeMillis() <= prepareDeadline) { + Thread.sleep(1); + } + + for (int i = 0; i < executed; i++) { + try (Statement st = c.createStatement()) { + st.execute("SELECT 1 /* executed " + i + " */"); + } + } + } + + ConcurrentHashMap<String,QueryStats> stats = + SlowQueryReport.getPoolStats(poolName); + for (int i = 0; i < executed; i++) { + Assertions.assertTrue( + stats.containsKey("SELECT 1 /* executed " + i + " */"), + "an executed query must outlive a churn of prepared-only " + + "statements, but SELECT 1 /* executed " + i + + " */ was evicted; the map held " + stats.keySet()); + } + Assertions.assertTrue( + stats.keySet().stream().noneMatch(sql -> sql.contains("prepare-only")), + "prepared-only entries are the oldest activity in the map and " + + "must be evicted first, but the map held " + + stats.keySet()); + } + + /* + * Preparation is activity on the entry, so it must be what the entry is + * aged by: the last invocation time the eviction orders on has to + * reflect it, and the statistics the reporting MBean publishes have to + * show it. + */ + @Test + void preparingAQueryUpdatesItsLastInvocationTime() throws Exception { + QueryStats stats = new QueryStats("SELECT 1 /* prepared only */"); + long before = System.currentTimeMillis(); + stats.prepare(3); + long after = System.currentTimeMillis(); + + CompositeType type = new CompositeType("QueryStats", "QueryStats", + QueryStats.getFieldNames(), QueryStats.getFieldDescriptions(), + QueryStats.getFieldTypes()); + CompositeData data = stats.getCompositeData(type); + long lastInvocation = ((Number) data.get("lastInvocation")).longValue(); + + Assertions.assertTrue(lastInvocation >= before && lastInvocation <= after, + "preparing a query must record when it happened, was " + + lastInvocation); + } } --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
