This is an automated email from the ASF dual-hosted git repository. rmaucher pushed a commit to branch 11.0.x in repository https://gitbox.apache.org/repos/asf/tomcat.git
commit c6cd9657ee137eb69dac144c9ac9de6a5f7d1bfc Author: opencode <[email protected]> AuthorDate: Mon Oct 26 23:00:30 2026 +0100 Stop the jdbc-pool tests from waiting on the clock The suite's runtime had drifted to 92 s of test time, dominated by fixed sleeps and one query sized to be slow. Timing-sensitive tests now observe the pool's own state instead of assuming how long things take: - slowQueryIsRecordedInPoolStats no longer runs a 1.2-billion-row COUNT to completion. Below the threshold the interceptor books a query into the pool stats exactly the same way as above it, so the billion rows tested nothing; the UPDATE is now made slow by a row lock a second session holds for a fixed wall-clock window, which exceeds the threshold on any hardware. The oracle gained the recorded execution time, pinning the slow branch itself. 60.7 s to 0.5 s. - The unlocked-sweep soak stops at an iteration budget (measured at ~210k borrow/sweeper collisions per second here) and on first error, keeping the old 6 s only as a cap. - The duplicate-release waiter test hands the remaining waiter a genuine release instead of making it sit out its maxWait timeout. - The slow-connect driver parks on a latch rather than sleeping, so the close is guaranteed to land mid-flight. - Sleeps that merely 'gave waiters time to register' became awaitUntil on the pool's wait count; the maxAge wait only crosses maxAge now that the borrow runs the expiry check. Suite total: 92 s to ~18-23 s, all 209 tests green, re-run repeatedly for stability. --- .../tomcat/jdbc/pool/TestCloseDuringBorrow.java | 55 +++++++++------ .../tomcat/jdbc/pool/TestCloseVsPoolCreation.java | 2 +- .../jdbc/pool/TestConnectionAcquireRelease.java | 8 +-- .../tomcat/jdbc/pool/TestInterruptedWaiter.java | 2 +- .../apache/tomcat/jdbc/pool/TestPoolEviction.java | 6 +- .../tomcat/jdbc/pool/TestReleaseWaiters.java | 18 ++++- .../jdbc/pool/TestUnlockedMaintenanceSweep.java | 15 ++++- .../pool/interceptor/TestInterceptorSemantics.java | 78 +++++++++++++++++++--- 8 files changed, 138 insertions(+), 46 deletions(-) diff --git a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/TestCloseDuringBorrow.java b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/TestCloseDuringBorrow.java index 330bb25b9b..e5ae0da0ca 100644 --- a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/TestCloseDuringBorrow.java +++ b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/TestCloseDuringBorrow.java @@ -41,19 +41,20 @@ import org.apache.tomcat.jdbc.JdbcPoolBaseTest; */ class TestCloseDuringBorrow extends JdbcPoolBaseTest { - /* A driver whose connect() is slow enough for a close() to complete - while a connection attempt is in flight. It signals when it enters - connect() so the test can close the pool mid-attempt deterministically. */ + /* A driver whose connect() parks until the test releases it, so the + close() is guaranteed to complete while a connection attempt is in + flight. It signals when it enters connect() so the test can close the + pool mid-attempt deterministically. */ public static class SlowConnectDriver implements Driver { static final CountDownLatch CONNECT_STARTED = new CountDownLatch(1); - static final long CONNECT_DELAY_MS = 1500; + static final CountDownLatch CONNECT_RELEASE = new CountDownLatch(1); @Override public Connection connect(String url, Properties info) throws SQLException { CONNECT_STARTED.countDown(); try { - Thread.sleep(CONNECT_DELAY_MS); + CONNECT_RELEASE.await(); } catch (InterruptedException e) { Thread.currentThread().interrupt(); throw new SQLException(e); @@ -110,22 +111,32 @@ class TestCloseDuringBorrow extends JdbcPoolBaseTest { }, "borrower-in-flight-during-close"); borrower.setDaemon(true); borrower.start(); - - // close while the physical connect() is in flight: the driver signals - // when it enters connect() and sleeps there for CONNECT_DELAY_MS - Assertions.assertTrue(SlowConnectDriver.CONNECT_STARTED.await(AWAIT_TIMEOUT_MS, - TimeUnit.MILLISECONDS), - "the borrower must be inside the driver's connect()"); - ds.close(true); - - borrower.join(AWAIT_TIMEOUT_MS); - Assertions.assertFalse(borrower.isAlive(), "the borrower must not outlive the close"); - - Assertions.assertNotNull(failure.get(), - "the borrower must not be handed a connection from the closed pool"); - Assertions.assertTrue(failure.get() instanceof SQLException, - "the borrower must be rejected with a SQLException, not " + failure.get()); - Assertions.assertNull(borrowed.get()); - awaitSessions(0); + try { + // close while the physical connect() is in flight: the driver + // parks inside connect() until the close has completed, so the + // race is decided deterministically in the test's favour + Assertions.assertTrue(SlowConnectDriver.CONNECT_STARTED.await(AWAIT_TIMEOUT_MS, + TimeUnit.MILLISECONDS), + "the borrower must be inside the driver's connect()"); + ds.close(true); + SlowConnectDriver.CONNECT_RELEASE.countDown(); + + borrower.join(AWAIT_TIMEOUT_MS); + Assertions.assertFalse(borrower.isAlive(), + "the borrower must not outlive the close"); + + Assertions.assertNotNull(failure.get(), + "the borrower must not be handed a connection from the closed pool"); + Assertions.assertTrue(failure.get() instanceof SQLException, + "the borrower must be rejected with a SQLException, not " + failure.get()); + Assertions.assertNull(borrowed.get()); + awaitSessions(0); + } finally { + // Never leave the borrower parked inside connect() if one of the + // assertions above failed: release it and reap it so a red run + // cannot linger on the class' database until the server stop. + SlowConnectDriver.CONNECT_RELEASE.countDown(); + borrower.join(AWAIT_TIMEOUT_MS); + } } } diff --git a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/TestCloseVsPoolCreation.java b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/TestCloseVsPoolCreation.java index 6a2a2d989b..d48d9ff9db 100644 --- a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/TestCloseVsPoolCreation.java +++ b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/TestCloseVsPoolCreation.java @@ -136,7 +136,7 @@ class TestCloseVsPoolCreation extends JdbcPoolBaseTest { closer.setDaemon(true); closer.start(); - closer.join(1000); + closer.join(500); Assertions.assertTrue(closer.isAlive(), "close() must wait for the in-flight pool creation instead of" + " returning while the pool is still unpublished"); diff --git a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/TestConnectionAcquireRelease.java b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/TestConnectionAcquireRelease.java index 3c729a7d41..8eba30db2b 100644 --- a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/TestConnectionAcquireRelease.java +++ b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/TestConnectionAcquireRelease.java @@ -132,11 +132,8 @@ class TestConnectionAcquireRelease extends JdbcPoolBaseTest { final CountDownLatch done = new CountDownLatch(1); final AtomicReference<Throwable> failure = new AtomicReference<>(); final AtomicInteger observedMarker = new AtomicInteger(-1); - final AtomicReference<Long> waitMillis = new AtomicReference<>(); Thread waiter = new Thread(() -> { - long start = System.currentTimeMillis(); try (Connection c = ds.getConnection()) { - waitMillis.set(Long.valueOf(System.currentTimeMillis() - start)); Integer marker = sessionMarker(c); if (marker != null) { observedMarker.set(marker.intValue()); @@ -149,15 +146,12 @@ class TestConnectionAcquireRelease extends JdbcPoolBaseTest { }); waiter.start(); - sleep(300); // let the waiter block on the exhausted pool + awaitUntil(() -> ds.getWaitCount() == 1); // the waiter is parked on the exhausted pool held.close(); Assertions.assertTrue(done.await(10, java.util.concurrent.TimeUnit.SECONDS), "waiter should have obtained a connection"); Assertions.assertNull(failure.get()); - Assertions.assertTrue(waitMillis.get().longValue() >= 200, - "waiter must actually have waited for the release, waited " - + waitMillis.get() + " ms"); Assertions.assertEquals(42, observedMarker.get(), "waiter must have received the released physical session"); } diff --git a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/TestInterruptedWaiter.java b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/TestInterruptedWaiter.java index 0c9d4abaad..031a23b60e 100644 --- a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/TestInterruptedWaiter.java +++ b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/TestInterruptedWaiter.java @@ -96,7 +96,7 @@ class TestInterruptedWaiter extends JdbcPoolBaseTest { waiters[i].setDaemon(true); waiters[i].start(); } - sleep(500); // give the waiters time to register with the queue + awaitUntil(() -> ds.getWaitCount() == HOLDERS); // the waiters are registered with the queue for (Thread waiter : waiters) { waiter.interrupt(); } diff --git a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/TestPoolEviction.java b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/TestPoolEviction.java index 5417922394..04c79febf6 100644 --- a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/TestPoolEviction.java +++ b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/TestPoolEviction.java @@ -103,8 +103,10 @@ class TestPoolEviction extends JdbcPoolBaseTest { } // past maxAge the connection is retired and a fresh one takes its - // place (sweeper and/or borrow-time check), keeping the pool size - sleep(3500); // ~2x maxAge plus sweeper interval + // place (sweeper and/or borrow-time check), keeping the pool size. + // The borrow itself runs the expiry check, so the wait only has to + // cross maxAge itself, not an extra sweeper cycle on top of it. + sleep(1800); // maxAge plus a margin for the elapsed-time check awaitSessions(1); try (Connection replacement = ds.getConnection()) { Assertions.assertNull(sessionMarker(replacement), diff --git a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/TestReleaseWaiters.java b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/TestReleaseWaiters.java index 78f781584b..477d98b08c 100644 --- a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/TestReleaseWaiters.java +++ b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/TestReleaseWaiters.java @@ -180,6 +180,21 @@ class TestReleaseWaiters extends JdbcPoolBaseTest { Assertions.assertEquals(1, ds.getWaitCount(), "the duplicate release must not wake the remaining waiter"); + // Only the destruction of the connection opened a slot: exactly one + // borrower was served while the other stayed parked. + awaitUntil(() -> served[0] != null || served[1] != null); + Assertions.assertTrue(served[0] == null || served[1] == null, + "the duplicate release must not serve a second borrower, " + + "both waiters hold a connection"); + + // Hand the remaining waiter a real connection instead of making it + // sit out the full maxWait timeout before it can be joined. A + // genuine release must reach a parked waiter; the duplicate release + // above was the one that must not. + Connection servedFirst = served[0] != null ? served[0] : served[1]; + servedFirst.close(); + awaitUntil(() -> served[0] != null && served[1] != null); + for (Thread waiter : waiters) { waiter.join(AWAIT_TIMEOUT_MS); if (waiter.isAlive()) { @@ -187,9 +202,6 @@ class TestReleaseWaiters extends JdbcPoolBaseTest { Assertions.fail("waiter is stuck"); } } - int servedCount = (served[0] == null ? 0 : 1) + (served[1] == null ? 0 : 1); - Assertions.assertEquals(1, servedCount, - "only the destruction of the connection should have opened a slot"); awaitSessions(1); for (Connection c : served) { if (c != null) { diff --git a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/TestUnlockedMaintenanceSweep.java b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/TestUnlockedMaintenanceSweep.java index 0d3328415a..756d981c68 100644 --- a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/TestUnlockedMaintenanceSweep.java +++ b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/TestUnlockedMaintenanceSweep.java @@ -40,7 +40,15 @@ import org.apache.tomcat.jdbc.JdbcPoolBaseTest; */ public class TestUnlockedMaintenanceSweep extends JdbcPoolBaseTest { + /* + * The window under test is hit once per borrow/sweep collision, and a + * hot borrow loop produces hundreds of thousands of them per second. + * The run therefore stops at an iteration budget that even a slow CI + * covers inside the wall-clock cap, and an error ends it at once, + * instead of always burning the full cap. + */ private static final long RUN_MILLIS = 6000; + private static final long ITERATIONS = 250_000; private static final int BORROWERS = 4; @Test @@ -99,7 +107,12 @@ public class TestUnlockedMaintenanceSweep extends JdbcPoolBaseTest { for (Thread b : borrowers) { b.start(); } - sleep(RUN_MILLIS); + long deadline = System.currentTimeMillis() + RUN_MILLIS; + while (System.currentTimeMillis() < deadline + && uses.get() + errors.get() < ITERATIONS + && firstError.get() == null) { + sleep(25); + } stop.set(true); sweeper.join(); for (Thread b : borrowers) { diff --git a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestInterceptorSemantics.java b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestInterceptorSemantics.java index 9657a80a7f..ed4fb3ed30 100644 --- a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestInterceptorSemantics.java +++ b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestInterceptorSemantics.java @@ -37,29 +37,89 @@ import org.apache.tomcat.jdbc.pool.DataSource; */ class TestInterceptorSemantics extends JdbcPoolBaseTest { - /** Heavy pure-SQL aggregate; H2 honours query timeouts on it (~2 s). */ - private static final String HEAVY_SQL_PREFIX = + /** + * Heavy pure-SQL aggregate that keeps running for well over a second. + * It must stay heavy: it has to still be executing when the query + * timeout interceptor's cancellation arrives. + */ + private static final String HEAVY_SQL = "SELECT COUNT(*) FROM SYSTEM_RANGE(1,400000000) r1, SYSTEM_RANGE(1,3)"; + /* + * A slow query that is slow for a wall-clock reason, not a CPU reason. + * Burning cycles until the clock crosses the threshold scales with the + * hardware - a billion-row COUNT cost a minute on a slow core and gives + * no margin on a fast one. Instead the instrumented UPDATE is made to + * wait on the row lock a second session holds open, and that session + * commits a fixed window later: the execution time is the lock wait, + * so it exceeds the threshold on any machine while the test itself + * stays sub-second. + */ @Test void slowQueryIsRecordedInPoolStats() throws Exception { + final long thresholdMillis = 100; + final long lockHoldMillis = 5 * thresholdMillis; + DataSource ds = newDataSource(); ds.getPoolProperties().setJdbcInterceptors( - "org.apache.tomcat.jdbc.pool.interceptor.SlowQueryReport(threshold=100)"); + "org.apache.tomcat.jdbc.pool.interceptor.SlowQueryReport(threshold=" + + thresholdMillis + ")"); ds.createPool(); String poolName = ds.getPoolProperties().getPoolName(); + String table = uniqueTable(); + + try (Connection c = ds.getConnection(); Statement st = c.createStatement()) { + st.execute("CREATE TABLE " + table + " (ID INT PRIMARY KEY, V INT)"); + st.execute("INSERT INTO " + table + " VALUES (1, 1)"); + } + + // hold the row lock open... + Connection blocker = ds.getConnection(); + blocker.setAutoCommit(false); + try (PreparedStatement ps = blocker.prepareStatement( + "UPDATE " + table + " SET V = V + 10 WHERE ID = 1")) { + Assertions.assertEquals(1, ps.executeUpdate()); + } + // ...and release it while the instrumented statement is blocked on it + Thread releaseLock = new Thread(() -> { + sleep(lockHoldMillis); + try { + blocker.commit(); + } catch (SQLException ignore) { + // the assertions below report the broken state + } + }, "release-row-lock"); String nonce = "nonce_" + System.nanoTime(); - String sql = HEAVY_SQL_PREFIX + " /* " + nonce + " */"; + String sql = "UPDATE " + table + " SET V = V + 1 WHERE ID = 1 /* " + nonce + " */"; + long start; + long elapsed; + releaseLock.start(); try (Connection c = ds.getConnection(); Statement st = c.createStatement()) { - Assertions.assertTrue(st.execute(sql)); + // the lock wait must not be cut short by the driver's own limit + st.execute("SET LOCK_TIMEOUT 60000"); + start = System.currentTimeMillis(); + Assertions.assertFalse(st.execute(sql), "an UPDATE yields no result set"); + elapsed = System.currentTimeMillis() - start; } + releaseLock.join(AWAIT_TIMEOUT_MS); + blocker.close(); + Assertions.assertTrue(elapsed >= thresholdMillis, + "the instrumented statement must have been slowed by the lock wait, took " + + elapsed + " ms"); ConcurrentHashMap<String, ?> stats = SlowQueryReport.getPoolStats(poolName); Assertions.assertNotNull(stats, "stats must exist once a slow query was run"); - Assertions.assertTrue(statsKeySet(stats).stream().anyMatch(k -> k.contains(nonce)), - "slow query must be reported under pool " + poolName - + ", recorded keys: " + statsKeySet(stats)); + String key = statsKeySet(stats).stream().filter(k -> k.contains(nonce)) + .findFirst().orElse(null); + Assertions.assertNotNull(key, "slow query must be reported under pool " + poolName + + ", recorded keys: " + statsKeySet(stats)); + // the entry must carry the slowness the interceptor measured + SlowQueryReport.QueryStats qs = (SlowQueryReport.QueryStats) stats.get(key); + Assertions.assertEquals(1, qs.getNrOfInvocations()); + Assertions.assertTrue(qs.getMaxInvocationTime() >= thresholdMillis, + "the recorded execution time must exceed the threshold, was " + + qs.getMaxInvocationTime() + " ms"); } @Test @@ -234,7 +294,7 @@ class TestInterceptorSemantics extends JdbcPoolBaseTest { long start = System.currentTimeMillis(); try (Connection c = ds.getConnection(); Statement st = c.createStatement()) { - Assertions.assertThrows(SQLException.class, () -> st.execute(HEAVY_SQL_PREFIX)); + Assertions.assertThrows(SQLException.class, () -> st.execute(HEAVY_SQL)); } long elapsed = System.currentTimeMillis() - start; Assertions.assertTrue(elapsed >= 900 && elapsed < 8000, --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
