GODRIVER-3172 Read response in the background after an op timeout.

[matthewdale]

• GODRIVER-3172
• GODRIVER-3151
• GODRIVER-3162

Summary

Experimental change to minimize connection churn during lots-of-timeout events caused by increased database latency.

Changes:

• Fix a bug that prevents maxTimeMS from being added to commands when a context with deadline is used on an operation, even if timeoutMS is set on the client.
  • For the Context-based deadlines, omit maxTimeMS from operations that return a cursor (Find, Aggregate) because the default behavior of maxTimeMS is to limit the lifetime of the cursor as well as the initial command, which may be surprising (see DRIVERS-2722). The existing automatic maxTimeMS behavior remains the same (i.e. when timeoutMS is set and no Context deadline is provided, Find and Aggregate still have maxTimeMS set).
• When an operation timeout occurs, mark the in-use connection as "awaiting response" and start a new goroutine that attempts to read the response on the connection. Wait for up to 1 second to get a response from the server. If the read is successful, check the connection into the pool to be reused. If the read fails, close the connection.

Background & Motivation

The Go Driver currently closes the in-use connection when a command times out on the client side. MongoDB processes commands sent on a single connection sequentially, so sending another command on the same connection after the previous one timed out could lead to the later command taking an unpredictable extra amount of time to complete (because it had to wait for the previous response to be read). Closing the connection is the simplest way to both resolve the unknown connection state and signal MongoDB to stop working on the command.

However, closing the connection after an operation timeout happens can cause problems when connection are closed and created at a very high rate. We've observed that setting maxTimeMS as described in the CSOT spec can cause MongoDB to reliably respond with a server-side timeout error 25-100ms after a client-side timeout occurs. That consistent response timing makes it feasible to await the response in the background after a client-side timeout instead of closing the connection.

[mongodb-drivers-pr-bot]

API Change Report

./x/mongo/driver

incompatible changes

##ExtractErrorFromServerResponse: changed from func(./x/bsonx/bsoncore.Document) error to func(context.Context, ./x/bsonx/bsoncore.Document) error

compatible changes

Operation.OmitCSOTMaxTimeMS: added

./x/mongo/driver/operation

compatible changes

(*Aggregate).OmitCSOTMaxTimeMS: added
(*Find).OmitCSOTMaxTimeMS: added

./x/mongo/driver/topology

compatible changes

BGReadCallback: added
BGReadTimeout: added

[ShaneHarvey]

Was this problem in the other PR addressed?

[prestonvasquez]

Suggest not using a bool here and instead pass in the context and use csot.IsTimeoutContext(ctx) within decodeResult. This ensures that the source of CSOT-ness is derived from a context.

[matthewdale]

Sounds good, will do.

[prestonvasquez]

Here is a UML diagram for the proposal:

[matthewdale]

Was this problem in the other PR addressed?

@ShaneHarvey I'm currently testing the tradeoffs between doing the read in the background vs doing it in-line with a subsequent operation. I'll document or link to those results here.

[JamesKovacs]

I would like to understand the reasoning behind the 1s deadline for reading any remaining server response. I'm wondering if this needs to be tuneable or whether it should be something dynamic like some multiple of P90 RTT.

[matthewdale]

The 1-second deadline is the failsafe timeout if the server doesn't respond in a reasonable period of time after the operation timed out. I picked 1 second because, in our testing, that value covered >99% of the server responses that came after the operation timed out when maxTimeMS is set (the "overshoot duration").

The "overshoot duration" is a combination of timing variability in the client application, database, and network, so it's not clear if there is a practical measurement-based algorithm for picking that value. In the updated PR, that failsafe value is configurable using a global setting in an experimental package (topology.BGReadTimeout). For now the goal is to make that a "safe" but not configurable value, but if we observe that different use cases need different values, we may make it generally configurable.

[prestonvasquez]

LGTM!

[ThatHurleyGuy]

@matthewdale We just discovered an edge case here. We apparently have a background job that sets a context timeout of ~25 days, more specifically 2211839988 milliseconds which is greater than 32-bit max int so they started getting BadValue) 2211839988 value for maxTimeMS is out of range [0, 2147483647] Obviously this is a somewhat far off edge case, I'm asking the team what's the reason of having a context with a deadline this long.

But wanted to flag this to you since this PR is going to start erroring out on those edge cases. The patch we applied internally is to just take min(math.MaxInt32 - (2 * time.Millisecond), time.Duration(float64(timeLeft))) to avoid triggering that validation error. Not sure if the logic in calculateMaxTimeMS should just say "That timeout is too long, I'm not going to set maxTimeMS at all" or if we'd want to apply the same min logic.

[ThatHurleyGuy]

Ah the explanation of why the timeout is so long makes sense. tl;dr - Processes for things like refunds/chargebacks can have month long time frames, and various workflow orchestration systems will set a golang context to timeout when that window ends even if the current step of the workflow won't take nearly that long.

Our team is going to look at tuning DB calls to have more granular contexts/timeouts, but this still might be a broader issue y'all might be concerned about since others could run into it

[matthewdale]

Wow, nice find! I've updated the driver to omit maxTimeMS if the calculated value is greater than max int32 so that there's no timeout you can set that will cause the "BadValue" error.

That means if an application starts an op with a timeout greater than 2147483647ms, there will be no database-side timeout automatically set. However, the client-side timeout logic will still work and will cause the driver to close the connection if that timeout is ever reached, cancelling the op on the server-side (unless the command returns within the new 1-second "grace period" after the timeout).

[ThatHurleyGuy]

Awesome, that approach makes sense to me and the code looks good. Nice job on the quick fix!

[matthewdale]

@ShaneHarvey I did a bunch of testing between "background reads" during check-in and "foreground reads" during check-out after an operation times out. The results unfortunately didn't show a clear winner as both behaved remarkably similarly, but each approach seemed to have one major downside:

• The "background reads" approach can create more connections when operations time out, increasing reliance on maxConnecting to limit connection creation rate until the max pool size is reached. That may also result in applications maintaining a larger connection pool when timeouts happen.
• The "foreground reads" approach can cause a higher error rate while lots of timeouts are happening. That may be caused by interaction between operations when timeouts occur, especially because pools by default use a LIFO algorithm to hand off idle connections.
  • The test that showed the difference in error rate attempts to replicate a database latency event by inserting then removing many documents from a collection while querying it, causing many timeouts as documents are inserted and the queries get slower. Across two test runs, the "foreground reads" approach recorded 15,910 errors over 37,605 requests, a 42.3% error rate. Across two test runs, the "background reads" approach recorded 11,538 errors over 34,141 requests, a 33.8% error rate. The average request rate for both approaches across all tests was around 350 req/sec with no significant difference in request rate between the two approaches.

I had to test both approaches at very high operation and timeout volume before I observed the above differences. In most other circumstances that I tested, they behaved almost identically.

For now I'm going to stick with the "background reads" approach to speed up delivering this fix. For the CSOT spec, I think we should allow driver teams to pick an approach suited to their language.