Account the time to deliver connection pool events as part of the reported duration (#1290)

JAVA-5121

Author: stIncMale

driver-core/src/main/com/mongodb/event/ConnectionCheckOutFailedEvent.java

@@ -109,15 +109,13 @@ public Reason getReason() {
 
     /**
      * The time it took to check out the connection.
-     * More specifically, the time elapsed between the {@link ConnectionCheckOutStartedEvent} emitted by the same checking out and this event.
+     * More specifically, the time elapsed between emitting a {@link ConnectionCheckOutStartedEvent}
+     * and emitting this event as part of the same checking out.
      * <p>
      * Naturally, if a new connection was not {@linkplain ConnectionCreatedEvent created}
      * and {@linkplain ConnectionReadyEvent established} as part of checking out,
      * this duration is usually not greater than {@link ConnectionPoolSettings#getMaxWaitTime(TimeUnit)},
      * but may occasionally be greater than that, because the driver does not provide hard real-time guarantees.</p>
-     * <p>
-     * This duration does not currently include the time to deliver the {@link ConnectionCheckOutStartedEvent}.
-     * Subject to change.</p>
      *
      * @param timeUnit The time unit of the result.
      * {@link TimeUnit#convert(long, TimeUnit)} specifies how the conversion from nanoseconds to {@code timeUnit} is done.

driver-core/src/main/com/mongodb/event/ConnectionCheckedOutEvent.java

@@ -71,15 +71,13 @@ public long getOperationId() {
 
     /**
      * The time it took to check out the connection.
-     * More specifically, the time elapsed between the {@link ConnectionCheckOutStartedEvent} emitted by the same checking out and this event.
+     * More specifically, the time elapsed between emitting a {@link ConnectionCheckOutStartedEvent}
+     * and emitting this event as part of the same checking out.
      * <p>
      * Naturally, if a new connection was not {@linkplain ConnectionCreatedEvent created}
      * and {@linkplain ConnectionReadyEvent established} as part of checking out,
      * this duration is usually not greater than {@link ConnectionPoolSettings#getMaxWaitTime(TimeUnit)},
      * but may occasionally be greater than that, because the driver does not provide hard real-time guarantees.</p>
-     * <p>
-     * This duration does not currently include the time to deliver the {@link ConnectionCheckOutStartedEvent}.
-     * Subject to change.</p>
      *
      * @param timeUnit The time unit of the result.
      * {@link TimeUnit#convert(long, TimeUnit)} specifies how the conversion from nanoseconds to {@code timeUnit} is done.

driver-core/src/main/com/mongodb/event/ConnectionReadyEvent.java

@@ -58,14 +58,12 @@ public ConnectionId getConnectionId() {
 
     /**
      * The time it took to establish the connection.
-     * More specifically, the time elapsed between the {@link ConnectionCreatedEvent} emitted by the same checking out and this event.
+     * More specifically, the time elapsed between emitting a {@link ConnectionCreatedEvent}
+     * and emitting this event as part of the same checking out.
      * <p>
      * Naturally, when establishing a connection is part of checking out,
      * this duration is not greater than
      * {@link ConnectionCheckedOutEvent#getElapsedTime(TimeUnit)}/{@link ConnectionCheckOutFailedEvent#getElapsedTime(TimeUnit)}.</p>
-     * <p>
-     * This duration does not currently include the time to deliver the {@link ConnectionCreatedEvent}.
-     * Subject to change.</p>
      *
      * @param timeUnit The time unit of the result.
      * {@link TimeUnit#convert(long, TimeUnit)} specifies how the conversion from nanoseconds to {@code timeUnit} is done.

driver-core/src/main/com/mongodb/internal/connection/DefaultConnectionPool.java

@@ -504,19 +504,19 @@ private void connectionPoolCreated(final ConnectionPoolListener connectionPoolLi
      * Send both current and deprecated events in order to preserve backwards compatibility.
      * Must not throw {@link Exception}s.
      *
-     * @return A {@link TimePoint} after executing {@link ConnectionPoolListener#connectionCreated(ConnectionCreatedEvent)},
-     * {@link ConnectionPoolListener#connectionCreated(ConnectionCreatedEvent)}.
-     * This order is required by
+     * @return A {@link TimePoint} before executing {@link ConnectionPoolListener#connectionCreated(ConnectionCreatedEvent)}
+     * and logging the event. This order is required by
      * <a href="https://github.com/mongodb/specifications/blob/master/source/connection-monitoring-and-pooling/connection-monitoring-and-pooling.rst#events">CMAP</a>
      * and {@link ConnectionReadyEvent#getElapsedTime(TimeUnit)}.
      */
     private TimePoint connectionCreated(final ConnectionPoolListener connectionPoolListener, final ConnectionId connectionId) {
+        TimePoint openStart = TimePoint.now();
         logEventMessage("Connection created",
                 "Connection created: address={}:{}, driver-generated ID={}",
                 connectionId.getLocalValue());
 
         connectionPoolListener.connectionCreated(new ConnectionCreatedEvent(connectionId));
-        return TimePoint.now();
+        return openStart;
     }
 
     /**
@@ -562,16 +562,18 @@ private void connectionCheckedOut(
     }
 
     /**
-     * @return A {@link TimePoint} after executing {@link ConnectionPoolListener#connectionCheckOutStarted(ConnectionCheckOutStartedEvent)}.
+     * @return A {@link TimePoint} before executing
+     * {@link ConnectionPoolListener#connectionCheckOutStarted(ConnectionCheckOutStartedEvent)} and logging the event.
      * This order is required by
      * <a href="https://github.com/mongodb/specifications/blob/master/source/connection-monitoring-and-pooling/connection-monitoring-and-pooling.rst#events">CMAP</a>
      * and {@link ConnectionCheckedOutEvent#getElapsedTime(TimeUnit)}, {@link ConnectionCheckOutFailedEvent#getElapsedTime(TimeUnit)}.
      */
     private TimePoint connectionCheckoutStarted(final OperationContext operationContext) {
+        TimePoint checkoutStart = TimePoint.now();
         logEventMessage("Connection checkout started", "Checkout started for connection to {}:{}");
 
         connectionPoolListener.connectionCheckOutStarted(new ConnectionCheckOutStartedEvent(serverId, operationContext.getId()));
-        return TimePoint.now();
+        return checkoutStart;
     }
 
     /**