This is an automated email from the ASF dual-hosted git repository. rmaucher pushed a commit to branch 10.1.x in repository https://gitbox.apache.org/repos/asf/tomcat.git
commit c5a0d15c0d9a0220caff3e978c34d6ecaca09042 Author: opencode <[email protected]> AuthorDate: Mon Nov 2 16:59:09 2026 +0100 Book the shared query statistics once when several report definitions share a pool Configuring more than one query reporting interceptor on a pool booked every query execution and every preparation into the shared per-pool statistics once per configured definition. The interceptor chain holds one instance of every definition per pooled connection and each layer's statement proxy measures the same logical execution and hands it to its own report hooks, so the invocation counts, the totals, the failure counter and the prepare counters of the one shared QueryStats entry all grew by the number of definitions - including in the two thresholds configuration the SlowQueryReportJmx javadoc recommends, where the JMX published numbers silently read twice as high as the truth. Booking is now decided by the position the definition holds in the chain rather than by every definition for itself: an instance books only when no statistics storing reporting definition lies beneath it, so the deepest storing definition of the chain books each execution exactly once. That definition sees every execution the layers above it see, so no execution goes unbooked, and its measurement is the one nearest the driver. The layers above it keep their per definition channels untouched - slow and failed query logging, and for SlowQueryReportJmx the notifications, which two tests already pinned at one notification per definition. A definition that stores no statistics (a maxQueries of zero) claims nothing, so it cannot hold the statistics silent for the definitions above it. The decision reads only the chain beneath the instance and the configured capacity of what it finds there, both fixed before the chain is published, and remembers nothing across executions; an execution re-entered from inside a report hook therefore books on its own chain's merits whatever the enclosing execution booked, which the new test exercises through a hook that runs its own query while the enclosing report is being delivered. Booked once per execution: 709 tests green. --- .../jdbc/pool/interceptor/SlowQueryReport.java | 56 ++++- .../TestSlowQueryReportSharedStatistics.java | 235 +++++++++++++++++++++ 2 files changed, 286 insertions(+), 5 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 fc5e671abe..6bc2ed6ec5 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 @@ -35,6 +35,7 @@ import javax.management.openmbean.SimpleType; import org.apache.juli.logging.Log; import org.apache.juli.logging.LogFactory; import org.apache.tomcat.jdbc.pool.ConnectionPool; +import org.apache.tomcat.jdbc.pool.JdbcInterceptor; import org.apache.tomcat.jdbc.pool.PoolProperties.InterceptorProperty; import org.apache.tomcat.jdbc.pool.PooledConnection; import org.apache.tomcat.jdbc.pool.util.MessageFactory; @@ -47,6 +48,14 @@ import org.apache.tomcat.jdbc.pool.util.MessageFactory; * possible with {@code jmxEnabled=false}, which removes the JMX ObjectName clash that would otherwise catch it - * therefore share one statistics map; closing one of them never takes the shared statistics away from the others. * </p> + * <p> + * More than one reporting definition can be configured on one pool - the two-thresholds configuration of + * {@link SlowQueryReportJmx} is documented as a supported use - and every definition sees every execution, so the + * shared statistics are booked by one definition only: the deepest one in the interceptor chain that stores statistics + * (see {@link #booksSharedStats()}). A configuration of several definitions books each execution once, like a single + * definition does; the per-definition channels - this definition's slow and failed query logging - keep firing for + * every definition that configures them. + * </p> */ public class SlowQueryReport extends AbstractQueryReport { @@ -126,7 +135,7 @@ public class SlowQueryReport extends AbstractQueryReport { // execution cannot make the booked duration negative, as it could // while this hook recomputed it from start. long now = System.currentTimeMillis(); - if (this.maxQueries > 0) { + if (booksSharedStats()) { QueryStats qs = this.getQueryStats(sql); if (qs != null) { qs.failure(delta, now); @@ -148,7 +157,7 @@ public class SlowQueryReport extends AbstractQueryReport { @Override protected String reportQuery(String query, Object[] args, final String name, long start, long delta) { String sql = super.reportQuery(query, args, name, start, delta); - if (this.maxQueries > 0) { + if (booksSharedStats()) { QueryStats qs = this.getQueryStats(sql); if (qs != null) { qs.add(delta, start); @@ -160,7 +169,7 @@ public class SlowQueryReport extends AbstractQueryReport { @Override protected String reportSlowQuery(String query, Object[] args, String name, long start, long delta) { String sql = super.reportSlowQuery(query, args, name, start, delta); - if (this.maxQueries > 0) { + if (booksSharedStats()) { QueryStats qs = this.getQueryStats(sql); if (qs != null) { qs.add(delta, start); @@ -201,7 +210,7 @@ public class SlowQueryReport extends AbstractQueryReport { */ @Override public void prepareStatement(String sql, long time) { - if (this.maxQueries > 0) { + if (booksSharedStats()) { QueryStats qs = getQueryStats(sql); if (qs != null) { qs.prepare(time); @@ -217,7 +226,7 @@ public class SlowQueryReport extends AbstractQueryReport { */ @Override public void prepareCall(String sql, long time) { - if (this.maxQueries > 0) { + if (booksSharedStats()) { QueryStats qs = getQueryStats(sql); if (qs != null) { qs.prepare(time); @@ -300,6 +309,43 @@ public class SlowQueryReport extends AbstractQueryReport { return last[0]; } + /** + * Whether this instance is the one to book the shared per-pool-name statistics for the executions its chain + * reports. + * <p> + * Every configured reporting definition wraps the statement again, so one logical execution passes through every + * definition's hooks; booking the shared map from each of them would multiply its invocation counts, totals and + * prepare counters by the number of definitions. The booking therefore belongs to the deepest definition in the + * chain that stores statistics: it sees every execution the layers above it see, so no booking is lost, and its + * measurement is the one closest to the driver. The layers above it report only their own channels - logging and, + * for {@link SlowQueryReportJmx}, notifications. A definition that stores no statistics (a {@code maxQueries} of + * zero) never claims the booking, so it cannot hold the statistics silent for the definitions above it. + * </p> + * <p> + * The decision reads only the chain below this instance and the configured capacity of each layer found there. + * Both are fixed when the chain is built (properties are set before the link, and the chain is published through + * the connection's volatile handler reference), and nothing is remembered across executions, so a re-entered + * execution - a report hook that itself runs a query on this pool - books on its own chain's merits, whatever the + * enclosing execution's layers have already booked or passed on. + * </p> + * + * @return {@code true} if this instance must book the shared statistics for the executions it reports + */ + protected boolean booksSharedStats() { + if (maxQueries <= 0) { + return false; + } + for (JdbcInterceptor i = getNext(); i != null; i = i.getNext()) { + if (i instanceof SlowQueryReport && ((SlowQueryReport) i).maxQueries > 0) { + // A definition that stores statistics lies beneath this one + // in the chain: it sees every execution this instance sees, + // and it is the one to book them + return false; + } + } + return true; + } + /** * Retrieves or creates a QueryStats entry for the given SQL string. * diff --git a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestSlowQueryReportSharedStatistics.java b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestSlowQueryReportSharedStatistics.java new file mode 100644 index 0000000000..e1c1d392e4 --- /dev/null +++ b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestSlowQueryReportSharedStatistics.java @@ -0,0 +1,235 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to You 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 org.apache.tomcat.jdbc.pool.interceptor; + +import java.sql.Connection; +import java.sql.PreparedStatement; +import java.sql.SQLException; +import java.sql.Statement; +import java.util.Map; +import java.util.concurrent.atomic.AtomicBoolean; + +import javax.management.openmbean.CompositeData; +import javax.management.openmbean.CompositeType; + +import org.junit.jupiter.api.Assertions; +import org.junit.jupiter.api.Test; + +import org.apache.tomcat.jdbc.JdbcPoolBaseTest; +import org.apache.tomcat.jdbc.pool.DataSource; + +/** + * Booking of the shared per-pool-name query statistics when more than + * one reporting definition is configured on one pool. + * <p> + * Every configured reporting definition wraps the statement again, so + * one logical execution passes through every definition's hooks. The + * statistics map is shared by all definitions of the pool's name, so it + * must be booked once per execution - by the deepest definition that + * stores statistics - while the per-definition channels (logging, JMX + * notifications, pinned by {@link TestSlowQueryJmxNotifications}) keep + * firing for every definition.</p> + */ +public class TestSlowQueryReportSharedStatistics extends JdbcPoolBaseTest { + + private static final String SQL_ONE = "SELECT 17"; + private static final String SQL_TWO = "SELECT 18"; + + private static final String SQ_REPORT = SlowQueryReport.class.getName(); + + /** + * A report whose {@code reportQuery} hook re-enters the pool: it runs + * its own query on a second borrowed connection while the enclosing + * execution's report is being delivered. Configured with + * {@code maxQueries=0} it opts out of the shared statistics but stays + * a live hook layer - the re-entry scenario in which a per-execution + * claim travelling on a thread-wide scope can starve the enclosing + * execution; the per-chain booking decision must not let it. + */ + public static class ReentryReport extends SlowQueryReport { + /** The pool the hook re-enters; set by the test before the borrow. */ + static volatile DataSource target; + /** The SQL the hook runs. */ + static volatile String innerSql = SQL_TWO; + /** One re-entrant execution per test, on any thread. */ + static final AtomicBoolean ENTERED = new AtomicBoolean(); + + @Override + protected String reportQuery(String query, Object[] args, final String name, long start, long delta) { + String sql = super.reportQuery(query, args, name, start, delta); + if (target != null && ENTERED.compareAndSet(false, true)) { + DataSource ds = target; + String sqlToRun = innerSql; + // The re-entry runs on the reporting thread, while the + // enclosing execution is inside this hook. The statement of + // the re-entered execution must be booked exactly once by + // its own chain, whatever the enclosing execution booked. + try (Connection con = ds.getConnection(); + Statement st = con.createStatement()) { + st.execute(sqlToRun); + } catch (SQLException x) { + throw new IllegalStateException(x); + } + } + return sql; + } + } + + private DataSource twoDefinitions(String interceptors, String poolName) { + DataSource ds = newDataSource(); + ds.setName(poolName); + ds.setJdbcInterceptors(interceptors); + ds.getPoolProperties().setInitialSize(0); + return ds; + } + + private static Map<String, SlowQueryReport.QueryStats> stats(String poolName) { + Map<String, SlowQueryReport.QueryStats> stats = SlowQueryReport.getPoolStats(poolName); + Assertions.assertNotNull(stats, "the running pool must publish statistics under its name"); + return stats; + } + + /** + * Reads a counter off the query statistics the same way the JMX + * {@code SlowQueriesCD} attribute publishes it. + */ + private static Object compositeValue(SlowQueryReport.QueryStats qs, String field) throws Exception { + CompositeType type = new CompositeType("QueryStats", "query statistics", + SlowQueryReport.QueryStats.getFieldNames(), SlowQueryReport.QueryStats.getFieldDescriptions(), + SlowQueryReport.QueryStats.getFieldTypes()); + CompositeData data = qs.getCompositeData(type); + return data.get(field); + } + + @Test + void oneExecutionIsBookedOnceWhenTwoReportDefinitionsShareAPool() throws Exception { + String poolName = "twoDefs-" + System.nanoTime(); + DataSource ds = twoDefinitions(SQ_REPORT + ";" + SQ_REPORT, poolName); + try (Connection con = ds.getConnection(); + PreparedStatement pst = con.prepareStatement(SQL_ONE)) { + pst.execute(); + } + + Map<String, SlowQueryReport.QueryStats> stats = stats(poolName); + SlowQueryReport.QueryStats qs = stats.get(SQL_ONE); + Assertions.assertNotNull(qs, "the executed query must be booked, saw " + stats.keySet()); + Assertions.assertEquals(1, qs.getNrOfInvocations(), + "two report definitions must book the shared statistics once per execution, not multiply them"); + Assertions.assertEquals(1, compositeValue(qs, "prepareCount"), + "the single preparation must be booked once, not once per definition"); + + ds.close(); + } + + @Test + void oneExecutionIsBookedOnceWhenAStatementWrapperSeparatesTheTwoDefinitions() throws Exception { + // The chain-position test that decides who books must not be + // blinded by a statement-wrapping interceptor between the two + // reporting definitions - the statement cache also hides the + // second preparation from the layers above it on a cache hit + String poolName = "twoDefsWrapped-" + System.nanoTime(); + DataSource ds = twoDefinitions(SQ_REPORT + ";org.apache.tomcat.jdbc.pool.interceptor.StatementCache;" + + SQ_REPORT, poolName); + try (Connection con = ds.getConnection()) { + try (PreparedStatement pst = con.prepareStatement(SQL_ONE)) { + pst.execute(); + } + try (PreparedStatement pst = con.prepareStatement(SQL_ONE)) { + pst.execute(); + } + } + + Map<String, SlowQueryReport.QueryStats> stats = stats(poolName); + SlowQueryReport.QueryStats qs = stats.get(SQL_ONE); + Assertions.assertNotNull(qs, "the executed query must be booked, saw " + stats.keySet()); + Assertions.assertEquals(2, qs.getNrOfInvocations(), + "the two executions must book two invocations through the cache, one each"); + Assertions.assertEquals(1, compositeValue(qs, "prepareCount"), + "the cache must book its single real preparation exactly once"); + + ds.close(); + } + + @Test + void theOuterDefinitionBooksWhenTheInnermostStoresNoStatistics() throws Exception { + // A definition with maxQueries=0 stores nothing; it must not hold + // the shared statistics silent for the definitions above it + String poolName = "outerBooks-" + System.nanoTime(); + DataSource ds = twoDefinitions(SQ_REPORT + "(maxQueries=100);" + SQ_REPORT + "(maxQueries=0)", poolName); + try (Connection con = ds.getConnection(); + Statement st = con.createStatement()) { + st.execute(SQL_ONE); + } + + Map<String, SlowQueryReport.QueryStats> stats = stats(poolName); + SlowQueryReport.QueryStats qs = stats.get(SQL_ONE); + Assertions.assertNotNull(qs, + "the outer definition must keep booking while the innermost one stores nothing"); + Assertions.assertEquals(1, qs.getNrOfInvocations(), + "the opted-out inner definition must not suppress the outer one's booking"); + + ds.close(); + } + + @Test + void theInnerDefinitionBooksWhenTheOuterStoresNoStatistics() throws Exception { + String poolName = "innerBooks-" + System.nanoTime(); + DataSource ds = twoDefinitions(SQ_REPORT + "(maxQueries=0);" + SQ_REPORT + "(maxQueries=100)", poolName); + try (Connection con = ds.getConnection(); + Statement st = con.createStatement()) { + st.execute(SQL_ONE); + } + + Map<String, SlowQueryReport.QueryStats> stats = stats(poolName); + SlowQueryReport.QueryStats qs = stats.get(SQL_ONE); + Assertions.assertNotNull(qs, "the inner definition that stores statistics must book"); + Assertions.assertEquals(1, qs.getNrOfInvocations(), + "the opted-out outer definition must add nothing to the shared booking"); + + ds.close(); + } + + @Test + void aReEnteredExecutionIsBookedByItsOwnChain() throws Exception { + String poolName = "reentry-" + System.nanoTime(); + DataSource ds = twoDefinitions(ReentryReport.class.getName() + "(maxQueries=0);" + + SQ_REPORT + "(maxQueries=100)", poolName); + ReentryReport.target = ds; + ReentryReport.ENTERED.set(false); + try { + try (Connection con = ds.getConnection(); + Statement st = con.createStatement()) { + st.execute(SQL_ONE); + } + + Map<String, SlowQueryReport.QueryStats> stats = stats(poolName); + SlowQueryReport.QueryStats outer = stats.get(SQL_ONE); + Assertions.assertNotNull(outer, "the enclosing execution must be booked, saw " + stats.keySet()); + Assertions.assertEquals(1, outer.getNrOfInvocations(), + "the enclosing execution must be booked exactly once"); + SlowQueryReport.QueryStats inner = stats.get(SQL_TWO); + Assertions.assertNotNull(inner, + "the re-entered execution must be booked by its own chain, saw " + stats.keySet()); + Assertions.assertEquals(1, inner.getNrOfInvocations(), + "the re-entered execution must be booked exactly once, neither starved by the " + + "enclosing execution nor multiplied"); + } finally { + ReentryReport.target = null; + ds.close(); + } + } +} --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
