Skip to content

DRIVERS-2469 Add durations to connection pool events #1448

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.

Sign up for GitHub

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

Merged
merged 8 commits into from
Aug 9, 2023
Merged

DRIVERS-2469 Add durations to connection pool events #1448

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
8 commits
Select commit Hold shift + click to select a range
52ea3b7
Add durations to connection pool events
stIncMale Aug 2, 2023
7da6db8
Fix the wording
stIncMale Aug 4, 2023
b28adf8
Fix the formatting
stIncMale Aug 8, 2023
31f29fb
Replace `ConnectionCheckedOutEvent`/`ConnectionCheckOutFailedEvent.wa…
stIncMale Aug 8, 2023
2ca3768
Fix the wording
stIncMale Aug 8, 2023
4d08e36
Fix the wording
stIncMale Aug 8, 2023
1ec330e
Use "not greater than" consistently
stIncMale Aug 8, 2023
1376092
Fix `ConnectionReadyEvent.duration`, take into account that this even…
stIncMale Aug 9, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
94 changes: 83 additions & 11 deletions source/connection-monitoring-and-pooling/connection-monitoring-and-pooling.rst
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -12,6 +12,8 @@ Abstract

Drivers currently support a variety of options that allow users to configure connection pooling behavior. Users are confused by drivers supporting different subsets of these options. Additionally, drivers implement their connection pools differently, making it difficult to design cross-driver pool functionality. By unifying and codifying pooling options and behavior across all drivers, we will increase user comprehension and code base maintainability.

This specification does not apply to drivers that do not support multitasking.
Copy link
Member Author

@stIncMale stIncMale Aug 4, 2023 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This fleshes out the current state of affairs. Not understanding this part costed me some time when working on this PR, which is why the change is relevant.


META
====

Expand Down Expand Up @@ -131,8 +133,9 @@ Additionally, Drivers that implement a Connection Pool MUST support the followin
/**
* NOTE: This option has been deprecated in favor of timeoutMS.
*
* The maximum amount of time a thread can wait for a connection
* to become available.
* The maximum amount of time a thread can wait for
* either an available non-perished connection (limited by `maxPoolSize`),
* or a pending connection (limited by `maxConnecting`).
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This clarifies the definition to match the reality. Needs to be done as part of this PR because this PR relies on the definition of waitQueueTimeoutMS.

* If specified, MUST be a number >= 0.
* A value of 0 means there is no limit.
* Defaults to 0.
Expand Down Expand Up @@ -641,12 +644,6 @@ Before a given `Connection <#connection>`_ is returned from checkOut, it must be
# This must be done in all drivers
leave wait queue

# If there is no background thread, the pool MUST ensure that
# there are at least minPoolSize total connections.
# This MUST be done in a non-blocking manner
while totalConnectionCount < minPoolSize:
populate the pool with a connection

# If the Connection has not been established yet (TCP, TLS,
# handshake, compression, and auth), it must be established
# before it is returned.
Expand All @@ -663,6 +660,13 @@ Before a given `Connection <#connection>`_ is returned from checkOut, it must be
else:
decrement availableConnectionCount
set connection state to "in use"

# If there is no background thread, the pool MUST ensure that
# there are at least minPoolSize total connections.
do asynchronously:
while totalConnectionCount < minPoolSize:
populate the pool with a connection

Comment on lines +663 to +669
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

  1. Moved the part of the checkOut logic that is concerned with populating the pool at the end of the checkOut logic because the previous position was weird: between creating a new connection that is about to be checked out and establishing it.
  2. Replaced This MUST be done in a non-blocking manner with the do asynchronously block, because it's the only interpretation of "non-blocking manner" I can see here, and I find it clearer. Expressing the requirement as pseudocode is also more explicit as opposed to being expressed in a comment.

emit ConnectionCheckedOutEvent and equivalent log message
return connection

