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 2d9c07067c829214dcf5c8b7e8d9bd61b892826b Author: opencode <[email protected]> AuthorDate: Fri Oct 30 22:50:43 2026 +0100 Measure the failed execution's duration with the monotonic clock too Commit 4e27e0086f made reported execution times monotonic, but only on the success paths: reportFailedQuery still carried just the wall-clock start, and SlowQueryReport recomputed the duration as the difference of two wall-clock reads. A backwards step of the wall clock during a failing execution - an NTP correction, a manual set, a resumed VM - therefore still booked a negative duration: QueryStats.failure has no lower bound, so the minimum went below zero and the total shrank, the very corruption the success-path fix removed, and the logFailed WARN printed a negative time=. The failure path was the one consumer left telling the truth about an interval with the wrong instrument. Thread the measurement instead of clamping the symptom. AbstractQueryReport now measures the elapsed milliseconds with the same extracted rule on both paths - shared elapsedMillis(startNanos), rounded to the nearest millisecond - and hands reportFailedQuery that duration as a delta parameter, exactly as the success hooks have had since 4e27e0086f; the wall-clock start remains the point in time the hook carries. SlowQueryReport stops recomputing and uses the threaded duration for its statistics and its WARN, keeping a fresh wall-clock reading only for the last-invocation timestamp. All three report hooks now share one contract, so a subclass cannot get an interval and a timestamp from different clocks; all overrides in the module (SlowQueryReport, SlowQueryReportJmx, ResetAbandonedTimer) take the new arity. Non-positive durations can no longer be produced by the interceptors; QueryStats keeps its unclamped public booking API. Testing: TestQueryReportTiming adds the failing-path counterparts of the success-path pins: the hook contract observed through the proxy (duration matches the execution, start remains a wall-clock instant, the driver's exception still reaches the application), and, with a fabricated future start standing for a backwards clock step, that the failure is booked - and WARNed - with the measured duration, not the stepped difference. Reverting the hook to the old recomputation fails that test with -600000 against the expected 42. --- .../jdbc/pool/interceptor/AbstractQueryReport.java | 55 +++++++-- .../jdbc/pool/interceptor/ResetAbandonedTimer.java | 7 +- .../jdbc/pool/interceptor/SlowQueryReport.java | 12 +- .../jdbc/pool/interceptor/SlowQueryReportJmx.java | 10 +- .../pool/interceptor/TestInterceptorSemantics.java | 4 +- .../interceptor/TestQueryReportExtraction.java | 6 +- .../pool/interceptor/TestQueryReportTiming.java | 135 ++++++++++++++++++++- 7 files changed, 201 insertions(+), 28 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 d0f70feee3..175bf44d02 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 @@ -100,13 +100,15 @@ public abstract class AbstractQueryReport extends AbstractCreateStatementInterce * @param args the arguments to the execution * @param name the name of the method used to execute * {@link AbstractCreateStatementInterceptor#isExecute(Method, boolean)} - * @param start the time the query execution started + * @param start the wall clock time the query execution started + * @param delta the time the execution took before it failed, measured with the monotonic clock * @param t the exception that happened * * @return - the SQL that was executed or the string "batch" if it was a batch execution, or {@code null} * if the invocation carries no SQL string */ - protected String reportFailedQuery(String query, Object[] args, final String name, long start, Throwable t) { + protected String reportFailedQuery(String query, Object[] args, final String name, long start, long delta, + Throwable t) { return extractQuery(query, args, name); } @@ -119,8 +121,8 @@ public abstract class AbstractQueryReport extends AbstractCreateStatementInterce * @param args the arguments to the execution * @param name the name of the method used to execute * {@link AbstractCreateStatementInterceptor#isExecute(Method, boolean)} - * @param start the time the query execution started - * @param delta the time the execution took + * @param start the wall clock time the query execution started + * @param delta the time the execution took, measured with the monotonic clock * * @return - the SQL that was executed or the string "batch" if it was a batch execution, or {@code null} * if the invocation carries no SQL string @@ -138,8 +140,8 @@ public abstract class AbstractQueryReport extends AbstractCreateStatementInterce * @param args the arguments to the execution * @param name the name of the method used to execute * {@link AbstractCreateStatementInterceptor#isExecute(Method, boolean)} - * @param start the time the query execution started - * @param delta the time the execution took + * @param start the wall clock time the query execution started + * @param delta the time the execution took, measured with the monotonic clock * * @return - the SQL that was executed or the string "batch" if it was a batch execution, or {@code null} * if the invocation carries no SQL string @@ -217,6 +219,23 @@ public abstract class AbstractQueryReport extends AbstractCreateStatementInterce } + /** + * Measures the milliseconds elapsed since the {@link System#nanoTime()} + * reading taken at {@code startNanos}, rounded to the nearest millisecond. + * <p> + * An interval is measured with the monotonic clock. The wall clock is not monotonic, so an NTP correction, a manual + * set, or resuming a suspended VM between two of its readings makes their difference negative, and a negative + * duration is never over the slow query threshold while the statistics book it as if it were real. + * </p> + * + * @param startNanos the {@link System#nanoTime()} reading the measurement began with + * + * @return the elapsed time in milliseconds + */ + private static long elapsedMillis(long startNanos) { + return (System.nanoTime() - startNanos + 500000) / 1000000; + } + /** * Class to measure query execute time */ @@ -304,10 +323,11 @@ public abstract class AbstractQueryReport extends AbstractCreateStatementInterce process = isExecute(method, process); // If we are executing, get the current time. The wall clock // only gives the timestamp the report hooks carry; the elapsed - // time is measured with the monotonic clock below, since a clock - // step between two wall clock reads could make a negative - // duration, which loses the slow query report and corrupts the - // statistics booked from it + // time is measured with the monotonic clock on both the success + // and the failure path below, since a clock step between two + // wall clock reads could make a negative duration, which loses + // the slow query report and corrupts the statistics booked from + // it either way long start = (process) ? System.currentTimeMillis() : 0; long startNanos = (process) ? System.nanoTime() : 0; Object result = null; @@ -323,8 +343,17 @@ public abstract class AbstractQueryReport extends AbstractCreateStatementInterce // reporting it would replace the exception that the // application is expecting with a reporting failure if (process) { + // The elapsed time of a failed execution is measured + // here, on the same monotonic clock the success path + // uses below, and handed to the hook along with the + // wall clock start. A hook that recomputed it from that + // start would read a step of the wall clock during the + // execution as a negative duration, and the statistics + // the failure is booked into are the ones the success + // path keeps + long failedDelta = elapsedMillis(startNanos); try { - reportFailedQuery(query, args, name, start, t); + reportFailedQuery(query, args, name, start, failedDelta, t); } catch (Throwable reporting) { // Reporting must never disturb the application - // the driver's exception is the one being thrown @@ -340,8 +369,8 @@ public abstract class AbstractQueryReport extends AbstractCreateStatementInterce throw t; } } - // Measure the time, rounded to the nearest millisecond - long delta = (process) ? (System.nanoTime() - startNanos + 500000) / 1000000 : Long.MIN_VALUE; + // Measure the elapsed time with the monotonic clock + long delta = (process) ? elapsedMillis(startNanos) : Long.MIN_VALUE; // 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 diff --git a/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/interceptor/ResetAbandonedTimer.java b/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/interceptor/ResetAbandonedTimer.java index 3a2f326d54..43833660d0 100644 --- a/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/interceptor/ResetAbandonedTimer.java +++ b/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/interceptor/ResetAbandonedTimer.java @@ -152,9 +152,12 @@ public class ResetAbandonedTimer extends AbstractQueryReport implements ResetAba } @Override - protected String reportFailedQuery(String query, Object[] args, String name, long start, Throwable t) { + protected String reportFailedQuery(String query, Object[] args, String name, long start, long delta, + Throwable t) { + // The timer only needs to know that the execution was attempted, so + // it takes no interest in the start or the duration it reports resetTimer(); - return super.reportFailedQuery(query, args, name, start, t); + return super.reportFailedQuery(query, args, name, start, delta, t); } @Override 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 dee33e635b..ed26310890 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 @@ -115,10 +115,16 @@ public class SlowQueryReport extends AbstractQueryReport { @Override - protected String reportFailedQuery(String query, Object[] args, String name, long start, Throwable t) { - String sql = super.reportFailedQuery(query, args, name, start, t); + protected String reportFailedQuery(String query, Object[] args, String name, long start, long delta, + Throwable t) { + String sql = super.reportFailedQuery(query, args, name, start, delta, t); + // The wall clock is read for the timestamp the failure is recorded + // against - a point in time, which is what the statistics keep the + // last invocation as. The duration is the monotonic elapsed time the + // statement proxy measured, so a step of the wall clock during the + // execution cannot make the booked duration negative, as it could + // while this hook recomputed it from start. long now = System.currentTimeMillis(); - long delta = now - start; if (this.maxQueries > 0) { QueryStats qs = this.getQueryStats(sql); if (qs != null) { diff --git a/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/interceptor/SlowQueryReportJmx.java b/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/interceptor/SlowQueryReportJmx.java index 33fcf85787..84f8bf9e38 100644 --- a/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/interceptor/SlowQueryReportJmx.java +++ b/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/interceptor/SlowQueryReportJmx.java @@ -340,15 +340,17 @@ public class SlowQueryReportJmx extends SlowQueryReport implements NotificationE * * @param query the SQL query * @param args the query arguments - * @param name the connection pool name - * @param start the start time in milliseconds + * @param name the name of the method used to execute + * @param start the wall clock time the query execution started + * @param delta the time the execution took before it failed, measured with the monotonic clock * @param t the throwable that caused the failure * * @return the formatted query string */ @Override - protected String reportFailedQuery(String query, Object[] args, String name, long start, Throwable t) { - query = super.reportFailedQuery(query, args, name, start, t); + protected String reportFailedQuery(String query, Object[] args, String name, long start, long delta, + Throwable t) { + query = super.reportFailedQuery(query, args, name, start, delta, t); if (isLogFailed()) { notifyJmx(query, FAILED_QUERY_NOTIFICATION); } 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 04f7e74f22..3c583910ff 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 @@ -440,8 +440,8 @@ class TestInterceptorSemantics extends JdbcPoolBaseTest { @Override protected String reportFailedQuery(String query, Object[] args, - String name, long start, Throwable t) { - super.reportFailedQuery(query, args, name, start, t); + String name, long start, long delta, Throwable t) { + super.reportFailedQuery(query, args, name, start, delta, t); throw new IllegalStateException("reporter intentionally fails"); } } diff --git a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestQueryReportExtraction.java b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestQueryReportExtraction.java index 6f2b53ecd0..f25f046f05 100644 --- a/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestQueryReportExtraction.java +++ b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestQueryReportExtraction.java @@ -60,17 +60,17 @@ class TestQueryReportExtraction { void aNonStringArgumentIsNotAQuery() { // the argument of setFetchSize(int) and friends is not SQL Assertions.assertNull(REPORT.reportFailedQuery(null, new Object[] { Integer.valueOf(5) }, - "setFetchSize", 0, null)); + "setFetchSize", 0, 1, null)); // but the SQL of the prepared statement still is Assertions.assertEquals("SELECT 1", REPORT.reportFailedQuery("SELECT 1", - new Object[] { Integer.valueOf(5) }, "setFetchSize", 0, null)); + new Object[] { Integer.valueOf(5) }, "setFetchSize", 0, 1, null)); } @Test void aBatchOnAPlainStatementIsNamedBatch() { // a batch execution carries no SQL and no arguments at all Assertions.assertEquals("batch", - REPORT.reportFailedQuery(null, null, "executeBatch", 0, null)); + REPORT.reportFailedQuery(null, null, "executeBatch", 0, 1, null)); Assertions.assertEquals("batch", REPORT.reportQuery(null, new Object[0], "executeBatch", 0, 1)); Assertions.assertEquals("batch", 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 53493f0856..1384afd54f 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,17 @@ */ package org.apache.tomcat.jdbc.pool.interceptor; +import java.lang.reflect.Method; import java.lang.reflect.Proxy; +import java.sql.SQLException; import java.sql.Statement; +import java.util.ArrayList; +import java.util.List; +import java.util.concurrent.ConcurrentHashMap; +import java.util.logging.Handler; +import java.util.logging.Level; +import java.util.logging.LogRecord; +import java.util.logging.Logger; import org.junit.jupiter.api.Assertions; import org.junit.jupiter.api.Test; @@ -29,7 +38,9 @@ import org.junit.jupiter.api.Test; * negative duration is never over the threshold and so loses the slow * query report, and the statistics book it as if it were real. The start * stays a wall clock timestamp, because that is what the reports record - * the invocations against. + * the invocations against. A failed execution is reported on the same + * rule: it is booked into the very same statistics, so its duration comes + * from the same measurement rather than from the reported start. */ class TestQueryReportTiming { @@ -41,10 +52,13 @@ class TestQueryReportTiming { private static class CapturingReport extends AbstractQueryReport { private boolean fastReported; private boolean slowReported; + private boolean failedReported; private long fastStart; private long fastDelta; private long slowStart; private long slowDelta; + private long failedStart; + private long failedDelta; @Override protected void prepareStatement(String sql, long time) { @@ -61,6 +75,15 @@ class TestQueryReportTiming { // timing only - nothing to record } + @Override + protected String reportFailedQuery(String query, Object[] args, String name, long start, long delta, + Throwable t) { + failedReported = true; + failedStart = start; + failedDelta = delta; + return super.reportFailedQuery(query, args, name, start, delta, t); + } + @Override protected String reportQuery(String query, Object[] args, String name, long start, long delta) { fastReported = true; @@ -99,6 +122,23 @@ class TestQueryReportTiming { new Class<?>[] { Statement.class }, report.new StatementProxy(delegate, SQL)); } + /** + * Statement whose executions take the given number of milliseconds and + * then fail, as a driver that refuses the statement does. + */ + private static Statement failingDelegate(long sleepMillis) { + return (Statement) Proxy.newProxyInstance(TestQueryReportTiming.class.getClassLoader(), + new Class<?>[] { Statement.class }, (proxy, method, args) -> { + if ("execute".equals(method.getName())) { + if (sleepMillis > 0) { + Thread.sleep(sleepMillis); + } + throw new SQLException("the driver refused the statement"); + } + return null; + }); + } + @Test void anExecutionReportsADurationMatchingItsDurationAndAWallClockStart() throws Throwable { final long sleepMillis = 40; @@ -163,6 +203,99 @@ class TestQueryReportTiming { "the recorded duration must be a real duration, was " + report.fastDelta); } + @Test + void aFailingExecutionReportsADurationMatchingItsDurationAndAWallClockStart() throws Throwable { + final long sleepMillis = 40; + CapturingReport report = new CapturingReport(); + long wallStart = System.currentTimeMillis(); + Object proxy = instrumentedProxy(report, failingDelegate(sleepMillis)); + final Method execute = Statement.class.getMethod("execute", String.class); + final Object[] args = new Object[] { SQL }; + Assertions.assertThrows(SQLException.class, + () -> Proxy.getInvocationHandler(proxy).invoke(proxy, execute, args), + "the driver's exception must reach the application, not the reporting"); + long wallEnd = System.currentTimeMillis(); + + Assertions.assertTrue(report.failedReported, + "a failed execution must reach the failed query hook"); + Assertions.assertFalse(report.fastReported || report.slowReported, + "an execution that failed must not be reported as measured or as slow"); + // the same bounds the successful execution above is held to: the + // failure is measured on the same clock, with the same rounding + Assertions.assertTrue(report.failedDelta >= sleepMillis - 10, + "the reported duration must track the time the failing execution took, was " + + report.failedDelta + " ms for a " + sleepMillis + " ms execution"); + Assertions.assertTrue(report.failedDelta <= sleepMillis + 900, + "the reported duration must stay near the time the failing execution took, was " + + report.failedDelta + " ms for a " + sleepMillis + " ms execution"); + Assertions.assertTrue(report.failedStart >= wallStart - 1000 && report.failedStart <= wallEnd + 1000, + "the start the failed query hook carries must be the wall clock instant the " + + "execution began, was " + report.failedStart + " with the test at " + wallStart); + } + + @Test + void aFailedExecutionIsBookedWithItsMeasuredDurationAndNotWithAClockStep() { + // The hook is handed the wall clock instant the execution started and + // the duration measured with the monotonic clock. A wall clock that + // stepped backwards while the execution was running leaves the + // reading taken after the failure behind that start, which is what a + // start ahead of the moment the hook is called at stands for: a + // duration recomputed from the start turns negative there, and this + // is where such a duration used to be booked into the statistics and + // written to the log. + String sql = "SELECT stepped_back_clock_" + System.nanoTime(); + final long measuredMillis = 42; + SlowQueryReport report = new SlowQueryReport(); + report.queries = new ConcurrentHashMap<>(); + report.setLogFailed(true); + long steppedBackStart = System.currentTimeMillis() + 600000; + + Logger logger = Logger.getLogger(SlowQueryReport.class.getName()); + Level originalLevel = logger.getLevel(); + List<LogRecord> records = new ArrayList<>(); + Handler handler = new Handler() { + @Override + public void publish(LogRecord record) { + records.add(record); + } + + @Override + public void flush() { + // no buffering + } + + @Override + public void close() { + // nothing to release + } + }; + logger.addHandler(handler); + logger.setLevel(Level.ALL); + try { + report.reportFailedQuery(sql, null, "executeQuery", steppedBackStart, measuredMillis, + new SQLException("the driver refused the statement")); + } finally { + logger.removeHandler(handler); + logger.setLevel(originalLevel); + } + + SlowQueryReport.QueryStats qs = report.queries.get(sql); + Assertions.assertNotNull(qs, "the failed execution must be booked in the store"); + Assertions.assertEquals(1, qs.getNrOfInvocations(), + "the failed execution must count as one invocation"); + Assertions.assertEquals(measuredMillis, qs.getTotalInvocationTime(), + "the booked total must be the measured duration, not the difference " + + "of two wall clock readings"); + Assertions.assertEquals(measuredMillis, qs.getMinInvocationTime(), + "a clock step must not pull the booked minimum below the measured duration"); + Assertions.assertEquals(measuredMillis, qs.getMaxInvocationTime(), + "the booked maximum must be the measured duration"); + Assertions.assertTrue(records.stream().anyMatch(r -> r.getLevel().intValue() == Level.WARNING.intValue() + && r.getMessage() != null && r.getMessage().contains(sql) + && r.getMessage().contains("; time=" + measuredMillis + " ms;")), + "the failed query WARN must report the measured duration, records: " + records); + } + @Test void aNonExecutionReachesNeitherReportHook() throws Throwable { CapturingReport report = new CapturingReport(); --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
