Add maxAcquireMicros and meanAcquireNanos for pool status metrics

Author: rbygrave

ebean-datasource-api/src/main/java/io/ebean/datasource/PoolStatus.java

@@ -108,4 +108,16 @@ default int getWaitCount() {
   default int getHitCount() {
     return hitCount();
   }
+
+  /**
+   * Return the max acquire time in micros.
+   */
+  long maxAcquireMicros();
+
+  /**
+   * Return the mean acquire time in nanos.
+   * <p>
+   * This should be in the ballpark of 150 nanos.
+   */
+  long meanAcquireNanos();
 }

ebean-datasource/src/main/java/io/ebean/datasource/pool/ConnectionPool.java

@@ -803,8 +803,10 @@ static final class Status implements PoolStatus {
     private final int highWaterMark;
     private final int waitCount;
     private final int hitCount;
+    private final long maxAcquireMicros;
+    private final long meanAcquireNanos;
 
-    Status(int minSize, int maxSize, int free, int busy, int waiting, int highWaterMark, int waitCount, int hitCount) {
+    Status(int minSize, int maxSize, int free, int busy, int waiting, int highWaterMark, int waitCount, int hitCount, long totalAcquireNanos, long maxAcquireNanos) {
       this.minSize = minSize;
       this.maxSize = maxSize;
       this.free = free;
@@ -813,12 +815,15 @@ static final class Status implements PoolStatus {
       this.highWaterMark = highWaterMark;
       this.waitCount = waitCount;
       this.hitCount = hitCount;
+      this.meanAcquireNanos = hitCount == 0 ? 0 : totalAcquireNanos / hitCount;
+      this.maxAcquireMicros = maxAcquireNanos / 1000;
     }
 
     @Override
     public String toString() {
       return "min[" + minSize + "] max[" + maxSize + "] free[" + free + "] busy[" + busy + "] waiting[" + waiting
-        + "] highWaterMark[" + highWaterMark + "] waitCount[" + waitCount + "] hitCount[" + hitCount + "]";
+        + "] highWaterMark[" + highWaterMark + "] waitCount[" + waitCount + "] hitCount[" + hitCount
+        + "] meanAcquireNanos[" + meanAcquireNanos + "] maxAcquireMicros[" + maxAcquireMicros + "]";
     }
 
     /**
@@ -890,6 +895,15 @@ public int hitCount() {
       return hitCount;
     }
 
+    @Override
+    public long maxAcquireMicros() {
+      return maxAcquireMicros;
+    }
+
+    @Override
+    public long meanAcquireNanos() {
+      return meanAcquireNanos;
+    }
   }
 
 }

ebean-datasource/src/main/java/io/ebean/datasource/pool/PooledConnectionQueue.java

@@ -52,6 +52,9 @@ final class PooledConnectionQueue {
    * Number of times a connection was got from this queue.
    */
   private int hitCount;
+  private long totalAcquireNanos;
+  private long maxAcquireNanos;
+
   /**
    * The high water mark for the queue size.
    */
@@ -81,7 +84,8 @@ final class PooledConnectionQueue {
   }
 
   private PoolStatus createStatus() {
-    return new Status(minSize, maxSize, freeList.size(), busyList.size(), waitingThreads, highWaterMark, waitCount, hitCount);
+    return new Status(minSize, maxSize, freeList.size(), busyList.size(), waitingThreads, highWaterMark,
+      waitCount, hitCount, totalAcquireNanos, maxAcquireNanos);
   }
 
   @Override
@@ -102,6 +106,8 @@ PoolStatus status(boolean reset) {
         highWaterMark = busyList.size();
         hitCount = 0;
         waitCount = 0;
+        maxAcquireNanos = 0;
+        totalAcquireNanos = 0;
       }
       return s;
     } finally {
@@ -237,6 +243,7 @@ private int registerBusyConnection(PooledConnection connection) {
   }
 
   private PooledConnection _obtainConnection() throws InterruptedException, SQLException {
+    var start = System.nanoTime();
     lock.lockInterruptibly();
     try {
       if (doingShutdown) {
@@ -272,6 +279,9 @@ private PooledConnection _obtainConnection() throws InterruptedException, SQLExc
         waitingThreads--;
       }
     } finally {
+      final var elapsed = System.nanoTime() - start;
+      totalAcquireNanos += elapsed;
+      maxAcquireNanos = Math.max(maxAcquireNanos, elapsed);
       lock.unlock();
     }
   }

ebean-datasource/src/test/java/io/ebean/datasource/pool/ConnectionPoolTest.java

@@ -1,6 +1,7 @@
 package io.ebean.datasource.pool;
 
 import io.ebean.datasource.DataSourceConfig;
+import io.ebean.datasource.PoolStatus;
 import org.junit.jupiter.api.AfterEach;
 import org.junit.jupiter.api.Test;
 
@@ -75,6 +76,22 @@ void getConnection_explicitUserPassword() throws SQLException {
 
     Connection another = pool.getConnection("testing", "123");
     another.close();
+
+    for (int i = 0; i < 10_000; i++) {
+      Connection another2 = pool.getConnection();
+      another2.close();
+    }
+    PoolStatus status0 = pool.status(true);
+
+    for (int i = 0; i < 10_000; i++) {
+      Connection another2 = pool.getConnection();
+      another2.close();
+    }
+    PoolStatus status = pool.status(false);
+
+    assertThat(status.hitCount()).isEqualTo(10_000);
+    assertThat(status.meanAcquireNanos()).isBetween(0L, 300L);
+    assertThat(status.maxAcquireMicros()).isBetween(0L, 100L);
   }
 
   @Test