diff --git a/doc/snippets/Microsoft.Data.SqlClient/SqlException.xml b/doc/snippets/Microsoft.Data.SqlClient/SqlException.xml index 780fbd95f8..5756f29a89 100644 --- a/doc/snippets/Microsoft.Data.SqlClient/SqlException.xml +++ b/doc/snippets/Microsoft.Data.SqlClient/SqlException.xml @@ -307,6 +307,41 @@ + + + Gets the transient failures that caused retries before this connection open operation ultimately failed. + + + A read-only list in retry order. The list is empty when the exception was not produced by a retried connection open operation. + + + + The terminal failure is represented by this . This property contains only earlier failures that caused the driver to retry the same connection open operation. + + + The list is scoped to one call to or and is discarded when the connection opens successfully. + + + Formatter-based serialization does not preserve this diagnostic list. + + + + + try + { + connection.Open(); + } + catch (SqlException ex) + { + Console.WriteLine($"Final failure: {ex.Message}"); + foreach (SqlException retryFailure in ex.ConnectionOpenRetryFailures) + { + Console.WriteLine($"Earlier retry failure: {retryFailure.Message}"); + } + } + + + To be added diff --git a/src/Microsoft.Data.SqlClient/ref/Microsoft.Data.SqlClient.cs b/src/Microsoft.Data.SqlClient/ref/Microsoft.Data.SqlClient.cs index a5e3f1a473..1fa75eadd5 100644 --- a/src/Microsoft.Data.SqlClient/ref/Microsoft.Data.SqlClient.cs +++ b/src/Microsoft.Data.SqlClient/ref/Microsoft.Data.SqlClient.cs @@ -1860,6 +1860,8 @@ private SqlException(System.Runtime.Serialization.SerializationInfo info, System /// [System.ComponentModel.DesignerSerializationVisibilityAttribute(System.ComponentModel.DesignerSerializationVisibility.Content)] public Microsoft.Data.SqlClient.SqlErrorCollection Errors { get { throw null; } } + /// + public System.Collections.Generic.IReadOnlyList ConnectionOpenRetryFailures { get { throw null; } } /// public int LineNumber { get { throw null; } } /// diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/Common/AdapterUtil.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/Common/AdapterUtil.cs index e2e73b55b1..2312d5d680 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/Common/AdapterUtil.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/Common/AdapterUtil.cs @@ -21,6 +21,7 @@ using Microsoft.Data.Common.ConnectionString; using Microsoft.Data.SqlClient; using Microsoft.Data.SqlClient.Connection; +using Microsoft.Data.SqlClient.ConnectionPool; using Microsoft.SqlServer.Server; using Microsoft.Win32; using IsolationLevel = System.Data.IsolationLevel; @@ -1337,6 +1338,17 @@ internal static Exception UndefinedPopulationMechanism(string populationMechanis internal static Exception PooledOpenTimeout() => ADP.InvalidOperation(StringsHelper.GetString(Strings.ADP_PooledOpenTimeout)); + internal static Exception PooledOpenTimeout(PoolAcquisitionDiagnostics diagnostics) + { + Exception exception = ADP.InvalidOperation( + string.Concat( + StringsHelper.GetString(Strings.ADP_PooledOpenTimeout), + " ", + diagnostics.GetMessage())); + diagnostics.AddTo(exception.Data); + return exception; + } + internal static Exception NonPooledOpenTimeout() => ADP.TimeoutException(StringsHelper.GetString(Strings.ADP_NonPooledOpenTimeout)); #endregion diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/ProviderBase/DbConnectionInternal.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/ProviderBase/DbConnectionInternal.cs index 338f0e65e9..3511ad503f 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/ProviderBase/DbConnectionInternal.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/ProviderBase/DbConnectionInternal.cs @@ -37,6 +37,12 @@ internal abstract class DbConnectionInternal private readonly int _objectId = Interlocked.Increment(ref _objectTypeCount); + /// + /// UTC time at which this internal connection was most recently handed to an owning + /// . Cleared when it returns to the pool. + /// + private DateTime _checkoutTime; + /// /// [usage must be thread safe] the owning object, when not in the pool. (both Pooled and Non-Pooled connections) /// @@ -119,6 +125,17 @@ internal DbConnectionInternal(ConnectionState state, bool hidePassword, bool all /// internal DateTime ReturnedTime { get; set; } + /// + /// UTC timestamp of the current checkout, or while the + /// connection is not owned by an application connection. The internal setter supports + /// deterministic timeout diagnostics tests. + /// + internal DateTime CheckoutTime + { + get => _checkoutTime; + set => _checkoutTime = value; + } + /// /// The pool generation at the time this connection was created or added to the pool. /// Used by 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(" {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(" {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); } + /// + /// Classifies the connection for a timeout-only pool diagnostics snapshot. + /// The caller must hold this connection's monitor. + /// + /// Current UTC time used to calculate checkout duration. + /// How long the current or abandoned checkout has lasted. + /// The connection's current pool usage state. + 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) + { + 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); diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Connection/SqlConnectionInternal.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Connection/SqlConnectionInternal.cs index ec210e407a..0fc268f087 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Connection/SqlConnectionInternal.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Connection/SqlConnectionInternal.cs @@ -313,6 +313,12 @@ internal class SqlConnectionInternal : DbConnectionInternal, IDisposable private readonly SqlConnectionTimeoutErrorInternal _timeoutErrorInternal; + /// + /// 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. + /// + private List _connectionOpenRetryFailures; + /// /// Cache the whereabouts (DTC Address) for exporting. /// @@ -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; } + /// + /// Records a transient failure immediately before the same connection open is retried. + /// + private void RecordConnectionOpenRetryFailure(SqlException exception) => + (_connectionOpenRetryFailures ??= new List()).Add(exception); + + /// + /// Attaches the retry ledger to the terminal failure without changing its errors or inner + /// exception. + /// + private void AttachConnectionOpenRetryFailures( + SqlException terminalException) + { + if (_connectionOpenRetryFailures is { Count: > 0 }) + { + terminalException.SetConnectionOpenRetryFailures( + _connectionOpenRetryFailures); + } + } + /// /// Returns true if the SQL error is transient, as per . /// diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/BlockingPeriodErrorState.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/BlockingPeriodErrorState.cs index 796f0e16dd..244c08ec08 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/BlockingPeriodErrorState.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/BlockingPeriodErrorState.cs @@ -122,7 +122,10 @@ internal void Enter(Exception ex) lock (_lock) { _inElevatedState = true; - _cachedException = ex; + _cachedException = ex is SqlException sqlException + ? sqlException.InternalClone( + includeConnectionOpenRetryFailures: false) + : ex; wait = _nextWait; ITimer newTimer = ADP.UnsafeCreateTimer( diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/ChannelDbConnectionPool.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/ChannelDbConnectionPool.cs index a547ce0fd4..bd7b6a0cd5 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/ChannelDbConnectionPool.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/ChannelDbConnectionPool.cs @@ -161,6 +161,12 @@ internal sealed class ChannelDbConnectionPool : IDbConnectionPool, IDisposable /// requester to start the loop, and reset to 0 by the loop when it drains. /// private int _warmupLoopRunning; + + /// + /// Number of abandoned connections this pool has reclaimed. Acquisition requests sample + /// this counter so a timeout can report reclamation that occurred while that request waited. + /// + private long _reclaimedConnectionCount; #endregion /// @@ -490,7 +496,9 @@ public DbConnectionInternal ReplaceConnection( lock (newConnection) { // PostPop requires a lock on the connection. - newConnection.PostPop(owningObject); + newConnection.PostPop( + owningObject, + _timeProvider.GetUtcNow().UtcDateTime); } // Carry the old connection's enlistment over to the replacement so that a @@ -1049,6 +1057,8 @@ public bool TryGetConnection( /// The cancellation token to cancel the operation. /// The overall timeout budget. Passed through to the physical connection /// so it uses the remaining budget rather than starting a fresh timeout. + /// Receives why no connection could be created when the method + /// returns null. /// The new internal connection, or null if the pool has no available slot or the /// rate limiter is currently saturated. In the latter case the caller should fall back to /// the idle-channel wait; the rate limiter will write a null to the idle channel when a @@ -1059,8 +1069,10 @@ public bool TryGetConnection( private DbConnectionInternal? OpenNewInternalConnection( DbConnection? owningConnection, CancellationToken cancellationToken, - TimeoutTimer timeout) + TimeoutTimer timeout, + out PoolAcquisitionWaitReason waitReason) { + waitReason = PoolAcquisitionWaitReason.Unknown; cancellationToken.ThrowIfCancellationRequested(); // Fast-fail if the pool is in the blocking-period error state. FR-006. Warmup goes @@ -1081,6 +1093,8 @@ public bool TryGetConnection( try { + bool rateLimited = false; + // Reserve a pool slot up front so we don't pay the rate-limit cost only to // discover the pool is full. Add() reserves synchronously and returns null // immediately if no slot is available; the rate-limit check only happens inside @@ -1112,6 +1126,8 @@ public bool TryGetConnection( { if (!lease.IsAcquired) { + rateLimited = true; + // TODO: When we fail to acquire a lease, surface the lease metadata // (e.g. RateLimitMetadataName.RetryAfter, ReasonPhrase) in the error // path so the user can identify why the lease was denied. @@ -1218,6 +1234,10 @@ _connectionCreationRateLimiter is not null && } else { + waitReason = rateLimited + ? PoolAcquisitionWaitReason.ConnectionCreationRateLimited + : PoolAcquisitionWaitReason.PoolFull; + SqlClientEventSource.Log.TryPoolerTraceEvent( "ChannelDbConnectionPool.OpenNewInternalConnection | INFO | {0}, No connection created; pool is full or creation is rate limited.", Id); @@ -1458,6 +1478,10 @@ private async Task GetInternalConnection( Transaction? ambientTransaction) { DbConnectionInternal? connection = null; + PoolAcquisitionWaitReason waitReason = PoolAcquisitionWaitReason.Unknown; + long reclaimedConnectionCountAtStart = + Interlocked.Read(ref _reclaimedConnectionCount); + bool enteredParkedWait = false; SqlClientEventSource.Log.TryPoolerTraceEvent( "ChannelDbConnectionPool.GetInternalConnection | INFO | {0}, Getting connection.", Id); @@ -1505,10 +1529,19 @@ private async Task GetInternalConnection( // If we didn't find an idle connection, try to open a new one. This may // return null if the pool is full or the rate limiter is currently saturated; // in either case the caller falls through to the idle-channel wait below. - connection ??= OpenNewInternalConnection( - owningConnection, - cancellationToken, - timeout); + if (connection is null) + { + connection = OpenNewInternalConnection( + owningConnection, + cancellationToken, + timeout, + out PoolAcquisitionWaitReason currentWaitReason); + + if (connection is null) + { + waitReason = currentWaitReason; + } + } // If we're at max capacity and couldn't open a connection. Block on the idle channel with a // timeout. Note that Channels guarantee fair FIFO behavior to callers of ReadAsync @@ -1520,6 +1553,7 @@ private async Task GetInternalConnection( // O(MaxPoolSize) walk on every saturated acquire in applications that never leak. if (connection is null) { + enteredParkedWait = true; Reclaimer.EnterParkedWait(); try { @@ -1538,7 +1572,14 @@ private async Task GetInternalConnection( SqlClientEventSource.Log.TryPoolerTraceEvent( "ChannelDbConnectionPool.GetInternalConnection | INFO | {0}, Wait timed out.", Id); - throw ADP.PooledOpenTimeout(); + int waitingRequestCount = + Reclaimer.ParkedWaiters + (enteredParkedWait ? 1 : 0); + PoolAcquisitionDiagnostics diagnostics = + CaptureAcquisitionDiagnostics( + waitReason, + reclaimedConnectionCountAtStart, + Math.Max(1, waitingRequestCount)); + throw ADP.PooledOpenTimeout(diagnostics); } catch (ChannelClosedException) { @@ -1662,6 +1703,7 @@ private void SweepEmancipatedConnections() } Metrics.ReclaimedConnectionRequest(); + Interlocked.Increment(ref _reclaimedConnectionCount); returned++; } @@ -1674,6 +1716,72 @@ private void SweepEmancipatedConnections() } } + /// + /// Captures a best-effort pool snapshot on the timeout path. + /// + private PoolAcquisitionDiagnostics CaptureAcquisitionDiagnostics( + PoolAcquisitionWaitReason waitReason, + long reclaimedConnectionCountAtStart, + int waitingRequestCount) + { + int connectionCount = Count; + int reservationCount = _connectionSlots.ReservationCount; + + if (waitReason == PoolAcquisitionWaitReason.Unknown) + { + waitReason = reservationCount >= checked((int)MaxPoolSize) + ? PoolAcquisitionWaitReason.PoolFull + : PoolAcquisitionWaitReason.ConnectionCreationInProgress; + } + + var builder = new PoolAcquisitionDiagnosticsBuilder( + _timeProvider.GetUtcNow().UtcDateTime); + + foreach (DbConnectionInternal connection in _connectionSlots) + { + bool locked = false; + try + { + Monitor.TryEnter(connection, ref locked); + if (locked) + { + builder.Observe(connection); + } + else + { + builder.ObserveLockContention(); + } + } + finally + { + if (locked) + { + Monitor.Exit(connection); + } + } + } + + long reclaimedConnectionCount = + Math.Max( + 0, + Interlocked.Read(ref _reclaimedConnectionCount) - + reclaimedConnectionCountAtStart); + + return new PoolAcquisitionDiagnostics( + waitReason, + checked((int)MaxPoolSize), + connectionCount, + builder.IdleConnectionCount, + Math.Max(0, reservationCount - connectionCount), + waitingRequestCount, + builder.CheckedOutConnectionCount, + builder.TransactionConnectionCount, + builder.AbandonedConnectionCount, + builder.UnclassifiedConnectionCount, + builder.LongestCheckoutDuration, + reclaimedConnectionCount); + } + /// /// Performs a blocking synchronous read from the idle connection channel. /// @@ -1722,7 +1830,9 @@ private void PrepareConnection(DbConnection owningObject, DbConnectionInternal c lock (connection) { // Protect against Clear which calls IsEmancipated, which is affected by PrePush and PostPop - connection.PostPop(owningObject); + connection.PostPop( + owningObject, + _timeProvider.GetUtcNow().UtcDateTime); } try @@ -1940,7 +2050,8 @@ private async Task RunWarmupLoopAsync() connection = OpenNewInternalConnection( owningConnection: null, cancellationToken: token, - timeout: timeout); + timeout: timeout, + waitReason: out _); } catch (OperationCanceledException) { diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/PoolAcquisitionDiagnostics.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/PoolAcquisitionDiagnostics.cs new file mode 100644 index 0000000000..3d0ba540cd --- /dev/null +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/PoolAcquisitionDiagnostics.cs @@ -0,0 +1,211 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System; +using System.Collections; +using System.Diagnostics; +using Microsoft.Data.ProviderBase; +using Microsoft.Data.SqlClient.Internal; + +#nullable enable + +namespace Microsoft.Data.SqlClient.ConnectionPool +{ + /// + /// Describes why a connection acquisition entered its final wait. + /// + internal enum PoolAcquisitionWaitReason + { + Unknown, + PoolFull, + ConnectionCreationInProgress, + ConnectionCreationRateLimited, + } + + /// + /// Classifies how one physical connection is currently held by the pool. + /// + internal enum PoolConnectionUsageState + { + Idle, + CheckedOut, + TransactionHeld, + Abandoned, + Unclassified, + } + + /// + /// Best-effort snapshot captured only when a pooled connection request times out. + /// + internal readonly struct PoolAcquisitionDiagnostics + { + internal const string DataKeyPrefix = "Microsoft.Data.SqlClient.ConnectionPool."; + internal const string WaitReasonDataKey = DataKeyPrefix + "WaitReason"; + internal const string MaxPoolSizeDataKey = DataKeyPrefix + "MaxPoolSize"; + internal const string ConnectionCountDataKey = DataKeyPrefix + "ConnectionCount"; + internal const string IdleConnectionCountDataKey = DataKeyPrefix + "IdleConnectionCount"; + internal const string PendingConnectionOpenCountDataKey = DataKeyPrefix + "PendingConnectionOpenCount"; + internal const string WaitingRequestCountDataKey = DataKeyPrefix + "WaitingRequestCount"; + internal const string CheckedOutConnectionCountDataKey = DataKeyPrefix + "CheckedOutConnectionCount"; + internal const string TransactionConnectionCountDataKey = DataKeyPrefix + "TransactionConnectionCount"; + internal const string AbandonedConnectionCountDataKey = DataKeyPrefix + "AbandonedConnectionCount"; + internal const string UnclassifiedConnectionCountDataKey = DataKeyPrefix + "UnclassifiedConnectionCount"; + internal const string LongestCheckoutDurationDataKey = DataKeyPrefix + "LongestCheckoutDuration"; + internal const string ReclaimedConnectionCountDataKey = DataKeyPrefix + "ReclaimedConnectionCount"; + + internal PoolAcquisitionDiagnostics( + PoolAcquisitionWaitReason waitReason, + int maxPoolSize, + int connectionCount, + int idleConnectionCount, + int pendingConnectionOpenCount, + int waitingRequestCount, + int checkedOutConnectionCount, + int transactionConnectionCount, + int abandonedConnectionCount, + int unclassifiedConnectionCount, + TimeSpan longestCheckoutDuration, + long reclaimedConnectionCount) + { + WaitReason = waitReason; + MaxPoolSize = maxPoolSize; + ConnectionCount = connectionCount; + IdleConnectionCount = idleConnectionCount; + PendingConnectionOpenCount = pendingConnectionOpenCount; + WaitingRequestCount = waitingRequestCount; + CheckedOutConnectionCount = checkedOutConnectionCount; + TransactionConnectionCount = transactionConnectionCount; + AbandonedConnectionCount = abandonedConnectionCount; + UnclassifiedConnectionCount = unclassifiedConnectionCount; + LongestCheckoutDuration = longestCheckoutDuration; + ReclaimedConnectionCount = reclaimedConnectionCount; + } + + internal PoolAcquisitionWaitReason WaitReason { get; } + + internal int MaxPoolSize { get; } + + internal int ConnectionCount { get; } + + internal int IdleConnectionCount { get; } + + internal int PendingConnectionOpenCount { get; } + + internal int WaitingRequestCount { get; } + + internal int CheckedOutConnectionCount { get; } + + internal int TransactionConnectionCount { get; } + + internal int AbandonedConnectionCount { get; } + + internal int UnclassifiedConnectionCount { get; } + + internal TimeSpan LongestCheckoutDuration { get; } + + internal long ReclaimedConnectionCount { get; } + + /// + /// Adds structured values to the timeout's data dictionary. + /// + internal void AddTo(IDictionary data) + { + data[WaitReasonDataKey] = WaitReason.ToString(); + data[MaxPoolSizeDataKey] = MaxPoolSize; + data[ConnectionCountDataKey] = ConnectionCount; + data[IdleConnectionCountDataKey] = IdleConnectionCount; + data[PendingConnectionOpenCountDataKey] = PendingConnectionOpenCount; + data[WaitingRequestCountDataKey] = WaitingRequestCount; + data[CheckedOutConnectionCountDataKey] = CheckedOutConnectionCount; + data[TransactionConnectionCountDataKey] = TransactionConnectionCount; + data[AbandonedConnectionCountDataKey] = AbandonedConnectionCount; + data[UnclassifiedConnectionCountDataKey] = UnclassifiedConnectionCount; + data[LongestCheckoutDurationDataKey] = LongestCheckoutDuration; + data[ReclaimedConnectionCountDataKey] = ReclaimedConnectionCount; + } + + /// + /// Formats the snapshot for the user-visible pooled-open timeout. + /// + internal string GetMessage() => + StringsHelper.GetString( + Strings.ADP_PooledOpenTimeoutDetails, + WaitReason, + MaxPoolSize, + ConnectionCount, + IdleConnectionCount, + PendingConnectionOpenCount, + WaitingRequestCount, + CheckedOutConnectionCount, + TransactionConnectionCount, + AbandonedConnectionCount, + UnclassifiedConnectionCount, + LongestCheckoutDuration, + ReclaimedConnectionCount); + } + + /// + /// Collects connection ownership information during a timeout-only pool scan. + /// + internal sealed class PoolAcquisitionDiagnosticsBuilder + { + private readonly DateTime _utcNow; + + internal PoolAcquisitionDiagnosticsBuilder(DateTime utcNow) + { + Debug.Assert(utcNow.Kind == DateTimeKind.Utc); + _utcNow = utcNow; + } + + internal int CheckedOutConnectionCount { get; private set; } + + internal int IdleConnectionCount { get; private set; } + + internal int TransactionConnectionCount { get; private set; } + + internal int AbandonedConnectionCount { get; private set; } + + internal int UnclassifiedConnectionCount { get; private set; } + + internal TimeSpan LongestCheckoutDuration { get; private set; } + + /// + /// Records one connection while its monitor is held. + /// + internal void Observe(DbConnectionInternal connection) + { + switch (connection.GetPoolUsageState(_utcNow, out TimeSpan checkoutDuration)) + { + case PoolConnectionUsageState.Idle: + IdleConnectionCount++; + break; + + case PoolConnectionUsageState.CheckedOut: + CheckedOutConnectionCount++; + if (checkoutDuration > LongestCheckoutDuration) + { + LongestCheckoutDuration = checkoutDuration; + } + break; + + case PoolConnectionUsageState.TransactionHeld: + TransactionConnectionCount++; + break; + + case PoolConnectionUsageState.Abandoned: + AbandonedConnectionCount++; + if (checkoutDuration > LongestCheckoutDuration) + { + LongestCheckoutDuration = checkoutDuration; + } + break; + + case PoolConnectionUsageState.Unclassified: + UnclassifiedConnectionCount++; + break; + } + } + + internal void ObserveLockContention() => UnclassifiedConnectionCount++; + } +} diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/WaitHandleDbConnectionPool.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/WaitHandleDbConnectionPool.cs index afaa827fce..b234c97cab 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/WaitHandleDbConnectionPool.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/WaitHandleDbConnectionPool.cs @@ -62,17 +62,24 @@ internal sealed class WaitHandleDbConnectionPool : IDbConnectionPool private sealed class PendingGetConnection { - public PendingGetConnection(long dueTime, DbConnection owner, TaskCompletionSource completion, TimeoutTimer timeout) + public PendingGetConnection( + long dueTime, + DbConnection owner, + TaskCompletionSource completion, + TimeoutTimer timeout, + long reclaimedConnectionCountAtStart) { DueTime = dueTime; Owner = owner; Completion = completion; Timeout = timeout; + ReclaimedConnectionCountAtStart = reclaimedConnectionCountAtStart; } public long DueTime { get; private set; } public DbConnection Owner { get; private set; } public TaskCompletionSource Completion { get; private set; } public TimeoutTimer Timeout { get; private set; } + public long ReclaimedConnectionCountAtStart { get; } } private sealed class PoolWaitHandles @@ -187,6 +194,7 @@ public void Dispose() private readonly ConcurrentQueue _pendingOpens = new ConcurrentQueue(); private int _pendingOpensWaiting = 0; + private int _pendingConnectionOpenCount; private readonly WaitCallback _poolCreateRequest; @@ -203,6 +211,12 @@ public void Dispose() private readonly List _objectList; private int _totalObjects; + /// + /// Number of abandoned connections this pool has reclaimed. Acquisition requests sample + /// this counter so a timeout can report reclamation that occurred while that request waited. + /// + private long _reclaimedConnectionCount; + // only created by DbConnectionPoolGroup.GetConnectionPool internal WaitHandleDbConnectionPool( SqlConnectionFactory connectionFactory, @@ -537,6 +551,7 @@ private Timer CreateCleanupTimer() => private DbConnectionInternal CreateObject(DbConnection owningObject, DbConnectionInternal oldConnection, TimeoutTimer timeout) { DbConnectionInternal newObj = null; + Interlocked.Increment(ref _pendingConnectionOpenCount); try { @@ -591,6 +606,10 @@ private DbConnectionInternal CreateObject(DbConnection owningObject, DbConnectio throw; } + finally + { + Interlocked.Decrement(ref _pendingConnectionOpenCount); + } return newObj; } @@ -823,7 +842,13 @@ private void WaitForPendingOpen() } else if (timeout) { - next.Completion.TrySetException(ADP.ExceptionWithStackTrace(ADP.PooledOpenTimeout())); + PoolAcquisitionDiagnostics diagnostics = + CaptureAcquisitionDiagnostics( + next.ReclaimedConnectionCountAtStart, + Math.Max(1, Volatile.Read(ref _waitCount) + 1)); + next.Completion.TrySetException( + ADP.ExceptionWithStackTrace( + ADP.PooledOpenTimeout(diagnostics))); } else { @@ -873,6 +898,8 @@ internal static uint ResolvePoolWaitTimeoutMs(TimeoutTimer timeout, int creation public bool TryGetConnection(DbConnection owningObject, TaskCompletionSource taskCompletionSource, TimeoutTimer timeout, out DbConnectionInternal connection) { + long reclaimedConnectionCountAtStart = + Interlocked.Read(ref _reclaimedConnectionCount); uint waitForMultipleObjectsTimeout = 0; bool allowCreate = false; @@ -896,8 +923,18 @@ public bool TryGetConnection(DbConnection owningObject, TaskCompletionSource {0}, Connection {1}, Reclaiming.", Id, obj.ObjectID); Metrics.ReclaimedConnectionRequest(); + Interlocked.Increment(ref _reclaimedConnectionCount); emancipatedObjectFound = true; @@ -1565,6 +1606,74 @@ private bool ReclaimEmancipatedObjects() return emancipatedObjectFound; } + /// + /// Captures a best-effort pool snapshot on the timeout path. + /// + private PoolAcquisitionDiagnostics CaptureAcquisitionDiagnostics( + long reclaimedConnectionCountAtStart, + int waitingRequestCount) + { + var builder = new PoolAcquisitionDiagnosticsBuilder( + _timeProvider.GetUtcNow().UtcDateTime); + int connectionCount; + + lock (_objectList) + { + connectionCount = _objectList.Count; + foreach (DbConnectionInternal connection in _objectList) + { + bool locked = false; + try + { + Monitor.TryEnter(connection, ref locked); + if (locked) + { + builder.Observe(connection); + } + else + { + builder.ObserveLockContention(); + } + } + finally + { + if (locked) + { + Monitor.Exit(connection); + } + } + } + } + + int pendingConnectionOpenCount = + Math.Max(0, Volatile.Read(ref _pendingConnectionOpenCount)); + PoolAcquisitionWaitReason waitReason = + connectionCount >= MaxPoolSize + ? PoolAcquisitionWaitReason.PoolFull + : pendingConnectionOpenCount > 0 + ? PoolAcquisitionWaitReason.ConnectionCreationInProgress + : PoolAcquisitionWaitReason.Unknown; + long reclaimedConnectionCount = + Math.Max( + 0, + Interlocked.Read(ref _reclaimedConnectionCount) - + reclaimedConnectionCountAtStart); + + return new PoolAcquisitionDiagnostics( + waitReason, + MaxPoolSize, + connectionCount, + builder.IdleConnectionCount, + pendingConnectionOpenCount, + waitingRequestCount, + builder.CheckedOutConnectionCount, + builder.TransactionConnectionCount, + builder.AbandonedConnectionCount, + builder.UnclassifiedConnectionCount, + builder.LongestCheckoutDuration, + reclaimedConnectionCount); + } + public void Startup() { SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, CleanupWait={1}", Id, _cleanupWait); diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlException.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlException.cs index c1ef429204..3ade7727c4 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlException.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlException.cs @@ -4,6 +4,8 @@ using System; using System.Collections; +using System.Collections.Generic; +using System.Collections.ObjectModel; using System.ComponentModel; using System.Data.Common; using System.Diagnostics; @@ -24,6 +26,10 @@ public sealed partial class SqlException : System.Data.Common.DbException private const int SqlExceptionHResult = unchecked((int)0x80131904); private readonly SqlErrorCollection _errors; + private static readonly ReadOnlyCollection s_emptyConnectionOpenRetryFailures = + Array.AsReadOnly(Array.Empty()); + private IReadOnlyList _connectionOpenRetryFailures = + s_emptyConnectionOpenRetryFailures; #if NETFRAMEWORK [OptionalField(VersionAdded = 4)] #endif @@ -49,6 +55,7 @@ private SqlException(string message, SqlErrorCollection errorCollection, Excepti #endif private SqlException(SerializationInfo si, StreamingContext sc) : base(si, sc) { + _connectionOpenRetryFailures = s_emptyConnectionOpenRetryFailures; #if NETFRAMEWORK _errors = (SqlErrorCollection)si.GetValue("Errors", typeof(SqlErrorCollection)); #endif @@ -69,6 +76,8 @@ private SqlException(SerializationInfo si, StreamingContext sc) : base(si, sc) #endif public override void GetObjectData(SerializationInfo si, StreamingContext context) { + // ConnectionOpenRetryFailures is request-scoped diagnostic context and is intentionally + // not carried through legacy formatter-based serialization. base.GetObjectData(si, context); si.AddValue("Errors", null); // Not specifying type to enable serialization of null value of non-serializable type si.AddValue("ClientConnectionId", _clientConnectionId, typeof(object)); @@ -92,6 +101,10 @@ public override void GetObjectData(SerializationInfo si, StreamingContext contex #endif public SqlErrorCollection Errors => _errors ?? new SqlErrorCollection(); + /// + public IReadOnlyList ConnectionOpenRetryFailures => + _connectionOpenRetryFailures ?? s_emptyConnectionOpenRetryFailures; + /// public Guid ClientConnectionId => _clientConnectionId; @@ -164,6 +177,27 @@ public override string ToString() sb.AppendFormat(SQLMessage.ExRoutingDestination(), Data[RoutingDestinationKey]); } + if (ConnectionOpenRetryFailures.Count > 0) + { + sb.AppendLine(); + sb.Append( + StringsHelper.GetString( + Strings.SQL_ConnectionOpenRetryFailures, + ConnectionOpenRetryFailures.Count)); + + for (int i = 0; i < ConnectionOpenRetryFailures.Count; i++) + { + SqlException failure = ConnectionOpenRetryFailures[i]; + sb.AppendLine(); + sb.Append( + StringsHelper.GetString( + Strings.SQL_ConnectionOpenRetryFailure, + i + 1, + failure.GetType().FullName, + failure.Message)); + } + } + return sb.ToString(); } @@ -294,6 +328,9 @@ errorCollection is not null && } internal SqlException InternalClone() + => InternalClone(includeConnectionOpenRetryFailures: true); + + internal SqlException InternalClone(bool includeConnectionOpenRetryFailures) { SqlException exception = new(Message, _errors, InnerException, _clientConnectionId); if (Data != null) @@ -305,7 +342,38 @@ internal SqlException InternalClone() } exception._batchCommand = _batchCommand; exception._doNotReconnect = _doNotReconnect; + exception._connectionOpenRetryFailures = includeConnectionOpenRetryFailures + ? ConnectionOpenRetryFailures + : s_emptyConnectionOpenRetryFailures; return exception; } + + /// + /// Attaches the transient failures observed before this terminal connection open failure. + /// Existing failures on this exception are appended after the supplied list. + /// + internal void SetConnectionOpenRetryFailures( + IReadOnlyList retryFailures) + { + if (retryFailures is null || retryFailures.Count == 0) + { + return; + } + + var combined = new SqlException[ + retryFailures.Count + ConnectionOpenRetryFailures.Count]; + for (int i = 0; i < retryFailures.Count; i++) + { + combined[i] = retryFailures[i]; + } + + for (int i = 0; i < ConnectionOpenRetryFailures.Count; i++) + { + combined[retryFailures.Count + i] = + ConnectionOpenRetryFailures[i]; + } + + _connectionOpenRetryFailures = Array.AsReadOnly(combined); + } } } diff --git a/src/Microsoft.Data.SqlClient/src/Resources/Strings.Designer.cs b/src/Microsoft.Data.SqlClient/src/Resources/Strings.Designer.cs index c8f18d38bc..b5945ff410 100644 --- a/src/Microsoft.Data.SqlClient/src/Resources/Strings.Designer.cs +++ b/src/Microsoft.Data.SqlClient/src/Resources/Strings.Designer.cs @@ -869,6 +869,15 @@ internal static string ADP_PooledOpenTimeout { return ResourceManager.GetString("ADP_PooledOpenTimeout", resourceCulture); } } + + /// + /// Looks up a localized string similar to Pool diagnostics: wait reason={0}; max pool size={1}; total connections={2}; idle connections={3}; pending opens={4}; waiting requests={5}; checked-out connections={6}; transaction-held connections={7}; abandoned connections={8}; unclassified connections={9}; longest checkout={10}; abandoned connections reclaimed during this wait={11}.. + /// + internal static string ADP_PooledOpenTimeoutDetails { + get { + return ResourceManager.GetString("ADP_PooledOpenTimeoutDetails", resourceCulture); + } + } /// /// Looks up a localized string similar to {0}.Prepare method requires parameters of type '{1}' have an explicitly set Precision and Scale.. @@ -3182,6 +3191,24 @@ internal static string SQL_ConnectionPoolShutDown { return ResourceManager.GetString("SQL_ConnectionPoolShutDown", resourceCulture); } } + + /// + /// Looks up a localized string similar to Retry {0}: {1}: {2}. + /// + internal static string SQL_ConnectionOpenRetryFailure { + get { + return ResourceManager.GetString("SQL_ConnectionOpenRetryFailure", resourceCulture); + } + } + + /// + /// Looks up a localized string similar to Connection open retry failures ({0}):. + /// + internal static string SQL_ConnectionOpenRetryFailures { + get { + return ResourceManager.GetString("SQL_ConnectionOpenRetryFailures", resourceCulture); + } + } /// /// Looks up a localized string similar to The connection attempt timed out.. diff --git a/src/Microsoft.Data.SqlClient/src/Resources/Strings.resx b/src/Microsoft.Data.SqlClient/src/Resources/Strings.resx index 57cbf80016..d4eddbd096 100644 --- a/src/Microsoft.Data.SqlClient/src/Resources/Strings.resx +++ b/src/Microsoft.Data.SqlClient/src/Resources/Strings.resx @@ -204,6 +204,9 @@ Timeout expired. The timeout period elapsed prior to obtaining a connection from the pool. This may have occurred because all pooled connections were in use and max pool size was reached. + + Pool diagnostics: wait reason={0}; max pool size={1}; total connections={2}; idle connections={3}; pending opens={4}; waiting requests={5}; checked-out connections={6}; transaction-held connections={7}; abandoned connections={8}; unclassified connections={9}; longest checkout={10}; abandoned connections reclaimed during this wait={11}. + Timeout attempting to open the connection. The time period elapsed prior to attempting to open the connection has been exceeded. This may have occurred because of too many simultaneous non-pooled connection attempts. @@ -2178,6 +2181,12 @@ The connection pool has been shut down. + + Connection open retry failures ({0}): + + + Retry {0}: {1}: {2} + Cannot get RequiredLength when HasDataLength is false. diff --git a/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/ChannelDbConnectionPoolTest.cs b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/ChannelDbConnectionPoolTest.cs index d647ab0914..90e9ca4883 100644 --- a/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/ChannelDbConnectionPoolTest.cs +++ b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/ChannelDbConnectionPoolTest.cs @@ -183,9 +183,7 @@ out DbConnectionInternal? internalConnection out DbConnectionInternal? extraConnection); }); - Assert.Equal( - "Timeout expired. The timeout period elapsed prior to obtaining a connection from the pool. This may have occurred because all pooled connections were in use and max pool size was reached.", - ex.Message); + Assert.StartsWith(ADP.PooledOpenTimeout().Message, ex.Message); Assert.Equal(pool.PoolGroupOptions.MaxPoolSize, pool.Count); } @@ -229,9 +227,7 @@ out DbConnectionInternal? internalConnection var ex = await Assert.ThrowsAsync(() => taskCompletionSource.Task); - Assert.Equal( - "Timeout expired. The timeout period elapsed prior to obtaining a connection from the pool. This may have occurred because all pooled connections were in use and max pool size was reached.", - ex.Message); + Assert.StartsWith(ADP.PooledOpenTimeout().Message, ex.Message); Assert.Equal(pool.PoolGroupOptions.MaxPoolSize, pool.Count); } @@ -2366,9 +2362,7 @@ public async Task ConcurrentCallers_ShouldTimeoutIndependently() // Assert: Caller A should observe the timeout var exA = await Assert.ThrowsAsync(() => callerATask); - Assert.Equal( - "Timeout expired. The timeout period elapsed prior to obtaining a connection from the pool. This may have occurred because all pooled connections were in use and max pool size was reached.", - exA.Message); + Assert.StartsWith(ADP.PooledOpenTimeout().Message, exA.Message); // Caller B should still be waiting (8s of virtual budget remain) Assert.False(callerBTask.IsCompleted, "Caller B should still be waiting"); diff --git a/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/PoolAcquisitionDiagnosticsTest.cs b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/PoolAcquisitionDiagnosticsTest.cs new file mode 100644 index 0000000000..a029bcf1f2 --- /dev/null +++ b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/PoolAcquisitionDiagnosticsTest.cs @@ -0,0 +1,206 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System; +using System.Data.Common; +using System.Threading.RateLimiting; +using System.Threading.Tasks; +using Microsoft.Data.Common; +using Microsoft.Data.ProviderBase; +using Microsoft.Data.SqlClient.ConnectionPool; +using Microsoft.Extensions.Time.Testing; +using Xunit; + +using static Microsoft.Data.SqlClient.UnitTests.ConnectionPool.PoolTestHarness; + +namespace Microsoft.Data.SqlClient.UnitTests.ConnectionPool +{ + /// + /// Verifies that a pooled-open timeout describes the request-local reason for waiting and + /// captures a cheap snapshot of pool usage for diagnosing capacity pressure and leaks. + /// + public sealed class PoolAcquisitionDiagnosticsTest + { + /// + /// Verifies both pool implementations report that every slot is occupied, including how + /// many connections remain checked out and how long the oldest checkout has been held. + /// + [Theory] + [InlineData(PoolImplementation.WaitHandle, false)] + [InlineData(PoolImplementation.WaitHandle, true)] + [InlineData(PoolImplementation.Channel, false)] + [InlineData(PoolImplementation.Channel, true)] + public async Task Timeout_FullPool_ReportsSaturationSnapshot( + PoolImplementation implementation, + bool async) + { + IDbConnectionPool pool = ConstructPool( + implementation, + timeProvider: TimeProvider.System, + maxPoolSize: 1, + creationTimeout: 100); + using SqlConnection checkedOutOwner = new(); + using SqlConnection waitingOwner = new(); + + Assert.True(pool.TryGetConnection( + checkedOutOwner, + taskCompletionSource: null, + TimeoutTimer.StartNew(TimeSpan.FromSeconds(5)), + out DbConnectionInternal? checkedOutConnection)); + Assert.NotNull(checkedOutConnection); + + checkedOutConnection!.CheckoutTime = DateTime.UtcNow - TimeSpan.FromMinutes(5); + + try + { + InvalidOperationException timeout = await AssertPoolTimeoutAsync( + pool, + waitingOwner, + async); + + Assert.Equal( + PoolAcquisitionWaitReason.PoolFull.ToString(), + timeout.Data[PoolAcquisitionDiagnostics.WaitReasonDataKey]); + Assert.Equal(1, timeout.Data[PoolAcquisitionDiagnostics.MaxPoolSizeDataKey]); + Assert.Equal(1, timeout.Data[PoolAcquisitionDiagnostics.ConnectionCountDataKey]); + Assert.Equal(0, timeout.Data[PoolAcquisitionDiagnostics.IdleConnectionCountDataKey]); + Assert.Equal(1, timeout.Data[PoolAcquisitionDiagnostics.CheckedOutConnectionCountDataKey]); + Assert.Equal(0, timeout.Data[PoolAcquisitionDiagnostics.AbandonedConnectionCountDataKey]); + Assert.Equal(0L, timeout.Data[PoolAcquisitionDiagnostics.ReclaimedConnectionCountDataKey]); + + TimeSpan longestCheckout = + Assert.IsType( + timeout.Data[PoolAcquisitionDiagnostics.LongestCheckoutDurationDataKey]); + Assert.True(longestCheckout >= TimeSpan.FromMinutes(4)); + } + finally + { + pool.ReturnInternalConnection(checkedOutConnection, checkedOutOwner); + } + + GC.KeepAlive(checkedOutOwner); + } + + /// + /// Verifies the channel pool identifies connection-creation throttling as the timeout cause + /// instead of incorrectly claiming that max pool size was reached. + /// + [Theory] + [InlineData(false)] + [InlineData(true)] + public async Task Timeout_RateLimiterSaturated_ReportsRateLimiting(bool async) + { + using ConcurrencyLimiter limiter = new( + new ConcurrencyLimiterOptions + { + PermitLimit = 1, + QueueLimit = 0, + }); + using RateLimitLease heldLease = limiter.AttemptAcquire(1); + Assert.True(heldLease.IsAcquired); + + DbConnectionPoolGroup poolGroup = ConstructPoolGroup( + maxPoolSize: 4, + creationTimeout: 100); + var pool = new ChannelDbConnectionPool( + new ChannelDbConnectionPoolTest.SuccessfulSqlConnectionFactory(), + poolGroup, + DbConnectionPoolIdentity.NoIdentity, + new DbConnectionPoolProviderInfo(), + connectionCreationRateLimiter: limiter); + using SqlConnection waitingOwner = new(); + + InvalidOperationException timeout = await AssertPoolTimeoutAsync( + pool, + waitingOwner, + async, + TimeSpan.FromSeconds(1)); + + Assert.Equal( + PoolAcquisitionWaitReason.ConnectionCreationRateLimited.ToString(), + timeout.Data[PoolAcquisitionDiagnostics.WaitReasonDataKey]); + Assert.Equal(4, timeout.Data[PoolAcquisitionDiagnostics.MaxPoolSizeDataKey]); + Assert.Equal(0, timeout.Data[PoolAcquisitionDiagnostics.ConnectionCountDataKey]); + Assert.Equal(0, timeout.Data[PoolAcquisitionDiagnostics.CheckedOutConnectionCountDataKey]); + } + + /// + /// Verifies a timeout snapshot identifies a connection whose owning application connection + /// was collected without being closed or disposed. + /// + [Fact] + public void Timeout_AbandonedOwner_ReportsAbandonedConnection() + { + var pool = (ChannelDbConnectionPool)ConstructPool( + PoolImplementation.Channel, + timeProvider: TimeProvider.System, + maxPoolSize: 1); + DbConnectionInternal abandonedConnection = + CheckOutAndAbandonOwner(pool); + abandonedConnection.CheckoutTime = + DateTime.UtcNow - TimeSpan.FromMinutes(5); + CollectAbandonedOwners(); + Assert.True(abandonedConnection.IsEmancipated); + var timeoutProvider = new FakeTimeProvider(); + TimeoutTimer expiredTimeout = + TimeoutTimer.StartNew(TimeSpan.FromSeconds(1), timeoutProvider); + timeoutProvider.Advance(TimeSpan.FromSeconds(2)); + + InvalidOperationException timeout = + Assert.Throws(() => + pool.TryGetConnection( + new SqlConnection(), + taskCompletionSource: null, + expiredTimeout, + out _)); + + Assert.Equal( + 1, + timeout.Data[PoolAcquisitionDiagnostics.AbandonedConnectionCountDataKey]); + Assert.Equal( + 0, + timeout.Data[PoolAcquisitionDiagnostics.CheckedOutConnectionCountDataKey]); + + pool.ReclaimEmancipatedConnections(); + } + + /// + /// Requests a connection synchronously or asynchronously and returns the pooled-open timeout. + /// + /// Pool from which to request a connection. + /// Connection that would own the acquired internal connection. + /// Whether to use the pool's asynchronous completion path. + /// Optional timeout budget for the acquisition. + /// The pooled-open timeout surfaced to the caller. + private static async Task AssertPoolTimeoutAsync( + IDbConnectionPool pool, + DbConnection owner, + bool async, + TimeSpan? timeoutDuration = null) + { + TimeoutTimer timeout = TimeoutTimer.StartNew( + timeoutDuration ?? TimeSpan.FromMilliseconds(100)); + + if (!async) + { + return Assert.Throws(() => + pool.TryGetConnection( + owner, + taskCompletionSource: null, + timeout, + out _)); + } + + TaskCompletionSource completion = new( + TaskCreationOptions.RunContinuationsAsynchronously); + Assert.False(pool.TryGetConnection( + owner, + completion, + timeout, + out _)); + + return await Assert.ThrowsAsync( + () => completion.Task); + } + } +} diff --git a/src/Microsoft.Data.SqlClient/tests/UnitTests/SimulatedServerTests/ConnectionTests.cs b/src/Microsoft.Data.SqlClient/tests/UnitTests/SimulatedServerTests/ConnectionTests.cs index f797797758..274a75f6d5 100644 --- a/src/Microsoft.Data.SqlClient/tests/UnitTests/SimulatedServerTests/ConnectionTests.cs +++ b/src/Microsoft.Data.SqlClient/tests/UnitTests/SimulatedServerTests/ConnectionTests.cs @@ -204,6 +204,135 @@ public void TransientFault_RetryDisabled_ShouldFail(uint errorCode) Assert.Equal(1, server.PreLoginCount - server.AbandonedPreLoginCount); } + /// + /// Verifies failed connection-open retries are preserved in chronological order on the + /// terminal exception without replacing that exception's own error details. + /// + [Theory] + [InlineData(false)] + [InlineData(true)] + public async Task TransientFault_RetriesExhausted_ExposesRetryFailures(bool async) + { + const int errorCode = 40613; + using TransientTdsErrorTdsServer server = new( + new TransientTdsErrorTdsServerArguments + { + IsEnabledTransientError = true, + Number = errorCode, + RepeatCount = 2, + }); + server.Start(); + SqlConnectionStringBuilder builder = new() + { + DataSource = "localhost," + server.EndPoint.Port, + ConnectRetryCount = 1, + ConnectRetryInterval = 1, + ConnectTimeout = 10, + Encrypt = SqlConnectionEncryptOption.Optional, + Pooling = false, + }; + using SqlConnection connection = new(builder.ConnectionString); + + SqlException terminal = async + ? await Assert.ThrowsAsync(() => connection.OpenAsync()) + : Assert.Throws(() => connection.Open()); + + Assert.Equal(errorCode, terminal.Number); + SqlException retryFailure = + Assert.Single(terminal.ConnectionOpenRetryFailures); + Assert.Equal(errorCode, retryFailure.Number); + Assert.Empty(retryFailure.ConnectionOpenRetryFailures); + Assert.Equal(ConnectionState.Closed, connection.State); + Assert.Equal(2, server.PreLoginCount - server.AbandonedPreLoginCount); + } + + /// + /// Verifies a timeout on the final connection attempt retains the transient server error + /// that caused the preceding retry. + /// + [Theory] + [InlineData(false)] + [InlineData(true)] + public async Task TransientFault_FinalRetryTimesOut_ExposesRetryFailure(bool async) + { + const int transientErrorCode = 40613; + using TransientTdsErrorTdsServer server = new( + new TransientTdsErrorTdsServerArguments + { + IsEnabledTransientError = true, + Number = transientErrorCode, + RepeatCount = 1, + DelayAfterTransientErrors = TimeSpan.FromSeconds(10), + }); + server.Start(); + SqlConnectionStringBuilder builder = new() + { + DataSource = "localhost," + server.EndPoint.Port, + ConnectRetryCount = 1, + ConnectRetryInterval = 1, + ConnectTimeout = 3, + Encrypt = SqlConnectionEncryptOption.Optional, + Pooling = false, + }; + using SqlConnection connection = new(builder.ConnectionString); + + SqlException terminal = async + ? await Assert.ThrowsAsync(() => connection.OpenAsync()) + : Assert.Throws(() => connection.Open()); + + Assert.Equal(TdsEnums.TIMEOUT_EXPIRED, terminal.Number); + Assert.NotEmpty(terminal.ConnectionOpenRetryFailures); + Assert.Contains( + terminal.ConnectionOpenRetryFailures, + failure => failure.Number == transientErrorCode); + Assert.All( + terminal.ConnectionOpenRetryFailures, + failure => Assert.Empty(failure.ConnectionOpenRetryFailures)); + Assert.Equal(ConnectionState.Closed, connection.State); + } + + /// + /// Verifies failures from a connection open that eventually succeeds are released rather + /// than appearing on later, unrelated errors from that connection. + /// + [Fact] + public void TransientFault_RetrySucceeds_DoesNotLeakFailuresToLaterErrors() + { + const int transientErrorCode = 40613; + const int commandErrorCode = 50000; + using TransientTdsErrorTdsServer server = new( + new TransientTdsErrorTdsServerArguments + { + IsEnabledTransientError = true, + Number = transientErrorCode, + RepeatCount = 1, + }); + server.Start(); + SqlConnectionStringBuilder builder = new() + { + DataSource = "localhost," + server.EndPoint.Port, + ConnectRetryCount = 1, + ConnectRetryInterval = 1, + ConnectTimeout = 10, + Encrypt = SqlConnectionEncryptOption.Optional, + Pooling = false, + }; + using SqlConnection connection = new(builder.ConnectionString); + connection.Open(); + server.SetErrorBehavior( + isEnabledTransientError: true, + errorNumber: commandErrorCode, + repeatCount: 2, + message: "later command failure"); + using SqlCommand command = new("SELECT 1", connection); + + SqlException commandFailure = + Assert.Throws(() => command.ExecuteNonQuery()); + + Assert.Equal(commandErrorCode, commandFailure.Number); + Assert.Empty(commandFailure.ConnectionOpenRetryFailures); + } + // Flaky under CI load only (never reproduces locally): the retry login can exhaust // the connect-timeout budget on a slow agent and surface a post-login Connection // Timeout (observed pre-login handshake ~4.4s), so the async open propagates a diff --git a/src/Microsoft.Data.SqlClient/tests/UnitTests/SqlExceptionRetryFailuresTest.cs b/src/Microsoft.Data.SqlClient/tests/UnitTests/SqlExceptionRetryFailuresTest.cs new file mode 100644 index 0000000000..27c02c4aed --- /dev/null +++ b/src/Microsoft.Data.SqlClient/tests/UnitTests/SqlExceptionRetryFailuresTest.cs @@ -0,0 +1,82 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System; +using System.ComponentModel; +using Microsoft.Data.SqlClient.ConnectionPool; +using Microsoft.Data.SqlClient.UnitTests.ConnectionPool; +using Xunit; + +namespace Microsoft.Data.SqlClient.UnitTests +{ + /// + /// Verifies the public connection-open retry ledger on . + /// + public sealed class SqlExceptionRetryFailuresTest + { + /// + /// Verifies exceptions that did not pass through a connection-open retry expose an empty + /// immutable ledger. + /// + [Fact] + public void ConnectionOpenRetryFailures_NoRetries_IsEmpty() + { + SqlException exception = SqlExceptionHelper.CreateSqlException("terminal failure"); + + Assert.Empty(exception.ConnectionOpenRetryFailures); + } + + /// + /// Verifies enriching a terminal failure retains its existing SQL errors, native inner + /// exception, connection metadata, and data entries. + /// + [Fact] + public void SetConnectionOpenRetryFailures_PreservesTerminalException() + { + var nativeTimeout = new Win32Exception(258); + var errors = new SqlErrorCollection(); + errors.Add(new SqlError(-2, 0, 11, "server", "terminal timeout", "", 0, 258)); + SqlException terminal = SqlException.CreateException( + errors, + serverVersion: "1.0", + conId: Guid.NewGuid(), + innerException: nativeTimeout); + terminal.Data["marker"] = "preserved"; + SqlException first = SqlExceptionHelper.CreateSqlException("first {transient} failure"); + SqlException second = SqlExceptionHelper.CreateSqlException("second transient failure"); + + terminal.SetConnectionOpenRetryFailures( + new[] { first, second }); + + Assert.Same(errors, terminal.Errors); + Assert.Same(nativeTimeout, terminal.InnerException); + Assert.Equal("preserved", terminal.Data["marker"]); + Assert.Collection( + terminal.ConnectionOpenRetryFailures, + failure => Assert.Same(first, failure), + failure => Assert.Same(second, failure)); + Assert.Contains("first {transient} failure", terminal.ToString()); + Assert.Contains("second transient failure", terminal.ToString()); + } + + /// + /// Verifies the blocking-period cache does not replay one Open call's retry ledger to later + /// callers that fast-fail against the cached connection error. + /// + [Fact] + public void BlockingPeriodCache_StripsConnectionOpenRetryFailures() + { + using var state = new BlockingPeriodErrorState(ownerPoolId: 1); + SqlException terminal = + SqlExceptionHelper.CreateSqlException("terminal failure"); + terminal.SetConnectionOpenRetryFailures( + new[] { SqlExceptionHelper.CreateSqlException("transient failure") }); + + state.Enter(terminal); + + SqlException replayed = Assert.Throws( + () => state.ThrowIfActive()); + Assert.Empty(replayed.ConnectionOpenRetryFailures); + } + } +} diff --git a/src/Microsoft.Data.SqlClient/tests/tools/TDS/TDS.Servers/TransientTdsErrorTdsServer.cs b/src/Microsoft.Data.SqlClient/tests/tools/TDS/TDS.Servers/TransientTdsErrorTdsServer.cs index 780ca6aea9..9b6e87f7c9 100644 --- a/src/Microsoft.Data.SqlClient/tests/tools/TDS/TDS.Servers/TransientTdsErrorTdsServer.cs +++ b/src/Microsoft.Data.SqlClient/tests/tools/TDS/TDS.Servers/TransientTdsErrorTdsServer.cs @@ -17,6 +17,8 @@ namespace Microsoft.SqlServer.TDS.Servers public class TransientTdsErrorTdsServer : GenericTdsServer, IDisposable { private int RequestCounter = 0; + private readonly CancellationTokenSource _disposeCts = new(); + private bool _disposed; public void SetErrorBehavior(bool isEnabledTransientError, uint errorNumber, int repeatCount = 1, string message = null) { @@ -65,6 +67,12 @@ public override TDSMessageCollection OnLogin7Request(ITDSServerSession session, return GenerateErrorMessage(request); } + if (Arguments.DelayAfterTransientErrors > TimeSpan.Zero) + { + _disposeCts.Token.WaitHandle.WaitOne( + Arguments.DelayAfterTransientErrors); + } + // Return login response from the base class return base.OnLogin7Request(session, request); } @@ -112,9 +120,24 @@ private TDSMessageCollection GenerateErrorMessage(TDSMessage request) return new TDSMessageCollection(responseMessage); } - public override void Dispose() { - base.Dispose(); - RequestCounter = 0; + public override void Dispose() + { + if (_disposed) + { + return; + } + + _disposed = true; + try + { + _disposeCts.Cancel(); + base.Dispose(); + RequestCounter = 0; + } + finally + { + _disposeCts.Dispose(); + } } } } diff --git a/src/Microsoft.Data.SqlClient/tests/tools/TDS/TDS.Servers/TransientTdsErrorTdsServerArguments.cs b/src/Microsoft.Data.SqlClient/tests/tools/TDS/TDS.Servers/TransientTdsErrorTdsServerArguments.cs index 5f1adacd61..f2b23b941e 100644 --- a/src/Microsoft.Data.SqlClient/tests/tools/TDS/TDS.Servers/TransientTdsErrorTdsServerArguments.cs +++ b/src/Microsoft.Data.SqlClient/tests/tools/TDS/TDS.Servers/TransientTdsErrorTdsServerArguments.cs @@ -2,6 +2,8 @@ // The .NET Foundation licenses this file to you under the MIT license. // See the LICENSE file in the project root for more information. +using System; + namespace Microsoft.SqlServer.TDS.Servers { public class TransientTdsErrorTdsServerArguments : TdsServerArguments @@ -33,5 +35,11 @@ public class TransientTdsErrorTdsServerArguments : TdsServerArguments /// when a test needs to avoid automatic break/doom behavior in the client. /// public byte ErrorClass { get; set; } = 20; + + /// + /// Optional delay applied to login responses after all configured transient errors have + /// been emitted. Tests use this to make a final retry exhaust the overall connect timeout. + /// + public TimeSpan DelayAfterTransientErrors { get; set; } = TimeSpan.Zero; } }