Merge pull request #132 from ebean-orm/feature/poolStatus-totalWaitMicros

Add totalAcquireMicros() and totalWaitMicros() to PoolStatus

Author: rbygrave

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

@@ -84,6 +84,9 @@ static DataSourceBuilder builder() {
   /**
    * Shutdown the pool.
    * <p>
+   * This will close all the free connections, and then go into a wait loop,
+   * waiting for the busy connections to be freed.
+   * <p>
    * This is functionally the same as {@link #offline()} but generally we expect to only
    * shut down the pool once whereas we can expect to make many calls to offline() and
    * online().

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

@@ -31,12 +31,14 @@ public interface PoolStatus {
   int waiting();
 
   /**
-   * Return the busy connection high water mark.
+   * Return the busy connection highwater mark.
    */
   int highWaterMark();
 
   /**
    * Return the number of times threads had to wait for connections.
+   * <p>
+   * This occurs when the pool is full and threads are waiting for a connection.
    */
   int waitCount();
 
@@ -45,6 +47,18 @@ public interface PoolStatus {
    */
   int hitCount();
 
+  /**
+   * Return the total time acquiring a connection from the pool.
+   */
+  long totalAcquireMicros();
+
+  /**
+   * Return the total time waiting in micros for a free connection when the pool has hit maxConnections.
+   * <p>
+   * When the pool is full and threads are waiting for a connection, this is the total time spent waiting.
+   */
+  long totalWaitMicros();
+
   /**
    * Return the max acquire time in micros.
    */

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

@@ -605,7 +605,7 @@ private void reset() {
   }
 
   /**
-   * Create an un-pooled connection with the given username and password.
+   * Create an unpooled connection with the given username and password.
    * <p>
    * This uses the default isolation level and autocommit mode.
    */
@@ -639,13 +639,6 @@ private PooledConnection getPooledConnection() throws SQLException {
     return c;
   }
 
-  /**
-   * This will close all the free connections, and then go into a wait loop,
-   * waiting for the busy connections to be freed.
-   * <p>
-   * The DataSources's should be shutdown AFTER thread pools. Leaked
-   * Connections are not waited on, as that would hang the server.
-   */
   @Override
   public void shutdown() {
     shutdownPool(true, false);
@@ -725,9 +718,6 @@ private void stopHeartBeatIfRunning() {
     }
   }
 
-  /**
-   * Return the default autoCommit setting for the pool.
-   */
   @Override
   public boolean isAutoCommit() {
     return autoCommit;
@@ -785,13 +775,6 @@ public void setLogWriter(PrintWriter writer) throws SQLException {
     throw new SQLException("Method not supported");
   }
 
-  /**
-   * Return the current status of the connection pool.
-   * <p>
-   * If you pass reset = true then the counters such as
-   * hitCount, waitCount and highWaterMark are reset.
-   * </p>
-   */
   @Override
   public PoolStatus status(boolean reset) {
     return queue.status(reset);
@@ -807,10 +790,12 @@ static final class Status implements PoolStatus {
     private final int highWaterMark;
     private final int waitCount;
     private final int hitCount;
+    private final long totalAcquireMicros;
     private final long maxAcquireMicros;
+    private final long totalWaitMicros;
     private final long meanAcquireNanos;
 
-    Status(int minSize, int maxSize, int free, int busy, int waiting, int highWaterMark, int waitCount, int hitCount, long totalAcquireNanos, long maxAcquireNanos) {
+    Status(int minSize, int maxSize, int free, int busy, int waiting, int highWaterMark, int waitCount, int hitCount, long totalAcquireNanos, long maxAcquireNanos, long totalWaitNanos) {
       this.minSize = minSize;
       this.maxSize = maxSize;
       this.free = free;
@@ -819,86 +804,69 @@ static final class Status implements PoolStatus {
       this.highWaterMark = highWaterMark;
       this.waitCount = waitCount;
       this.hitCount = hitCount;
-      this.meanAcquireNanos = hitCount == 0 ? 0 : totalAcquireNanos / hitCount;
+      this.totalAcquireMicros = totalAcquireNanos / 1000;
       this.maxAcquireMicros = maxAcquireNanos / 1000;
+      this.totalWaitMicros = totalWaitNanos / 1000;
+      this.meanAcquireNanos = hitCount == 0 ? 0 : totalAcquireNanos / hitCount;
     }
 
     @Override
     public String toString() {
       return "min[" + minSize + "] max[" + maxSize + "] free[" + free + "] busy[" + busy + "] waiting[" + waiting
         + "] highWaterMark[" + highWaterMark + "] waitCount[" + waitCount + "] hitCount[" + hitCount
-        + "] meanAcquireNanos[" + meanAcquireNanos + "] maxAcquireMicros[" + maxAcquireMicros + "]";
+        + "] totalAcquireMicros[" + totalAcquireMicros + "] maxAcquireMicros[" + maxAcquireMicros + "] totalWaitMicros[" + totalWaitMicros + "]";
     }
 
-    /**
-     * Return the min pool size.
-     */
     @Override
     public int minSize() {
       return minSize;
     }
 
-    /**
-     * Return the max pool size.
-     */
     @Override
     public int maxSize() {
       return maxSize;
     }
 
-    /**
-     * Return the current number of free connections in the pool.
-     */
     @Override
     public int free() {
       return free;
     }
 
-    /**
-     * Return the current number of busy connections in the pool.
-     */
     @Override
     public int busy() {
       return busy;
     }
 
-    /**
-     * Return the current number of threads waiting for a connection.
-     */
     @Override
     public int waiting() {
       return waiting;
     }
 
-    /**
-     * Return the high water mark of busy connections.
-     */
     @Override
     public int highWaterMark() {
       return highWaterMark;
     }
 
-    /**
-     * Return the total number of times a thread had to wait.
-     */
     @Override
     public int waitCount() {
       return waitCount;
     }
 
-    /**
-     * Return the total number of times there was an attempt to get a
-     * connection.
-     * <p>
-     * If the attempt to get a connection failed with a timeout or other
-     * exception those attempts are still included in this hit count.
-     * </p>
-     */
     @Override
     public int hitCount() {
       return hitCount;
     }
 
+    @Override
+    public long totalAcquireMicros() {
+      return totalAcquireMicros;
+    }
+
+    @Override
+    public long totalWaitMicros() {
+      return totalWaitMicros;
+    }
+
     @Override
     public long maxAcquireMicros() {
       return maxAcquireMicros;

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

@@ -53,6 +53,7 @@ final class PooledConnectionQueue {
   private int hitCount;
   private long totalAcquireNanos;
   private long maxAcquireNanos;
+  private long totalWaitNanos;
 
   /**
    * The high water mark for the queue size.
@@ -82,7 +83,7 @@ final class PooledConnectionQueue {
 
   private PoolStatus createStatus() {
     return new Status(minSize, maxSize, freeList.size(), busyList.size(), waitingThreads, highWaterMark,
-      waitCount, hitCount, totalAcquireNanos, maxAcquireNanos);
+      waitCount, hitCount, totalAcquireNanos, maxAcquireNanos, totalWaitNanos);
   }
 
   @Override
@@ -105,6 +106,7 @@ PoolStatus status(boolean reset) {
         waitCount = 0;
         maxAcquireNanos = 0;
         totalAcquireNanos = 0;
+        totalWaitNanos = 0;
       }
       return s;
     } finally {
@@ -244,6 +246,7 @@ private PooledConnection _obtainConnection() throws InterruptedException, SQLExc
         return _obtainConnectionWaitLoop();
       } finally {
         waitingThreads--;
+        totalWaitNanos += (System.nanoTime() - start);
       }
     } finally {
       final var elapsed = System.nanoTime() - start;

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

@@ -3,6 +3,7 @@
 import io.ebean.datasource.DataSourceAlert;
 import io.ebean.datasource.DataSourceBuilder;
 import io.ebean.datasource.DataSourcePool;
+import io.ebean.datasource.PoolStatus;
 import org.junit.jupiter.api.Test;
 
 import javax.sql.DataSource;
@@ -68,6 +69,11 @@ void testPoolFullWithHeartbeat() throws Exception {
       assertThat(up).isEqualTo(2);
       assertThat(down).isEqualTo(1);
 
+      PoolStatus status = pool.status(true);
+      assertThat(status.waitCount()).isGreaterThan(0);
+      assertThat(status.totalWaitMicros()).isBetween(0L, 9_000_000L);
+      assertThat(status.totalAcquireMicros()).isBetween(0L, 20_000_000L);
+      assertThat(status.maxAcquireMicros()).isBetween(0L, 3_000_000L);
 
     } finally {
       pool.shutdown();

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

@@ -64,9 +64,18 @@ void getConnection_expect_poolGrowsAboveMin() throws SQLException {
 
     con1.rollback();
     con1.close();
-    assertThat(pool.status(false).busy()).isEqualTo(0);
-    assertThat(pool.status(false).free()).isEqualTo(3);
+    PoolStatus status = pool.status(true);
+    assertThat(status.busy()).isEqualTo(0);
+    assertThat(status.free()).isEqualTo(3);
     assertThat(pool.size()).isEqualTo(3);
+    assertThat(status.waitCount()).isEqualTo(0);
+    assertThat(status.totalWaitMicros()).isEqualTo(0);
+    assertThat(status.hitCount()).isEqualTo(3);
+    assertThat(status.maxAcquireMicros()).isBetween(0L, 900L);
+    assertThat(status.meanAcquireNanos() / 1000).isBetween(0L, 900L);
+    assertThat(status.highWaterMark()).isEqualTo(3);
+    assertThat(status.minSize()).isEqualTo(2);
+    assertThat(status.maxSize()).isEqualTo(4);
   }
 
   @Test