(jackrabbit-oak) 01/01: OAK-11186: Failure in RDBConnectionHandlerTest - add warmup, add more diagnostics, bump LOGTHRESHOLD from 20ms to 100ms

[re...@apache.org]

This is an automated email from the ASF dual-hosted git repository.

reschke pushed a commit to branch OAK-11186
in repository https://gitbox.apache.org/repos/asf/jackrabbit-oak.git

commit 285d2195c4ce37e056f1713baadb44e65d52e132
Author: Julian Reschke <re...@apache.org>
AuthorDate: Fri Oct 11 13:41:38 2024 +0100

    OAK-11186: Failure in RDBConnectionHandlerTest - add warmup, add more diagnostics, bump LOGTHRESHOLD from 20ms to 100ms
---
 .../plugins/document/rdb/RDBConnectionHandler.java  | 10 +++++++---
 .../document/rdb/RDBConnectionHandlerTest.java      | 21 +++++++++++++--------
 2 files changed, 20 insertions(+), 11 deletions(-)

diff --git a/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/rdb/RDBConnectionHandler.java b/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/rdb/RDBConnectionHandler.java
index 889b7a5118..419f73d459 100644
--- a/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/rdb/RDBConnectionHandler.java
+++ b/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/rdb/RDBConnectionHandler.java
@@ -154,7 +154,7 @@ public class RDBConnectionHandler implements Closeable {
         remember(c);
         if (LOG.isDebugEnabled()) {
             long elapsed = System.currentTimeMillis() - ts;
-            if (elapsed >= 100) {
+            if (elapsed >= 20) {
                 LOG.debug("Obtaining a new connection from " + this.ds + " took " + elapsed + "ms", new Exception("call stack"));
             }
         }
@@ -221,10 +221,14 @@ public class RDBConnectionHandler implements Closeable {
         }
     }
 
-    private final int LOGTHRESHOLD = 20;
-
+    // map holding references to currently open connections
     private ConcurrentMap<WeakReference<Connection>, ConnectionHolder> connectionMap = new ConcurrentHashMap<>();
 
+    // time in millis for a connection in the map to be logged as "old"; note
+    // that this is meant to catch both connection leaks and long-running
+    // transactions
+    private final int LOGTHRESHOLD = 100;
+
     private void dumpConnectionMap(long ts) {
         if (LOG.isTraceEnabled()) {
             connectionMap.forEach((k, v) -> {
diff --git a/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/rdb/RDBConnectionHandlerTest.java b/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/rdb/RDBConnectionHandlerTest.java
index 86532eefbf..be62d2ec96 100644
--- a/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/rdb/RDBConnectionHandlerTest.java
+++ b/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/rdb/RDBConnectionHandlerTest.java
@@ -17,6 +17,7 @@
 package org.apache.jackrabbit.oak.plugins.document.rdb;
 
 import static org.junit.Assert.assertEquals;
+import static org.junit.Assert.assertTrue;
 
 import java.sql.Connection;
 
@@ -30,25 +31,29 @@ public class RDBConnectionHandlerTest {
 
     @Test
     public void logging() throws Exception {
-        LogCustomizer customLogs = LogCustomizer.forLogger(RDBConnectionHandler.class.getName()).enable(Level.TRACE)
+        LogCustomizer customLogs = LogCustomizer.forLogger(RDBConnectionHandler.class).enable(Level.TRACE)
                 .contains("while obtaining new").create();
         DataSource ds = RDBDataSourceFactory.forJdbcUrl("jdbc:h2:mem:", "", "");
         Connection c1 = null, c2 = null, c3 = null;
 
         try (RDBConnectionHandler ch = new RDBConnectionHandler(ds)) {
+            // warmup
+            ch.getROConnection().close();
+            // test
             customLogs.starting();
+            long ts1 = System.currentTimeMillis();
             c1 = ch.getROConnection();
-            long ts = System.currentTimeMillis();
-            assertEquals(0, customLogs.getLogs().size());
+            assertTrue("There should be no log message yet, but got: " + customLogs.getLogs(), customLogs.getLogs().isEmpty());
+            long ts2 = System.currentTimeMillis();
+            assertTrue("unexpected elapsed time between two fetches of connections: " + (ts2 - ts1), ts2 - ts1 <= 20);
             c2 = ch.getROConnection();
             // age threshold not reached
-            assertEquals(0, customLogs.getLogs().size());
-            while (System.currentTimeMillis() - ts < 21) {
-                // busy wait for LOGTHRESHOLD to pass
+            assertTrue("There should be no log message get, but got: " + customLogs.getLogs(), customLogs.getLogs().isEmpty());
+            while (System.currentTimeMillis() - ts2 < 101) {
+                // busy wait for RDBConnectionHandler.LOGTHRESHOLD to pass
             }
             c3 = ch.getROConnection();
-            assertEquals(1, customLogs.getLogs().size());
-            // System.out.println(customLogs.getLogs());
+            assertEquals("There should be exacly one log message get, but got: " + customLogs.getLogs(), 1, customLogs.getLogs().size());
         } finally {
             close(c1);
             close(c2);