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 f7e70028dca1a18ecdfdfa5839abc8e826ff2cd2 Author: opencode <[email protected]> AuthorDate: Wed Nov 4 08:58:02 2026 +0100 Book successful query executions against their recording time The slow query statistics keep a wall clock point in time per query - the dates of the longest and shortest executions and the last-invocation timestamp the capacity eviction orders on. The failure hook had been given a fresh wall clock read for that moment when its duration measurement moved to the monotonic clock, but the two success hooks - reportQuery and reportSlowQuery, which the statement proxy calls one or the other per successful execution - still handed the execution's start timestamp into QueryStats.add as its "now", contradicting both the contract of add and the failure path beside them. The dates of a successful execution therefore lagged the moment it actually happened by the whole duration of the query: a long query that had just finished looked last-invoked at its start, so near capacity the eviction could age it out ahead of queries that had genuinely been idle that long, and the JMX max/min invocation dates read early by the execution duration. Both hooks now take the wall clock at the moment they book, the way the failure hook does, so all three report paths agree on what "now" is for the same fields. The booked durations are unchanged: they stay the monotonic elapsed times the statement proxy measures, so the fix adds no wall clock step sensitivity. A real-pool test pins the rule with a query that sleeps in the database: the booked invocation dates must sit past the point the execution started by at least the slept duration. --- .../jdbc/pool/interceptor/SlowQueryReport.java | 12 ++- .../interceptor/TestSlowQueryBookingTimestamp.java | 97 ++++++++++++++++++++++ 2 files changed, 107 insertions(+), 2 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 f45527bddc..2369a20e78 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 @@ -160,7 +160,13 @@ public class SlowQueryReport extends AbstractQueryReport { if (booksSharedStats()) { QueryStats qs = this.getQueryStats(sql); if (qs != null) { - qs.add(delta, start); + // The wall clock is read for the timestamp the execution is + // recorded against, like the failure path books its event: + // the start time would leave a long query aged by its own + // duration against the entries that age by when they + // finished. The duration itself is the monotonic elapsed + // time the statement proxy measured. + qs.add(delta, System.currentTimeMillis()); } } return sql; @@ -172,7 +178,9 @@ public class SlowQueryReport extends AbstractQueryReport { if (booksSharedStats()) { QueryStats qs = this.getQueryStats(sql); if (qs != null) { - qs.add(delta, start); + // Booked against the time of recording, not the execution + // start, for the same reason as in reportQuery above + qs.add(delta, System.currentTimeMillis()); } } // The WARN reports the event, not the statistics booking: the diff --git a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestSlowQueryBookingTimestamp.java b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestSlowQueryBookingTimestamp.java new file mode 100644 index 0000000000..e08227f05b --- /dev/null +++ b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestSlowQueryBookingTimestamp.java @@ -0,0 +1,97 @@ +/* + * 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.SQLException; +import java.sql.Statement; +import java.util.Map; + +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; + +/** + * The successful execution hooks book their statistics against a point in + * time on the wall clock - the moment the execution is recorded as having + * happened - the same way the failure hook books its event. Handing them + * the execution's start instead left the recorded dates lagging by the + * whole duration of the query: a long query that had just finished looked + * last-invoked at its start time, aged out of the statistics ahead of its + * turn by the eviction that orders on that timestamp, and reported its + * max/min invocation dates early through JMX. The duration booked + * alongside the timestamp is unaffected: it stays the monotonic elapsed + * time the statement proxy measured. + * + * <p>Reproducer for the booking-timestamp defect of + * {@code defects-reports/defects-org.apache.tomcat.jdbc.pool.interceptor.SlowQueryReport.md}.</p> + */ +class TestSlowQueryBookingTimestamp extends JdbcPoolBaseTest { + + /* A database-side wait long enough that a booking against the + * execution start trails the correct timestamp by more than any + * scheduling jitter in the test itself. */ + private static final long SLOW_WAIT_MILLIS = 300; + + private String slowSql() 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 1 FROM SYSTEM_RANGE(1,1) WHERE SLOW_SLEEP(" + SLOW_WAIT_MILLIS + ") IS NULL"; + } + + @Test + void aSlowQueryIsBookedAgainstTheTimeItFinishedNotTheTimeItStarted() throws Exception { + String poolName = "booking-" + System.nanoTime(); + DataSource ds = newDataSource(); + ds.getPoolProperties().setName(poolName); + ds.getPoolProperties().setJdbcInterceptors( + "org.apache.tomcat.jdbc.pool.interceptor.SlowQueryReport(threshold=0)"); + ds.createPool(); + + String sql = slowSql(); + long beforeExecution = System.currentTimeMillis(); + try (Connection pooled = ds.getConnection(); + Statement st = pooled.createStatement()) { + st.execute(sql); + } + + Map<String, SlowQueryReport.QueryStats> stats = SlowQueryReport.getPoolStats(poolName); + Assertions.assertNotNull(stats, "the running pool must publish its statistics"); + SlowQueryReport.QueryStats booked = stats.get(sql); + Assertions.assertNotNull(booked, "the executed query must be booked"); + Assertions.assertEquals(1, booked.getNrOfInvocations()); + + // The execution is recorded when it is booked, which is after the + // database-side wait: the timestamps must therefore sit past the + // point the execution started by at least the duration it slept. + // A booking against the execution start sat at the start instead, + // this many milliseconds too early. + String message = "the invocation date must be the time the execution was " + + "recorded, not the time it started"; + Assertions.assertTrue(booked.getMaxInvocationDate() >= beforeExecution + SLOW_WAIT_MILLIS, + message + ", maxInvocationDate=" + booked.getMaxInvocationDate() + + " beforeExecution=" + beforeExecution); + Assertions.assertTrue(booked.getMinInvocationDate() >= beforeExecution + SLOW_WAIT_MILLIS, + message + ", minInvocationDate=" + booked.getMinInvocationDate() + + " beforeExecution=" + beforeExecution); + } +} --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
