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 ec16cdf0d27038a06a682dbd9981c79175c251a3 Author: opencode <[email protected]> AuthorDate: Fri Oct 30 09:23:25 2026 +0100 Measure reported query execution times with the monotonic clock StatementProxy.invoke timed executions by subtracting two System.currentTimeMillis() reads. The wall clock is not monotonic, so an NTP correction, a manual set, or resuming a suspended VM between the reads made the measured duration negative; a negative duration never exceeds the slow-query threshold, so the slow query report - the one thing the interceptor exists to produce - was silently lost for that execution, while the same negative value was still booked into the SlowQueryReport statistics unclamped, driving the minimum below zero and reducing the total. The elapsed time is now measured with System.nanoTime() and rounded to the nearest millisecond, while the wall-clock reading is kept as the timestamp the report hooks carry, since that is a point in time rather than an interval. Non-executions keep their Long.MIN_VALUE sentinel and remain out of both report paths. A new TestQueryReportTiming pins that reported durations track true elapsed time, that the reported start is still a wall-clock instant, and that non-executions reach no hook even at a negative threshold. --- .../jdbc/pool/interceptor/AbstractQueryReport.java | 12 +- .../pool/interceptor/TestQueryReportTiming.java | 159 +++++++++++++++++++++ 2 files changed, 168 insertions(+), 3 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 ec3afd7740..27e94d53e0 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 @@ -268,8 +268,14 @@ public abstract class AbstractQueryReport extends AbstractCreateStatementInterce boolean process = false; // Check to see if we are about to execute a query process = isExecute(method, process); - // If we are executing, get the current time + // 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 long start = (process) ? System.currentTimeMillis() : 0; + long startNanos = (process) ? System.nanoTime() : 0; Object result = null; try { // Execute the query @@ -297,8 +303,8 @@ public abstract class AbstractQueryReport extends AbstractCreateStatementInterce throw t; } } - // Measure the time - long delta = (process) ? (System.currentTimeMillis() - start) : Long.MIN_VALUE; + // 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) { try { 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 new file mode 100644 index 0000000000..80d8139efb --- /dev/null +++ b/modules/jdbc-pool/src/test/java/org/apache/tomcat/jdbc/pool/interceptor/TestQueryReportTiming.java @@ -0,0 +1,159 @@ +/* + * 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.lang.reflect.InvocationHandler; +import java.lang.reflect.Method; +import java.lang.reflect.Proxy; +import java.sql.Statement; + +import org.junit.jupiter.api.Assertions; +import org.junit.jupiter.api.Test; + +/** + * The duration and the timestamp an execution is reported with, checked + * in isolation. The duration is a milliseconds interval measured with the + * monotonic clock, so no step of the wall clock can make it negative - a + * 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. + */ +class TestQueryReportTiming { + + private static final String SQL = "SELECT 1"; + + /** + * Report that records what the statement proxy hands its report hooks. + */ + private static class CapturingReport extends AbstractQueryReport { + private boolean fastReported; + private boolean slowReported; + private long fastStart; + private long fastDelta; + private long slowStart; + private long slowDelta; + + @Override + protected void prepareStatement(String sql, long time) { + // timing only - nothing to record + } + + @Override + protected void prepareCall(String query, long time) { + // timing only - nothing to record + } + + @Override + public void closeInvoked() { + // timing only - nothing to record + } + + @Override + protected String reportQuery(String query, Object[] args, String name, long start, long delta) { + fastReported = true; + fastStart = start; + fastDelta = delta; + return super.reportQuery(query, args, name, start, delta); + } + + @Override + protected String reportSlowQuery(String query, Object[] args, String name, long start, long delta) { + slowReported = true; + slowStart = start; + slowDelta = delta; + return super.reportSlowQuery(query, args, name, start, delta); + } + } + + /** + * Statement whose executions take the given number of milliseconds. + */ + private static Statement slowDelegate(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); + } + return Boolean.TRUE; + } + return null; + }); + } + + private static Object instrumentedProxy(CapturingReport report, Statement delegate) { + return Proxy.newProxyInstance(TestQueryReportTiming.class.getClassLoader(), + new Class<?>[] { Statement.class }, report.new StatementProxy(delegate, SQL)); + } + + @Test + void anExecutionReportsADurationMatchingItsDurationAndAWallClockStart() throws Throwable { + final long sleepMillis = 40; + CapturingReport report = new CapturingReport(); + long wallStart = System.currentTimeMillis(); + Object proxy = instrumentedProxy(report, slowDelegate(sleepMillis)); + Proxy.getInvocationHandler(proxy).invoke(proxy, Statement.class.getMethod("execute", String.class), + new Object[] { SQL }); + long wallEnd = System.currentTimeMillis(); + + Assertions.assertTrue(report.fastReported && !report.slowReported, + "an execution below the threshold must be reported as a query, not as a slow query"); + // Thread.sleep is a lower bound and the duration is rounded to the + // nearest millisecond, so the lower bound only takes a little slack + // and the upper bound stays wide for a loaded machine + Assertions.assertTrue(report.fastDelta >= sleepMillis - 10, + "the reported duration must track the time the execution took, was " + + report.fastDelta + " ms for a " + sleepMillis + " ms execution"); + Assertions.assertTrue(report.fastDelta <= sleepMillis + 900, + "the reported duration must stay near the time the execution took, was " + + report.fastDelta + " ms for a " + sleepMillis + " ms execution"); + Assertions.assertTrue(report.fastStart >= wallStart - 1000 && report.fastStart <= wallEnd + 1000, + "the start the hooks carry must be the wall clock instant the execution " + + "began, was " + report.fastStart + " with the test at " + wallStart); + } + + @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)); + Proxy.getInvocationHandler(proxy).invoke(proxy, Statement.class.getMethod("execute", String.class), + new Object[] { SQL }); + + Assertions.assertTrue(report.slowReported && !report.fastReported, + "an execution over the threshold must be reported as a slow query"); + Assertions.assertTrue(report.slowDelta >= 0, + "a duration handed to the report hooks can never be negative, was " + report.slowDelta); + Assertions.assertTrue(report.slowStart > 0, + "a reported execution must carry a wall clock start, was " + report.slowStart); + } + + @Test + void aNonExecutionReachesNeitherReportHook() throws Throwable { + CapturingReport report = new CapturingReport(); + // even with every execution reported, a method that is not an + // execution keeps its sentinel duration and reaches no hook at all + report.setThreshold(-1); + Object proxy = instrumentedProxy(report, slowDelegate(0)); + Proxy.getInvocationHandler(proxy).invoke(proxy, Statement.class.getMethod("clearBatch"), null); + + Assertions.assertFalse(report.fastReported || report.slowReported, + "a method that is not an execution must not reach any report hook"); + } +} --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
