-
Notifications
You must be signed in to change notification settings - Fork 336
Improve connection pool failure diagnostics #4590
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
base: main
Are you sure you want to change the base?
Changes from all commits
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -37,6 +37,12 @@ internal abstract class DbConnectionInternal | |
|
|
||
| private readonly int _objectId = Interlocked.Increment(ref _objectTypeCount); | ||
|
|
||
| /// <summary> | ||
| /// UTC time at which this internal connection was most recently handed to an owning | ||
| /// <see cref="DbConnection"/>. Cleared when it returns to the pool. | ||
| /// </summary> | ||
| private DateTime _checkoutTime; | ||
|
|
||
| /// <summary> | ||
| /// [usage must be thread safe] the owning object, when not in the pool. (both Pooled and Non-Pooled connections) | ||
| /// </summary> | ||
|
|
@@ -119,6 +125,17 @@ internal DbConnectionInternal(ConnectionState state, bool hidePassword, bool all | |
| /// </summary> | ||
| internal DateTime ReturnedTime { get; set; } | ||
|
|
||
| /// <summary> | ||
| /// UTC timestamp of the current checkout, or <see cref="DateTime.MinValue"/> while the | ||
| /// connection is not owned by an application connection. The internal setter supports | ||
| /// deterministic timeout diagnostics tests. | ||
| /// </summary> | ||
| internal DateTime CheckoutTime | ||
| { | ||
| get => _checkoutTime; | ||
| set => _checkoutTime = value; | ||
| } | ||
|
|
||
| /// <summary> | ||
| /// The pool generation at the time this connection was created or added to the pool. | ||
| /// Used by <see cref="ChannelDbConnectionPool"/> to detect stale connections after a pool clear. | ||
|
|
@@ -730,8 +747,10 @@ internal void MakePooledConnection(IDbConnectionPool connectionPool) | |
| Pool = connectionPool; | ||
| } | ||
|
|
||
| internal void PostPop(DbConnection newOwner) | ||
| internal void PostPop(DbConnection newOwner, DateTime checkoutTime) | ||
| { | ||
| Debug.Assert(checkoutTime.Kind == DateTimeKind.Utc); | ||
|
|
||
| // Called by IDbConnectionPool right after it pulls this from its pool, we take this | ||
| // opportunity to ensure ownership and pool counts are legit. | ||
| Debug.Assert(!IsEmancipated, "pooled object not in pool"); | ||
|
|
@@ -746,6 +765,7 @@ internal void PostPop(DbConnection newOwner) | |
|
|
||
| _owningObject.SetTarget(newOwner); | ||
| _pooledCount--; | ||
| _checkoutTime = checkoutTime; | ||
|
|
||
| SqlClientEventSource.Log.TryPoolerTraceEvent("<prov.DbConnectionInternal.PostPop|RES|CPOOL> {0}, Preparing to pop from pool, owning connection {1}, pooledCount={2}", ObjectID, 0, _pooledCount); | ||
|
|
||
|
|
@@ -819,12 +839,60 @@ internal void PrePush(DbConnection expectedOwner) | |
| SqlClientEventSource.Log.TryPoolerTraceEvent("<prov.DbConnectionInternal.PrePush|RES|CPOOL> {0}, Preparing to push into pool, owning connection {1}, pooledCount={2}", ObjectID, 0, _pooledCount); | ||
|
|
||
| _pooledCount++; | ||
| _checkoutTime = DateTime.MinValue; | ||
|
|
||
| // NOTE: doing this and checking for InternalError.PooledObjectHasOwner degrades the | ||
| // close by 2% | ||
| _owningObject.SetTarget(null); | ||
| } | ||
|
|
||
| /// <summary> | ||
| /// Classifies the connection for a timeout-only pool diagnostics snapshot. | ||
| /// The caller must hold this connection's monitor. | ||
| /// </summary> | ||
| /// <param name="utcNow">Current UTC time used to calculate checkout duration.</param> | ||
| /// <param name="checkoutDuration">How long the current or abandoned checkout has lasted.</param> | ||
| /// <returns>The connection's current pool usage state.</returns> | ||
| internal PoolConnectionUsageState GetPoolUsageState( | ||
| DateTime utcNow, | ||
| out TimeSpan checkoutDuration) | ||
| { | ||
| Debug.Assert(Monitor.IsEntered(this)); | ||
| Debug.Assert(utcNow.Kind == DateTimeKind.Utc); | ||
|
|
||
| checkoutDuration = TimeSpan.Zero; | ||
|
|
||
| if (IsTxRootWaitingForTxEnd || | ||
| (IsInPool && EnlistedTransaction is not null)) | ||
| { | ||
| return PoolConnectionUsageState.TransactionHeld; | ||
| } | ||
|
|
||
| if (IsInPool) | ||
| { | ||
| return PoolConnectionUsageState.Idle; | ||
| } | ||
|
|
||
| if (_owningObject.TryGetTarget(out _)) | ||
| { | ||
| checkoutDuration = GetCheckoutDuration(utcNow); | ||
| return PoolConnectionUsageState.CheckedOut; | ||
| } | ||
|
|
||
| if (_checkoutTime != DateTime.MinValue && IsEmancipated) | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. We already know the connection is checked out (from line 871). If there was no sentinel, we wouldn't have to check for it here. |
||
| { | ||
| checkoutDuration = GetCheckoutDuration(utcNow); | ||
| return PoolConnectionUsageState.Abandoned; | ||
| } | ||
|
|
||
| return PoolConnectionUsageState.Unclassified; | ||
| } | ||
|
|
||
| private TimeSpan GetCheckoutDuration(DateTime utcNow) => | ||
| utcNow > _checkoutTime | ||
| ? utcNow - _checkoutTime | ||
| : TimeSpan.Zero; | ||
|
|
||
| internal void RemoveWeakReference(object value) => | ||
| ReferenceCollection?.Remove(value); | ||
|
|
||
|
|
||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -313,6 +313,12 @@ internal class SqlConnectionInternal : DbConnectionInternal, IDisposable | |
|
|
||
| private readonly SqlConnectionTimeoutErrorInternal _timeoutErrorInternal; | ||
|
|
||
| /// <summary> | ||
| /// Transient failures that caused this physical connection open to retry. The list exists | ||
| /// only while the constructor's open operation is in progress and is cleared on success. | ||
| /// </summary> | ||
| private List<SqlException> _connectionOpenRetryFailures; | ||
|
|
||
| /// <summary> | ||
| /// Cache the whereabouts (DTC Address) for exporting. | ||
| /// </summary> | ||
|
|
@@ -452,9 +458,17 @@ internal SqlConnectionInternal( | |
| && _timeout.MillisecondsRemaining >= transientRetryIntervalInMilliSeconds | ||
| && IsTransientError(sqlex)) | ||
| { | ||
| RecordConnectionOpenRetryFailure(sqlex); | ||
| Thread.Sleep(transientRetryIntervalInMilliSeconds); | ||
| } | ||
| catch (SqlException sqlex) | ||
| { | ||
| AttachConnectionOpenRetryFailures(sqlex); | ||
| throw; | ||
| } | ||
| } | ||
|
|
||
| _connectionOpenRetryFailures = null; | ||
| } | ||
| // @TODO: CER Exception Handling was removed here (see GH#3581) | ||
| finally | ||
|
|
@@ -3407,6 +3421,7 @@ private void LoginNoFailover( | |
| { | ||
| if (AttemptRetryADAuthWithTimeoutError(sqlex, timeout)) | ||
| { | ||
| RecordConnectionOpenRetryFailure(sqlex); | ||
| continue; | ||
| } | ||
|
|
||
|
|
@@ -3429,6 +3444,8 @@ private void LoginNoFailover( | |
| { | ||
| throw; | ||
| } | ||
|
|
||
| RecordConnectionOpenRetryFailure(sqlex); | ||
| } | ||
|
|
||
| // We only get here when we failed to connect, but are going to re-try | ||
|
|
@@ -3731,6 +3748,7 @@ private void LoginWithFailover( | |
| { | ||
| if (AttemptRetryADAuthWithTimeoutError(sqlex, timeout)) | ||
| { | ||
| RecordConnectionOpenRetryFailure(sqlex); | ||
| continue; | ||
| } | ||
|
|
||
|
|
@@ -3768,6 +3786,8 @@ private void LoginWithFailover( | |
| throw; | ||
| } | ||
| } | ||
|
|
||
| RecordConnectionOpenRetryFailure(sqlex); | ||
| } | ||
|
|
||
| // We only get here when we failed to connect, but are going to re-try | ||
|
|
@@ -3838,6 +3858,26 @@ private bool IsDoNotRetryConnectError(SqlException exc) | |
| return errorNumberMatch || exc._doNotReconnect; | ||
| } | ||
|
|
||
| /// <summary> | ||
| /// Records a transient failure immediately before the same connection open is retried. | ||
| /// </summary> | ||
| private void RecordConnectionOpenRetryFailure(SqlException exception) => | ||
| (_connectionOpenRetryFailures ??= new List<SqlException>()).Add(exception); | ||
|
|
||
| /// <summary> | ||
| /// Attaches the retry ledger to the terminal failure without changing its errors or inner | ||
| /// exception. | ||
| /// </summary> | ||
| private void AttachConnectionOpenRetryFailures( | ||
| SqlException terminalException) | ||
| { | ||
| if (_connectionOpenRetryFailures is { Count: > 0 }) | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. I think this would be more clear if inlined on line 466. |
||
| { | ||
| terminalException.SetConnectionOpenRetryFailures( | ||
| _connectionOpenRetryFailures); | ||
| } | ||
| } | ||
|
|
||
| /// <summary> | ||
| /// Returns <c>true</c> if the SQL error is transient, as per <see cref="s_transientErrors"/>. | ||
| /// </summary> | ||
|
|
||
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Why would we be examining
CheckoutTimeif the connection isn't checked-out? I wondering if this sentinel is necessary and if we could save an assignment on each return-to-pool.