Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Merged
merged 2 commits into from
Jan 5, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}

/**
Expand Down Expand Up @@ -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;
}

/**
Expand Down