Expand Down Expand Up @@ -909,6 +913,30 @@ See the `Load Balancer Specification <../load-balancers/load-balancers.rst#event
* The ID of the Connection
*/
connectionId: int64;

/**
* The time it took to establish the connection.
* In accordance with the definition of establishment of a connection
* specified by `ConnectionPoolOptions.maxConnecting`,
* it is the time elapsed between the `ConnectionCreatedEvent`
* emitted by the same checking out and this event.
*
* Naturally, when establishing a connection is part of checking out,
* this duration is not greater than
* `ConnectionCheckedOutEvent`/`ConnectionCheckOutFailedEvent.duration`.
*
* A driver that delivers events synchronously MUST NOT include in this duration
* the time to deliver the `ConnectionCreatedEvent`.
* Doing so eliminates a thing to worry about in support cases related to this duration,
* because the time to deliver synchronously is affected by user code.
* The driver MUST document this behavior
* as well as explicitly warn users that the behavior may change in the future.
*
* A driver MAY choose the type idiomatic to the driver.
* If the type chosen does not convey units, e.g., `int64`,
* then the driver MAY include units in the name, e.g., `durationMS`.
*/
duration: Duration;
}

/**
Expand Down Expand Up @@ -966,6 +994,11 @@ See the `Load Balancer Specification <../load-balancers/load-balancers.rst#event
* - "connectionError": The Connection check out attempt experienced an error while setting up a new Connection
*/
reason: string|Enum;

/**
* See `ConnectionCheckedOutEvent.duration`.
*/
duration: Duration;
}

/**
Expand All @@ -981,6 +1014,32 @@ See the `Load Balancer Specification <../load-balancers/load-balancers.rst#event
* The ID of the Connection
*/
connectionId: int64;

/**
* The time it took to check out the connection.
* More specifically, the time elapsed between
* the `ConnectionCheckOutStartedEvent`
* emitted by the same checking out and this event.
*
* Naturally, if a new connection was not created (`ConnectionCreatedEvent`)
* and established (`ConnectionReadyEvent`) as part of checking out,
* this duration is usually
* not greater than `ConnectionPoolOptions.waitQueueTimeoutMS`,
* but MAY occasionally be greater than that,
* because a driver does not provide hard real-time guarantees.
*
* A driver that delivers events synchronously MUST NOT include in this duration
* the time to deliver the `ConnectionCheckOutStartedEvent`.
* Doing so eliminates a thing to worry about in support cases related to this duration,
* because the time to deliver synchronously is affected by user code.
* The driver MUST document this behavior
* as well as explicitly warn users that the behavior may change in the future.
*
* A driver MAY choose the type idiomatic to the driver.
* If the type chosen does not convey units, e.g., `int64`,
* then the driver MAY include units in the name, e.g., `durationMS`.
*/
duration: Duration;
}

