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 09095a230a1fffcc31c66df887819558a144c59e Author: opencode <[email protected]> AuthorDate: Fri Oct 30 09:49:22 2026 +0100 Stop reporting every query as slow at a negative query report threshold StatementProxy.invoke chose between reportSlowQuery and reportQuery with a bare "delta > threshold" comparison, and execution durations are never negative, so any negative threshold - including the documented -1 "record every query" setting - sent every execution down the slow path and left reportQuery unreachable. For SlowQueryReport, whose slow path logs at WARN by default and whose JMX variant notifies on every slow query, following the documented configuration flooded logs and notifications instead of merely recording queries. A negative threshold now keeps executions out of the slow path: every execution is still measured and reported as measured, and only non-negative thresholds compare against the duration. threshold >= 0 behaves exactly as before, non-executions still reach neither hook, and the threshold javadoc now describes what the value actually does. Existing tests that had used threshold=-1 to force the slow path in fixtures now make their test queries genuinely slow instead. --- .../jdbc/pool/interceptor/AbstractQueryReport.java | 39 +++++++--- .../pool/interceptor/TestQueryReportTiming.java | 29 ++++++-- .../interceptor/TestSlowQueryJmxNotifications.java | 83 +++++++++++++++------- 3 files changed, 110 insertions(+), 41 deletions(-) diff --git a/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/interceptor/AbstractQueryReport.java b/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/interceptor/AbstractQueryReport.java index 27e94d53e0..719df84a9f 100644 --- a/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/interceptor/AbstractQueryReport.java +++ b/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/interceptor/AbstractQueryReport.java @@ -37,9 +37,13 @@ public abstract class AbstractQueryReport extends AbstractCreateStatementInterce private static final Log log = LogFactory.getLog(AbstractQueryReport.class); /** - * The threshold in milliseconds. If the query is faster than this, we don't measure it + * The threshold in milliseconds. An execution that takes longer than + * this is reported as a slow query; one that takes no longer is + * reported as a measured query. A negative threshold keeps every + * execution out of the slow path, so every execution is reported as + * measured. */ - protected long threshold = 1000; // Don't report queries less than this + protected long threshold = 1000; // Executions slower than this are slow /** * Constructs a new {@code AbstractQueryReport} with the default threshold. @@ -145,8 +149,10 @@ public abstract class AbstractQueryReport extends AbstractCreateStatementInterce } /** - * returns the query measure threshold. This value is in milliseconds. If the query is faster than this threshold - * than it won't be accounted for + * returns the query measure threshold. This value is in milliseconds. + * An execution that takes longer than this threshold is reported as a + * slow query; see {@link #setThreshold(long)} for the meaning of a + * negative value. * * @return the threshold in milliseconds */ @@ -155,10 +161,16 @@ public abstract class AbstractQueryReport extends AbstractCreateStatementInterce } /** - * Sets the query measurement threshold. The value is in milliseconds. If the query goes faster than this threshold - * it will not be recorded. + * Sets the query measurement threshold. The value is in milliseconds. + * A successful execution that takes longer than this threshold is + * reported through {@link #reportSlowQuery}; one that takes no longer + * is reported through {@link #reportQuery}. A negative threshold + * records every query: every execution is measured and reported as + * measured, and no execution is ever reported as slow. * - * @param threshold set to -1 to record every query. Value is in milliseconds. + * @param threshold the threshold in milliseconds; set to a negative + * value (conventionally -1) to record every query as + * measured without reporting any of them as slow */ public void setThreshold(long threshold) { this.threshold = threshold; @@ -305,8 +317,17 @@ public abstract class AbstractQueryReport extends AbstractCreateStatementInterce } // Measure the time, rounded to the nearest millisecond long delta = (process) ? (System.nanoTime() - startNanos + 500000) / 1000000 : Long.MIN_VALUE; - // See if we meet the requirements to measure - if (delta > threshold) { + // See if we meet the requirements to measure. A negative + // threshold keeps every execution out of the slow path: the + // duration of an execution is never negative, so a bare + // comparison against a negative threshold would pass for + // every execution and leave reportQuery unreachable - the + // documented "record every query" setting must record the + // queries as measured, not report them all as slow. A + // non-execution never reaches either hook: it is not + // processed, and its sentinel duration would stay under every + // threshold anyway. + if (process && threshold >= 0 && delta > threshold) { try { // Report the slow query reportSlowQuery(query, args, name, start, delta); diff --git a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestQueryReportTiming.java b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestQueryReportTiming.java index 80d8139efb..53493f0856 100644 --- a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestQueryReportTiming.java +++ b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestQueryReportTiming.java @@ -16,8 +16,6 @@ */ package org.apache.tomcat.jdbc.pool.interceptor; -import java.lang.reflect.InvocationHandler; -import java.lang.reflect.Method; import java.lang.reflect.Proxy; import java.sql.Statement; @@ -130,9 +128,10 @@ class TestQueryReportTiming { @Test void anExecutionIsNeverReportedWithANegativeDuration() throws Throwable { CapturingReport report = new CapturingReport(); - // every execution goes down the slow path, even a trivially fast one - report.setThreshold(-1); - Object proxy = instrumentedProxy(report, slowDelegate(0)); + // an execution slower than a threshold of zero reaches the slow + // path, which must receive a sound duration and start too + report.setThreshold(0); + Object proxy = instrumentedProxy(report, slowDelegate(40)); Proxy.getInvocationHandler(proxy).invoke(proxy, Statement.class.getMethod("execute", String.class), new Object[] { SQL }); @@ -144,6 +143,26 @@ class TestQueryReportTiming { "a reported execution must carry a wall clock start, was " + report.slowStart); } + @Test + void aNegativeThresholdRecordsEveryExecutionAsMeasuredAndNoneAsSlow() throws Throwable { + CapturingReport report = new CapturingReport(); + // the documented meaning of the negative threshold: record every + // query - which means every execution reaches reportQuery, the + // hook for an execution that was measured and is not slow; it + // must not arrive as a slow query, which for SlowQueryReport is a + // WARN log line for every query the pool executes + report.setThreshold(-1); + Object proxy = instrumentedProxy(report, slowDelegate(0)); + Proxy.getInvocationHandler(proxy).invoke(proxy, Statement.class.getMethod("execute", String.class), + new Object[] { SQL }); + + Assertions.assertTrue(report.fastReported && !report.slowReported, + "a fast execution under a negative threshold must be recorded as a measured " + + "query and must never be reported as slow"); + Assertions.assertTrue(report.fastDelta >= 0, + "the recorded duration must be a real duration, was " + report.fastDelta); + } + @Test void aNonExecutionReachesNeitherReportHook() throws Throwable { CapturingReport report = new CapturingReport(); diff --git a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestSlowQueryJmxNotifications.java b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestSlowQueryJmxNotifications.java index 99c481cedc..10b8127b16 100644 --- a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestSlowQueryJmxNotifications.java +++ b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestSlowQueryJmxNotifications.java @@ -96,13 +96,42 @@ class TestSlowQueryJmxNotifications extends JdbcPoolBaseTest { } } + /* + * The notification under test is the one a slow query raises, so the + * query that must notify has to really run long: the pools here are + * configured with a threshold of zero - a negative threshold records + * every query as measured and never reports one as slow - and the + * query is made slow for a wall-clock reason: the database itself + * waits SLOW_WAIT_MILLIS while the WHERE clause is evaluated + * (java.lang.Thread.sleep exposed to SQL by an alias), holding the + * client's execute() open for at least that long on any hardware. + * A CPU-heavy query would scale with the machine; the wait does not. + */ + private static final long SLOW_WAIT_MILLIS = 60; + + /* + * The SQL of a query that reports itself under the "SELECT marker" + * name the assertions look for, while waiting inside the database. + * The alias is registered once per database; IF NOT EXISTS keeps + * every call cheap. + */ + private String slowSql(int marker) throws SQLException { + try (Connection admin = adminConnection(); + Statement st = admin.createStatement()) { + st.execute("CREATE ALIAS IF NOT EXISTS SLOW_SLEEP FOR " + + "\"java.lang.Thread.sleep(long)\""); + } + return "SELECT " + marker + " FROM SYSTEM_RANGE(1,1) WHERE SLOW_SLEEP(" + + SLOW_WAIT_MILLIS + ") IS NULL"; + } + @Test void notificationOfEveryConnectionSurvivesSerializationWithItsSource() throws Exception { String poolName = "JmxNotifySource-" + System.nanoTime(); DataSource ds = newDataSource(); ds.setName(poolName); ds.setJdbcInterceptors("org.apache.tomcat.jdbc.pool.interceptor.SlowQueryReportJmx" - + "(notifyPool=false,threshold=-1)"); + + "(notifyPool=false,threshold=0)"); ds.getPoolProperties().setMaxActive(2); ds.getPoolProperties().setInitialSize(0); @@ -125,8 +154,8 @@ class TestSlowQueryJmxNotifications extends JdbcPoolBaseTest { .addNotificationListener(listener, null, null); try (Statement st1 = first.createStatement(); Statement st2 = second.createStatement()) { - st1.execute("SELECT 1"); - st2.execute("SELECT 2"); + st1.execute(slowSql(1)); + st2.execute(slowSql(2)); } } @@ -154,7 +183,7 @@ class TestSlowQueryJmxNotifications extends JdbcPoolBaseTest { DataSource ds = newDataSource(); ds.setName(poolName); ds.setJdbcInterceptors("org.apache.tomcat.jdbc.pool.interceptor.SlowQueryReportJmx" - + "(notifyPool=false,threshold=-1)"); + + "(notifyPool=false,threshold=0)"); ds.getPoolProperties().setInitialSize(0); MBeanServer server = ManagementFactory.getPlatformMBeanServer(); @@ -169,7 +198,7 @@ class TestSlowQueryJmxNotifications extends JdbcPoolBaseTest { interceptorOf(con, SlowQueryReportJmx.class) .addNotificationListener(listener, null, null); try (Statement st = con.createStatement()) { - st.execute("SELECT 1"); + st.execute(slowSql(1)); } } @@ -194,7 +223,7 @@ class TestSlowQueryJmxNotifications extends JdbcPoolBaseTest { DataSource ds = newDataSource(); ds.setName(poolName); ds.setJdbcInterceptors("org.apache.tomcat.jdbc.pool.interceptor.SlowQueryReportJmx" - + "(notifyPool=false,threshold=-1,objectName=" + customName + ")"); + + "(notifyPool=false,threshold=0,objectName=" + customName + ")"); ds.getPoolProperties().setInitialSize(0); MBeanServer server = ManagementFactory.getPlatformMBeanServer(); @@ -208,7 +237,7 @@ class TestSlowQueryJmxNotifications extends JdbcPoolBaseTest { interceptorOf(con, SlowQueryReportJmx.class) .addNotificationListener(listener, null, null); try (Statement st = con.createStatement()) { - st.execute("SELECT 1"); + st.execute(slowSql(1)); } } @@ -229,7 +258,7 @@ class TestSlowQueryJmxNotifications extends JdbcPoolBaseTest { DataSource ds = newDataSource(); ds.setName(poolName); ds.setJdbcInterceptors("org.apache.tomcat.jdbc.pool.interceptor.SlowQueryReportJmx" - + "(notifyPool=false,threshold=-1)"); + + "(notifyPool=false,threshold=0)"); ds.getPoolProperties().setInitialSize(0); MBeanServer server = ManagementFactory.getPlatformMBeanServer(); @@ -243,7 +272,7 @@ class TestSlowQueryJmxNotifications extends JdbcPoolBaseTest { interceptorOf(con, SlowQueryReportJmx.class) .addNotificationListener(listener, null, null); try (Statement st = con.createStatement()) { - st.execute("SELECT 1"); + st.execute(slowSql(1)); } } @@ -267,7 +296,7 @@ class TestSlowQueryJmxNotifications extends JdbcPoolBaseTest { DataSource ds = newDataSource(); ds.setName(poolName); ds.setJdbcInterceptors("org.apache.tomcat.jdbc.pool.interceptor.SlowQueryReportJmx" - + "(notifyPool=false,threshold=-1)"); + + "(notifyPool=false,threshold=0)"); ds.getPoolProperties().setMaxActive(2); ds.getPoolProperties().setInitialSize(0); @@ -288,8 +317,8 @@ class TestSlowQueryJmxNotifications extends JdbcPoolBaseTest { Assertions.assertEquals(2, ds.getNumActive()); try (Statement st1 = first.createStatement(); Statement st2 = second.createStatement()) { - st1.execute("SELECT 1"); - st2.execute("SELECT 2"); + st1.execute(slowSql(1)); + st2.execute(slowSql(2)); } } server.removeNotificationListener(oname, listener); @@ -312,7 +341,7 @@ class TestSlowQueryJmxNotifications extends JdbcPoolBaseTest { DataSource ds = newDataSource(); ds.setName(poolName); ds.setJdbcInterceptors("org.apache.tomcat.jdbc.pool.interceptor.SlowQueryReportJmx" - + "(notifyPool=false,threshold=-1)"); + + "(notifyPool=false,threshold=0)"); ds.getPoolProperties().setMaxActive(2); ds.getPoolProperties().setInitialSize(0); ds.getPoolProperties().setMaxIdle(1); @@ -341,8 +370,8 @@ class TestSlowQueryJmxNotifications extends JdbcPoolBaseTest { server.addNotificationListener(oname, listener, null, null); try (Statement st1 = ownerConnection.createStatement(); Statement st2 = otherConnection.createStatement()) { - st1.execute("SELECT 1"); - st2.execute("SELECT 2"); + st1.execute(slowSql(1)); + st2.execute(slowSql(2)); } // return the non-owning connection first so it stays within @@ -362,7 +391,7 @@ class TestSlowQueryJmxNotifications extends JdbcPoolBaseTest { // listener that was attached before the eviction try (Connection survivor = ds.getConnection(); Statement st = survivor.createStatement()) { - st.execute("SELECT 3"); + st.execute(slowSql(3)); } List<String> messages = received.stream().map(Notification::getMessage) @@ -390,7 +419,7 @@ class TestSlowQueryJmxNotifications extends JdbcPoolBaseTest { DataSource ds = newDataSource(); ds.setName(poolName); ds.setJdbcInterceptors("org.apache.tomcat.jdbc.pool.interceptor.SlowQueryReportJmx" - + "(notifyPool=false,threshold=-1)"); + + "(notifyPool=false,threshold=0)"); ds.getPoolProperties().setInitialSize(0); MBeanServer server = ManagementFactory.getPlatformMBeanServer(); @@ -426,7 +455,7 @@ class TestSlowQueryJmxNotifications extends JdbcPoolBaseTest { // pools' own ObjectName clash; the interceptor registers by name ds.getPoolProperties().setName(name); ds.setJdbcInterceptors("org.apache.tomcat.jdbc.pool.interceptor.SlowQueryReportJmx" - + "(notifyPool=false,threshold=-1)"); + + "(notifyPool=false,threshold=0)"); ds.getPoolProperties().setInitialSize(0); return ds; } @@ -455,9 +484,9 @@ class TestSlowQueryJmxNotifications extends JdbcPoolBaseTest { server.addNotificationListener(oname, listener, null, null); try (Statement st = survivorConnection.createStatement()) { - st.execute("SELECT 1"); + st.execute(slowSql(1)); } - Assertions.assertTrue(received.stream().anyMatch(n -> "SELECT 1".equals(n.getMessage())), + Assertions.assertTrue(received.stream().anyMatch(n -> n.getMessage().contains("SELECT 1")), "while both pools are live, the sharing pool's queries must reach the " + "listener attached to the owning pool's MBean, received: " + received); @@ -469,9 +498,9 @@ class TestSlowQueryJmxNotifications extends JdbcPoolBaseTest { awaitSessions(1); // the owner pool's physical session is really gone try (Statement st = survivorConnection.createStatement()) { - st.execute("SELECT 2"); + st.execute(slowSql(2)); } - Assertions.assertTrue(received.stream().anyMatch(n -> "SELECT 2".equals(n.getMessage())), + Assertions.assertTrue(received.stream().anyMatch(n -> n.getMessage().contains("SELECT 2")), "a query of the surviving pool must still reach the listener that " + "subscribed before the other same-named pool closed, received: " + received); @@ -515,9 +544,9 @@ class TestSlowQueryJmxNotifications extends JdbcPoolBaseTest { // twice on one pool; each connection's chain then holds two // instances of it, only one of which can win the registration ds.setJdbcInterceptors("org.apache.tomcat.jdbc.pool.interceptor.SlowQueryReportJmx" - + "(notifyPool=false,threshold=-1);" + + "(notifyPool=false,threshold=0);" + "org.apache.tomcat.jdbc.pool.interceptor.SlowQueryReportJmx" - + "(notifyPool=false,threshold=-1)"); + + "(notifyPool=false,threshold=0)"); ds.getPoolProperties().setInitialSize(0); MBeanServer server = ManagementFactory.getPlatformMBeanServer(); @@ -550,7 +579,7 @@ class TestSlowQueryJmxNotifications extends JdbcPoolBaseTest { Assertions.assertTrue(ownerIsFromThisChain, "the registration must be owned by one of the pool's own instances"); - st.execute("SELECT 1"); + st.execute(slowSql(1)); } // both instances of the chain see the one query; both must notify @@ -594,7 +623,7 @@ class TestSlowQueryJmxNotifications extends JdbcPoolBaseTest { DataSource ds = newDataSource(); ds.setName(poolName); ds.setJdbcInterceptors("org.apache.tomcat.jdbc.pool.interceptor.SlowQueryReportJmx" - + "(notifyPool=false,threshold=-1)"); + + "(notifyPool=false,threshold=0)"); ds.getPoolProperties().setInitialSize(0); MBeanServer server = ManagementFactory.getPlatformMBeanServer(); @@ -691,7 +720,7 @@ class TestSlowQueryJmxNotifications extends JdbcPoolBaseTest { // must release together with the name even though no MBean // registration of this pool ever succeeded try (Statement st = first.createStatement()) { - st.execute("SELECT 1"); + st.execute(slowSql(1)); } Assertions.assertNotNull(SlowQueryReportJmx.notifiers.get(poolName), "reporting a query must have created the name's broadcaster"); --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