/**
Expand Down Expand Up @@ -1195,9 +1254,13 @@ In addition to the common fields defined above, this message MUST contain the fo
- Int64
- The driver-generated ID for the connection as defined in `Connection <#connection>`_.

* - durationMS
- Int64
- ``ConnectionReadyEvent.duration`` converted to milliseconds.

The unstructured form SHOULD be as follows, using the values defined in the structured format above to fill in placeholders as appropriate:

Connection ready: address={{serverHost}}:{{serverPort}}, driver-generated ID={{driverConnectionId}}
Connection ready: address={{serverHost}}:{{serverPort}}, driver-generated ID={{driverConnectionId}}, established in={{durationMS}} ms

Connection Closed Message
-------------------------
Expand Down Expand Up @@ -1288,9 +1351,13 @@ In addition to the common fields defined above, this message MUST contain the fo
- If ``reason`` is ``ConnectionError``, the associated error. The type and format of this value is flexible; see the
`logging specification <../logging/logging.rst#representing-errors-in-log-messages>`_ for details on representing errors in log messages.

* - durationMS
- Int64
- ``ConnectionCheckOutFailedEvent.duration`` converted to milliseconds.

The unstructured form SHOULD be as follows, using the values defined in the structured format above to fill in placeholders as appropriate:

Checkout failed for connection to {{serverHost}}:{{serverPort}}. Reason: {{reason}}. Error: {{error}}
Checkout failed for connection to {{serverHost}}:{{serverPort}}. Reason: {{reason}}. Error: {{error}}. Duration: {{durationMS}} ms

Connection Checked Out
-----------------------
Expand All @@ -1312,9 +1379,13 @@ In addition to the common fields defined above, this message MUST contain the fo
- Int64
- The driver-generated ID for the connection as defined in `Connection <#connection>`_.

* - durationMS
- Int64
- ``ConnectionCheckedOutEvent.duration`` converted to milliseconds.

The unstructured form SHOULD be as follows, using the values defined in the structured format above to fill in placeholders as appropriate:

Connection checked out: address={serverHost}}:{{serverPort}}, driver-generated ID={{driverConnectionId}}
Connection checked out: address={serverHost}}:{{serverPort}}, driver-generated ID={{driverConnectionId}}, duration={{durationMS}} ms

Connection Checked In
---------------------
Expand Down Expand Up @@ -1549,6 +1620,7 @@ Changelog
:2022-10-05: Remove spec front matter and reformat changelog.
:2022-10-14: Add connection pool log messages and associated tests.
:2023-04-17: Fix duplicate logging test description.
:2023-08-04: Add durations to connection pool events.

----

Expand Down
28 changes: 28 additions & 0 deletions source/connection-monitoring-and-pooling/tests/logging/connection-logging.json
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -140,6 +140,13 @@
"int",
"long"
]
},
"durationMS": {
"$$type": [
"double",
"int",
"long"
]
}
}
},
Expand All @@ -162,6 +169,13 @@
"int",
"long"
]
},
"durationMS": {
"$$type": [
"double",
"int",
"long"
]
}
}
},
Expand Down Expand Up @@ -222,6 +236,13 @@
"int",
"long"
]
},
"durationMS": {
"$$type": [
"double",
"int",
"long"
]
}
}
},
Expand Down Expand Up @@ -484,6 +505,13 @@
"reason": "An error occurred while trying to establish a new connection",
"error": {
"$$exists": true
},
"durationMS": {
"$$type": [
"double",
"int",
"long"
]
}
}
}
Expand Down
4 changes: 4 additions & 0 deletions source/connection-monitoring-and-pooling/tests/logging/connection-logging.yml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -66,6 +66,7 @@ tests:
driverConnectionId: { $$type: [int, long] }
serverHost: { $$type: string }
serverPort: { $$type: [int, long] }
durationMS: { $$type: [double, int, long] }

- level: debug
component: connection
Expand All @@ -74,6 +75,7 @@ tests:
driverConnectionId: { $$type: [int, long] }
serverHost: { $$type: string }
serverPort: { $$type: [int, long] }
durationMS: { $$type: [double, int, long] }

- level: debug
component: connection
Expand All @@ -98,6 +100,7 @@ tests:
driverConnectionId: { $$type: [int, long] }
serverHost: { $$type: string }
serverPort: { $$type: [int, long] }
durationMS: { $$type: [double, int, long] }

- level: debug
component: connection
Expand Down Expand Up @@ -218,3 +221,4 @@ tests:
serverPort: { $$type: [int, long] }
reason: "An error occurred while trying to establish a new connection"
error: { $$exists: true }
durationMS: { $$type: [double, int, long] }
7 changes: 7 additions & 0 deletions source/connection-monitoring-and-pooling/tests/logging/connection-pool-options.json
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -128,6 +128,13 @@
"int",
"long"
]
},
"durationMS": {
"$$type": [
"double",
"int",
"long"
]
}
}
}
Expand Down
1 change: 1 addition & 0 deletions source/connection-monitoring-and-pooling/tests/logging/connection-pool-options.yml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -71,6 +71,7 @@ tests:
driverConnectionId: { $$type: [int, long] }
serverHost: { $$type: string }
serverPort: { $$type: [int, long] }
durationMS: { $$type: [double, int, long] }

# Drivers who have not done DRIVERS-1943 will need to skip this test.
- description: "maxConnecting should be included in connection pool created message when specified"
Expand Down