From 018196a42f0f366440c23716ccc4a189d884d757 Mon Sep 17 00:00:00 2001 From: Malcolm Daigle Date: Wed, 12 Aug 2026 12:34:45 -0700 Subject: [PATCH 01/19] Emit pool metrics and fix Count semantics in ChannelDbConnectionPool ChannelDbConnectionPool did not emit any of the connection pool counters that WaitHandleDbConnectionPool emits, and reported Count as the reservation count, which includes connections that are still being opened. - Wire the pooled/free connection and soft/hard connect/disconnect counters through ChannelDbConnectionPool and IdleConnectionChannel, at the call sites matching WaitHandleDbConnectionPool. - Add ConnectionPoolSlots.ConnectionCount and point Count at it, so Count reflects connections that actually belong to the pool. This matches WaitHandleDbConnectionPool and fixes the SQL Express user instance path, which branches on pool.Count <= 0. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- .../ConnectionPool/ChannelDbConnectionPool.cs | 23 +++++++++++++++++-- .../ConnectionPool/ConnectionPoolSlots.cs | 14 ++++++++++- .../ConnectionPool/IdleConnectionChannel.cs | 3 +++ 3 files changed, 37 insertions(+), 3 deletions(-) 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 9f75c50c1a..49e23e6911 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 @@ -209,7 +209,17 @@ public ConcurrentDictionary< public SqlConnectionFactory ConnectionFactory { get; } /// - public int Count => _connectionSlots.ReservationCount; + /// + /// Reports connections that actually belong to the pool, not + /// , which also counts reservations held + /// for connections that are still being opened. The distinction matters to the SQL Express + /// user instance path in : it treats + /// Count <= 0 as "nothing in the pool yet", opens a probe connection, and caches the + /// resolved instance name on the pool's provider info. Counting an in-flight open here sends + /// the first caller down the cached branch instead, where it reads an instance name that + /// nothing has set yet. + /// + public int Count => _connectionSlots.ConnectionCount; /// public int IdleCount => _idleChannel.Count; @@ -496,6 +506,8 @@ public DbConnectionInternal ReplaceConnection( /// public void ReturnInternalConnection(DbConnectionInternal connection, DbConnection owningObject) { + SqlClientDiagnostics.Metrics.SoftDisconnectRequest(); + ValidateOwnershipAndSetPoolingState(connection, owningObject); SqlClientEventSource.Log.TryPoolerTraceEvent( @@ -1091,6 +1103,8 @@ _connectionCreationRateLimiter is not null && if (connection is not null) { + SqlClientDiagnostics.Metrics.EnterPooledConnection(); + // A new connection was added to the pool. If we've grown past MinPoolSize, // start the pruning timer so idle connections can be reclaimed. Pruner?.UpdateTimer(); @@ -1217,7 +1231,10 @@ private void RemoveConnection(DbConnectionInternal connection) return; } - _connectionSlots.TryRemove(connection); + if (_connectionSlots.TryRemove(connection)) + { + SqlClientDiagnostics.Metrics.ExitPooledConnection(); + } // Removing a connection from the pool opens a free slot. // Write a null to the idle connection channel to wake up a waiter, who can now open a new @@ -1225,6 +1242,7 @@ private void RemoveConnection(DbConnectionInternal connection) _idleChannel.TryWrite(null); connection.Dispose(); + SqlClientDiagnostics.Metrics.HardDisconnectRequest(); // If this removal brought us back to MinPoolSize, disable the pruning timer. Pruner?.UpdateTimer(); @@ -1370,6 +1388,7 @@ private async Task GetInternalConnection( } PrepareConnection(owningConnection, connection, transaction); + SqlClientDiagnostics.Metrics.SoftConnectRequest(); return connection; } diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/ConnectionPoolSlots.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/ConnectionPoolSlots.cs index c9d268fd29..5eabf04cfe 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/ConnectionPoolSlots.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/ConnectionPoolSlots.cs @@ -60,6 +60,7 @@ internal void Keep() private readonly DbConnectionInternal?[] _connections; private readonly uint _capacity; private volatile int _reservations; + private volatile int _connectionCount; /// /// Constructs a ConnectionPoolSlots instance with the given fixed capacity. @@ -82,14 +83,23 @@ internal ConnectionPoolSlots(uint fixedCapacity) _capacity = fixedCapacity; _reservations = 0; + _connectionCount = 0; _connections = new DbConnectionInternal?[fixedCapacity]; } /// - /// Gets the total number of reservations currently held. + /// Gets the total number of reservations currently held. This includes reservations held on + /// behalf of connections that are still being opened and are therefore not yet tracked. /// internal int ReservationCount => _reservations; + /// + /// Gets the number of connections currently tracked by this collection. Unlike + /// , this excludes reservations held for connections that are + /// still being opened, so it reports connections that actually belong to the pool. + /// + internal int ConnectionCount => _connectionCount; + /// /// Adds a connection to the collection. /// @@ -127,6 +137,7 @@ internal ConnectionPoolSlots(uint fixedCapacity) { if (Interlocked.CompareExchange(ref _connections[i], connection, null) == null) { + Interlocked.Increment(ref _connectionCount); reservation.Keep(); return connection; } @@ -162,6 +173,7 @@ internal bool TryRemove(DbConnectionInternal connection) { if (Interlocked.CompareExchange(ref _connections[i], null, connection) == connection) { + Interlocked.Decrement(ref _connectionCount); ReleaseReservation(); return true; } diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/IdleConnectionChannel.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/IdleConnectionChannel.cs index 348ad33d9e..e263ae77b7 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/IdleConnectionChannel.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/IdleConnectionChannel.cs @@ -56,6 +56,7 @@ internal bool TryWrite(DbConnectionInternal? connection) if (connection is not null) { Interlocked.Increment(ref _count); + SqlClientDiagnostics.Metrics.EnterFreeConnection(); } return true; } @@ -74,6 +75,7 @@ internal bool TryRead(out DbConnectionInternal? connection) if (connection is not null) { Interlocked.Decrement(ref _count); + SqlClientDiagnostics.Metrics.ExitFreeConnection(); } return true; @@ -93,6 +95,7 @@ internal bool TryRead(out DbConnectionInternal? connection) if (connection is not null) { Interlocked.Decrement(ref _count); + SqlClientDiagnostics.Metrics.ExitFreeConnection(); } return connection; From 6d7710d019f88ed257ba2dcdbab6c9ffb97273d6 Mon Sep 17 00:00:00 2001 From: Malcolm Daigle Date: Wed, 12 Aug 2026 12:34:51 -0700 Subject: [PATCH 02/19] Add pool tracing parity for ChannelDbConnectionPool Bring ChannelDbConnectionPool's pooler tracing up to parity with WaitHandleDbConnectionPool: emit a per-reason trace for connections rejected by the liveness gate, and trace connections held by a transaction, which otherwise vanish from the trace stream after deactivation. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- .../ConnectionPool/ChannelDbConnectionPool.cs | 125 +++- ...nnelDbConnectionPoolInstrumentationTest.cs | 625 ++++++++++++++++++ 2 files changed, 749 insertions(+), 1 deletion(-) create mode 100644 src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/ChannelDbConnectionPoolInstrumentationTest.cs 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 49e23e6911..07e2f45804 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 @@ -197,6 +197,12 @@ internal ChannelDbConnectionPool( } State = Running; + + SqlClientEventSource.Log.TryPoolerTraceEvent( + " {0}, Constructed. MinPoolSize={1}, MaxPoolSize={2}", + Id, + MinPoolSize, + MaxPoolSize); } #region Properties @@ -484,6 +490,11 @@ public DbConnectionInternal ReplaceConnection( } newConnection.Dispose(); + + // The physical connection was opened (and counted by HardConnectRequest in the + // factory) before activation failed, so balance the counter here. The + // connection never occupied a slot, so the pooled gauge is untouched. + SqlClientDiagnostics.Metrics.HardDisconnectRequest(); throw; } @@ -493,6 +504,16 @@ public DbConnectionInternal ReplaceConnection( // Only retire the old connection after the replacement is fully activated and we know we won't fail. oldConnection.DeactivateConnection(); oldConnection.Dispose(); + + // The replacement took over the old connection's slot, so the pooled gauge is + // already correct and only the hard-disconnect counter needs balancing. Traced as a + // destroy so the connection's exit is visible in the pooler trace stream. + SqlClientDiagnostics.Metrics.HardDisconnectRequest(); + + SqlClientEventSource.Log.TryPoolerTraceEvent( + " {0}, Connection {1}, Disposed.", + Id, + oldConnection.ObjectID); } SqlClientDiagnostics.Metrics.SoftConnectRequest(); @@ -591,7 +612,13 @@ public void ReturnInternalConnection(DbConnectionInternal connection, DbConnecti case ReturnDisposition.HeldByTransaction: // Nothing further to do. The connection is parked in the transacted store or // in stasis, and comes back through PutObjectFromTransactedPool once its - // transaction ends. + // transaction ends. Neither path returns it to the idle channel, so without + // this trace the connection simply disappears from the pool's trace stream + // after deactivation. + SqlClientEventSource.Log.TryPoolerTraceEvent( + " {0}, Connection {1}, Held by a transaction; not returned to the general pool.", + Id, + connection.ObjectID); break; } } @@ -657,6 +684,11 @@ private void PutConnectionInIdleChannel(DbConnectionInternal connection, bool pr return; } + SqlClientEventSource.Log.TryPoolerTraceEvent( + " {0}, Connection {1}, Pushing to general pool.", + Id, + connection.ObjectID); + if (!_idleChannel.TryWrite(connection)) { // The channel has been completed (pool is shutting down). Race window @@ -991,8 +1023,17 @@ public bool TryGetConnection( // pool, whose replenishment enters/clears the same error state as user requests. In // practice the warmup loop already stands down before reaching here (its loop condition // checks ErrorOccurred); this covers the narrow race where the state flips in between. + if (ErrorOccurred) + { + SqlClientEventSource.Log.TryPoolerTraceEvent( + " {0}, Errors are set.", Id); + } + _errorState?.ThrowIfActive(); + SqlClientEventSource.Log.TryPoolerTraceEvent( + " {0}, Creating new connection.", Id); + try { // Reserve a pool slot up front so we don't pay the rate-limit cost only to @@ -1029,6 +1070,9 @@ public bool TryGetConnection( // 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. + SqlClientEventSource.Log.TryPoolerTraceEvent( + " {0}, Rate limiter saturated; deferring creation to the idle wait.", + Id); faulted = false; return null; } @@ -1103,6 +1147,11 @@ _connectionCreationRateLimiter is not null && if (connection is not null) { + SqlClientEventSource.Log.TryPoolerTraceEvent( + " {0}, Connection {1}, Added to pool.", + Id, + connection.ObjectID); + SqlClientDiagnostics.Metrics.EnterPooledConnection(); // A new connection was added to the pool. If we've grown past MinPoolSize, @@ -1114,11 +1163,22 @@ _connectionCreationRateLimiter is not null && // WaitHandle pool: a connection that opens proves the server is reachable. _errorState?.Clear(); } + else + { + SqlClientEventSource.Log.TryPoolerTraceEvent( + " {0}, No connection created; pool is full or creation is rate limited.", + Id); + } return connection; } catch (Exception ex) when (ADP.IsCatchableExceptionType(ex) && ex is not OperationCanceledException) { + SqlClientEventSource.Log.TryPoolerTraceEvent( + " {0}, PoolCreateRequest called CreateConnection which threw an exception: {1}", + Id, + ex); + // Enter the blocking period error state on creation failure if configured. Warmup // goes through this same path (the warmup loop absorbs the rethrow in its own catch), // mirroring the legacy WaitHandle pool, whose replenishment failures also enter the @@ -1171,6 +1231,7 @@ private bool IsLiveConnection(DbConnectionInternal connection, bool probeLivenes idleTimeout != TimeSpan.Zero && _timeProvider.GetUtcNow().UtcDateTime - connection.ReturnedTime > idleTimeout) { + TraceNotLive(connection, "exceeded the connection idle timeout"); return false; } @@ -1178,24 +1239,43 @@ private bool IsLiveConnection(DbConnectionInternal connection, bool probeLivenes // polls the socket, so it must not run on a thread we do not own. if (probeLiveness && !connection.IsConnectionAlive()) { + TraceNotLive(connection, "found dead"); return false; } // Connection has been alive longer than the load balance timeout if (LoadBalanceTimeout != TimeSpan.Zero && DateTime.UtcNow > connection.CreateTime + LoadBalanceTimeout) { + TraceNotLive(connection, "exceeded the load balance timeout"); return false; } // Connection was created before the last Clear, so it's stale. if (connection.ClearGeneration != _clearGeneration) { + TraceNotLive(connection, "was created before the last Clear"); return false; } return true; } + /// + /// Emits the trace for a connection that failed the gate. + /// Split out so each rejection reason is reported individually: the caller only sees that + /// the connection was discarded, which on its own does not explain whether the pool is + /// churning because of idle timeout, load balancing, a Clear, or genuine server failures. + /// + /// The connection that failed the liveness gate. + /// Why the connection was rejected, phrased to read as + /// "Connection {id}, {reason} and removed." + private void TraceNotLive(DbConnectionInternal connection, string reason) => + SqlClientEventSource.Log.TryPoolerTraceEvent( + " {0}, Connection {1}, {2} and removed.", + Id, + connection.ObjectID, + reason); + /// /// Closes the provided connection and removes it from the pool, freeing its slot. /// @@ -1218,6 +1298,11 @@ private bool IsLiveConnection(DbConnectionInternal connection, bool probeLivenes /// The connection to be closed. private void RemoveConnection(DbConnectionInternal connection) { + SqlClientEventSource.Log.TryPoolerTraceEvent( + " {0}, Connection {1}, Removing from pool.", + Id, + connection.ObjectID); + // A connection with a delegated transaction cannot be disposed of until the delegated // transaction has actually completed; disposing it would abort the (possibly // distributed) transaction. Leave it alone: when the transaction completes it comes @@ -1233,6 +1318,11 @@ private void RemoveConnection(DbConnectionInternal connection) if (_connectionSlots.TryRemove(connection)) { + SqlClientEventSource.Log.TryPoolerTraceEvent( + " {0}, Connection {1}, Removed from pool.", + Id, + connection.ObjectID); + SqlClientDiagnostics.Metrics.ExitPooledConnection(); } @@ -1244,6 +1334,11 @@ private void RemoveConnection(DbConnectionInternal connection) connection.Dispose(); SqlClientDiagnostics.Metrics.HardDisconnectRequest(); + SqlClientEventSource.Log.TryPoolerTraceEvent( + " {0}, Connection {1}, Disposed.", + Id, + connection.ObjectID); + // If this removal brought us back to MinPoolSize, disable the pruning timer. Pruner?.UpdateTimer(); @@ -1276,6 +1371,11 @@ private void RemoveConnection(DbConnectionInternal connection) continue; } + SqlClientEventSource.Log.TryPoolerTraceEvent( + " {0}, Connection {1}, Popped from general pool.", + Id, + connection.ObjectID); + return connection; } @@ -1310,6 +1410,9 @@ private async Task GetInternalConnection( { DbConnectionInternal? connection = null; + SqlClientEventSource.Log.TryPoolerTraceEvent( + " {0}, Getting connection.", Id); + // When automatic enlistment is disabled, the connection must never be bound to the // ambient transaction, so we neither consult the transacted store nor hand the // transaction to activation. HasTransactionAffinity is derived from the connection @@ -1372,10 +1475,15 @@ private async Task GetInternalConnection( } catch (OperationCanceledException) { + SqlClientEventSource.Log.TryPoolerTraceEvent( + " {0}, Wait timed out.", Id); + throw ADP.PooledOpenTimeout(); } catch (ChannelClosedException) { + SqlClientEventSource.Log.TryPoolerTraceEvent( + " {0}, Pool is shutting down; abandoning wait.", Id); throw new InvalidOperationException(StringsHelper.GetString(Strings.SQL_ConnectionPoolShutDown)); } @@ -1732,6 +1840,15 @@ private async Task RunWarmupLoopAsync() /// internal void PruneConnections(int count) { + SqlClientEventSource.Log.TryPoolerTraceEvent( + " {0}, Pruning up to {1} idle connections. IdleCount={2}, Count={3}", + Id, + count, + IdleCount, + Count); + + int pruned = 0; + while (count > 0 && IsRunning && _connectionSlots.ReservationCount > MinPoolSize @@ -1744,7 +1861,13 @@ internal void PruneConnections(int count) RemoveConnection(connection); count--; + pruned++; } + + SqlClientEventSource.Log.TryPoolerTraceEvent( + " {0}, Pruned {1} idle connections.", + Id, + pruned); } #endregion } diff --git a/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/ChannelDbConnectionPoolInstrumentationTest.cs b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/ChannelDbConnectionPoolInstrumentationTest.cs new file mode 100644 index 0000000000..ef996bf952 --- /dev/null +++ b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/ChannelDbConnectionPoolInstrumentationTest.cs @@ -0,0 +1,625 @@ +// Licensed to the .NET Foundation under one or more agreements. +// 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; +using System.Collections.Concurrent; +using System.Collections.Generic; +using System.Data.Common; +using System.Diagnostics.Tracing; +using System.Globalization; +using System.Linq; +using System.Reflection; +using System.Text.RegularExpressions; +using System.Threading; +using System.Threading.RateLimiting; +using Microsoft.Data.Common; +using Microsoft.Data.Common.ConnectionString; +using Microsoft.Data.ProviderBase; +using Microsoft.Data.SqlClient.ConnectionPool; +using Microsoft.Data.SqlClient.Diagnostics; +using Microsoft.Data.SqlClient.Tests.Common; +using Xunit; + +using static Microsoft.Data.SqlClient.UnitTests.ConnectionPool.ChannelDbConnectionPoolTest; + +namespace Microsoft.Data.SqlClient.UnitTests.ConnectionPool +{ + /// + /// Verifies the diagnostic instrumentation of : the pooler + /// trace events emitted across the connection lifecycle. + /// + public class ChannelDbConnectionPoolInstrumentationTest + { + /// + /// Builds a pool for instrumentation tests. Defaults mirror + /// so behavior is comparable across suites. + /// + /// The factory used to create physical connections. + /// Connection string backing the pool group. Tests override + /// it to control the Pool Blocking Period. + /// Maximum pool size. + /// Minimum pool size. + /// Connection Idle Timeout, in seconds. + /// Optional limiter throttling physical creates. + private static ChannelDbConnectionPool ConstructPool( + SqlConnectionFactory connectionFactory, + string connectionString = "Data Source=localhost;", + int maxPoolSize = 50, + int minPoolSize = 0, + int idleTimeout = 0, + ConcurrencyLimiter? connectionCreationRateLimiter = null) + => new( + connectionFactory, + ConstructPoolGroup(connectionString, maxPoolSize, minPoolSize, idleTimeout), + DbConnectionPoolIdentity.NoIdentity, + new DbConnectionPoolProviderInfo(), + connectionCreationRateLimiter); + + /// + /// Builds the pool group shared by both pool implementations. + /// + private static DbConnectionPoolGroup ConstructPoolGroup( + string connectionString, + int maxPoolSize, + int minPoolSize, + int idleTimeout) + { + DbConnectionPoolGroupOptions poolGroupOptions = new( + poolByIdentity: false, + minPoolSize: minPoolSize, + maxPoolSize: maxPoolSize, + creationTimeout: 15, + loadBalanceTimeout: 0, + hasTransactionAffinity: true, + idleTimeout: idleTimeout); + + return new DbConnectionPoolGroup( + new SqlConnectionOptions(connectionString), + new ConnectionPoolKey("TestDataSource", credential: null, accessToken: null, accessTokenCallback: null, sspiContextProvider: null), + poolGroupOptions); + } + + #region Trace parity + + /// + /// Verifies that the pool traces its own construction, so a trace capture can attribute + /// every later pool-scoped event to a pool whose creation it observed. + /// + [Fact] + public void Construction_EmitsConstructedTrace() + { + // Arrange + using PoolerTraceListener listener = new(); + + // Act + ChannelDbConnectionPool pool = ConstructPool(new SuccessfulSqlConnectionFactory()); + + // Assert + TraceAssert.Contains("Constructed.", listener.MessagesForPool(pool.Id)); + } + + /// + /// Verifies that creating a new physical connection is traced, covering Story 1 scenario 2. + /// + [Fact] + public void NewConnection_EmitsCreationTraces() + { + // Arrange + ChannelDbConnectionPool pool = ConstructPool(new SuccessfulSqlConnectionFactory()); + using PoolerTraceListener listener = new(); + + // Act + Assert.True(pool.TryGetConnection( + new SqlConnection(), + taskCompletionSource: null, + TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), + out DbConnectionInternal? connection)); + + // Assert + IReadOnlyList messages = listener.MessagesForPool(pool.Id); + Assert.NotNull(connection); + TraceAssert.Contains("Getting connection.", messages); + TraceAssert.Contains("Creating new connection.", messages); + TraceAssert.Contains("Added to pool.", messages); + } + + /// + /// Verifies that retrieving a connection from the idle pool is traced, covering Story 1 + /// scenario 1. + /// + [Fact] + public void IdleConnectionReuse_EmitsPoppedFromGeneralPoolTrace() + { + // Arrange + ChannelDbConnectionPool pool = ConstructPool(new SuccessfulSqlConnectionFactory()); + SqlConnection owner = new(); + Assert.True(pool.TryGetConnection(owner, null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out DbConnectionInternal? connection)); + Assert.NotNull(connection); + pool.ReturnInternalConnection(connection!, owner); + + using PoolerTraceListener listener = new(); + + // Act + Assert.True(pool.TryGetConnection(new SqlConnection(), null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out DbConnectionInternal? reused)); + + // Assert + Assert.Same(connection, reused); + TraceAssert.Contains("Popped from general pool.", listener.MessagesForPool(pool.Id)); + } + + /// + /// Verifies that returning a connection traces both the deactivation and the routing + /// decision that put it back into the idle pool, covering Story 1 scenario 3. + /// + [Fact] + public void Return_EmitsDeactivateAndPushTraces() + { + // Arrange + ChannelDbConnectionPool pool = ConstructPool(new SuccessfulSqlConnectionFactory()); + SqlConnection owner = new(); + Assert.True(pool.TryGetConnection(owner, null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out DbConnectionInternal? connection)); + Assert.NotNull(connection); + + using PoolerTraceListener listener = new(); + + // Act + pool.ReturnInternalConnection(connection!, owner); + + // Assert + IReadOnlyList messages = listener.MessagesForPool(pool.Id); + TraceAssert.Contains("Deactivating.", messages); + TraceAssert.Contains("Pushing to general pool.", messages); + } + + /// + /// Verifies that destroying a connection traces the removal and the disposal, covering + /// Story 1 scenario 4. Clear is used as the destruction trigger because it drains the idle + /// channel through the same removal path as every other destroy. + /// + [Fact] + public void Destroy_EmitsRemoveAndDisposeTraces() + { + // Arrange + ChannelDbConnectionPool pool = ConstructPool(new SuccessfulSqlConnectionFactory()); + SqlConnection owner = new(); + Assert.True(pool.TryGetConnection(owner, null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out DbConnectionInternal? connection)); + Assert.NotNull(connection); + pool.ReturnInternalConnection(connection!, owner); + + using PoolerTraceListener listener = new(); + + // Act + pool.Clear(); + + // Assert + IReadOnlyList messages = listener.MessagesForPool(pool.Id); + TraceAssert.Contains("Clearing.", messages); + TraceAssert.Contains("Removing from pool.", messages); + TraceAssert.Contains("Removed from pool.", messages); + TraceAssert.Contains("Disposed.", messages); + TraceAssert.Contains("Cleared.", messages); + } + + /// + /// Verifies that startup and shutdown are traced with the pool identifier, covering Story 1 + /// scenario 5. + /// + [Fact] + public void StartupAndShutdown_EmitTraces() + { + // Arrange + ChannelDbConnectionPool pool = ConstructPool(new SuccessfulSqlConnectionFactory()); + using PoolerTraceListener listener = new(); + + // Act + pool.Startup(); + pool.Shutdown(); + + // Assert + IReadOnlyList messages = listener.MessagesForPool(pool.Id); + Assert.Contains(messages, m => m.IndexOf("Startup", StringComparison.Ordinal) >= 0); + Assert.Contains(messages, m => m.IndexOf("Shutdown", StringComparison.Ordinal) >= 0); + } + + /// + /// Verifies that a failed physical open is traced on the pool's create path, so an operator + /// can see why the pool stopped growing. + /// + [Fact] + public void CreateFailure_EmitsCreateThrewTrace() + { + // Arrange + ChannelDbConnectionPool pool = ConstructPool(new FailingSqlConnectionFactory()); + using PoolerTraceListener listener = new(); + + // Act + Assert.ThrowsAny(() => + pool.TryGetConnection(new SqlConnection(), null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out _)); + + // Assert + TraceAssert.Contains("which threw an exception", listener.MessagesForPool(pool.Id)); + } + + /// + /// Verifies that a connection discarded for exceeding the Connection Idle Timeout is traced + /// with that specific reason, rather than silently disappearing from the pool. + /// + [Fact] + public void IdleTimeoutEviction_EmitsReasonTrace() + { + // Arrange - idle-timeout eviction is opt-in; the switch defaults to legacy behavior. + using LocalAppContextSwitchesHelper switchesHelper = new(); + switchesHelper.UseLegacyIdleTimeoutBehavior = false; + + ChannelDbConnectionPool pool = ConstructPool(new SuccessfulSqlConnectionFactory(), idleTimeout: 1); + SqlConnection owner = new(); + Assert.True(pool.TryGetConnection(owner, null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out DbConnectionInternal? connection)); + Assert.NotNull(connection); + pool.ReturnInternalConnection(connection!, owner); + + // Back-date the return stamp only after the connection is parked in the idle channel: + // the return path re-stamps it so that time spent checked out is not counted as idle. + connection!.SetReturnedTime(DateTime.UtcNow - TimeSpan.FromMinutes(5)); + + using PoolerTraceListener listener = new(); + + // Act - retrieval trips the idle-expiry gate and discards the connection. + Assert.True(pool.TryGetConnection(new SqlConnection(), null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out DbConnectionInternal? replacement)); + + // Assert + Assert.NotNull(replacement); + Assert.NotSame(connection, replacement); + TraceAssert.Contains("exceeded the connection idle timeout and removed.", listener.MessagesForPool(pool.Id)); + } + + /// + /// Verifies that pruning traces each invocation, so idle reclamation is attributable in a + /// trace capture even when it removes nothing (Story 3). + /// + [Fact] + public void Prune_EmitsTracePerInvocation() + { + // Arrange + ChannelDbConnectionPool pool = ConstructPool(new SuccessfulSqlConnectionFactory(), maxPoolSize: 4, idleTimeout: 300); + SqlConnection owner = new(); + Assert.True(pool.TryGetConnection(owner, null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out DbConnectionInternal? connection)); + Assert.NotNull(connection); + pool.ReturnInternalConnection(connection!, owner); + + using PoolerTraceListener listener = new(); + + // Act + pool.PruneConnections(1); + + // Assert + IReadOnlyList messages = listener.MessagesForPool(pool.Id); + TraceAssert.Contains("Pruning up to 1 idle connections.", messages); + TraceAssert.Contains("Pruned 1 idle connections.", messages); + } + + #endregion + +#if NET + #region Metric parity + + // The metric counters are process-wide and other suites run in parallel, so these tests + // assert that a counter advanced by at least the expected amount rather than by exactly it. + // The rate counters only ever increase, which makes that assertion stable under concurrency. + // + // These run against both pool implementations so that any divergence in the counters the + // channel pool emits shows up as a failing test rather than as a silent telemetry gap. + + /// + /// Identifies which pool implementation a parameterized metric test exercises. + /// + public enum PoolImplementation + { + /// The legacy . + WaitHandle, + + /// The . + Channel, + } + + /// + /// Builds the requested pool implementation behind the shared pool interface. + /// + private static IDbConnectionPool ConstructPool( + PoolImplementation implementation, + SqlConnectionFactory connectionFactory, + string connectionString = "Data Source=localhost;", + int maxPoolSize = 50, + int minPoolSize = 0, + int idleTimeout = 0) + { + DbConnectionPoolGroup poolGroup = ConstructPoolGroup(connectionString, maxPoolSize, minPoolSize, idleTimeout); + + return implementation switch + { + PoolImplementation.WaitHandle => new WaitHandleDbConnectionPool( + connectionFactory, + poolGroup, + DbConnectionPoolIdentity.NoIdentity, + new DbConnectionPoolProviderInfo()), + + PoolImplementation.Channel => new ChannelDbConnectionPool( + connectionFactory, + poolGroup, + DbConnectionPoolIdentity.NoIdentity, + new DbConnectionPoolProviderInfo()), + + _ => throw new ArgumentOutOfRangeException(nameof(implementation)), + }; + } + + /// + /// Verifies that creating a physical connection counts a hard connect, covering Story 2 + /// scenario 1. + /// + [Theory] + [InlineData(PoolImplementation.WaitHandle)] + [InlineData(PoolImplementation.Channel)] + public void NewConnection_CountsHardConnect(PoolImplementation implementation) + { + // Arrange + IDbConnectionPool pool = ConstructPool(implementation, new SuccessfulSqlConnectionFactory()); + SqlConnection owner = new(); + + long before = MetricReader.Read("_hardConnectsRate"); + + // Act + Assert.True(pool.TryGetConnection(owner, null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out DbConnectionInternal? connection)); + + // Assert + Assert.NotNull(connection); + Assert.True(MetricReader.Read("_hardConnectsRate") >= before + 1); + } + + /// + /// Verifies that retrieving an idle connection counts a soft connect, covering Story 2 + /// scenario 3. + /// + [Theory] + [InlineData(PoolImplementation.WaitHandle)] + [InlineData(PoolImplementation.Channel)] + public void IdleConnectionReuse_CountsSoftConnect(PoolImplementation implementation) + { + // Arrange + IDbConnectionPool pool = ConstructPool(implementation, new SuccessfulSqlConnectionFactory()); + SqlConnection owner = new(); + Assert.True(pool.TryGetConnection(owner, null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out DbConnectionInternal? connection)); + Assert.NotNull(connection); + pool.ReturnInternalConnection(connection!, owner); + + long before = MetricReader.Read("_softConnectsRate"); + + // Act + Assert.True(pool.TryGetConnection(new SqlConnection(), null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out DbConnectionInternal? reused)); + + // Assert + Assert.Same(connection, reused); + Assert.True(MetricReader.Read("_softConnectsRate") >= before + 1); + } + + /// + /// Verifies that returning a connection to the idle pool counts a soft disconnect, covering + /// Story 2 scenario 4. + /// + [Theory] + [InlineData(PoolImplementation.WaitHandle)] + [InlineData(PoolImplementation.Channel)] + public void Return_CountsSoftDisconnect(PoolImplementation implementation) + { + // Arrange + IDbConnectionPool pool = ConstructPool(implementation, new SuccessfulSqlConnectionFactory()); + SqlConnection owner = new(); + Assert.True(pool.TryGetConnection(owner, null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out DbConnectionInternal? connection)); + Assert.NotNull(connection); + + long before = MetricReader.Read("_softDisconnectsRate"); + + // Act + pool.ReturnInternalConnection(connection!, owner); + + // Assert + Assert.True(MetricReader.Read("_softDisconnectsRate") >= before + 1); + } + + /// + /// Verifies that destroying a physical connection counts a hard disconnect, covering Story 2 + /// scenario 2. + /// + [Theory] + [InlineData(PoolImplementation.WaitHandle)] + [InlineData(PoolImplementation.Channel)] + public void Destroy_CountsHardDisconnect(PoolImplementation implementation) + { + // Arrange + IDbConnectionPool pool = ConstructPool(implementation, new SuccessfulSqlConnectionFactory()); + SqlConnection owner = new(); + Assert.True(pool.TryGetConnection(owner, null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out DbConnectionInternal? connection)); + Assert.NotNull(connection); + pool.ReturnInternalConnection(connection!, owner); + + long before = MetricReader.Read("_hardDisconnectsRate"); + + // Act + pool.Clear(); + + // Assert + Assert.True(MetricReader.Read("_hardDisconnectsRate") >= before + 1); + } + + /// + /// Verifies that replacing a connection counts a hard disconnect for the connection it + /// discards. The channel pool swaps the new connection into the old connection's slot, so + /// the pooled-connection gauge is deliberately left untouched. + /// + /// + /// This is not parameterized over the wait handle pool: that implementation disposes the + /// replaced connection directly rather than through its destroy path, so it emits neither + /// the hard disconnect nor the pooled-connection decrement. + /// + [Fact] + public void ReplaceConnection_CountsHardDisconnectForDiscardedConnection() + { + // Arrange + ChannelDbConnectionPool pool = ConstructPool(new SuccessfulSqlConnectionFactory()); + SqlConnection owner = new(); + Assert.True(pool.TryGetConnection(owner, null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out DbConnectionInternal? oldConnection)); + Assert.NotNull(oldConnection); + + long beforeDisconnects = MetricReader.Read("_hardDisconnectsRate"); + long beforePooled = MetricReader.Read("_pooledConnections"); + + // Act + DbConnectionInternal newConnection = pool.ReplaceConnection(owner, oldConnection!, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15))); + + // Assert + Assert.NotSame(oldConnection, newConnection); + Assert.True(MetricReader.Read("_hardDisconnectsRate") >= beforeDisconnects + 1); + Assert.Equal(beforePooled, MetricReader.Read("_pooledConnections")); + } + + #endregion +#endif + + #region Test classes + + /// + /// Distinctive exception type used to prove that the exact failure recorded by the pool is + /// the one attached to the pooled-open timeout. + /// + internal sealed class TestConnectionCreateException : Exception + { + internal TestConnectionCreateException() + : base("Simulated physical connection failure.") + { + } + } + + /// + /// Connection factory that always fails with . + /// + internal sealed class FailingSqlConnectionFactory : SqlConnectionFactory + { + /// + protected override DbConnectionInternal CreateConnection( + SqlConnectionOptions options, + ConnectionPoolKey poolKey, + DbConnectionPoolGroupProviderInfo poolGroupProviderInfo, + IDbConnectionPool pool, + DbConnection owningConnection, + TimeoutTimer timeout) + => throw new TestConnectionCreateException(); + } + + /// + /// Captures PoolerTrace events from the SqlClient event source. + /// + /// Tests filter captured messages by pool id (see ) because the + /// event source is process-wide: xUnit runs test classes in parallel, so traces from other + /// pools are expected to appear in the same capture. + /// + /// + internal sealed class PoolerTraceListener : EventListener + { + private const string SqlClientEventSourceName = "Microsoft.Data.SqlClient.EventSource"; + + // Mirrors SqlClientEventSource.Keywords.PoolerTrace. Duplicated as a literal because + // that type is not visible to this assembly. + private const EventKeywords PoolerTraceKeyword = (EventKeywords)32; + + // Lazily initialized: EventListener's base constructor invokes OnEventSourceCreated, + // which enables events, before this class's field initializers have run. Traces can + // therefore arrive on another thread before a plain field initializer would have + // assigned the queue. + private ConcurrentQueue? _messages; + + private ConcurrentQueue Messages => + LazyInitializer.EnsureInitialized(ref _messages)!; + + /// + protected override void OnEventSourceCreated(EventSource eventSource) + { + if (eventSource.Name == SqlClientEventSourceName) + { + EnableEvents(eventSource, EventLevel.Informational, PoolerTraceKeyword); + } + } + + /// + protected override void OnEventWritten(EventWrittenEventArgs eventData) + { + if (eventData.Payload is null) + { + return; + } + + foreach (object? payload in eventData.Payload) + { + if (payload is string message) + { + Messages.Enqueue(message); + } + } + } + + /// + /// Returns the captured messages emitted for the given pool. + /// + /// The to filter on. + internal IReadOnlyList MessagesForPool(int poolId) + { + // Pool-scoped traces render the id as the first substituted argument, immediately + // after the "|CPOOL> " marker, e.g. + // " 7, Clearing." + // " 7" + // The trailing boundary keeps pool 7 from matching pool 70. + Regex pattern = new( + @"CPOOL> " + Regex.Escape(poolId.ToString(CultureInfo.InvariantCulture)) + @"(\D|$)", + RegexOptions.CultureInvariant); + + return Messages.Where(m => pattern.IsMatch(m)).ToList(); + } + } + + #endregion + } + +#if NET + /// + /// Reads the private counter fields of the process-wide instance. + /// The counters are not otherwise observable without an EventCounter listener and its polling + /// interval, which would make these tests slow and timing dependent. + /// + internal static class MetricReader + { + /// + /// Reads the current value of the named counter field. + /// + /// Private field name declared on . + internal static long Read(string fieldName) + { + FieldInfo? field = typeof(SqlClientMetrics).GetField(fieldName, BindingFlags.Instance | BindingFlags.NonPublic); + Assert.NotNull(field); + return (long)field!.GetValue(SqlClientDiagnostics.Metrics)!; + } + } +#endif + + /// + /// xUnit assertion helper for substring matching over a captured trace stream. + /// + internal static class TraceAssert + { + /// + /// Asserts that at least one captured message contains . + /// + internal static void Contains(string fragment, IReadOnlyList messages) => + Assert.True( + messages.Any(m => m.IndexOf(fragment, StringComparison.Ordinal) >= 0), + $"Expected a trace containing \"{fragment}\". Captured:{Environment.NewLine}{string.Join(Environment.NewLine, messages)}"); + } +} From 6f0261c6e2124d57ca9af9a30e09b17f733a734c Mon Sep 17 00:00:00 2001 From: Malcolm Daigle Date: Wed, 12 Aug 2026 13:16:52 -0700 Subject: [PATCH 03/19] Give connection pools an injectable metrics sink The pool metric counters lived on a single process-wide SqlClientMetrics instance, so a unit test could only assert that a counter had advanced by at least some amount. Unrelated connection activity elsewhere in the process could always inflate it. Add a Metrics property to IDbConnectionPool, supplied by an optional constructor parameter that defaults to the process-wide instance. Route the counters a pool owns through it: both pool implementations, IdleConnectionChannel, TransactedConnectionPool, and the pooled-connection branch of SqlConnectionFactory. Production behavior is unchanged, since every caller still resolves to the same singleton. Counters emitted outside the pool stay global. DbConnectionInternal reports active-connection and stasis counts, and the factory reports non-pooled and pool-group counts, none of which are attributable to a single pool. The metric parity tests now give each pool its own counters and assert exact values instead of lower bounds, which additionally covers the free- and pooled-connection gauges. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- .../ConnectionPool/ChannelDbConnectionPool.cs | 30 +-- .../ConnectionPool/IDbConnectionPool.cs | 11 ++ .../ConnectionPool/IdleConnectionChannel.cs | 15 +- .../TransactedConnectionPool.cs | 4 +- .../WaitHandleDbConnectionPool.cs | 36 ++-- .../SqlClient/Diagnostics/SqlClientMetrics.cs | 15 ++ .../Data/SqlClient/SqlConnectionFactory.cs | 2 +- ...nnelDbConnectionPoolInstrumentationTest.cs | 176 +++++++++++++----- .../TransactedConnectionPoolTest.cs | 4 + 9 files changed, 211 insertions(+), 82 deletions(-) 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 07e2f45804..cabdc7f782 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 @@ -14,6 +14,7 @@ using System.Transactions; using Microsoft.Data.Common; using Microsoft.Data.ProviderBase; +using Microsoft.Data.SqlClient.Diagnostics; using static Microsoft.Data.SqlClient.ConnectionPool.DbConnectionPoolState; using Microsoft.Data.SqlClient.Internal; @@ -163,9 +164,13 @@ internal ChannelDbConnectionPool( DbConnectionPoolIdentity identity, DbConnectionPoolProviderInfo connectionPoolProviderInfo, ConcurrencyLimiter? connectionCreationRateLimiter = null, - TimeProvider? timeProvider = null) + TimeProvider? timeProvider = null, + SqlClientMetrics? metrics = null) { ConnectionFactory = connectionFactory; + // metrics is injected only by tests, so a pool's counters can be asserted without + // interference from unrelated connection activity elsewhere in the process. + Metrics = metrics ?? SqlClientDiagnostics.Metrics; PoolGroup = connectionPoolGroup; PoolGroupOptions = connectionPoolGroup.PoolGroupOptions; ProviderInfo = connectionPoolProviderInfo; @@ -180,7 +185,7 @@ internal ChannelDbConnectionPool( _timeProvider = timeProvider ?? TimeProvider.System; _connectionSlots = new(MaxPoolSize); - _idleChannel = new(); + _idleChannel = new(Metrics); if (PoolGroup.IsBlockingPeriodEnabled()) { _errorState = new BlockingPeriodErrorState(_instanceId, timeProvider: _timeProvider); @@ -214,6 +219,9 @@ public ConcurrentDictionary< /// public SqlConnectionFactory ConnectionFactory { get; } + /// + public SqlClientMetrics Metrics { get; } + /// /// /// Reports connections that actually belong to the pool, not @@ -494,7 +502,7 @@ public DbConnectionInternal ReplaceConnection( // The physical connection was opened (and counted by HardConnectRequest in the // factory) before activation failed, so balance the counter here. The // connection never occupied a slot, so the pooled gauge is untouched. - SqlClientDiagnostics.Metrics.HardDisconnectRequest(); + Metrics.HardDisconnectRequest(); throw; } @@ -508,7 +516,7 @@ public DbConnectionInternal ReplaceConnection( // The replacement took over the old connection's slot, so the pooled gauge is // already correct and only the hard-disconnect counter needs balancing. Traced as a // destroy so the connection's exit is visible in the pooler trace stream. - SqlClientDiagnostics.Metrics.HardDisconnectRequest(); + Metrics.HardDisconnectRequest(); SqlClientEventSource.Log.TryPoolerTraceEvent( " {0}, Connection {1}, Disposed.", @@ -516,7 +524,7 @@ public DbConnectionInternal ReplaceConnection( oldConnection.ObjectID); } - SqlClientDiagnostics.Metrics.SoftConnectRequest(); + Metrics.SoftConnectRequest(); SqlClientEventSource.Log.TryPoolerTraceEvent( " {0}, connection replaced successfully.", Id); @@ -527,7 +535,7 @@ public DbConnectionInternal ReplaceConnection( /// public void ReturnInternalConnection(DbConnectionInternal connection, DbConnection owningObject) { - SqlClientDiagnostics.Metrics.SoftDisconnectRequest(); + Metrics.SoftDisconnectRequest(); ValidateOwnershipAndSetPoolingState(connection, owningObject); @@ -1152,7 +1160,7 @@ _connectionCreationRateLimiter is not null && Id, connection.ObjectID); - SqlClientDiagnostics.Metrics.EnterPooledConnection(); + Metrics.EnterPooledConnection(); // A new connection was added to the pool. If we've grown past MinPoolSize, // start the pruning timer so idle connections can be reclaimed. @@ -1323,7 +1331,7 @@ private void RemoveConnection(DbConnectionInternal connection) Id, connection.ObjectID); - SqlClientDiagnostics.Metrics.ExitPooledConnection(); + Metrics.ExitPooledConnection(); } // Removing a connection from the pool opens a free slot. @@ -1332,7 +1340,7 @@ private void RemoveConnection(DbConnectionInternal connection) _idleChannel.TryWrite(null); connection.Dispose(); - SqlClientDiagnostics.Metrics.HardDisconnectRequest(); + Metrics.HardDisconnectRequest(); SqlClientEventSource.Log.TryPoolerTraceEvent( " {0}, Connection {1}, Disposed.", @@ -1496,7 +1504,7 @@ private async Task GetInternalConnection( } PrepareConnection(owningConnection, connection, transaction); - SqlClientDiagnostics.Metrics.SoftConnectRequest(); + Metrics.SoftConnectRequest(); return connection; } @@ -1584,7 +1592,7 @@ private void PrepareConnection(DbConnection owningObject, DbConnectionInternal c transaction.GetHashCode(), connection.ObjectID); - SqlClientDiagnostics.Metrics.ExitFreeConnection(); + Metrics.ExitFreeConnection(); // Transacting connections are exempt from idle-timeout and clear-generation eviction // (closing them would abort the transaction, which may be distributed), so only diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/IDbConnectionPool.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/IDbConnectionPool.cs index 3799cf54ea..5fbcb5f897 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/IDbConnectionPool.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/IDbConnectionPool.cs @@ -8,6 +8,7 @@ using System.Threading.Tasks; using System.Transactions; using Microsoft.Data.ProviderBase; +using Microsoft.Data.SqlClient.Diagnostics; #nullable enable @@ -31,6 +32,16 @@ internal interface IDbConnectionPool /// SqlConnectionFactory ConnectionFactory { get; } + /// + /// Gets the metrics sink that the pool and the objects it owns report to. + /// + /// + /// In production this is the process-wide + /// instance. Making it a pool property lets a test give a pool its own counters so + /// assertions are not perturbed by unrelated connection activity elsewhere in the process. + /// + SqlClientMetrics Metrics { get; } + /// /// The number of connections currently managed by the pool. /// May be larger than the number of connections currently sitting idle in the pool. diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/IdleConnectionChannel.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/IdleConnectionChannel.cs index e263ae77b7..405da18c79 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/IdleConnectionChannel.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/IdleConnectionChannel.cs @@ -5,6 +5,7 @@ using System.Threading.Tasks; using System.Threading.Channels; using Microsoft.Data.ProviderBase; +using Microsoft.Data.SqlClient.Diagnostics; #nullable enable @@ -20,13 +21,19 @@ internal sealed class IdleConnectionChannel { private readonly ChannelReader _reader; private readonly ChannelWriter _writer; + private readonly SqlClientMetrics _metrics; private volatile int _count; - internal IdleConnectionChannel() + /// + /// The metrics sink of the pool that owns this channel. Defaults to the process-wide + /// instance so tests can construct a channel without a pool. + /// + internal IdleConnectionChannel(SqlClientMetrics? metrics = null) { var channel = Channel.CreateUnbounded(); _reader = channel.Reader; _writer = channel.Writer; + _metrics = metrics ?? SqlClientDiagnostics.Metrics; } /// @@ -56,7 +63,7 @@ internal bool TryWrite(DbConnectionInternal? connection) if (connection is not null) { Interlocked.Increment(ref _count); - SqlClientDiagnostics.Metrics.EnterFreeConnection(); + _metrics.EnterFreeConnection(); } return true; } @@ -75,7 +82,7 @@ internal bool TryRead(out DbConnectionInternal? connection) if (connection is not null) { Interlocked.Decrement(ref _count); - SqlClientDiagnostics.Metrics.ExitFreeConnection(); + _metrics.ExitFreeConnection(); } return true; @@ -95,7 +102,7 @@ internal bool TryRead(out DbConnectionInternal? connection) if (connection is not null) { Interlocked.Decrement(ref _count); - SqlClientDiagnostics.Metrics.ExitFreeConnection(); + _metrics.ExitFreeConnection(); } return connection; diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/TransactedConnectionPool.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/TransactedConnectionPool.cs index 3ce203c071..2183bbb86d 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/TransactedConnectionPool.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/TransactedConnectionPool.cs @@ -263,7 +263,7 @@ internal void PutTransactedObject(Transaction transaction, DbConnectionInternal SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Transaction {1}, Connection {2}, Added.", Id, transaction.GetHashCode(), transactedObject.ObjectID); } - SqlClientDiagnostics.Metrics.EnterFreeConnection(); + Pool.Metrics.EnterFreeConnection(); } /// @@ -344,7 +344,7 @@ internal void TransactionEnded(Transaction transaction, DbConnectionInternal tra // TODO: can we give this responsibility to the main pool? // The bi-directional dependency between the main pool and this pool // is messy and hard to understand. - SqlClientDiagnostics.Metrics.ExitFreeConnection(); + Pool.Metrics.ExitFreeConnection(); Pool.PutObjectFromTransactedPool(transactedObject); } } 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 00ddb01c26..721c06f1f0 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 @@ -14,6 +14,7 @@ using System.Transactions; using Microsoft.Data.Common; using Microsoft.Data.ProviderBase; +using Microsoft.Data.SqlClient.Diagnostics; using static Microsoft.Data.SqlClient.ConnectionPool.DbConnectionPoolState; using Microsoft.Data.SqlClient.Internal; @@ -208,7 +209,8 @@ internal WaitHandleDbConnectionPool( DbConnectionPoolGroup connectionPoolGroup, DbConnectionPoolIdentity identity, DbConnectionPoolProviderInfo connectionPoolProviderInfo, - TimeProvider timeProvider = null) + TimeProvider timeProvider = null, + SqlClientMetrics metrics = null) { Debug.Assert(connectionPoolGroup != null, "null connectionPoolGroup"); @@ -241,6 +243,9 @@ internal WaitHandleDbConnectionPool( } _connectionFactory = connectionFactory; + // metrics is injected only by tests, so a pool's counters can be asserted without + // interference from unrelated connection activity elsewhere in the process. + Metrics = metrics ?? SqlClientDiagnostics.Metrics; _connectionPoolGroup = connectionPoolGroup; _connectionPoolGroupOptions = connectionPoolGroup.PoolGroupOptions; _connectionPoolProviderInfo = connectionPoolProviderInfo; @@ -286,6 +291,9 @@ private int CreationTimeout public SqlConnectionFactory ConnectionFactory => _connectionFactory; + /// + public SqlClientMetrics Metrics { get; } + public bool ErrorOccurred => _errorState.HasError; private bool HasTransactionAffinity => PoolGroupOptions.HasTransactionAffinity; @@ -402,7 +410,7 @@ internal void CleanupCallback(object state) // If we obtained one from the old stack, destroy it. - SqlClientDiagnostics.Metrics.ExitFreeConnection(); + Metrics.ExitFreeConnection(); // Transaction roots must survive even aging out (TxEnd event will clean them up). bool shouldDestroy = true; @@ -502,14 +510,14 @@ public void Clear() { Debug.Assert(obj != null, "null connection is not expected"); - SqlClientDiagnostics.Metrics.ExitFreeConnection(); + Metrics.ExitFreeConnection(); DestroyObject(obj); } while (_stackOld.TryPop(out obj)) { Debug.Assert(obj != null, "null connection is not expected"); - SqlClientDiagnostics.Metrics.ExitFreeConnection(); + Metrics.ExitFreeConnection(); DestroyObject(obj); } @@ -546,7 +554,7 @@ private DbConnectionInternal CreateObject(DbConnection owningObject, DbConnectio _objectList.Add(newObj); _totalObjects = _objectList.Count; - SqlClientDiagnostics.Metrics.EnterPooledConnection(); + Metrics.EnterPooledConnection(); } SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Connection {1}, Added to pool.", Id, newObj?.ObjectID); @@ -738,12 +746,12 @@ private void DestroyObject(DbConnectionInternal obj) { SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Connection {1}, Removed from pool.", Id, obj.ObjectID); - SqlClientDiagnostics.Metrics.ExitPooledConnection(); + Metrics.ExitPooledConnection(); } obj.Dispose(); SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Connection {1}, Disposed.", Id, obj.ObjectID); - SqlClientDiagnostics.Metrics.HardDisconnectRequest(); + Metrics.HardDisconnectRequest(); } } @@ -1143,7 +1151,7 @@ private bool TryGetConnection(DbConnection owningObject, uint waitForMultipleObj connection = obj; - SqlClientDiagnostics.Metrics.SoftConnectRequest(); + Metrics.SoftConnectRequest(); return true; } @@ -1181,7 +1189,7 @@ public DbConnectionInternal ReplaceConnection(DbConnection owningObject, DbConne if (newConnection != null) { - SqlClientDiagnostics.Metrics.SoftConnectRequest(); + Metrics.SoftConnectRequest(); PrepareConnection(owningObject, newConnection, oldConnection.EnlistedTransaction); oldConnection.DeactivateConnection(); oldConnection.Dispose(); @@ -1219,7 +1227,7 @@ private DbConnectionInternal GetFromGeneralPool() { SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Connection {1}, Popped from general pool.", Id, obj.ObjectID); - SqlClientDiagnostics.Metrics.ExitFreeConnection(); + Metrics.ExitFreeConnection(); } return obj; } @@ -1237,7 +1245,7 @@ private DbConnectionInternal GetFromTransactedPool(out Transaction transaction) { SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Connection {1}, Popped from transacted pool.", Id, obj.ObjectID); - SqlClientDiagnostics.Metrics.ExitFreeConnection(); + Metrics.ExitFreeConnection(); if (obj.IsTransactionRoot) { @@ -1389,7 +1397,7 @@ private void PutNewObject(DbConnectionInternal obj) _stackNew.Push(obj); _waitHandles.PoolSemaphore.Release(1); - SqlClientDiagnostics.Metrics.EnterFreeConnection(); + Metrics.EnterFreeConnection(); } @@ -1414,7 +1422,7 @@ public void ReturnInternalConnection(DbConnectionInternal obj, DbConnection owni { Debug.Assert(obj != null, "null obj?"); - SqlClientDiagnostics.Metrics.SoftDisconnectRequest(); + Metrics.SoftDisconnectRequest(); // Once a connection is closing (which is the state that we're in at // this point in time) you cannot delegate a transaction to or enlist @@ -1531,7 +1539,7 @@ private bool ReclaimEmancipatedObjects() DbConnectionInternal obj = reclaimedObjects[i]; SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Connection {1}, Reclaiming.", Id, obj.ObjectID); - SqlClientDiagnostics.Metrics.ReclaimedConnectionRequest(); + Metrics.ReclaimedConnectionRequest(); emancipatedObjectFound = true; diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Diagnostics/SqlClientMetrics.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Diagnostics/SqlClientMetrics.cs index cb8c224440..77305ecd04 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Diagnostics/SqlClientMetrics.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Diagnostics/SqlClientMetrics.cs @@ -107,6 +107,21 @@ public SqlClientMetrics(SqlClientEventSource eventSource, bool enableMetrics) #endif } +#if NET + /// + /// Creates a metrics instance that is not published as EventCounters and is therefore + /// isolated from the process-wide instance. + /// + /// + /// Intended for tests, which give a component its own counters so that assertions are not + /// perturbed by unrelated connection activity elsewhere in the process. Counter increments + /// operate on plain fields and do not depend on the counters being enabled, so a disabled + /// instance still records every value a test needs to observe. + /// + internal static SqlClientMetrics CreateIsolated() + => new(SqlClientEventSource.Log, enableMetrics: false); +#endif + #if NET private static void IncrementPlatformSpecificCounter(ref long counter) => Interlocked.Increment(ref counter); diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlConnectionFactory.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlConnectionFactory.cs index db7c6302c7..6d2127d281 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlConnectionFactory.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlConnectionFactory.cs @@ -208,7 +208,7 @@ internal DbConnectionInternal CreatePooledConnection( throw ADP.InternalError(ADP.InternalErrorCode.NewObjectCannotBePooled); // CreateObject succeeded, but non-poolable object } - SqlClientDiagnostics.Metrics.HardConnectRequest(); + pool.Metrics.HardConnectRequest(); newConnection.MakePooledConnection(pool); SqlClientEventSource.Log.TryTraceEvent(" {0}, Pooled database connection created.", ObjectId); diff --git a/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/ChannelDbConnectionPoolInstrumentationTest.cs b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/ChannelDbConnectionPoolInstrumentationTest.cs index ef996bf952..d4085412ba 100644 --- a/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/ChannelDbConnectionPoolInstrumentationTest.cs +++ b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/ChannelDbConnectionPoolInstrumentationTest.cs @@ -303,12 +303,14 @@ public void Prune_EmitsTracePerInvocation() #if NET #region Metric parity - // The metric counters are process-wide and other suites run in parallel, so these tests - // assert that a counter advanced by at least the expected amount rather than by exactly it. - // The rate counters only ever increase, which makes that assertion stable under concurrency. + // Each test gives its pool its own metrics instance, so the counters observe only that + // pool's activity and can be asserted exactly. They run against both pool implementations + // so that any divergence in what the channel pool emits shows up as a failing test rather + // than as a silent telemetry gap. // - // These run against both pool implementations so that any divergence in the counters the - // channel pool emits shows up as a failing test rather than as a silent telemetry gap. + // Counters emitted outside the pool are still process-wide: DbConnectionInternal reports + // active-connection and stasis counts against the global instance, so those are not + // asserted here. /// /// Identifies which pool implementation a parameterized metric test exercises. @@ -323,10 +325,12 @@ public enum PoolImplementation } /// - /// Builds the requested pool implementation behind the shared pool interface. + /// Builds the requested pool implementation behind the shared pool interface, reporting to + /// the supplied metrics instance. /// private static IDbConnectionPool ConstructPool( PoolImplementation implementation, + SqlClientMetrics metrics, SqlConnectionFactory connectionFactory, string connectionString = "Data Source=localhost;", int maxPoolSize = 50, @@ -341,44 +345,99 @@ private static IDbConnectionPool ConstructPool( connectionFactory, poolGroup, DbConnectionPoolIdentity.NoIdentity, - new DbConnectionPoolProviderInfo()), + new DbConnectionPoolProviderInfo(), + timeProvider: null, + metrics: metrics), PoolImplementation.Channel => new ChannelDbConnectionPool( connectionFactory, poolGroup, DbConnectionPoolIdentity.NoIdentity, - new DbConnectionPoolProviderInfo()), + new DbConnectionPoolProviderInfo(), + connectionCreationRateLimiter: null, + timeProvider: null, + metrics: metrics), _ => throw new ArgumentOutOfRangeException(nameof(implementation)), }; } /// - /// Verifies that creating a physical connection counts a hard connect, covering Story 2 - /// scenario 1. + /// Asserts the exact value of every counter a pool is responsible for. Any counter not named + /// by the caller is expected to be zero, so an unexpected emission fails the test. + /// + /// + /// The active-connection gauges are not parameters because they are mechanically derived: + /// each connect increments one and the matching disconnect decrements it. + /// + private static void AssertCounters( + SqlClientMetrics metrics, + long hardConnects = 0, + long hardDisconnects = 0, + long softConnects = 0, + long softDisconnects = 0, + long pooledConnections = 0, + long freeConnections = 0, + long reclaimedConnections = 0) + { + Dictionary expected = new() + { + ["_hardConnectsRate"] = hardConnects, + ["_hardDisconnectsRate"] = hardDisconnects, + ["_activeHardConnections"] = hardConnects - hardDisconnects, + ["_softConnectsRate"] = softConnects, + ["_softDisconnectsRate"] = softDisconnects, + ["_activeSoftConnections"] = softConnects - softDisconnects, + ["_pooledConnections"] = pooledConnections, + ["_freeConnections"] = freeConnections, + ["_reclaimedConnections"] = reclaimedConnections, + }; + + // Reported as a single message listing only the counters that differ. Comparing the + // dictionaries directly would be truncated by the assertion formatter, which hides the + // one counter the test is about. + List mismatches = new(); + foreach (KeyValuePair counter in expected) + { + long actual = MetricReader.Read(metrics, counter.Key); + if (actual != counter.Value) + { + mismatches.Add($"{counter.Key}: expected {counter.Value}, actual {actual}"); + } + } + + Assert.True(mismatches.Count == 0, string.Join(Environment.NewLine, mismatches)); + } + + /// + /// Verifies the counters emitted when the pool creates a physical connection to satisfy a + /// request, covering Story 2 scenario 1. /// [Theory] [InlineData(PoolImplementation.WaitHandle)] [InlineData(PoolImplementation.Channel)] - public void NewConnection_CountsHardConnect(PoolImplementation implementation) + public void NewConnection_CountsHardConnectAndPooledConnection(PoolImplementation implementation) { // Arrange - IDbConnectionPool pool = ConstructPool(implementation, new SuccessfulSqlConnectionFactory()); + SqlClientMetrics metrics = SqlClientMetrics.CreateIsolated(); + IDbConnectionPool pool = ConstructPool(implementation, metrics, new SuccessfulSqlConnectionFactory()); SqlConnection owner = new(); - long before = MetricReader.Read("_hardConnectsRate"); - // Act Assert.True(pool.TryGetConnection(owner, null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out DbConnectionInternal? connection)); - // Assert + // Assert - the connection was handed straight to the caller, so it never became free. Assert.NotNull(connection); - Assert.True(MetricReader.Read("_hardConnectsRate") >= before + 1); + AssertCounters( + metrics, + hardConnects: 1, + softConnects: 1, + pooledConnections: 1); } /// - /// Verifies that retrieving an idle connection counts a soft connect, covering Story 2 - /// scenario 3. + /// Verifies the counters emitted when a request is satisfied from the idle pool rather than + /// by creating a connection, covering Story 2 scenario 3. /// [Theory] [InlineData(PoolImplementation.WaitHandle)] @@ -386,24 +445,28 @@ public void NewConnection_CountsHardConnect(PoolImplementation implementation) public void IdleConnectionReuse_CountsSoftConnect(PoolImplementation implementation) { // Arrange - IDbConnectionPool pool = ConstructPool(implementation, new SuccessfulSqlConnectionFactory()); + SqlClientMetrics metrics = SqlClientMetrics.CreateIsolated(); + IDbConnectionPool pool = ConstructPool(implementation, metrics, new SuccessfulSqlConnectionFactory()); SqlConnection owner = new(); Assert.True(pool.TryGetConnection(owner, null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out DbConnectionInternal? connection)); Assert.NotNull(connection); pool.ReturnInternalConnection(connection!, owner); - long before = MetricReader.Read("_softConnectsRate"); - // Act Assert.True(pool.TryGetConnection(new SqlConnection(), null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out DbConnectionInternal? reused)); - // Assert + // Assert - the second request was served without a second physical connect. Assert.Same(connection, reused); - Assert.True(MetricReader.Read("_softConnectsRate") >= before + 1); + AssertCounters( + metrics, + hardConnects: 1, + softConnects: 2, + softDisconnects: 1, + pooledConnections: 1); } /// - /// Verifies that returning a connection to the idle pool counts a soft disconnect, covering + /// Verifies the counters emitted when a connection is returned to the idle pool, covering /// Story 2 scenario 4. /// [Theory] @@ -412,22 +475,27 @@ public void IdleConnectionReuse_CountsSoftConnect(PoolImplementation implementat public void Return_CountsSoftDisconnect(PoolImplementation implementation) { // Arrange - IDbConnectionPool pool = ConstructPool(implementation, new SuccessfulSqlConnectionFactory()); + SqlClientMetrics metrics = SqlClientMetrics.CreateIsolated(); + IDbConnectionPool pool = ConstructPool(implementation, metrics, new SuccessfulSqlConnectionFactory()); SqlConnection owner = new(); Assert.True(pool.TryGetConnection(owner, null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out DbConnectionInternal? connection)); Assert.NotNull(connection); - long before = MetricReader.Read("_softDisconnectsRate"); - // Act pool.ReturnInternalConnection(connection!, owner); - // Assert - Assert.True(MetricReader.Read("_softDisconnectsRate") >= before + 1); + // Assert - the connection is still pooled, and is now also free. + AssertCounters( + metrics, + hardConnects: 1, + softConnects: 1, + softDisconnects: 1, + pooledConnections: 1, + freeConnections: 1); } /// - /// Verifies that destroying a physical connection counts a hard disconnect, covering Story 2 + /// Verifies the counters emitted when a physical connection is destroyed, covering Story 2 /// scenario 2. /// [Theory] @@ -436,25 +504,29 @@ public void Return_CountsSoftDisconnect(PoolImplementation implementation) public void Destroy_CountsHardDisconnect(PoolImplementation implementation) { // Arrange - IDbConnectionPool pool = ConstructPool(implementation, new SuccessfulSqlConnectionFactory()); + SqlClientMetrics metrics = SqlClientMetrics.CreateIsolated(); + IDbConnectionPool pool = ConstructPool(implementation, metrics, new SuccessfulSqlConnectionFactory()); SqlConnection owner = new(); Assert.True(pool.TryGetConnection(owner, null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out DbConnectionInternal? connection)); Assert.NotNull(connection); pool.ReturnInternalConnection(connection!, owner); - long before = MetricReader.Read("_hardDisconnectsRate"); - // Act pool.Clear(); - // Assert - Assert.True(MetricReader.Read("_hardDisconnectsRate") >= before + 1); + // Assert - every gauge the connection contributed to is back to zero. + AssertCounters( + metrics, + hardConnects: 1, + hardDisconnects: 1, + softConnects: 1, + softDisconnects: 1); } /// - /// Verifies that replacing a connection counts a hard disconnect for the connection it - /// discards. The channel pool swaps the new connection into the old connection's slot, so - /// the pooled-connection gauge is deliberately left untouched. + /// Verifies the counters emitted when a checked-out connection is replaced. The channel pool + /// swaps the new connection into the old connection's slot, so the pooled-connection gauge + /// is deliberately left untouched. /// /// /// This is not parameterized over the wait handle pool: that implementation disposes the @@ -465,21 +537,24 @@ public void Destroy_CountsHardDisconnect(PoolImplementation implementation) public void ReplaceConnection_CountsHardDisconnectForDiscardedConnection() { // Arrange - ChannelDbConnectionPool pool = ConstructPool(new SuccessfulSqlConnectionFactory()); + SqlClientMetrics metrics = SqlClientMetrics.CreateIsolated(); + IDbConnectionPool pool = ConstructPool(PoolImplementation.Channel, metrics, new SuccessfulSqlConnectionFactory()); SqlConnection owner = new(); Assert.True(pool.TryGetConnection(owner, null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out DbConnectionInternal? oldConnection)); Assert.NotNull(oldConnection); - long beforeDisconnects = MetricReader.Read("_hardDisconnectsRate"); - long beforePooled = MetricReader.Read("_pooledConnections"); - // Act DbConnectionInternal newConnection = pool.ReplaceConnection(owner, oldConnection!, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15))); - // Assert + // Assert - two physical connections were opened and one was retired, leaving the pooled + // count unchanged because the replacement inherited the slot. Assert.NotSame(oldConnection, newConnection); - Assert.True(MetricReader.Read("_hardDisconnectsRate") >= beforeDisconnects + 1); - Assert.Equal(beforePooled, MetricReader.Read("_pooledConnections")); + AssertCounters( + metrics, + hardConnects: 2, + hardDisconnects: 1, + softConnects: 2, + pooledConnections: 1); } #endregion @@ -590,21 +665,22 @@ internal IReadOnlyList MessagesForPool(int poolId) #if NET /// - /// Reads the private counter fields of the process-wide instance. - /// The counters are not otherwise observable without an EventCounter listener and its polling - /// interval, which would make these tests slow and timing dependent. + /// Reads the private counter fields of a instance. The counters + /// are not otherwise observable without an EventCounter listener and its polling interval, + /// which would make these tests slow and timing dependent. /// internal static class MetricReader { /// /// Reads the current value of the named counter field. /// + /// The metrics instance to read from. /// Private field name declared on . - internal static long Read(string fieldName) + internal static long Read(SqlClientMetrics metrics, string fieldName) { FieldInfo? field = typeof(SqlClientMetrics).GetField(fieldName, BindingFlags.Instance | BindingFlags.NonPublic); Assert.NotNull(field); - return (long)field!.GetValue(SqlClientDiagnostics.Metrics)!; + return (long)field!.GetValue(metrics)!; } } #endif diff --git a/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/TransactedConnectionPoolTest.cs b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/TransactedConnectionPoolTest.cs index 588418ac03..4b9d987dc6 100644 --- a/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/TransactedConnectionPoolTest.cs +++ b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/TransactedConnectionPoolTest.cs @@ -6,6 +6,7 @@ using System.Threading.Tasks; using Microsoft.Data.SqlClient.ConnectionPool; using Microsoft.Data.ProviderBase; +using Microsoft.Data.SqlClient.Diagnostics; using Xunit; using System.Data; using System.Data.Common; @@ -658,6 +659,9 @@ internal class MockDbConnectionPool : IDbConnectionPool { public ConcurrentDictionary AuthenticationContexts { get; } = new(); public SqlConnectionFactory ConnectionFactory => throw new NotImplementedException(); + // TransactedConnectionPool reports free-connection counts through its owning pool, so this + // has to be a real sink rather than a throwing stub. + public SqlClientMetrics Metrics => SqlClientDiagnostics.Metrics; public int Count => throw new NotImplementedException(); public bool ErrorOccurred => throw new NotImplementedException(); public int Id { get; } = 1; From 787823b918a73af1588069c39d84251652610341 Mon Sep 17 00:00:00 2001 From: Malcolm Daigle Date: Wed, 12 Aug 2026 16:40:10 -0700 Subject: [PATCH 04/19] Define the pool metrics seam as an interface The metric parity tests were gated to .NET because they read the counter fields reflectively, and those fields are performance counters rather than longs on .NET Framework. Give SqlClientMetrics an interface and let the tests supply a recording implementation, so the tests run on every target framework and the set of counters cannot drift between the two. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- .../ConnectionPool/ChannelDbConnectionPool.cs | 6 +- .../ConnectionPool/IDbConnectionPool.cs | 2 +- .../ConnectionPool/IdleConnectionChannel.cs | 4 +- .../TransactedConnectionPool.cs | 10 +- .../WaitHandleDbConnectionPool.cs | 6 +- .../Diagnostics/ISqlClientMetrics.cs | 135 +++++++++++++++ .../SqlClient/Diagnostics/SqlClientMetrics.cs | 155 ++++++------------ .../Data/SqlClient/SqlConnectionFactory.cs | 25 ++- ...nnelDbConnectionPoolInstrumentationTest.cs | 92 +++++------ .../ChannelDbConnectionPoolTest.cs | 15 ++ .../ConnectionPool/FakeSqlClientMetrics.cs | 132 +++++++++++++++ .../TransactedConnectionPoolTest.cs | 63 ++++--- 12 files changed, 440 insertions(+), 205 deletions(-) create mode 100644 src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Diagnostics/ISqlClientMetrics.cs create mode 100644 src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/FakeSqlClientMetrics.cs 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 cabdc7f782..7adeefc947 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 @@ -165,7 +165,7 @@ internal ChannelDbConnectionPool( DbConnectionPoolProviderInfo connectionPoolProviderInfo, ConcurrencyLimiter? connectionCreationRateLimiter = null, TimeProvider? timeProvider = null, - SqlClientMetrics? metrics = null) + ISqlClientMetrics? metrics = null) { ConnectionFactory = connectionFactory; // metrics is injected only by tests, so a pool's counters can be asserted without @@ -177,7 +177,7 @@ internal ChannelDbConnectionPool( Identity = identity; AuthenticationContexts = new(); MaxPoolSize = Convert.ToUInt32(PoolGroupOptions.MaxPoolSize); - TransactedConnectionPool = new(this); + TransactedConnectionPool = new(this, Metrics); _connectionCreationRateLimiter = connectionCreationRateLimiter; // timeProvider is injected only by tests so idle-timeout expiry and the blocking-period // exit timer can be driven deterministically; in production it is null and falls back to @@ -220,7 +220,7 @@ public ConcurrentDictionary< public SqlConnectionFactory ConnectionFactory { get; } /// - public SqlClientMetrics Metrics { get; } + public ISqlClientMetrics Metrics { get; } /// /// diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/IDbConnectionPool.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/IDbConnectionPool.cs index 5fbcb5f897..665d7b5038 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/IDbConnectionPool.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/IDbConnectionPool.cs @@ -40,7 +40,7 @@ internal interface IDbConnectionPool /// instance. Making it a pool property lets a test give a pool its own counters so /// assertions are not perturbed by unrelated connection activity elsewhere in the process. /// - SqlClientMetrics Metrics { get; } + ISqlClientMetrics Metrics { get; } /// /// The number of connections currently managed by the pool. diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/IdleConnectionChannel.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/IdleConnectionChannel.cs index 405da18c79..801c0e7c2f 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/IdleConnectionChannel.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/IdleConnectionChannel.cs @@ -21,14 +21,14 @@ internal sealed class IdleConnectionChannel { private readonly ChannelReader _reader; private readonly ChannelWriter _writer; - private readonly SqlClientMetrics _metrics; + private readonly ISqlClientMetrics _metrics; private volatile int _count; /// /// The metrics sink of the pool that owns this channel. Defaults to the process-wide /// instance so tests can construct a channel without a pool. /// - internal IdleConnectionChannel(SqlClientMetrics? metrics = null) + internal IdleConnectionChannel(ISqlClientMetrics? metrics = null) { var channel = Channel.CreateUnbounded(); _reader = channel.Reader; diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/TransactedConnectionPool.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/TransactedConnectionPool.cs index 2183bbb86d..32e6865efb 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/TransactedConnectionPool.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/TransactedConnectionPool.cs @@ -6,6 +6,7 @@ using System.Diagnostics; using System.Transactions; using Microsoft.Data.ProviderBase; +using Microsoft.Data.SqlClient.Diagnostics; using Microsoft.Data.SqlClient.Internal; #nullable enable @@ -62,6 +63,7 @@ internal void Dispose() #region Fields private static int _objectTypeCount; internal readonly int _objectID = System.Threading.Interlocked.Increment(ref _objectTypeCount); + private readonly ISqlClientMetrics _metrics; #endregion @@ -69,14 +71,16 @@ internal void Dispose() /// Initializes a new instance of the TransactedConnectionPool class for the specified connection pool. /// /// The main connection pool that this transacted pool is associated with. + /// The metrics instance to report counters to. /// /// The transacted connection pool works as a companion to the main connection pool, /// temporarily holding connections that are enlisted in transactions until those /// transactions complete. /// - internal TransactedConnectionPool(IDbConnectionPool pool) + internal TransactedConnectionPool(IDbConnectionPool pool, ISqlClientMetrics metrics) { Pool = pool; + _metrics = metrics; TransactedConnections = new Dictionary(); SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Constructed for connection pool {1}", Id, Pool.Id); } @@ -263,7 +267,7 @@ internal void PutTransactedObject(Transaction transaction, DbConnectionInternal SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Transaction {1}, Connection {2}, Added.", Id, transaction.GetHashCode(), transactedObject.ObjectID); } - Pool.Metrics.EnterFreeConnection(); + _metrics.EnterFreeConnection(); } /// @@ -344,7 +348,7 @@ internal void TransactionEnded(Transaction transaction, DbConnectionInternal tra // TODO: can we give this responsibility to the main pool? // The bi-directional dependency between the main pool and this pool // is messy and hard to understand. - Pool.Metrics.ExitFreeConnection(); + _metrics.ExitFreeConnection(); Pool.PutObjectFromTransactedPool(transactedObject); } } 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 721c06f1f0..311663721b 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 @@ -210,7 +210,7 @@ internal WaitHandleDbConnectionPool( DbConnectionPoolIdentity identity, DbConnectionPoolProviderInfo connectionPoolProviderInfo, TimeProvider timeProvider = null, - SqlClientMetrics metrics = null) + ISqlClientMetrics metrics = null) { Debug.Assert(connectionPoolGroup != null, "null connectionPoolGroup"); @@ -268,7 +268,7 @@ internal WaitHandleDbConnectionPool( _pooledDbAuthenticationContexts = new ConcurrentDictionary(concurrencyLevel: 4 * Environment.ProcessorCount /* default value in ConcurrentDictionary*/, capacity: 2); - _transactedConnectionPool = new TransactedConnectionPool(this); + _transactedConnectionPool = new TransactedConnectionPool(this, Metrics); _poolCreateRequest = new WaitCallback(PoolCreateRequest); // used by CleanupCallback State = Running; @@ -292,7 +292,7 @@ private int CreationTimeout public SqlConnectionFactory ConnectionFactory => _connectionFactory; /// - public SqlClientMetrics Metrics { get; } + public ISqlClientMetrics Metrics { get; } public bool ErrorOccurred => _errorState.HasError; diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Diagnostics/ISqlClientMetrics.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Diagnostics/ISqlClientMetrics.cs new file mode 100644 index 0000000000..c74e60dfab --- /dev/null +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Diagnostics/ISqlClientMetrics.cs @@ -0,0 +1,135 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +namespace Microsoft.Data.SqlClient.Diagnostics +{ + /// + /// The connection pool counters, as reported by . + /// + /// + /// Components that report counters depend on this rather than on + /// so that tests can substitute a recording implementation. The production counters are not + /// usable for assertions: on .NET they are only observable through an EventCounter listener, + /// whose polling interval would make such tests slow and timing dependent, and on .NET + /// Framework they are performance counters whose instance name is derived from the assembly + /// name and process id, so every instance in the process shares one counter. + /// + internal interface ISqlClientMetrics + { + /// + /// The number of actual connections that are being made to servers + /// + void HardConnectRequest(); + + /// + /// The number of actual disconnects that are being made to servers + /// + void HardDisconnectRequest(); + + /// + /// The number of connections we get from the pool + /// + void SoftConnectRequest(); + + /// + /// The number of connections we return to the pool + /// + void SoftDisconnectRequest(); + + /// + /// The number of connections that are not using connection pooling + /// + void EnterNonPooledConnection(); + + /// + /// The number of connections that are not using connection pooling + /// + void ExitNonPooledConnection(); + + /// + /// The number of connections that are managed by the connection pool + /// + void EnterPooledConnection(); + + /// + /// The number of connections that are managed by the connection pool + /// + void ExitPooledConnection(); + + /// + /// The number of unique connection strings + /// + void EnterActiveConnectionPoolGroup(); + + /// + /// The number of unique connection strings + /// + void ExitActiveConnectionPoolGroup(); + + /// + /// The number of unique connection strings waiting for pruning + /// + void EnterInactiveConnectionPoolGroup(); + + /// + /// The number of unique connection strings waiting for pruning + /// + void ExitInactiveConnectionPoolGroup(); + + /// + /// The number of connection pools + /// + void EnterActiveConnectionPool(); + + /// + /// The number of connection pools + /// + void ExitActiveConnectionPool(); + + /// + /// The number of connection pools + /// + void EnterInactiveConnectionPool(); + + /// + /// The number of connection pools + /// + void ExitInactiveConnectionPool(); + + /// + /// The number of connections currently in-use + /// + void EnterActiveConnection(); + + /// + /// The number of connections currently in-use + /// + void ExitActiveConnection(); + + /// + /// The number of connections currently available for use + /// + void EnterFreeConnection(); + + /// + /// The number of connections currently available for use + /// + void ExitFreeConnection(); + + /// + /// The number of connections currently waiting to be made ready for use + /// + void EnterStasisConnection(); + + /// + /// The number of connections currently waiting to be made ready for use + /// + void ExitStasisConnection(); + + /// + /// The number of connections we reclaim from GC'd external connections + /// + void ReclaimedConnectionRequest(); + } +} diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Diagnostics/SqlClientMetrics.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Diagnostics/SqlClientMetrics.cs index 77305ecd04..e1eb814bbd 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Diagnostics/SqlClientMetrics.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/Diagnostics/SqlClientMetrics.cs @@ -24,7 +24,7 @@ namespace Microsoft.Data.SqlClient.Diagnostics #if NETFRAMEWORK [PermissionSet(SecurityAction.LinkDemand, Name = "FullTrust")] #endif - internal sealed partial class SqlClientMetrics + internal sealed partial class SqlClientMetrics : ISqlClientMetrics { #if NETFRAMEWORK private const string PerformanceCounterCategoryName = ".NET Data Provider for SqlServer"; @@ -107,21 +107,6 @@ public SqlClientMetrics(SqlClientEventSource eventSource, bool enableMetrics) #endif } -#if NET - /// - /// Creates a metrics instance that is not published as EventCounters and is therefore - /// isolated from the process-wide instance. - /// - /// - /// Intended for tests, which give a component its own counters so that assertions are not - /// perturbed by unrelated connection activity elsewhere in the process. Counter increments - /// operate on plain fields and do not depend on the counters being enabled, so a disabled - /// instance still records every value a test needs to observe. - /// - internal static SqlClientMetrics CreateIsolated() - => new(SqlClientEventSource.Log, enableMetrics: false); -#endif - #if NET private static void IncrementPlatformSpecificCounter(ref long counter) => Interlocked.Increment(ref counter); @@ -139,10 +124,8 @@ private static void DecrementPlatformSpecificCounter(ref PerformanceCounter? cou => counter?.Decrement(); #endif - /// - /// The number of actual connections that are being made to servers - /// - internal void HardConnectRequest() + /// + public void HardConnectRequest() { #if NET IncrementPlatformSpecificCounter(ref _activeHardConnections); @@ -150,10 +133,8 @@ internal void HardConnectRequest() IncrementPlatformSpecificCounter(ref _hardConnectsRate); } - /// - /// The number of actual disconnects that are being made to servers - /// - internal void HardDisconnectRequest() + /// + public void HardDisconnectRequest() { #if NET DecrementPlatformSpecificCounter(ref _activeHardConnections); @@ -161,10 +142,8 @@ internal void HardDisconnectRequest() IncrementPlatformSpecificCounter(ref _hardDisconnectsRate); } - /// - /// The number of connections we get from the pool - /// - internal void SoftConnectRequest() + /// + public void SoftConnectRequest() { #if NET IncrementPlatformSpecificCounter(ref _activeSoftConnections); @@ -172,10 +151,8 @@ internal void SoftConnectRequest() IncrementPlatformSpecificCounter(ref _softConnectsRate); } - /// - /// The number of connections we return to the pool - /// - internal void SoftDisconnectRequest() + /// + public void SoftDisconnectRequest() { #if NET DecrementPlatformSpecificCounter(ref _activeSoftConnections); @@ -183,154 +160,116 @@ internal void SoftDisconnectRequest() IncrementPlatformSpecificCounter(ref _softDisconnectsRate); } - /// - /// The number of connections that are not using connection pooling - /// - internal void EnterNonPooledConnection() + /// + public void EnterNonPooledConnection() { IncrementPlatformSpecificCounter(ref _nonPooledConnections); } - /// - /// The number of connections that are not using connection pooling - /// - internal void ExitNonPooledConnection() + /// + public void ExitNonPooledConnection() { DecrementPlatformSpecificCounter(ref _nonPooledConnections); } - /// - /// The number of connections that are managed by the connection pool - /// - internal void EnterPooledConnection() + /// + public void EnterPooledConnection() { IncrementPlatformSpecificCounter(ref _pooledConnections); } - /// - /// The number of connections that are managed by the connection pool - /// - internal void ExitPooledConnection() + /// + public void ExitPooledConnection() { DecrementPlatformSpecificCounter(ref _pooledConnections); } - /// - /// The number of unique connection strings - /// - internal void EnterActiveConnectionPoolGroup() + /// + public void EnterActiveConnectionPoolGroup() { IncrementPlatformSpecificCounter(ref _activeConnectionPoolGroups); } - /// - /// The number of unique connection strings - /// - internal void ExitActiveConnectionPoolGroup() + /// + public void ExitActiveConnectionPoolGroup() { DecrementPlatformSpecificCounter(ref _activeConnectionPoolGroups); } - /// - /// The number of unique connection strings waiting for pruning - /// - internal void EnterInactiveConnectionPoolGroup() + /// + public void EnterInactiveConnectionPoolGroup() { IncrementPlatformSpecificCounter(ref _inactiveConnectionPoolGroups); } - /// - /// The number of unique connection strings waiting for pruning - /// - internal void ExitInactiveConnectionPoolGroup() + /// + public void ExitInactiveConnectionPoolGroup() { DecrementPlatformSpecificCounter(ref _inactiveConnectionPoolGroups); } - /// - /// The number of connection pools - /// - internal void EnterActiveConnectionPool() + /// + public void EnterActiveConnectionPool() { IncrementPlatformSpecificCounter(ref _activeConnectionPools); } - /// - /// The number of connection pools - /// - internal void ExitActiveConnectionPool() + /// + public void ExitActiveConnectionPool() { DecrementPlatformSpecificCounter(ref _activeConnectionPools); } - /// - /// The number of connection pools - /// - internal void EnterInactiveConnectionPool() + /// + public void EnterInactiveConnectionPool() { IncrementPlatformSpecificCounter(ref _inactiveConnectionPools); } - /// - /// The number of connection pools - /// - internal void ExitInactiveConnectionPool() + /// + public void ExitInactiveConnectionPool() { DecrementPlatformSpecificCounter(ref _inactiveConnectionPools); } - /// - /// The number of connections currently in-use - /// - internal void EnterActiveConnection() + /// + public void EnterActiveConnection() { IncrementPlatformSpecificCounter(ref _activeConnections); } - /// - /// The number of connections currently in-use - /// - internal void ExitActiveConnection() + /// + public void ExitActiveConnection() { DecrementPlatformSpecificCounter(ref _activeConnections); } - /// - /// The number of connections currently available for use - /// - internal void EnterFreeConnection() + /// + public void EnterFreeConnection() { IncrementPlatformSpecificCounter(ref _freeConnections); } - /// - /// The number of connections currently available for use - /// - internal void ExitFreeConnection() + /// + public void ExitFreeConnection() { DecrementPlatformSpecificCounter(ref _freeConnections); } - /// - /// The number of connections currently waiting to be made ready for use - /// - internal void EnterStasisConnection() + /// + public void EnterStasisConnection() { IncrementPlatformSpecificCounter(ref _stasisConnections); } - /// - /// The number of connections currently waiting to be made ready for use - /// - internal void ExitStasisConnection() + /// + public void ExitStasisConnection() { DecrementPlatformSpecificCounter(ref _stasisConnections); } - /// - /// The number of connections we reclaim from GC'd external connections - /// - internal void ReclaimedConnectionRequest() + /// + public void ReclaimedConnectionRequest() { IncrementPlatformSpecificCounter(ref _reclaimedConnections); } diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlConnectionFactory.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlConnectionFactory.cs index 6d2127d281..086d607179 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlConnectionFactory.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlConnectionFactory.cs @@ -16,6 +16,7 @@ using Microsoft.Data.ProviderBase; using Microsoft.Data.SqlClient.Connection; using Microsoft.Data.SqlClient.ConnectionPool; +using Microsoft.Data.SqlClient.Diagnostics; using Microsoft.Data.SqlClient.Internal; #if NET @@ -64,8 +65,8 @@ internal class SqlConnectionFactory #region Constructors - protected SqlConnectionFactory() - : this(PruningDueTime, PruningPeriod) + protected SqlConnectionFactory(ISqlClientMetrics metrics = null) + : this(PruningDueTime, PruningPeriod, metrics) { } @@ -74,10 +75,21 @@ protected SqlConnectionFactory() /// otherwise have to wait minutes for the default schedule to produce an observable /// result. /// - protected SqlConnectionFactory(TimeSpan pruningDueTime, TimeSpan pruningPeriod) + /// Delay before the first pruning pass. + /// Interval between subsequent pruning passes. + /// + /// Metrics sink for counters recorded by the factory itself (e.g. hard connect requests). + /// Tests construct their own subclass, so they can pass + /// the same metrics instance used by the pool under test instead of relying on the + /// process-wide default. Defaults to in + /// production, where a single factory instance () is shared by every + /// pool. + /// + protected SqlConnectionFactory(TimeSpan pruningDueTime, TimeSpan pruningPeriod, ISqlClientMetrics metrics = null) { _pruningDueTime = pruningDueTime; _pruningPeriod = pruningPeriod; + Metrics = metrics ?? SqlClientDiagnostics.Metrics; _connectionPoolGroups = new Dictionary(); _poolsToRelease = new List(); _poolGroupsToRelease = new List(); @@ -106,6 +118,11 @@ protected SqlConnectionFactory(TimeSpan pruningDueTime, TimeSpan pruningPeriod) internal int ObjectId { get; } = Interlocked.Increment(ref s_objectTypeCount); + /// + /// The metrics sink this factory reports its own counters (e.g. hard connect requests) to. + /// + protected ISqlClientMetrics Metrics { get; } + /// /// Whether the pruning timer is currently armed. Test hook. /// @@ -208,7 +225,7 @@ internal DbConnectionInternal CreatePooledConnection( throw ADP.InternalError(ADP.InternalErrorCode.NewObjectCannotBePooled); // CreateObject succeeded, but non-poolable object } - pool.Metrics.HardConnectRequest(); + Metrics.HardConnectRequest(); newConnection.MakePooledConnection(pool); SqlClientEventSource.Log.TryTraceEvent(" {0}, Pooled database connection created.", ObjectId); diff --git a/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/ChannelDbConnectionPoolInstrumentationTest.cs b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/ChannelDbConnectionPoolInstrumentationTest.cs index d4085412ba..13fb0f4ea2 100644 --- a/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/ChannelDbConnectionPoolInstrumentationTest.cs +++ b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/ChannelDbConnectionPoolInstrumentationTest.cs @@ -9,7 +9,6 @@ using System.Diagnostics.Tracing; using System.Globalization; using System.Linq; -using System.Reflection; using System.Text.RegularExpressions; using System.Threading; using System.Threading.RateLimiting; @@ -300,7 +299,6 @@ public void Prune_EmitsTracePerInvocation() #endregion -#if NET #region Metric parity // Each test gives its pool its own metrics instance, so the counters observe only that @@ -330,7 +328,7 @@ public enum PoolImplementation /// private static IDbConnectionPool ConstructPool( PoolImplementation implementation, - SqlClientMetrics metrics, + ISqlClientMetrics metrics, SqlConnectionFactory connectionFactory, string connectionString = "Data Source=localhost;", int maxPoolSize = 50, @@ -371,7 +369,7 @@ private static IDbConnectionPool ConstructPool( /// each connect increments one and the matching disconnect decrements it. /// private static void AssertCounters( - SqlClientMetrics metrics, + FakeSqlClientMetrics metrics, long hardConnects = 0, long hardDisconnects = 0, long softConnects = 0, @@ -380,29 +378,38 @@ private static void AssertCounters( long freeConnections = 0, long reclaimedConnections = 0) { - Dictionary expected = new() + (string Name, long Expected, long Actual)[] counters = { - ["_hardConnectsRate"] = hardConnects, - ["_hardDisconnectsRate"] = hardDisconnects, - ["_activeHardConnections"] = hardConnects - hardDisconnects, - ["_softConnectsRate"] = softConnects, - ["_softDisconnectsRate"] = softDisconnects, - ["_activeSoftConnections"] = softConnects - softDisconnects, - ["_pooledConnections"] = pooledConnections, - ["_freeConnections"] = freeConnections, - ["_reclaimedConnections"] = reclaimedConnections, + ("hardConnects", hardConnects, metrics.HardConnects), + ("hardDisconnects", hardDisconnects, metrics.HardDisconnects), + ("activeHardConnections", hardConnects - hardDisconnects, metrics.ActiveHardConnections), + ("softConnects", softConnects, metrics.SoftConnects), + ("softDisconnects", softDisconnects, metrics.SoftDisconnects), + ("activeSoftConnections", softConnects - softDisconnects, metrics.ActiveSoftConnections), + ("pooledConnections", pooledConnections, metrics.PooledConnections), + ("freeConnections", freeConnections, metrics.FreeConnections), + ("reclaimedConnections", reclaimedConnections, metrics.ReclaimedConnections), + + // Not emitted through a pool's metrics instance, so any non-zero value here means a + // counter has moved to the pool that the tests have not accounted for. + ("nonPooledConnections", 0, metrics.NonPooledConnections), + ("activeConnectionPoolGroups", 0, metrics.ActiveConnectionPoolGroups), + ("inactiveConnectionPoolGroups", 0, metrics.InactiveConnectionPoolGroups), + ("activeConnectionPools", 0, metrics.ActiveConnectionPools), + ("inactiveConnectionPools", 0, metrics.InactiveConnectionPools), + ("activeConnections", 0, metrics.ActiveConnections), + ("stasisConnections", 0, metrics.StasisConnections), }; - // Reported as a single message listing only the counters that differ. Comparing the - // dictionaries directly would be truncated by the assertion formatter, which hides the - // one counter the test is about. + // Reported as a single message listing only the counters that differ. Asserting on a + // collection instead would be truncated by the assertion formatter, which hides the one + // counter the test is about. List mismatches = new(); - foreach (KeyValuePair counter in expected) + foreach ((string name, long expected, long actual) in counters) { - long actual = MetricReader.Read(metrics, counter.Key); - if (actual != counter.Value) + if (actual != expected) { - mismatches.Add($"{counter.Key}: expected {counter.Value}, actual {actual}"); + mismatches.Add($"{name}: expected {expected}, actual {actual}"); } } @@ -419,8 +426,8 @@ private static void AssertCounters( public void NewConnection_CountsHardConnectAndPooledConnection(PoolImplementation implementation) { // Arrange - SqlClientMetrics metrics = SqlClientMetrics.CreateIsolated(); - IDbConnectionPool pool = ConstructPool(implementation, metrics, new SuccessfulSqlConnectionFactory()); + FakeSqlClientMetrics metrics = new(); + IDbConnectionPool pool = ConstructPool(implementation, metrics, new SuccessfulSqlConnectionFactory(metrics)); SqlConnection owner = new(); // Act @@ -445,8 +452,8 @@ public void NewConnection_CountsHardConnectAndPooledConnection(PoolImplementatio public void IdleConnectionReuse_CountsSoftConnect(PoolImplementation implementation) { // Arrange - SqlClientMetrics metrics = SqlClientMetrics.CreateIsolated(); - IDbConnectionPool pool = ConstructPool(implementation, metrics, new SuccessfulSqlConnectionFactory()); + FakeSqlClientMetrics metrics = new(); + IDbConnectionPool pool = ConstructPool(implementation, metrics, new SuccessfulSqlConnectionFactory(metrics)); SqlConnection owner = new(); Assert.True(pool.TryGetConnection(owner, null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out DbConnectionInternal? connection)); Assert.NotNull(connection); @@ -475,8 +482,8 @@ public void IdleConnectionReuse_CountsSoftConnect(PoolImplementation implementat public void Return_CountsSoftDisconnect(PoolImplementation implementation) { // Arrange - SqlClientMetrics metrics = SqlClientMetrics.CreateIsolated(); - IDbConnectionPool pool = ConstructPool(implementation, metrics, new SuccessfulSqlConnectionFactory()); + FakeSqlClientMetrics metrics = new(); + IDbConnectionPool pool = ConstructPool(implementation, metrics, new SuccessfulSqlConnectionFactory(metrics)); SqlConnection owner = new(); Assert.True(pool.TryGetConnection(owner, null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out DbConnectionInternal? connection)); Assert.NotNull(connection); @@ -504,8 +511,8 @@ public void Return_CountsSoftDisconnect(PoolImplementation implementation) public void Destroy_CountsHardDisconnect(PoolImplementation implementation) { // Arrange - SqlClientMetrics metrics = SqlClientMetrics.CreateIsolated(); - IDbConnectionPool pool = ConstructPool(implementation, metrics, new SuccessfulSqlConnectionFactory()); + FakeSqlClientMetrics metrics = new(); + IDbConnectionPool pool = ConstructPool(implementation, metrics, new SuccessfulSqlConnectionFactory(metrics)); SqlConnection owner = new(); Assert.True(pool.TryGetConnection(owner, null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out DbConnectionInternal? connection)); Assert.NotNull(connection); @@ -537,8 +544,8 @@ public void Destroy_CountsHardDisconnect(PoolImplementation implementation) public void ReplaceConnection_CountsHardDisconnectForDiscardedConnection() { // Arrange - SqlClientMetrics metrics = SqlClientMetrics.CreateIsolated(); - IDbConnectionPool pool = ConstructPool(PoolImplementation.Channel, metrics, new SuccessfulSqlConnectionFactory()); + FakeSqlClientMetrics metrics = new(); + IDbConnectionPool pool = ConstructPool(PoolImplementation.Channel, metrics, new SuccessfulSqlConnectionFactory(metrics)); SqlConnection owner = new(); Assert.True(pool.TryGetConnection(owner, null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out DbConnectionInternal? oldConnection)); Assert.NotNull(oldConnection); @@ -558,7 +565,6 @@ public void ReplaceConnection_CountsHardDisconnectForDiscardedConnection() } #endregion -#endif #region Test classes @@ -663,28 +669,6 @@ internal IReadOnlyList MessagesForPool(int poolId) #endregion } -#if NET - /// - /// Reads the private counter fields of a instance. The counters - /// are not otherwise observable without an EventCounter listener and its polling interval, - /// which would make these tests slow and timing dependent. - /// - internal static class MetricReader - { - /// - /// Reads the current value of the named counter field. - /// - /// The metrics instance to read from. - /// Private field name declared on . - internal static long Read(SqlClientMetrics metrics, string fieldName) - { - FieldInfo? field = typeof(SqlClientMetrics).GetField(fieldName, BindingFlags.Instance | BindingFlags.NonPublic); - Assert.NotNull(field); - return (long)field!.GetValue(metrics)!; - } - } -#endif - /// /// xUnit assertion helper for substring matching over a captured trace stream. /// diff --git a/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/ChannelDbConnectionPoolTest.cs b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/ChannelDbConnectionPoolTest.cs index 228e949cd0..6fc0baf2cf 100644 --- a/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/ChannelDbConnectionPoolTest.cs +++ b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/ChannelDbConnectionPoolTest.cs @@ -13,6 +13,7 @@ using Microsoft.Data.Common.ConnectionString; using Microsoft.Data.ProviderBase; using Microsoft.Data.SqlClient.ConnectionPool; +using Microsoft.Data.SqlClient.Diagnostics; using Microsoft.Data.SqlClient.Tests.Common; using Microsoft.Extensions.Time.Testing; using Xunit; @@ -1365,6 +1366,20 @@ private static void BackdateReturnedTime(DbConnectionInternal connection, TimeSp /// internal class SuccessfulSqlConnectionFactory : SqlConnectionFactory { + internal SuccessfulSqlConnectionFactory() + { + } + + /// + /// Constructs a factory reporting to instead of the + /// process-wide default, so a test can assert exact counters on the same instance + /// used by the pool under test. + /// + internal SuccessfulSqlConnectionFactory(ISqlClientMetrics metrics) + : base(metrics) + { + } + /// /// Gets the last timeout budget passed through by the pool to the factory. /// diff --git a/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/FakeSqlClientMetrics.cs b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/FakeSqlClientMetrics.cs new file mode 100644 index 0000000000..b39aaa78cd --- /dev/null +++ b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/FakeSqlClientMetrics.cs @@ -0,0 +1,132 @@ +// Licensed to the .NET Foundation under one or more agreements. +// 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.Threading; +using Microsoft.Data.SqlClient.Diagnostics; + +namespace Microsoft.Data.SqlClient.UnitTests.ConnectionPool +{ + /// + /// Records every counter exposes, into fields the tests can + /// read directly. + /// + /// + /// The production counters are not usable for assertions. On .NET they are only observable + /// through an EventCounter listener, whose polling interval would make these tests slow and + /// timing dependent. On .NET Framework they are performance counters whose instance name is + /// derived from the assembly name and process id, so every instance in the process shares one + /// counter, and constructing one resets it. + /// + internal sealed class FakeSqlClientMetrics : ISqlClientMetrics + { + private long _hardConnects; + private long _hardDisconnects; + private long _softConnects; + private long _softDisconnects; + private long _nonPooledConnections; + private long _pooledConnections; + private long _activeConnectionPoolGroups; + private long _inactiveConnectionPoolGroups; + private long _activeConnectionPools; + private long _inactiveConnectionPools; + private long _activeConnections; + private long _freeConnections; + private long _stasisConnections; + private long _reclaimedConnections; + + /// Physical connections opened. + internal long HardConnects => Interlocked.Read(ref _hardConnects); + + /// Physical connections closed. + internal long HardDisconnects => Interlocked.Read(ref _hardDisconnects); + + /// Physical connections currently open. + internal long ActiveHardConnections => HardConnects - HardDisconnects; + + /// Connections handed out from the pool. + internal long SoftConnects => Interlocked.Read(ref _softConnects); + + /// Connections returned to the pool. + internal long SoftDisconnects => Interlocked.Read(ref _softDisconnects); + + /// Connections currently handed out. + internal long ActiveSoftConnections => SoftConnects - SoftDisconnects; + + /// Connections currently bypassing the pool. + internal long NonPooledConnections => Interlocked.Read(ref _nonPooledConnections); + + /// Connections currently owned by a pool. + internal long PooledConnections => Interlocked.Read(ref _pooledConnections); + + /// Connection pool groups currently active. + internal long ActiveConnectionPoolGroups => Interlocked.Read(ref _activeConnectionPoolGroups); + + /// Connection pool groups currently awaiting pruning. + internal long InactiveConnectionPoolGroups => Interlocked.Read(ref _inactiveConnectionPoolGroups); + + /// Connection pools currently active. + internal long ActiveConnectionPools => Interlocked.Read(ref _activeConnectionPools); + + /// Connection pools currently awaiting pruning. + internal long InactiveConnectionPools => Interlocked.Read(ref _inactiveConnectionPools); + + /// Connections currently in use by the application. + internal long ActiveConnections => Interlocked.Read(ref _activeConnections); + + /// Connections currently idle in a pool. + internal long FreeConnections => Interlocked.Read(ref _freeConnections); + + /// Connections currently awaiting cleanup. + internal long StasisConnections => Interlocked.Read(ref _stasisConnections); + + /// Connections reclaimed after being abandoned without being closed. + internal long ReclaimedConnections => Interlocked.Read(ref _reclaimedConnections); + + public void HardConnectRequest() => Interlocked.Increment(ref _hardConnects); + + public void HardDisconnectRequest() => Interlocked.Increment(ref _hardDisconnects); + + public void SoftConnectRequest() => Interlocked.Increment(ref _softConnects); + + public void SoftDisconnectRequest() => Interlocked.Increment(ref _softDisconnects); + + public void EnterNonPooledConnection() => Interlocked.Increment(ref _nonPooledConnections); + + public void ExitNonPooledConnection() => Interlocked.Decrement(ref _nonPooledConnections); + + public void EnterPooledConnection() => Interlocked.Increment(ref _pooledConnections); + + public void ExitPooledConnection() => Interlocked.Decrement(ref _pooledConnections); + + public void EnterActiveConnectionPoolGroup() => Interlocked.Increment(ref _activeConnectionPoolGroups); + + public void ExitActiveConnectionPoolGroup() => Interlocked.Decrement(ref _activeConnectionPoolGroups); + + public void EnterInactiveConnectionPoolGroup() => Interlocked.Increment(ref _inactiveConnectionPoolGroups); + + public void ExitInactiveConnectionPoolGroup() => Interlocked.Decrement(ref _inactiveConnectionPoolGroups); + + public void EnterActiveConnectionPool() => Interlocked.Increment(ref _activeConnectionPools); + + public void ExitActiveConnectionPool() => Interlocked.Decrement(ref _activeConnectionPools); + + public void EnterInactiveConnectionPool() => Interlocked.Increment(ref _inactiveConnectionPools); + + public void ExitInactiveConnectionPool() => Interlocked.Decrement(ref _inactiveConnectionPools); + + public void EnterActiveConnection() => Interlocked.Increment(ref _activeConnections); + + public void ExitActiveConnection() => Interlocked.Decrement(ref _activeConnections); + + public void EnterFreeConnection() => Interlocked.Increment(ref _freeConnections); + + public void ExitFreeConnection() => Interlocked.Decrement(ref _freeConnections); + + public void EnterStasisConnection() => Interlocked.Increment(ref _stasisConnections); + + public void ExitStasisConnection() => Interlocked.Decrement(ref _stasisConnections); + + public void ReclaimedConnectionRequest() => Interlocked.Increment(ref _reclaimedConnections); + } +} diff --git a/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/TransactedConnectionPoolTest.cs b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/TransactedConnectionPoolTest.cs index 4b9d987dc6..6866fb1fa2 100644 --- a/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/TransactedConnectionPoolTest.cs +++ b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/TransactedConnectionPoolTest.cs @@ -23,6 +23,14 @@ namespace Microsoft.Data.SqlClient.UnitTests.ConnectionPool; public class TransactedConnectionPoolTest { + /// + /// Constructs a reporting to 's + /// own metrics instance, matching how constructs one + /// in production. + /// + private static TransactedConnectionPool NewTransactedPool(MockDbConnectionPool pool) => + new(pool, pool.Metrics); + #region Constructor Tests [Fact] @@ -32,7 +40,7 @@ public void Constructor_WithValidPool_SetsPoolProperty() var mockPool = new MockDbConnectionPool(); // Act - var transactedPool = new TransactedConnectionPool(mockPool); + var transactedPool = NewTransactedPool(mockPool); // Assert Assert.Same(mockPool, transactedPool.Pool); @@ -43,8 +51,8 @@ public void Constructor_WithValidPool_SetsPoolProperty() public void Constructor_UniqueIds() { // Arrange - var pool1 = new TransactedConnectionPool(new MockDbConnectionPool()); - var pool2 = new TransactedConnectionPool(new MockDbConnectionPool()); + var pool1 = NewTransactedPool(new MockDbConnectionPool()); + var pool2 = NewTransactedPool(new MockDbConnectionPool()); // Act & Assert Assert.NotEqual(pool1.Id, pool2.Id); @@ -60,7 +68,7 @@ public void Constructor_UniqueIds() public void GetTransactedObject_WithNonExistentTransaction_ReturnsNull() { // Arrange - var transactedPool = new TransactedConnectionPool(new MockDbConnectionPool()); + var transactedPool = NewTransactedPool(new MockDbConnectionPool()); using var transactionScope = new TransactionScope(); var transaction = Transaction.Current!; @@ -75,7 +83,7 @@ public void GetTransactedObject_WithNonExistentTransaction_ReturnsNull() public void GetTransactedObject_WithExistingTransaction_ReturnsAndRemovesConnection() { // Arrange - var transactedPool = new TransactedConnectionPool(new MockDbConnectionPool()); + var transactedPool = NewTransactedPool(new MockDbConnectionPool()); var connection = new MockDbConnectionInternal(); using var transactionScope = new TransactionScope(); @@ -99,7 +107,7 @@ public void GetTransactedObject_WithExistingTransaction_ReturnsAndRemovesConnect public void GetTransactedObject_WithMultipleConnections_ReturnsLastAdded() { // Arrange - var transactedPool = new TransactedConnectionPool(new MockDbConnectionPool()); + var transactedPool = NewTransactedPool(new MockDbConnectionPool()); var connection1 = new MockDbConnectionInternal(); var connection2 = new MockDbConnectionInternal(); @@ -121,7 +129,7 @@ public void GetTransactedObject_WithMultipleConnections_ReturnsLastAdded() public void GetTransactedObject_ConcurrentAccess_ThreadSafe() { // Arrange - var transactedPool = new TransactedConnectionPool(new MockDbConnectionPool()); + var transactedPool = NewTransactedPool(new MockDbConnectionPool()); var connections = new DbConnectionInternal[10]; for (int i = 0; i < connections.Length; i++) { @@ -166,7 +174,7 @@ public void GetTransactedObject_ConcurrentAccess_ThreadSafe() public void PutTransactedObject_WithNullConnection_ThrowsArgumentNullException() { // Arrange - var transactedPool = new TransactedConnectionPool(new MockDbConnectionPool()); + var transactedPool = NewTransactedPool(new MockDbConnectionPool()); using var transactionScope = new TransactionScope(); var transaction = Transaction.Current!; @@ -180,7 +188,7 @@ public void PutTransactedObject_WithNullConnection_ThrowsArgumentNullException() public void PutTransactedObject_WithNewTransaction_CreatesNewConnectionList() { // Arrange - var transactedPool = new TransactedConnectionPool(new MockDbConnectionPool()); + var transactedPool = NewTransactedPool(new MockDbConnectionPool()); var connection = new MockDbConnectionInternal(); using var transactionScope = new TransactionScope(); @@ -198,7 +206,7 @@ public void PutTransactedObject_WithNewTransaction_CreatesNewConnectionList() public void PutTransactedObject_WithExistingTransaction_AddsToExistingConnectionList() { // Arrange - var transactedPool = new TransactedConnectionPool(new MockDbConnectionPool()); + var transactedPool = NewTransactedPool(new MockDbConnectionPool()); var connection1 = new MockDbConnectionInternal(); var connection2 = new MockDbConnectionInternal(); @@ -221,7 +229,7 @@ public void PutTransactedObject_WithExistingTransaction_AddsToExistingConnection public void PutTransactedObject_ConcurrentAccess_ThreadSafe() { // Arrange - var transactedPool = new TransactedConnectionPool(new MockDbConnectionPool()); + var transactedPool = NewTransactedPool(new MockDbConnectionPool()); var connections = new DbConnectionInternal[10]; for (int i = 0; i < connections.Length; i++) { @@ -260,7 +268,7 @@ public void PutTransactedObject_SameConnectionTwice_AddsToPoolTwice() // TODO: this behavior is suspicious should we prevent this? // Arrange - var transactedPool = new TransactedConnectionPool(new MockDbConnectionPool()); + var transactedPool = NewTransactedPool(new MockDbConnectionPool()); var connection = new MockDbConnectionInternal(); using var transactionScope = new TransactionScope(); @@ -286,7 +294,7 @@ public void PutTransactedObject_SameConnectionTwice_AddsToPoolTwice() public void TransactionEnded_WithNullConnection_ThrowsNullReferenceException() { // Arrange - var transactedPool = new TransactedConnectionPool(new MockDbConnectionPool()); + var transactedPool = NewTransactedPool(new MockDbConnectionPool()); using var transactionScope = new TransactionScope(); var transaction = Transaction.Current!; @@ -300,7 +308,7 @@ public void TransactionEnded_WithNullConnection_ThrowsNullReferenceException() public void TransactionEnded_WithNonExistentTransaction_DoesNotThrow() { // Arrange - var transactedPool = new TransactedConnectionPool(new MockDbConnectionPool()); + var transactedPool = NewTransactedPool(new MockDbConnectionPool()); var connection = new MockDbConnectionInternal(); using var transactionScope = new TransactionScope(); @@ -316,7 +324,7 @@ public void TransactionEnded_WithExistingConnection_RemovesConnectionAndReturnsT { // Arrange var mockPool = new MockDbConnectionPool(); - var transactedPool = new TransactedConnectionPool(mockPool); + var transactedPool = NewTransactedPool(mockPool); var connection = new MockDbConnectionInternal(); using var transactionScope = new TransactionScope(); @@ -341,7 +349,7 @@ public void TransactionEnded_WithMultipleConnections_RemovesOnlySpecifiedConnect { // Arrange var mockPool = new MockDbConnectionPool(); - var transactedPool = new TransactedConnectionPool(mockPool); + var transactedPool = NewTransactedPool(mockPool); var connection1 = new MockDbConnectionInternal(); var connection2 = new MockDbConnectionInternal(); @@ -371,7 +379,7 @@ public void TransactionEnded_WithConnectionNotInPool_DoesNotReturnToMainPool() { // Arrange var mockPool = new MockDbConnectionPool(); - var transactedPool = new TransactedConnectionPool(mockPool); + var transactedPool = NewTransactedPool(mockPool); var connection = new MockDbConnectionInternal(); using var transactionScope = new TransactionScope(); @@ -391,7 +399,7 @@ public void TransactionEnded_ConcurrentAccess_ThreadSafe() { // Arrange var mockPool = new MockDbConnectionPool(); - var transactedPool = new TransactedConnectionPool(mockPool); + var transactedPool = NewTransactedPool(mockPool); var connections = new DbConnectionInternal[10]; for (int i = 0; i < connections.Length; i++) { @@ -428,7 +436,7 @@ public void TransactionEnded_MultipleCallsWithSameConnection_OnlyReturnsOnce() { // Arrange var mockPool = new MockDbConnectionPool(); - var transactedPool = new TransactedConnectionPool(mockPool); + var transactedPool = NewTransactedPool(mockPool); var connection = new MockDbConnectionInternal(); using var transactionScope = new TransactionScope(); @@ -455,7 +463,7 @@ public void TransactionEnded_CalledBeforePut_HandlesRaceCondition() // Arrange var mockPool = new MockDbConnectionPool(); - var transactedPool = new TransactedConnectionPool(mockPool); + var transactedPool = NewTransactedPool(mockPool); var connection = new MockDbConnectionInternal(); using var transactionScope = new TransactionScope(); @@ -479,7 +487,7 @@ public void FullLifecycle_PutGetEnd_WorksCorrectly() { // Arrange var mockPool = new MockDbConnectionPool(); - var transactedPool = new TransactedConnectionPool(mockPool); + var transactedPool = NewTransactedPool(mockPool); var connection = new MockDbConnectionInternal(); using var transactionScope = new TransactionScope(); @@ -511,7 +519,7 @@ public void FullLifecycle_PutGetEnd_WorksCorrectly() public void MultipleTransactions_IsolatedCorrectly() { // Arrange - var transactedPool = new TransactedConnectionPool(new MockDbConnectionPool()); + var transactedPool = NewTransactedPool(new MockDbConnectionPool()); var connection1 = new MockDbConnectionInternal(); var connection2 = new MockDbConnectionInternal(); @@ -542,7 +550,7 @@ public void MultipleTransactions_IsolatedCorrectly() public void ConcurrentPutAndGet_DifferentTransactions_Isolated() { // Arrange - var transactedPool = new TransactedConnectionPool(new MockDbConnectionPool()); + var transactedPool = NewTransactedPool(new MockDbConnectionPool()); var numberOfTransactions = 5; var connectionsPerTransaction = 3; var results = new ConcurrentDictionary>(); @@ -605,7 +613,7 @@ public void TransactionScope_CompleteAndDispose_HandledCorrectly() // the pool state will match the transaction state. // Arrange - var transactedPool = new TransactedConnectionPool(new MockDbConnectionPool()); + var transactedPool = NewTransactedPool(new MockDbConnectionPool()); var connection = new MockDbConnectionInternal(); Transaction? capturedTransaction = null; @@ -628,7 +636,7 @@ public void PutTransactedObject_WithDisposedTransaction_HandlesGracefully() //TODO: this test should not pass! why would we store connections from a disposed transaction? // Arrange - var transactedPool = new TransactedConnectionPool(new MockDbConnectionPool()); + var transactedPool = NewTransactedPool(new MockDbConnectionPool()); var connection = new MockDbConnectionInternal(); Transaction? disposedTransaction = null; @@ -660,8 +668,9 @@ internal class MockDbConnectionPool : IDbConnectionPool public ConcurrentDictionary AuthenticationContexts { get; } = new(); public SqlConnectionFactory ConnectionFactory => throw new NotImplementedException(); // TransactedConnectionPool reports free-connection counts through its owning pool, so this - // has to be a real sink rather than a throwing stub. - public SqlClientMetrics Metrics => SqlClientDiagnostics.Metrics; + // has to be a real sink rather than a throwing stub. A fake rather than the global + // instance, so these tests do not perturb process-wide counters. + public ISqlClientMetrics Metrics { get; } = new FakeSqlClientMetrics(); public int Count => throw new NotImplementedException(); public bool ErrorOccurred => throw new NotImplementedException(); public int Id { get; } = 1; From 2a0ed0906115ca571e168b458ce36a3e775a6258 Mon Sep 17 00:00:00 2001 From: Malcolm Daigle Date: Wed, 12 Aug 2026 17:11:27 -0700 Subject: [PATCH 05/19] Remove trace-message parity tests These duplicated the metric-parity tests' coverage of pool lifecycle events without adding an assertable contract; the counters are the signal we actually want to keep exact. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- ...nnelDbConnectionPoolInstrumentationTest.cs | 312 +----------------- 1 file changed, 2 insertions(+), 310 deletions(-) diff --git a/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/ChannelDbConnectionPoolInstrumentationTest.cs b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/ChannelDbConnectionPoolInstrumentationTest.cs index 13fb0f4ea2..cd0d8970de 100644 --- a/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/ChannelDbConnectionPoolInstrumentationTest.cs +++ b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/ChannelDbConnectionPoolInstrumentationTest.cs @@ -3,13 +3,9 @@ // See the LICENSE file in the project root for more information. using System; -using System.Collections.Concurrent; using System.Collections.Generic; using System.Data.Common; -using System.Diagnostics.Tracing; -using System.Globalization; using System.Linq; -using System.Text.RegularExpressions; using System.Threading; using System.Threading.RateLimiting; using Microsoft.Data.Common; @@ -25,8 +21,8 @@ namespace Microsoft.Data.SqlClient.UnitTests.ConnectionPool { /// - /// Verifies the diagnostic instrumentation of : the pooler - /// trace events emitted across the connection lifecycle. + /// Verifies the diagnostic instrumentation of : the pool + /// metrics counters emitted across the connection lifecycle. /// public class ChannelDbConnectionPoolInstrumentationTest { @@ -79,226 +75,6 @@ private static DbConnectionPoolGroup ConstructPoolGroup( poolGroupOptions); } - #region Trace parity - - /// - /// Verifies that the pool traces its own construction, so a trace capture can attribute - /// every later pool-scoped event to a pool whose creation it observed. - /// - [Fact] - public void Construction_EmitsConstructedTrace() - { - // Arrange - using PoolerTraceListener listener = new(); - - // Act - ChannelDbConnectionPool pool = ConstructPool(new SuccessfulSqlConnectionFactory()); - - // Assert - TraceAssert.Contains("Constructed.", listener.MessagesForPool(pool.Id)); - } - - /// - /// Verifies that creating a new physical connection is traced, covering Story 1 scenario 2. - /// - [Fact] - public void NewConnection_EmitsCreationTraces() - { - // Arrange - ChannelDbConnectionPool pool = ConstructPool(new SuccessfulSqlConnectionFactory()); - using PoolerTraceListener listener = new(); - - // Act - Assert.True(pool.TryGetConnection( - new SqlConnection(), - taskCompletionSource: null, - TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), - out DbConnectionInternal? connection)); - - // Assert - IReadOnlyList messages = listener.MessagesForPool(pool.Id); - Assert.NotNull(connection); - TraceAssert.Contains("Getting connection.", messages); - TraceAssert.Contains("Creating new connection.", messages); - TraceAssert.Contains("Added to pool.", messages); - } - - /// - /// Verifies that retrieving a connection from the idle pool is traced, covering Story 1 - /// scenario 1. - /// - [Fact] - public void IdleConnectionReuse_EmitsPoppedFromGeneralPoolTrace() - { - // Arrange - ChannelDbConnectionPool pool = ConstructPool(new SuccessfulSqlConnectionFactory()); - SqlConnection owner = new(); - Assert.True(pool.TryGetConnection(owner, null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out DbConnectionInternal? connection)); - Assert.NotNull(connection); - pool.ReturnInternalConnection(connection!, owner); - - using PoolerTraceListener listener = new(); - - // Act - Assert.True(pool.TryGetConnection(new SqlConnection(), null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out DbConnectionInternal? reused)); - - // Assert - Assert.Same(connection, reused); - TraceAssert.Contains("Popped from general pool.", listener.MessagesForPool(pool.Id)); - } - - /// - /// Verifies that returning a connection traces both the deactivation and the routing - /// decision that put it back into the idle pool, covering Story 1 scenario 3. - /// - [Fact] - public void Return_EmitsDeactivateAndPushTraces() - { - // Arrange - ChannelDbConnectionPool pool = ConstructPool(new SuccessfulSqlConnectionFactory()); - SqlConnection owner = new(); - Assert.True(pool.TryGetConnection(owner, null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out DbConnectionInternal? connection)); - Assert.NotNull(connection); - - using PoolerTraceListener listener = new(); - - // Act - pool.ReturnInternalConnection(connection!, owner); - - // Assert - IReadOnlyList messages = listener.MessagesForPool(pool.Id); - TraceAssert.Contains("Deactivating.", messages); - TraceAssert.Contains("Pushing to general pool.", messages); - } - - /// - /// Verifies that destroying a connection traces the removal and the disposal, covering - /// Story 1 scenario 4. Clear is used as the destruction trigger because it drains the idle - /// channel through the same removal path as every other destroy. - /// - [Fact] - public void Destroy_EmitsRemoveAndDisposeTraces() - { - // Arrange - ChannelDbConnectionPool pool = ConstructPool(new SuccessfulSqlConnectionFactory()); - SqlConnection owner = new(); - Assert.True(pool.TryGetConnection(owner, null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out DbConnectionInternal? connection)); - Assert.NotNull(connection); - pool.ReturnInternalConnection(connection!, owner); - - using PoolerTraceListener listener = new(); - - // Act - pool.Clear(); - - // Assert - IReadOnlyList messages = listener.MessagesForPool(pool.Id); - TraceAssert.Contains("Clearing.", messages); - TraceAssert.Contains("Removing from pool.", messages); - TraceAssert.Contains("Removed from pool.", messages); - TraceAssert.Contains("Disposed.", messages); - TraceAssert.Contains("Cleared.", messages); - } - - /// - /// Verifies that startup and shutdown are traced with the pool identifier, covering Story 1 - /// scenario 5. - /// - [Fact] - public void StartupAndShutdown_EmitTraces() - { - // Arrange - ChannelDbConnectionPool pool = ConstructPool(new SuccessfulSqlConnectionFactory()); - using PoolerTraceListener listener = new(); - - // Act - pool.Startup(); - pool.Shutdown(); - - // Assert - IReadOnlyList messages = listener.MessagesForPool(pool.Id); - Assert.Contains(messages, m => m.IndexOf("Startup", StringComparison.Ordinal) >= 0); - Assert.Contains(messages, m => m.IndexOf("Shutdown", StringComparison.Ordinal) >= 0); - } - - /// - /// Verifies that a failed physical open is traced on the pool's create path, so an operator - /// can see why the pool stopped growing. - /// - [Fact] - public void CreateFailure_EmitsCreateThrewTrace() - { - // Arrange - ChannelDbConnectionPool pool = ConstructPool(new FailingSqlConnectionFactory()); - using PoolerTraceListener listener = new(); - - // Act - Assert.ThrowsAny(() => - pool.TryGetConnection(new SqlConnection(), null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out _)); - - // Assert - TraceAssert.Contains("which threw an exception", listener.MessagesForPool(pool.Id)); - } - - /// - /// Verifies that a connection discarded for exceeding the Connection Idle Timeout is traced - /// with that specific reason, rather than silently disappearing from the pool. - /// - [Fact] - public void IdleTimeoutEviction_EmitsReasonTrace() - { - // Arrange - idle-timeout eviction is opt-in; the switch defaults to legacy behavior. - using LocalAppContextSwitchesHelper switchesHelper = new(); - switchesHelper.UseLegacyIdleTimeoutBehavior = false; - - ChannelDbConnectionPool pool = ConstructPool(new SuccessfulSqlConnectionFactory(), idleTimeout: 1); - SqlConnection owner = new(); - Assert.True(pool.TryGetConnection(owner, null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out DbConnectionInternal? connection)); - Assert.NotNull(connection); - pool.ReturnInternalConnection(connection!, owner); - - // Back-date the return stamp only after the connection is parked in the idle channel: - // the return path re-stamps it so that time spent checked out is not counted as idle. - connection!.SetReturnedTime(DateTime.UtcNow - TimeSpan.FromMinutes(5)); - - using PoolerTraceListener listener = new(); - - // Act - retrieval trips the idle-expiry gate and discards the connection. - Assert.True(pool.TryGetConnection(new SqlConnection(), null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out DbConnectionInternal? replacement)); - - // Assert - Assert.NotNull(replacement); - Assert.NotSame(connection, replacement); - TraceAssert.Contains("exceeded the connection idle timeout and removed.", listener.MessagesForPool(pool.Id)); - } - - /// - /// Verifies that pruning traces each invocation, so idle reclamation is attributable in a - /// trace capture even when it removes nothing (Story 3). - /// - [Fact] - public void Prune_EmitsTracePerInvocation() - { - // Arrange - ChannelDbConnectionPool pool = ConstructPool(new SuccessfulSqlConnectionFactory(), maxPoolSize: 4, idleTimeout: 300); - SqlConnection owner = new(); - Assert.True(pool.TryGetConnection(owner, null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out DbConnectionInternal? connection)); - Assert.NotNull(connection); - pool.ReturnInternalConnection(connection!, owner); - - using PoolerTraceListener listener = new(); - - // Act - pool.PruneConnections(1); - - // Assert - IReadOnlyList messages = listener.MessagesForPool(pool.Id); - TraceAssert.Contains("Pruning up to 1 idle connections.", messages); - TraceAssert.Contains("Pruned 1 idle connections.", messages); - } - - #endregion - #region Metric parity // Each test gives its pool its own metrics instance, so the counters observe only that @@ -596,90 +372,6 @@ protected override DbConnectionInternal CreateConnection( => throw new TestConnectionCreateException(); } - /// - /// Captures PoolerTrace events from the SqlClient event source. - /// - /// Tests filter captured messages by pool id (see ) because the - /// event source is process-wide: xUnit runs test classes in parallel, so traces from other - /// pools are expected to appear in the same capture. - /// - /// - internal sealed class PoolerTraceListener : EventListener - { - private const string SqlClientEventSourceName = "Microsoft.Data.SqlClient.EventSource"; - - // Mirrors SqlClientEventSource.Keywords.PoolerTrace. Duplicated as a literal because - // that type is not visible to this assembly. - private const EventKeywords PoolerTraceKeyword = (EventKeywords)32; - - // Lazily initialized: EventListener's base constructor invokes OnEventSourceCreated, - // which enables events, before this class's field initializers have run. Traces can - // therefore arrive on another thread before a plain field initializer would have - // assigned the queue. - private ConcurrentQueue? _messages; - - private ConcurrentQueue Messages => - LazyInitializer.EnsureInitialized(ref _messages)!; - - /// - protected override void OnEventSourceCreated(EventSource eventSource) - { - if (eventSource.Name == SqlClientEventSourceName) - { - EnableEvents(eventSource, EventLevel.Informational, PoolerTraceKeyword); - } - } - - /// - protected override void OnEventWritten(EventWrittenEventArgs eventData) - { - if (eventData.Payload is null) - { - return; - } - - foreach (object? payload in eventData.Payload) - { - if (payload is string message) - { - Messages.Enqueue(message); - } - } - } - - /// - /// Returns the captured messages emitted for the given pool. - /// - /// The to filter on. - internal IReadOnlyList MessagesForPool(int poolId) - { - // Pool-scoped traces render the id as the first substituted argument, immediately - // after the "|CPOOL> " marker, e.g. - // " 7, Clearing." - // " 7" - // The trailing boundary keeps pool 7 from matching pool 70. - Regex pattern = new( - @"CPOOL> " + Regex.Escape(poolId.ToString(CultureInfo.InvariantCulture)) + @"(\D|$)", - RegexOptions.CultureInvariant); - - return Messages.Where(m => pattern.IsMatch(m)).ToList(); - } - } - #endregion } - - /// - /// xUnit assertion helper for substring matching over a captured trace stream. - /// - internal static class TraceAssert - { - /// - /// Asserts that at least one captured message contains . - /// - internal static void Contains(string fragment, IReadOnlyList messages) => - Assert.True( - messages.Any(m => m.IndexOf(fragment, StringComparison.Ordinal) >= 0), - $"Expected a trace containing \"{fragment}\". Captured:{Environment.NewLine}{string.Join(Environment.NewLine, messages)}"); - } } From efd55a07b9684b4622b1b6b9a36137a24cb18e16 Mon Sep 17 00:00:00 2001 From: Malcolm Daigle Date: Thu, 13 Aug 2026 09:46:25 -0700 Subject: [PATCH 06/19] Fix trace-message class/method references in pool V2 Trace strings in ChannelDbConnectionPool.cs, TransactedConnectionPool.cs, and PoolPruner.cs were copy-pasted from WaitHandleDbConnectionPool.cs and referenced the wrong class name (DbConnectionPool) and, in many cases, a stale method name (e.g. CreateObject, DeactivateObject, DestroyObject, GetConnection, PutNewObject) left over from the method they were ported from rather than the method they now live in. Corrected every TryPoolerTraceEvent call site so its prefix names the actual enclosing class and method, and gave the one PoolPruner trace (previously missing a method segment) a proper PoolPruner.PoolPruner reference since it's emitted from the constructor. WaitHandleDbConnectionPool.cs's own trace strings are unchanged: they were not modified by this branch and remain historically correct for that class's traces. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- .../ConnectionPool/ChannelDbConnectionPool.cs | 88 +++++++++---------- .../SqlClient/ConnectionPool/PoolPruner.cs | 2 +- .../TransactedConnectionPool.cs | 18 ++-- 3 files changed, 54 insertions(+), 54 deletions(-) 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 7adeefc947..3bcee4f227 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 @@ -204,7 +204,7 @@ internal ChannelDbConnectionPool( State = Running; SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Constructed. MinPoolSize={1}, MaxPoolSize={2}", + " {0}, Constructed. MinPoolSize={1}, MaxPoolSize={2}", Id, MinPoolSize, MaxPoolSize); @@ -302,7 +302,7 @@ public ConcurrentDictionary< public void Clear() { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Clearing.", Id); + " {0}, Clearing.", Id); // Clearing the pool implies the caller wants a clean slate, so abandon any cached // error state. FR-011. @@ -316,7 +316,7 @@ public void Clear() if (Interlocked.CompareExchange(ref _isClearing, 1, 0) == 1) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Skip drain, already clearing.", Id); + " {0}, Skip drain, already clearing.", Id); return; } @@ -343,7 +343,7 @@ public void Clear() } SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Cleared.", Id); + " {0}, Cleared.", Id); } /// @@ -363,7 +363,7 @@ public void PutObjectFromTransactedPool(DbConnectionInternal connection) if (State is Running && connection.CanBePooled) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Connection {1}, Transaction has ended; returning connection to pool.", + " {0}, Connection {1}, Transaction has ended; returning connection to pool.", Id, connection.ObjectID); @@ -384,7 +384,7 @@ public void PutObjectFromTransactedPool(DbConnectionInternal connection) else { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Connection {1}, Transaction has ended; destroying unpoolable connection.", + " {0}, Connection {1}, Transaction has ended; destroying unpoolable connection.", Id, connection.ObjectID); @@ -401,7 +401,7 @@ public DbConnectionInternal ReplaceConnection( TimeoutTimer timeout) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, replacing connection.", Id); + " {0}, replacing connection.", Id); // First, prefer to get an idle connection from the pool. // If one is available, we can avoid the cost of creating a new connection. @@ -519,7 +519,7 @@ public DbConnectionInternal ReplaceConnection( Metrics.HardDisconnectRequest(); SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Connection {1}, Disposed.", + " {0}, Connection {1}, Disposed.", Id, oldConnection.ObjectID); } @@ -527,7 +527,7 @@ public DbConnectionInternal ReplaceConnection( Metrics.SoftConnectRequest(); SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, connection replaced successfully.", Id); + " {0}, connection replaced successfully.", Id); return newConnection; } @@ -540,7 +540,7 @@ public void ReturnInternalConnection(DbConnectionInternal connection, DbConnecti ValidateOwnershipAndSetPoolingState(connection, owningObject); SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Connection {1}, Deactivating.", + " {0}, Connection {1}, Deactivating.", Id, connection.ObjectID); @@ -624,7 +624,7 @@ public void ReturnInternalConnection(DbConnectionInternal connection, DbConnecti // this trace the connection simply disappears from the pool's trace stream // after deactivation. SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Connection {1}, Held by a transaction; not returned to the general pool.", + " {0}, Connection {1}, Held by a transaction; not returned to the general pool.", Id, connection.ObjectID); break; @@ -693,7 +693,7 @@ private void PutConnectionInIdleChannel(DbConnectionInternal connection, bool pr } SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Connection {1}, Pushing to general pool.", + " {0}, Connection {1}, Pushing to general pool.", Id, connection.ObjectID); @@ -715,7 +715,7 @@ public void Shutdown() } SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}", Id); + " {0}", Id); // Transition to ShuttingDown. After this point, ReturnInternalConnection // routes returning connections to RemoveConnection. @@ -738,7 +738,7 @@ public void Shutdown() catch (Exception ex) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, _warmupCts.Cancel threw, continuing shutdown: {1}", Id, ex); + " {0}, _warmupCts.Cancel threw, continuing shutdown: {1}", Id, ex); } // Each cleanup step is independent and best-effort. A failure in one step must not @@ -755,7 +755,7 @@ public void Shutdown() catch (Exception ex) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Pruner.Dispose threw, continuing shutdown: {1}", Id, ex); + " {0}, Pruner.Dispose threw, continuing shutdown: {1}", Id, ex); } // Dispose the error state so its exit timer is released. Otherwise a timer scheduled @@ -768,7 +768,7 @@ public void Shutdown() catch (Exception ex) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, _errorState.Dispose threw, continuing shutdown: {1}", Id, ex); + " {0}, _errorState.Dispose threw, continuing shutdown: {1}", Id, ex); } // Complete the channel writer so: @@ -789,7 +789,7 @@ public void Shutdown() catch (Exception ex) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Clear threw, continuing shutdown: {1}", Id, ex); + " {0}, Clear threw, continuing shutdown: {1}", Id, ex); } // Clear() may short-circuit if another caller is already draining. Because the @@ -811,7 +811,7 @@ public void Shutdown() catch (Exception ex) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, RemoveConnection threw during drain, continuing: {1}", Id, ex); + " {0}, RemoveConnection threw during drain, continuing: {1}", Id, ex); } } @@ -829,7 +829,7 @@ public void Shutdown() catch (Exception ex) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, _warmupCts.Dispose threw, continuing shutdown: {1}", Id, ex); + " {0}, _warmupCts.Dispose threw, continuing shutdown: {1}", Id, ex); } } @@ -846,7 +846,7 @@ public void Startup() // via UpdateTimer() calls from OpenNewInternalConnection and RemoveConnection as the // pool grows/shrinks. SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}", Id); + " {0}", Id); // Kick off background warmup so the pool pre-creates connections up to MinPoolSize // without blocking the caller (Story 1). No-op when MinPoolSize == 0. @@ -859,7 +859,7 @@ public void TransactionEnded(Transaction transaction, DbConnectionInternal trans // Note: the connection may still be associated with the transaction due to the explicit // unbinding requirement. SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Transaction {1}, Connection {2}, Transaction Completed", + " {0}, Transaction {1}, Connection {2}, Transaction Completed", Id, transaction.GetHashCode(), transactedObject.ObjectID); @@ -893,7 +893,7 @@ public bool TryGetConnection( if (State is not Running) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, State != Running.", Id); + " {0}, State != Running.", Id); connection = null; return true; } @@ -1034,13 +1034,13 @@ public bool TryGetConnection( if (ErrorOccurred) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Errors are set.", Id); + " {0}, Errors are set.", Id); } _errorState?.ThrowIfActive(); SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Creating new connection.", Id); + " {0}, Creating new connection.", Id); try { @@ -1079,7 +1079,7 @@ public bool TryGetConnection( // (e.g. RateLimitMetadataName.RetryAfter, ReasonPhrase) in the error // path so the user can identify why the lease was denied. SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Rate limiter saturated; deferring creation to the idle wait.", + " {0}, Rate limiter saturated; deferring creation to the idle wait.", Id); faulted = false; return null; @@ -1156,7 +1156,7 @@ _connectionCreationRateLimiter is not null && if (connection is not null) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Connection {1}, Added to pool.", + " {0}, Connection {1}, Added to pool.", Id, connection.ObjectID); @@ -1174,7 +1174,7 @@ _connectionCreationRateLimiter is not null && else { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, No connection created; pool is full or creation is rate limited.", + " {0}, No connection created; pool is full or creation is rate limited.", Id); } @@ -1183,7 +1183,7 @@ _connectionCreationRateLimiter is not null && catch (Exception ex) when (ADP.IsCatchableExceptionType(ex) && ex is not OperationCanceledException) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, PoolCreateRequest called CreateConnection which threw an exception: {1}", + " {0}, PoolCreateRequest called CreateConnection which threw an exception: {1}", Id, ex); @@ -1279,7 +1279,7 @@ private bool IsLiveConnection(DbConnectionInternal connection, bool probeLivenes /// "Connection {id}, {reason} and removed." private void TraceNotLive(DbConnectionInternal connection, string reason) => SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Connection {1}, {2} and removed.", + " {0}, Connection {1}, {2} and removed.", Id, connection.ObjectID, reason); @@ -1307,7 +1307,7 @@ private void TraceNotLive(DbConnectionInternal connection, string reason) => private void RemoveConnection(DbConnectionInternal connection) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Connection {1}, Removing from pool.", + " {0}, Connection {1}, Removing from pool.", Id, connection.ObjectID); @@ -1318,7 +1318,7 @@ private void RemoveConnection(DbConnectionInternal connection) if (connection.IsTxRootWaitingForTxEnd) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Connection {1}, Has Delegated Transaction, waiting to Dispose.", + " {0}, Connection {1}, Has Delegated Transaction, waiting to Dispose.", Id, connection.ObjectID); return; @@ -1327,7 +1327,7 @@ private void RemoveConnection(DbConnectionInternal connection) if (_connectionSlots.TryRemove(connection)) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Connection {1}, Removed from pool.", + " {0}, Connection {1}, Removed from pool.", Id, connection.ObjectID); @@ -1343,7 +1343,7 @@ private void RemoveConnection(DbConnectionInternal connection) Metrics.HardDisconnectRequest(); SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Connection {1}, Disposed.", + " {0}, Connection {1}, Disposed.", Id, connection.ObjectID); @@ -1380,7 +1380,7 @@ private void RemoveConnection(DbConnectionInternal connection) } SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Connection {1}, Popped from general pool.", + " {0}, Connection {1}, Popped from general pool.", Id, connection.ObjectID); @@ -1419,7 +1419,7 @@ private async Task GetInternalConnection( DbConnectionInternal? connection = null; SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Getting connection.", Id); + " {0}, Getting connection.", Id); // When automatic enlistment is disabled, the connection must never be bound to the // ambient transaction, so we neither consult the transacted store nor hand the @@ -1484,14 +1484,14 @@ private async Task GetInternalConnection( catch (OperationCanceledException) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Wait timed out.", Id); + " {0}, Wait timed out.", Id); throw ADP.PooledOpenTimeout(); } catch (ChannelClosedException) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Pool is shutting down; abandoning wait.", Id); + " {0}, Pool is shutting down; abandoning wait.", Id); throw new InvalidOperationException(StringsHelper.GetString(Strings.SQL_ConnectionPoolShutDown)); } @@ -1587,7 +1587,7 @@ private void PrepareConnection(DbConnection owningObject, DbConnectionInternal c } SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Transaction {1}, Connection {2}, Popped from transacted pool.", + " {0}, Transaction {1}, Connection {2}, Popped from transacted pool.", Id, transaction.GetHashCode(), connection.ObjectID); @@ -1611,7 +1611,7 @@ private void PrepareConnection(DbConnection owningObject, DbConnectionInternal c if (!isAlive) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Connection {1}, found dead and removed.", + " {0}, Connection {1}, found dead and removed.", Id, connection.ObjectID); RemoveConnection(connection); @@ -1702,7 +1702,7 @@ internal void RequestWarmup() } SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Failed to schedule warmup loop, absorbing: {1}", Id, ex); + " {0}, Failed to schedule warmup loop, absorbing: {1}", Id, ex); } } @@ -1778,7 +1778,7 @@ private async Task RunWarmupLoopAsync() // during the blocking window and resume creating on demand once it expires, // and the next below-minimum trigger re-requests warmup (Story 3). SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Warmup connection creation failed, stopping pass: {1}", Id, ex); + " {0}, Warmup connection creation failed, stopping pass: {1}", Id, ex); break; } @@ -1822,7 +1822,7 @@ private async Task RunWarmupLoopAsync() // rather than absorbed into a pool that keeps running in a potentially corrupted // state; the finally below still releases the single-loop guard on that path. SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Warmup loop failed, absorbing: {1}", Id, ex); + " {0}, Warmup loop failed, absorbing: {1}", Id, ex); } finally { @@ -1849,7 +1849,7 @@ private async Task RunWarmupLoopAsync() internal void PruneConnections(int count) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Pruning up to {1} idle connections. IdleCount={2}, Count={3}", + " {0}, Pruning up to {1} idle connections. IdleCount={2}, Count={3}", Id, count, IdleCount, @@ -1873,7 +1873,7 @@ internal void PruneConnections(int count) } SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Pruned {1} idle connections.", + " {0}, Pruned {1} idle connections.", Id, pruned); } diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/PoolPruner.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/PoolPruner.cs index 9c6621f5f0..cd096299a4 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/PoolPruner.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/PoolPruner.cs @@ -136,7 +136,7 @@ internal PoolPruner(ChannelDbConnectionPool pool, TimeSpan idleTimeout) // cadence so operators can tell why a very large Connection Idle Timeout samples less // frequently than the default 10-second interval. SqlClientEventSource.Log.TryPoolerTraceEvent( - " Idle timeout {0}s derived a pruning interval of {1}s with {2} samples (max {3}).", + " Idle timeout {0}s derived a pruning interval of {1}s with {2} samples (max {3}).", idleTimeoutSeconds, intervalSeconds, sampleSize, MaxSampleSize); } diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/TransactedConnectionPool.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/TransactedConnectionPool.cs index 32e6865efb..cf72f8753d 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/TransactedConnectionPool.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/TransactedConnectionPool.cs @@ -82,7 +82,7 @@ internal TransactedConnectionPool(IDbConnectionPool pool, ISqlClientMetrics metr Pool = pool; _metrics = metrics; TransactedConnections = new Dictionary(); - SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Constructed for connection pool {1}", Id, Pool.Id); + SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Constructed for connection pool {1}", Id, Pool.Id); } #region Properties @@ -156,7 +156,7 @@ internal TransactedConnectionPool(IDbConnectionPool pool, ISqlClientMetrics metr if (transactedObject != null) { - SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Transaction {1}, Connection {2}, Popped.", Id, transaction.GetHashCode(), transactedObject.ObjectID); + SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Transaction {1}, Connection {2}, Popped.", Id, transaction.GetHashCode(), transactedObject.ObjectID); } return transactedObject; } @@ -196,7 +196,7 @@ internal void PutTransactedObject(Transaction transaction, DbConnectionInternal { // TODO: validate that we're not adding the same connection twice? // Debug.Assert(0 > connections.IndexOf(transactedObject), "adding to pool a second time?"); - SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Transaction {1}, Connection {2}, Pushing.", Id, transaction.GetHashCode(), transactedObject.ObjectID); + SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Transaction {1}, Connection {2}, Pushing.", Id, transaction.GetHashCode(), transactedObject.ObjectID); connections.Add(transactedObject); } } @@ -230,13 +230,13 @@ internal void PutTransactedObject(Transaction transaction, DbConnectionInternal lock (connections) { Debug.Assert(0 > connections.IndexOf(transactedObject), "adding to pool a second time?"); - SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Transaction {1}, Connection {2}, Pushing.", Id, transaction.GetHashCode(), transactedObject.ObjectID); + SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Transaction {1}, Connection {2}, Pushing.", Id, transaction.GetHashCode(), transactedObject.ObjectID); connections.Add(transactedObject); } } else { - SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Transaction {1}, Connection {2}, Adding List to transacted pool.", Id, transaction.GetHashCode(), transactedObject.ObjectID); + SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Transaction {1}, Connection {2}, Adding List to transacted pool.", Id, transaction.GetHashCode(), transactedObject.ObjectID); // add the connection/transacted object to the list newConnections.Add(transactedObject); @@ -264,7 +264,7 @@ internal void PutTransactedObject(Transaction transaction, DbConnectionInternal } } } - SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Transaction {1}, Connection {2}, Added.", Id, transaction.GetHashCode(), transactedObject.ObjectID); + SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Transaction {1}, Connection {2}, Added.", Id, transaction.GetHashCode(), transactedObject.ObjectID); } _metrics.EnterFreeConnection(); @@ -288,7 +288,7 @@ internal void PutTransactedObject(Transaction transaction, DbConnectionInternal /// internal void TransactionEnded(Transaction transaction, DbConnectionInternal transactedObject) { - SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Transaction {1}, Connection {2}, Transaction Completed", Id, transaction.GetHashCode(), transactedObject.ObjectID); + SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Transaction {1}, Connection {2}, Transaction Completed", Id, transaction.GetHashCode(), transactedObject.ObjectID); TransactedConnectionList? connections; int entry = -1; @@ -321,7 +321,7 @@ internal void TransactionEnded(Transaction transaction, DbConnectionInternal tra // safely remove the list from the transacted pool. if (0 >= connections.Count) { - SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Transaction {1}, Removing List from transacted pool.", Id, transaction.GetHashCode()); + SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Transaction {1}, Removing List from transacted pool.", Id, transaction.GetHashCode()); TransactedConnections.Remove(transaction); // we really need to dispose our connection list; it may have @@ -337,7 +337,7 @@ internal void TransactionEnded(Transaction transaction, DbConnectionInternal tra } else { - SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Transaction {1}, Connection {2}, Transacted pool not yet created prior to transaction completing. Connection may be leaked.", Id, transaction.GetHashCode(), transactedObject.ObjectID); + SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Transaction {1}, Connection {2}, Transacted pool not yet created prior to transaction completing. Connection may be leaked.", Id, transaction.GetHashCode(), transactedObject.ObjectID); } } From c63d491a706bf6884a21f66d0e1e69e83cdece8a Mon Sep 17 00:00:00 2001 From: Malcolm Daigle Date: Thu, 13 Aug 2026 09:51:41 -0700 Subject: [PATCH 07/19] Adopt new trace message format in pool V2 Convert pool V2's trace strings from the legacy wrapper to the plain "Class.Method | SEV | " format used elsewhere in the codebase (e.g. SqlCommand.InternalExecuteNonQuery | INFO | ...), per the formatting introduced as part of the project merge. Drops the RES/CPOOL resource-category tags entirely in favor of a single severity marker (INFO), since none of these traces are errors. Affects ChannelDbConnectionPool.cs, TransactedConnectionPool.cs, and PoolPruner.cs. Message text and arguments are unchanged, only the class/method/severity prefix syntax. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- .../ConnectionPool/ChannelDbConnectionPool.cs | 88 +++++++++---------- .../SqlClient/ConnectionPool/PoolPruner.cs | 2 +- .../TransactedConnectionPool.cs | 18 ++-- 3 files changed, 54 insertions(+), 54 deletions(-) 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 3bcee4f227..42ecde7e28 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 @@ -204,7 +204,7 @@ internal ChannelDbConnectionPool( State = Running; SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Constructed. MinPoolSize={1}, MaxPoolSize={2}", + "ChannelDbConnectionPool.ChannelDbConnectionPool | INFO | {0}, Constructed. MinPoolSize={1}, MaxPoolSize={2}", Id, MinPoolSize, MaxPoolSize); @@ -302,7 +302,7 @@ public ConcurrentDictionary< public void Clear() { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Clearing.", Id); + "ChannelDbConnectionPool.Clear | INFO | {0}, Clearing.", Id); // Clearing the pool implies the caller wants a clean slate, so abandon any cached // error state. FR-011. @@ -316,7 +316,7 @@ public void Clear() if (Interlocked.CompareExchange(ref _isClearing, 1, 0) == 1) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Skip drain, already clearing.", Id); + "ChannelDbConnectionPool.Clear | INFO | {0}, Skip drain, already clearing.", Id); return; } @@ -343,7 +343,7 @@ public void Clear() } SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Cleared.", Id); + "ChannelDbConnectionPool.Clear | INFO | {0}, Cleared.", Id); } /// @@ -363,7 +363,7 @@ public void PutObjectFromTransactedPool(DbConnectionInternal connection) if (State is Running && connection.CanBePooled) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Connection {1}, Transaction has ended; returning connection to pool.", + "ChannelDbConnectionPool.PutObjectFromTransactedPool | INFO | {0}, Connection {1}, Transaction has ended; returning connection to pool.", Id, connection.ObjectID); @@ -384,7 +384,7 @@ public void PutObjectFromTransactedPool(DbConnectionInternal connection) else { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Connection {1}, Transaction has ended; destroying unpoolable connection.", + "ChannelDbConnectionPool.PutObjectFromTransactedPool | INFO | {0}, Connection {1}, Transaction has ended; destroying unpoolable connection.", Id, connection.ObjectID); @@ -401,7 +401,7 @@ public DbConnectionInternal ReplaceConnection( TimeoutTimer timeout) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, replacing connection.", Id); + "ChannelDbConnectionPool.ReplaceConnection | INFO | {0}, replacing connection.", Id); // First, prefer to get an idle connection from the pool. // If one is available, we can avoid the cost of creating a new connection. @@ -519,7 +519,7 @@ public DbConnectionInternal ReplaceConnection( Metrics.HardDisconnectRequest(); SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Connection {1}, Disposed.", + "ChannelDbConnectionPool.ReplaceConnection | INFO | {0}, Connection {1}, Disposed.", Id, oldConnection.ObjectID); } @@ -527,7 +527,7 @@ public DbConnectionInternal ReplaceConnection( Metrics.SoftConnectRequest(); SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, connection replaced successfully.", Id); + "ChannelDbConnectionPool.ReplaceConnection | INFO | {0}, connection replaced successfully.", Id); return newConnection; } @@ -540,7 +540,7 @@ public void ReturnInternalConnection(DbConnectionInternal connection, DbConnecti ValidateOwnershipAndSetPoolingState(connection, owningObject); SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Connection {1}, Deactivating.", + "ChannelDbConnectionPool.ReturnInternalConnection | INFO | {0}, Connection {1}, Deactivating.", Id, connection.ObjectID); @@ -624,7 +624,7 @@ public void ReturnInternalConnection(DbConnectionInternal connection, DbConnecti // this trace the connection simply disappears from the pool's trace stream // after deactivation. SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Connection {1}, Held by a transaction; not returned to the general pool.", + "ChannelDbConnectionPool.ReturnInternalConnection | INFO | {0}, Connection {1}, Held by a transaction; not returned to the general pool.", Id, connection.ObjectID); break; @@ -693,7 +693,7 @@ private void PutConnectionInIdleChannel(DbConnectionInternal connection, bool pr } SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Connection {1}, Pushing to general pool.", + "ChannelDbConnectionPool.PutConnectionInIdleChannel | INFO | {0}, Connection {1}, Pushing to general pool.", Id, connection.ObjectID); @@ -715,7 +715,7 @@ public void Shutdown() } SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}", Id); + "ChannelDbConnectionPool.Shutdown | INFO | {0}", Id); // Transition to ShuttingDown. After this point, ReturnInternalConnection // routes returning connections to RemoveConnection. @@ -738,7 +738,7 @@ public void Shutdown() catch (Exception ex) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, _warmupCts.Cancel threw, continuing shutdown: {1}", Id, ex); + "ChannelDbConnectionPool.Shutdown | INFO | {0}, _warmupCts.Cancel threw, continuing shutdown: {1}", Id, ex); } // Each cleanup step is independent and best-effort. A failure in one step must not @@ -755,7 +755,7 @@ public void Shutdown() catch (Exception ex) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Pruner.Dispose threw, continuing shutdown: {1}", Id, ex); + "ChannelDbConnectionPool.Shutdown | INFO | {0}, Pruner.Dispose threw, continuing shutdown: {1}", Id, ex); } // Dispose the error state so its exit timer is released. Otherwise a timer scheduled @@ -768,7 +768,7 @@ public void Shutdown() catch (Exception ex) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, _errorState.Dispose threw, continuing shutdown: {1}", Id, ex); + "ChannelDbConnectionPool.Shutdown | INFO | {0}, _errorState.Dispose threw, continuing shutdown: {1}", Id, ex); } // Complete the channel writer so: @@ -789,7 +789,7 @@ public void Shutdown() catch (Exception ex) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Clear threw, continuing shutdown: {1}", Id, ex); + "ChannelDbConnectionPool.Shutdown | INFO | {0}, Clear threw, continuing shutdown: {1}", Id, ex); } // Clear() may short-circuit if another caller is already draining. Because the @@ -811,7 +811,7 @@ public void Shutdown() catch (Exception ex) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, RemoveConnection threw during drain, continuing: {1}", Id, ex); + "ChannelDbConnectionPool.Shutdown | INFO | {0}, RemoveConnection threw during drain, continuing: {1}", Id, ex); } } @@ -829,7 +829,7 @@ public void Shutdown() catch (Exception ex) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, _warmupCts.Dispose threw, continuing shutdown: {1}", Id, ex); + "ChannelDbConnectionPool.Shutdown | INFO | {0}, _warmupCts.Dispose threw, continuing shutdown: {1}", Id, ex); } } @@ -846,7 +846,7 @@ public void Startup() // via UpdateTimer() calls from OpenNewInternalConnection and RemoveConnection as the // pool grows/shrinks. SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}", Id); + "ChannelDbConnectionPool.Startup | INFO | {0}", Id); // Kick off background warmup so the pool pre-creates connections up to MinPoolSize // without blocking the caller (Story 1). No-op when MinPoolSize == 0. @@ -859,7 +859,7 @@ public void TransactionEnded(Transaction transaction, DbConnectionInternal trans // Note: the connection may still be associated with the transaction due to the explicit // unbinding requirement. SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Transaction {1}, Connection {2}, Transaction Completed", + "ChannelDbConnectionPool.TransactionEnded | INFO | {0}, Transaction {1}, Connection {2}, Transaction Completed", Id, transaction.GetHashCode(), transactedObject.ObjectID); @@ -893,7 +893,7 @@ public bool TryGetConnection( if (State is not Running) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, State != Running.", Id); + "ChannelDbConnectionPool.TryGetConnection | INFO | {0}, State != Running.", Id); connection = null; return true; } @@ -1034,13 +1034,13 @@ public bool TryGetConnection( if (ErrorOccurred) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Errors are set.", Id); + "ChannelDbConnectionPool.OpenNewInternalConnection | INFO | {0}, Errors are set.", Id); } _errorState?.ThrowIfActive(); SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Creating new connection.", Id); + "ChannelDbConnectionPool.OpenNewInternalConnection | INFO | {0}, Creating new connection.", Id); try { @@ -1079,7 +1079,7 @@ public bool TryGetConnection( // (e.g. RateLimitMetadataName.RetryAfter, ReasonPhrase) in the error // path so the user can identify why the lease was denied. SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Rate limiter saturated; deferring creation to the idle wait.", + "ChannelDbConnectionPool.OpenNewInternalConnection | INFO | {0}, Rate limiter saturated; deferring creation to the idle wait.", Id); faulted = false; return null; @@ -1156,7 +1156,7 @@ _connectionCreationRateLimiter is not null && if (connection is not null) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Connection {1}, Added to pool.", + "ChannelDbConnectionPool.OpenNewInternalConnection | INFO | {0}, Connection {1}, Added to pool.", Id, connection.ObjectID); @@ -1174,7 +1174,7 @@ _connectionCreationRateLimiter is not null && else { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, No connection created; pool is full or creation is rate limited.", + "ChannelDbConnectionPool.OpenNewInternalConnection | INFO | {0}, No connection created; pool is full or creation is rate limited.", Id); } @@ -1183,7 +1183,7 @@ _connectionCreationRateLimiter is not null && catch (Exception ex) when (ADP.IsCatchableExceptionType(ex) && ex is not OperationCanceledException) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, PoolCreateRequest called CreateConnection which threw an exception: {1}", + "ChannelDbConnectionPool.OpenNewInternalConnection | INFO | {0}, PoolCreateRequest called CreateConnection which threw an exception: {1}", Id, ex); @@ -1279,7 +1279,7 @@ private bool IsLiveConnection(DbConnectionInternal connection, bool probeLivenes /// "Connection {id}, {reason} and removed." private void TraceNotLive(DbConnectionInternal connection, string reason) => SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Connection {1}, {2} and removed.", + "ChannelDbConnectionPool.TraceNotLive | INFO | {0}, Connection {1}, {2} and removed.", Id, connection.ObjectID, reason); @@ -1307,7 +1307,7 @@ private void TraceNotLive(DbConnectionInternal connection, string reason) => private void RemoveConnection(DbConnectionInternal connection) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Connection {1}, Removing from pool.", + "ChannelDbConnectionPool.RemoveConnection | INFO | {0}, Connection {1}, Removing from pool.", Id, connection.ObjectID); @@ -1318,7 +1318,7 @@ private void RemoveConnection(DbConnectionInternal connection) if (connection.IsTxRootWaitingForTxEnd) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Connection {1}, Has Delegated Transaction, waiting to Dispose.", + "ChannelDbConnectionPool.RemoveConnection | INFO | {0}, Connection {1}, Has Delegated Transaction, waiting to Dispose.", Id, connection.ObjectID); return; @@ -1327,7 +1327,7 @@ private void RemoveConnection(DbConnectionInternal connection) if (_connectionSlots.TryRemove(connection)) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Connection {1}, Removed from pool.", + "ChannelDbConnectionPool.RemoveConnection | INFO | {0}, Connection {1}, Removed from pool.", Id, connection.ObjectID); @@ -1343,7 +1343,7 @@ private void RemoveConnection(DbConnectionInternal connection) Metrics.HardDisconnectRequest(); SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Connection {1}, Disposed.", + "ChannelDbConnectionPool.RemoveConnection | INFO | {0}, Connection {1}, Disposed.", Id, connection.ObjectID); @@ -1380,7 +1380,7 @@ private void RemoveConnection(DbConnectionInternal connection) } SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Connection {1}, Popped from general pool.", + "ChannelDbConnectionPool.GetIdleConnection | INFO | {0}, Connection {1}, Popped from general pool.", Id, connection.ObjectID); @@ -1419,7 +1419,7 @@ private async Task GetInternalConnection( DbConnectionInternal? connection = null; SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Getting connection.", Id); + "ChannelDbConnectionPool.GetInternalConnection | INFO | {0}, Getting connection.", Id); // When automatic enlistment is disabled, the connection must never be bound to the // ambient transaction, so we neither consult the transacted store nor hand the @@ -1484,14 +1484,14 @@ private async Task GetInternalConnection( catch (OperationCanceledException) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Wait timed out.", Id); + "ChannelDbConnectionPool.GetInternalConnection | INFO | {0}, Wait timed out.", Id); throw ADP.PooledOpenTimeout(); } catch (ChannelClosedException) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Pool is shutting down; abandoning wait.", Id); + "ChannelDbConnectionPool.GetInternalConnection | INFO | {0}, Pool is shutting down; abandoning wait.", Id); throw new InvalidOperationException(StringsHelper.GetString(Strings.SQL_ConnectionPoolShutDown)); } @@ -1587,7 +1587,7 @@ private void PrepareConnection(DbConnection owningObject, DbConnectionInternal c } SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Transaction {1}, Connection {2}, Popped from transacted pool.", + "ChannelDbConnectionPool.GetFromTransactedPool | INFO | {0}, Transaction {1}, Connection {2}, Popped from transacted pool.", Id, transaction.GetHashCode(), connection.ObjectID); @@ -1611,7 +1611,7 @@ private void PrepareConnection(DbConnection owningObject, DbConnectionInternal c if (!isAlive) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Connection {1}, found dead and removed.", + "ChannelDbConnectionPool.GetFromTransactedPool | INFO | {0}, Connection {1}, found dead and removed.", Id, connection.ObjectID); RemoveConnection(connection); @@ -1702,7 +1702,7 @@ internal void RequestWarmup() } SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Failed to schedule warmup loop, absorbing: {1}", Id, ex); + "ChannelDbConnectionPool.RequestWarmup | INFO | {0}, Failed to schedule warmup loop, absorbing: {1}", Id, ex); } } @@ -1778,7 +1778,7 @@ private async Task RunWarmupLoopAsync() // during the blocking window and resume creating on demand once it expires, // and the next below-minimum trigger re-requests warmup (Story 3). SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Warmup connection creation failed, stopping pass: {1}", Id, ex); + "ChannelDbConnectionPool.RunWarmupLoopAsync | INFO | {0}, Warmup connection creation failed, stopping pass: {1}", Id, ex); break; } @@ -1822,7 +1822,7 @@ private async Task RunWarmupLoopAsync() // rather than absorbed into a pool that keeps running in a potentially corrupted // state; the finally below still releases the single-loop guard on that path. SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Warmup loop failed, absorbing: {1}", Id, ex); + "ChannelDbConnectionPool.RunWarmupLoopAsync | INFO | {0}, Warmup loop failed, absorbing: {1}", Id, ex); } finally { @@ -1849,7 +1849,7 @@ private async Task RunWarmupLoopAsync() internal void PruneConnections(int count) { SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Pruning up to {1} idle connections. IdleCount={2}, Count={3}", + "ChannelDbConnectionPool.PruneConnections | INFO | {0}, Pruning up to {1} idle connections. IdleCount={2}, Count={3}", Id, count, IdleCount, @@ -1873,7 +1873,7 @@ internal void PruneConnections(int count) } SqlClientEventSource.Log.TryPoolerTraceEvent( - " {0}, Pruned {1} idle connections.", + "ChannelDbConnectionPool.PruneConnections | INFO | {0}, Pruned {1} idle connections.", Id, pruned); } diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/PoolPruner.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/PoolPruner.cs index cd096299a4..3611afda5e 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/PoolPruner.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/PoolPruner.cs @@ -136,7 +136,7 @@ internal PoolPruner(ChannelDbConnectionPool pool, TimeSpan idleTimeout) // cadence so operators can tell why a very large Connection Idle Timeout samples less // frequently than the default 10-second interval. SqlClientEventSource.Log.TryPoolerTraceEvent( - " Idle timeout {0}s derived a pruning interval of {1}s with {2} samples (max {3}).", + "PoolPruner.PoolPruner | INFO | Idle timeout {0}s derived a pruning interval of {1}s with {2} samples (max {3}).", idleTimeoutSeconds, intervalSeconds, sampleSize, MaxSampleSize); } diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/TransactedConnectionPool.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/TransactedConnectionPool.cs index cf72f8753d..9da6759a0b 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/TransactedConnectionPool.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/TransactedConnectionPool.cs @@ -82,7 +82,7 @@ internal TransactedConnectionPool(IDbConnectionPool pool, ISqlClientMetrics metr Pool = pool; _metrics = metrics; TransactedConnections = new Dictionary(); - SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Constructed for connection pool {1}", Id, Pool.Id); + SqlClientEventSource.Log.TryPoolerTraceEvent("TransactedConnectionPool.TransactedConnectionPool | INFO | {0}, Constructed for connection pool {1}", Id, Pool.Id); } #region Properties @@ -156,7 +156,7 @@ internal TransactedConnectionPool(IDbConnectionPool pool, ISqlClientMetrics metr if (transactedObject != null) { - SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Transaction {1}, Connection {2}, Popped.", Id, transaction.GetHashCode(), transactedObject.ObjectID); + SqlClientEventSource.Log.TryPoolerTraceEvent("TransactedConnectionPool.GetTransactedObject | INFO | {0}, Transaction {1}, Connection {2}, Popped.", Id, transaction.GetHashCode(), transactedObject.ObjectID); } return transactedObject; } @@ -196,7 +196,7 @@ internal void PutTransactedObject(Transaction transaction, DbConnectionInternal { // TODO: validate that we're not adding the same connection twice? // Debug.Assert(0 > connections.IndexOf(transactedObject), "adding to pool a second time?"); - SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Transaction {1}, Connection {2}, Pushing.", Id, transaction.GetHashCode(), transactedObject.ObjectID); + SqlClientEventSource.Log.TryPoolerTraceEvent("TransactedConnectionPool.PutTransactedObject | INFO | {0}, Transaction {1}, Connection {2}, Pushing.", Id, transaction.GetHashCode(), transactedObject.ObjectID); connections.Add(transactedObject); } } @@ -230,13 +230,13 @@ internal void PutTransactedObject(Transaction transaction, DbConnectionInternal lock (connections) { Debug.Assert(0 > connections.IndexOf(transactedObject), "adding to pool a second time?"); - SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Transaction {1}, Connection {2}, Pushing.", Id, transaction.GetHashCode(), transactedObject.ObjectID); + SqlClientEventSource.Log.TryPoolerTraceEvent("TransactedConnectionPool.PutTransactedObject | INFO | {0}, Transaction {1}, Connection {2}, Pushing.", Id, transaction.GetHashCode(), transactedObject.ObjectID); connections.Add(transactedObject); } } else { - SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Transaction {1}, Connection {2}, Adding List to transacted pool.", Id, transaction.GetHashCode(), transactedObject.ObjectID); + SqlClientEventSource.Log.TryPoolerTraceEvent("TransactedConnectionPool.PutTransactedObject | INFO | {0}, Transaction {1}, Connection {2}, Adding List to transacted pool.", Id, transaction.GetHashCode(), transactedObject.ObjectID); // add the connection/transacted object to the list newConnections.Add(transactedObject); @@ -264,7 +264,7 @@ internal void PutTransactedObject(Transaction transaction, DbConnectionInternal } } } - SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Transaction {1}, Connection {2}, Added.", Id, transaction.GetHashCode(), transactedObject.ObjectID); + SqlClientEventSource.Log.TryPoolerTraceEvent("TransactedConnectionPool.PutTransactedObject | INFO | {0}, Transaction {1}, Connection {2}, Added.", Id, transaction.GetHashCode(), transactedObject.ObjectID); } _metrics.EnterFreeConnection(); @@ -288,7 +288,7 @@ internal void PutTransactedObject(Transaction transaction, DbConnectionInternal /// internal void TransactionEnded(Transaction transaction, DbConnectionInternal transactedObject) { - SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Transaction {1}, Connection {2}, Transaction Completed", Id, transaction.GetHashCode(), transactedObject.ObjectID); + SqlClientEventSource.Log.TryPoolerTraceEvent("TransactedConnectionPool.TransactionEnded | INFO | {0}, Transaction {1}, Connection {2}, Transaction Completed", Id, transaction.GetHashCode(), transactedObject.ObjectID); TransactedConnectionList? connections; int entry = -1; @@ -321,7 +321,7 @@ internal void TransactionEnded(Transaction transaction, DbConnectionInternal tra // safely remove the list from the transacted pool. if (0 >= connections.Count) { - SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Transaction {1}, Removing List from transacted pool.", Id, transaction.GetHashCode()); + SqlClientEventSource.Log.TryPoolerTraceEvent("TransactedConnectionPool.TransactionEnded | INFO | {0}, Transaction {1}, Removing List from transacted pool.", Id, transaction.GetHashCode()); TransactedConnections.Remove(transaction); // we really need to dispose our connection list; it may have @@ -337,7 +337,7 @@ internal void TransactionEnded(Transaction transaction, DbConnectionInternal tra } else { - SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Transaction {1}, Connection {2}, Transacted pool not yet created prior to transaction completing. Connection may be leaked.", Id, transaction.GetHashCode(), transactedObject.ObjectID); + SqlClientEventSource.Log.TryPoolerTraceEvent("TransactedConnectionPool.TransactionEnded | INFO | {0}, Transaction {1}, Connection {2}, Transacted pool not yet created prior to transaction completing. Connection may be leaked.", Id, transaction.GetHashCode(), transactedObject.ObjectID); } } From 56731d23111eb1e71ceaa40d9b8830f8a813f273 Mon Sep 17 00:00:00 2001 From: Malcolm Daigle Date: Thu, 13 Aug 2026 10:22:44 -0700 Subject: [PATCH 08/19] Simplify pool V2 trace call sites Inline the TraceNotLive helper directly into each IsLiveConnection rejection branch. The indirection obscured which specific check failed at the call site and added an extra frame for no real benefit over four short, self-contained trace calls. Also fix stack-flavored wording ("Popped"/"Pushing... to general pool") left over from the wait-handle pool's stack-based implementation. ChannelDbConnectionPool uses a Channel, not a stack, so GetIdleConnection/PutConnectionInIdleChannel now read "Read from idle channel"/"Writing to idle channel" instead. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- .../ConnectionPool/ChannelDbConnectionPool.cs | 40 +++++++++---------- 1 file changed, 18 insertions(+), 22 deletions(-) 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 42ecde7e28..df7eaea5c9 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 @@ -693,7 +693,7 @@ private void PutConnectionInIdleChannel(DbConnectionInternal connection, bool pr } SqlClientEventSource.Log.TryPoolerTraceEvent( - "ChannelDbConnectionPool.PutConnectionInIdleChannel | INFO | {0}, Connection {1}, Pushing to general pool.", + "ChannelDbConnectionPool.PutConnectionInIdleChannel | INFO | {0}, Connection {1}, Writing to idle channel.", Id, connection.ObjectID); @@ -1239,7 +1239,10 @@ private bool IsLiveConnection(DbConnectionInternal connection, bool probeLivenes idleTimeout != TimeSpan.Zero && _timeProvider.GetUtcNow().UtcDateTime - connection.ReturnedTime > idleTimeout) { - TraceNotLive(connection, "exceeded the connection idle timeout"); + SqlClientEventSource.Log.TryPoolerTraceEvent( + "ChannelDbConnectionPool.IsLiveConnection | INFO | {0}, Connection {1}, exceeded the connection idle timeout and removed.", + Id, + connection.ObjectID); return false; } @@ -1247,43 +1250,36 @@ private bool IsLiveConnection(DbConnectionInternal connection, bool probeLivenes // polls the socket, so it must not run on a thread we do not own. if (probeLiveness && !connection.IsConnectionAlive()) { - TraceNotLive(connection, "found dead"); + SqlClientEventSource.Log.TryPoolerTraceEvent( + "ChannelDbConnectionPool.IsLiveConnection | INFO | {0}, Connection {1}, found dead and removed.", + Id, + connection.ObjectID); return false; } // Connection has been alive longer than the load balance timeout if (LoadBalanceTimeout != TimeSpan.Zero && DateTime.UtcNow > connection.CreateTime + LoadBalanceTimeout) { - TraceNotLive(connection, "exceeded the load balance timeout"); + SqlClientEventSource.Log.TryPoolerTraceEvent( + "ChannelDbConnectionPool.IsLiveConnection | INFO | {0}, Connection {1}, exceeded the load balance timeout and removed.", + Id, + connection.ObjectID); return false; } // Connection was created before the last Clear, so it's stale. if (connection.ClearGeneration != _clearGeneration) { - TraceNotLive(connection, "was created before the last Clear"); + SqlClientEventSource.Log.TryPoolerTraceEvent( + "ChannelDbConnectionPool.IsLiveConnection | INFO | {0}, Connection {1}, was created before the last Clear and removed.", + Id, + connection.ObjectID); return false; } return true; } - /// - /// Emits the trace for a connection that failed the gate. - /// Split out so each rejection reason is reported individually: the caller only sees that - /// the connection was discarded, which on its own does not explain whether the pool is - /// churning because of idle timeout, load balancing, a Clear, or genuine server failures. - /// - /// The connection that failed the liveness gate. - /// Why the connection was rejected, phrased to read as - /// "Connection {id}, {reason} and removed." - private void TraceNotLive(DbConnectionInternal connection, string reason) => - SqlClientEventSource.Log.TryPoolerTraceEvent( - "ChannelDbConnectionPool.TraceNotLive | INFO | {0}, Connection {1}, {2} and removed.", - Id, - connection.ObjectID, - reason); - /// /// Closes the provided connection and removes it from the pool, freeing its slot. /// @@ -1380,7 +1376,7 @@ private void RemoveConnection(DbConnectionInternal connection) } SqlClientEventSource.Log.TryPoolerTraceEvent( - "ChannelDbConnectionPool.GetIdleConnection | INFO | {0}, Connection {1}, Popped from general pool.", + "ChannelDbConnectionPool.GetIdleConnection | INFO | {0}, Connection {1}, Read from idle channel.", Id, connection.ObjectID); From 2e0dcf9c93e69d0f92821e258b955cb8725c8dad Mon Sep 17 00:00:00 2001 From: Malcolm Daigle Date: Thu, 13 Aug 2026 10:25:51 -0700 Subject: [PATCH 09/19] Add missing coverage traces for warmup and connection retrieval RequestWarmup only traced the failure-to-schedule path; add a trace on successful scheduling so a warmup pass is visible from start to finish. RunWarmupLoopAsync had no start-of-loop trace and no summary of how many connections it actually warmed up; add both, including the count on the absorbed-exception path. GetInternalConnection traced entry, timeout, and shutdown, but never a success line; add one once a connection is obtained and prepared. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- .../ConnectionPool/ChannelDbConnectionPool.cs | 19 ++++++++++++++++++- 1 file changed, 18 insertions(+), 1 deletion(-) 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 df7eaea5c9..c9e0be819e 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 @@ -1501,6 +1501,10 @@ private async Task GetInternalConnection( PrepareConnection(owningConnection, connection, transaction); Metrics.SoftConnectRequest(); + + SqlClientEventSource.Log.TryPoolerTraceEvent( + "ChannelDbConnectionPool.GetInternalConnection | INFO | {0}, Connection {1}, Obtained.", Id, connection.ObjectID); + return connection; } @@ -1683,6 +1687,9 @@ internal void RequestWarmup() // absorbs its own exceptions and always releases the single-loop guard on exit. The // task is published so tests can await a warmup pass to a deterministic completion. WarmupLoopTask = Task.Run(RunWarmupLoopAsync); + + SqlClientEventSource.Log.TryPoolerTraceEvent( + "ChannelDbConnectionPool.RequestWarmup | INFO | {0}, Scheduled warmup loop. Count={1}, MinPoolSize={2}", Id, Count, MinPoolSize); } catch (Exception ex) { @@ -1714,6 +1721,11 @@ internal void RequestWarmup() /// private async Task RunWarmupLoopAsync() { + int warmedUp = 0; + + SqlClientEventSource.Log.TryPoolerTraceEvent( + "ChannelDbConnectionPool.RunWarmupLoopAsync | INFO | {0}, Warmup loop starting. Count={1}, MinPoolSize={2}", Id, Count, MinPoolSize); + try { CancellationToken token; @@ -1803,6 +1815,8 @@ private async Task RunWarmupLoopAsync() break; } + warmedUp++; + // OpenNewInternalConnection is synchronous and blocks the loop's thread for // the duration of the physical open. Yield between creations so a multi- // connection warmup returns its thread-pool worker to the scheduler between @@ -1810,6 +1824,9 @@ private async Task RunWarmupLoopAsync() // responsive to cancellation. There is no sync-over-async anywhere in this path. await Task.Yield(); } + + SqlClientEventSource.Log.TryPoolerTraceEvent( + "ChannelDbConnectionPool.RunWarmupLoopAsync | INFO | {0}, Warmup loop finished. Warmed up {1} connections. Count={2}", Id, warmedUp, Count); } catch (Exception ex) when (ADP.IsCatchableExceptionType(ex)) { @@ -1818,7 +1835,7 @@ private async Task RunWarmupLoopAsync() // rather than absorbed into a pool that keeps running in a potentially corrupted // state; the finally below still releases the single-loop guard on that path. SqlClientEventSource.Log.TryPoolerTraceEvent( - "ChannelDbConnectionPool.RunWarmupLoopAsync | INFO | {0}, Warmup loop failed, absorbing: {1}", Id, ex); + "ChannelDbConnectionPool.RunWarmupLoopAsync | INFO | {0}, Warmup loop failed, absorbing. Warmed up {1} connections: {2}", Id, warmedUp, ex); } finally { From a005f3c63f60f4a4304641d6a5a0b08bdd916417 Mon Sep 17 00:00:00 2001 From: Malcolm Daigle Date: Thu, 13 Aug 2026 11:19:29 -0700 Subject: [PATCH 10/19] Feed connection metrics through DbConnectionInternal's constructor Decouple the metrics sink DbConnectionInternal reports to from Pool: it is not inherently tied to a pool instance, and a connection need not be pooled at all. Metrics is now a readonly property set via a new constructor overload, defaulting to the process-wide instance when none is supplied. SqlConnectionInternal threads its own metrics parameter down to the base constructor, and SqlConnectionFactory passes its injected Metrics instance at both construction sites instead of assigning the property after construction. Rename ChannelDbConnectionPoolInstrumentationTest -> DbConnectionPoolInstrumentationTest since it already covers both ChannelDbConnectionPool and WaitHandleDbConnectionPool, parameterized over PoolImplementation. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- .../Data/ProviderBase/DbConnectionInternal.cs | 22 ++- .../Connection/SqlConnectionInternal.cs | 6 +- .../Data/SqlClient/SqlConnectionFactory.cs | 8 +- .../ChannelDbConnectionPoolTest.cs | 15 +- ...=> DbConnectionPoolInstrumentationTest.cs} | 129 ++++++++++++++++-- 5 files changed, 161 insertions(+), 19 deletions(-) rename src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/{ChannelDbConnectionPoolInstrumentationTest.cs => DbConnectionPoolInstrumentationTest.cs} (73%) 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 00df93f788..3008f59c38 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/ProviderBase/DbConnectionInternal.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/ProviderBase/DbConnectionInternal.cs @@ -12,6 +12,7 @@ using Microsoft.Data.Common; using Microsoft.Data.SqlClient; using Microsoft.Data.SqlClient.ConnectionPool; +using Microsoft.Data.SqlClient.Diagnostics; using Microsoft.Data.SqlClient.Internal; #if NETFRAMEWORK @@ -77,6 +78,12 @@ protected DbConnectionInternal() : this(ConnectionState.Open, true, false) // Constructor for internal connections internal DbConnectionInternal(ConnectionState state, bool hidePassword, bool allowSetConnectionString) + : this(state, hidePassword, allowSetConnectionString, metrics: null) + { + } + + // Constructor for internal connections + internal DbConnectionInternal(ConnectionState state, bool hidePassword, bool allowSetConnectionString, ISqlClientMetrics metrics) { AllowSetConnectionString = allowSetConnectionString; ShouldHidePassword = hidePassword; @@ -87,6 +94,7 @@ internal DbConnectionInternal(ConnectionState state, bool hidePassword, bool all // Without this initialization, ReturnedTime would default to DateTime.MinValue, which would cause // IsLiveConnection to immediately evict every new connection whenever IdleTimeout is configured. ReturnedTime = CreateTime; + Metrics = metrics ?? SqlClientDiagnostics.Metrics; } #region Properties @@ -179,6 +187,16 @@ internal bool IsInPool /// internal IDbConnectionPool Pool { get; private set; } + /// + /// The metrics sink this connection reports its activation state to. Supplied by the + /// that created this connection, from its own injected + /// instance, rather than derived from : the metrics sink is not + /// inherently tied to a pool, and a connection is not necessarily pooled at all. Defaults + /// to the process-wide instance when no metrics sink is supplied to the constructor (e.g. + /// a test double constructed directly), so it still reports somewhere. + /// + internal ISqlClientMetrics Metrics { get; } + public abstract string ServerVersion { get; } public virtual ConnectionCapabilities Capabilities => null; @@ -368,7 +386,7 @@ internal void ActivateConnection(Transaction transaction) Activate(transaction); - SqlClientDiagnostics.Metrics.EnterActiveConnection(); + Metrics.EnterActiveConnection(); } internal void AddWeakReference(object value, int tag) @@ -522,7 +540,7 @@ internal void DeactivateConnection() // the Deactivate method publicly. SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Deactivating", ObjectID); - SqlClientDiagnostics.Metrics.ExitActiveConnection(); + Metrics.ExitActiveConnection(); if (!IsConnectionDoomed && Pool.UseLoadBalancing) { 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 408564f855..06fc89f201 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 @@ -4,6 +4,7 @@ using System; using System.Collections.Generic; +using System.Data; using System.Data.Common; using System.Diagnostics; using System.Globalization; @@ -15,6 +16,7 @@ using Microsoft.Data.Common; using Microsoft.Data.ProviderBase; using Microsoft.Data.SqlClient.ConnectionPool; +using Microsoft.Data.SqlClient.Diagnostics; using Microsoft.Data.SqlClient.Internal; using Microsoft.Data.SqlClient.Utilities; using IsolationLevel = System.Data.IsolationLevel; @@ -306,7 +308,9 @@ internal SqlConnectionInternal( string accessToken = null, IDbConnectionPool pool = null, Func> accessTokenCallback = null, - SspiContextProvider sspiContextProvider = null) + SspiContextProvider sspiContextProvider = null, + ISqlClientMetrics metrics = null) + : base(ConnectionState.Open, true, false, metrics) { Debug.Assert(connectionOptions is not null, "null connectionOptions"); diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlConnectionFactory.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlConnectionFactory.cs index 086d607179..c3b7bfd13b 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlConnectionFactory.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/SqlConnectionFactory.cs @@ -192,7 +192,7 @@ internal DbConnectionInternal CreateNonPooledConnection( timeout); if (newConnection is not null) { - SqlClientDiagnostics.Metrics.HardConnectRequest(); + Metrics.HardConnectRequest(); newConnection.MakeNonPooledObject(owningConnection); } @@ -711,7 +711,8 @@ protected virtual DbConnectionInternal CreateConnection( newSecurePassword: null, redirectedUserInstance: false, applyTransientFaultHandling: applyTransientFaultHandling, - sspiContextProvider: key.SspiContextProvider); + sspiContextProvider: key.SspiContextProvider, + metrics: Metrics); using (sseConnection) { // NOTE: Retrieve here. This user instance name will be @@ -772,7 +773,8 @@ protected virtual DbConnectionInternal CreateConnection( key.AccessToken, pool, key.AccessTokenCallback, - key.SspiContextProvider); + key.SspiContextProvider, + metrics: Metrics); } private static DbConnectionPoolGroupOptions CreateConnectionPoolGroupOptions(SqlConnectionOptions connectionOptions) diff --git a/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/ChannelDbConnectionPoolTest.cs b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/ChannelDbConnectionPoolTest.cs index 6fc0baf2cf..a1fb11b9b1 100644 --- a/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/ChannelDbConnectionPoolTest.cs +++ b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/ChannelDbConnectionPoolTest.cs @@ -4,6 +4,7 @@ using System; using System.Collections.Concurrent; +using System.Data; using System.Data.Common; using System.Threading; using System.Threading.RateLimiting; @@ -1398,7 +1399,7 @@ protected override DbConnectionInternal CreateConnection( TimeoutTimer timeout) { CapturedTimeout = timeout; - return new StubDbConnectionInternal(); + return new StubDbConnectionInternal(Metrics); } } @@ -1430,6 +1431,11 @@ protected override DbConnectionInternal CreateConnection( /// internal class StubDbConnectionInternal : DbConnectionInternal { + internal StubDbConnectionInternal(ISqlClientMetrics? metrics = null) + : base(ConnectionState.Open, true, false, metrics) + { + } + #region Not Implemented Members public override string ServerVersion => throw new NotImplementedException(); @@ -1442,12 +1448,15 @@ public override DbTransaction BeginTransaction(System.Data.IsolationLevel il) public override void EnlistTransaction(Transaction transaction) { - return; + if (transaction != null) + { + EnlistedTransaction = transaction; + } } protected override void Activate(Transaction transaction) { - return; + EnlistedTransaction = transaction; } protected override void Deactivate() diff --git a/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/ChannelDbConnectionPoolInstrumentationTest.cs b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/DbConnectionPoolInstrumentationTest.cs similarity index 73% rename from src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/ChannelDbConnectionPoolInstrumentationTest.cs rename to src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/DbConnectionPoolInstrumentationTest.cs index cd0d8970de..3a240ab5e9 100644 --- a/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/ChannelDbConnectionPoolInstrumentationTest.cs +++ b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/DbConnectionPoolInstrumentationTest.cs @@ -8,6 +8,7 @@ using System.Linq; using System.Threading; using System.Threading.RateLimiting; +using System.Transactions; using Microsoft.Data.Common; using Microsoft.Data.Common.ConnectionString; using Microsoft.Data.ProviderBase; @@ -21,10 +22,12 @@ namespace Microsoft.Data.SqlClient.UnitTests.ConnectionPool { /// - /// Verifies the diagnostic instrumentation of : the pool - /// metrics counters emitted across the connection lifecycle. + /// Verifies the diagnostic instrumentation shared by and + /// : the pool metrics counters emitted across the + /// connection lifecycle, parameterized over both pool implementations via + /// wherever their behavior is expected to match. /// - public class ChannelDbConnectionPoolInstrumentationTest + public class DbConnectionPoolInstrumentationTest { /// /// Builds a pool for instrumentation tests. Defaults mirror @@ -141,8 +144,11 @@ private static IDbConnectionPool ConstructPool( /// by the caller is expected to be zero, so an unexpected emission fails the test. /// /// - /// The active-connection gauges are not parameters because they are mechanically derived: - /// each connect increments one and the matching disconnect decrements it. + /// is a parameter, not derived from the soft-connect + /// counters, precisely because it is not guaranteed to move in lockstep with them: this is + /// the counter https://github.com/dotnet/SqlClient/issues/3640 broke by deactivating a + /// transacted connection twice on its way back to general circulation, which decremented + /// activeConnections an extra time without touching softConnects/softDisconnects at all. /// private static void AssertCounters( FakeSqlClientMetrics metrics, @@ -152,7 +158,8 @@ private static void AssertCounters( long softDisconnects = 0, long pooledConnections = 0, long freeConnections = 0, - long reclaimedConnections = 0) + long reclaimedConnections = 0, + long activeConnections = 0) { (string Name, long Expected, long Actual)[] counters = { @@ -165,6 +172,7 @@ private static void AssertCounters( ("pooledConnections", pooledConnections, metrics.PooledConnections), ("freeConnections", freeConnections, metrics.FreeConnections), ("reclaimedConnections", reclaimedConnections, metrics.ReclaimedConnections), + ("activeConnections", activeConnections, metrics.ActiveConnections), // Not emitted through a pool's metrics instance, so any non-zero value here means a // counter has moved to the pool that the tests have not accounted for. @@ -173,7 +181,6 @@ private static void AssertCounters( ("inactiveConnectionPoolGroups", 0, metrics.InactiveConnectionPoolGroups), ("activeConnectionPools", 0, metrics.ActiveConnectionPools), ("inactiveConnectionPools", 0, metrics.InactiveConnectionPools), - ("activeConnections", 0, metrics.ActiveConnections), ("stasisConnections", 0, metrics.StasisConnections), }; @@ -215,7 +222,8 @@ public void NewConnection_CountsHardConnectAndPooledConnection(PoolImplementatio metrics, hardConnects: 1, softConnects: 1, - pooledConnections: 1); + pooledConnections: 1, + activeConnections: 1); } /// @@ -245,7 +253,8 @@ public void IdleConnectionReuse_CountsSoftConnect(PoolImplementation implementat hardConnects: 1, softConnects: 2, softDisconnects: 1, - pooledConnections: 1); + pooledConnections: 1, + activeConnections: 1); } /// @@ -337,7 +346,107 @@ public void ReplaceConnection_CountsHardDisconnectForDiscardedConnection() hardConnects: 2, hardDisconnects: 1, softConnects: 2, - pooledConnections: 1); + pooledConnections: 1, + activeConnections: 1); + } + + /// + /// Regression test for https://github.com/dotnet/SqlClient/issues/3640. Returning a + /// connection while it is still enlisted in a transaction parks it in the transacted + /// store rather than handing it back for reuse, but the connection is still deactivated + /// exactly once. When the transaction later ends and the connection rejoins the idle + /// pool, that hand-off must not deactivate it a second time, or activeConnections is + /// decremented twice for a single logical checkout. + /// + [Theory] + [InlineData(PoolImplementation.WaitHandle)] + [InlineData(PoolImplementation.Channel)] + public void TransactionCommit_ReleasingParkedConnection_KeepsActiveConnectionCountBalanced(PoolImplementation implementation) + { + // Arrange + FakeSqlClientMetrics metrics = new(); + IDbConnectionPool pool = ConstructPool(implementation, metrics, new SuccessfulSqlConnectionFactory(metrics)); + + using (TransactionScope scope = new()) + { + SqlConnection owner = new(); + Assert.True(pool.TryGetConnection(owner, null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out DbConnectionInternal? connection)); + Assert.NotNull(connection); + + // Act - the connection is still enlisted, so it is parked rather than reused. + pool.ReturnInternalConnection(connection!, owner); + + // Assert - the park deactivates the connection exactly once. + AssertCounters( + metrics, + hardConnects: 1, + softConnects: 1, + softDisconnects: 1, + pooledConnections: 1, + freeConnections: 1, + activeConnections: 0); + + scope.Complete(); + } + + // Assert - once the transaction commits and the connection rejoins the idle pool, the + // counters must be unchanged from the park above. If the #3640 bug pattern were + // reintroduced (deactivating on the way out of the transacted store, rather than + // resetting), activeConnections would go negative here. + AssertCounters( + metrics, + hardConnects: 1, + softConnects: 1, + softDisconnects: 1, + pooledConnections: 1, + freeConnections: 1, + activeConnections: 0); + } + + /// + /// Same regression as , + /// but the transaction is rolled back rather than committed. Rollback and commit both end + /// the transaction through the same completion callback, so this covers that the fix does + /// not depend on the outcome of the transaction. + /// + [Theory] + [InlineData(PoolImplementation.WaitHandle)] + [InlineData(PoolImplementation.Channel)] + public void TransactionRollback_ReleasingParkedConnection_KeepsActiveConnectionCountBalanced(PoolImplementation implementation) + { + // Arrange + FakeSqlClientMetrics metrics = new(); + IDbConnectionPool pool = ConstructPool(implementation, metrics, new SuccessfulSqlConnectionFactory(metrics)); + + using (TransactionScope scope = new()) + { + SqlConnection owner = new(); + Assert.True(pool.TryGetConnection(owner, null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out DbConnectionInternal? connection)); + Assert.NotNull(connection); + + pool.ReturnInternalConnection(connection!, owner); + + AssertCounters( + metrics, + hardConnects: 1, + softConnects: 1, + softDisconnects: 1, + pooledConnections: 1, + freeConnections: 1, + activeConnections: 0); + + // Act - scope disposed without Complete(), rolling the transaction back. + } + + // Assert - same expectation as the commit case: no extra deactivation on rollback. + AssertCounters( + metrics, + hardConnects: 1, + softConnects: 1, + softDisconnects: 1, + pooledConnections: 1, + freeConnections: 1, + activeConnections: 0); } #endregion From 21644e4f5f99d46f0274e915ef074dae5335dbb2 Mon Sep 17 00:00:00 2001 From: Malcolm Daigle Date: Thu, 13 Aug 2026 11:30:15 -0700 Subject: [PATCH 11/19] Avoid duplicating base constructor defaults; drop dead pool helper Add a metrics-only DbConnectionInternal(ISqlClientMetrics) constructor that delegates to the existing this(ConnectionState.Open, true, false, metrics) constructor, so SqlConnectionInternal and StubDbConnectionInternal call base(metrics) instead of re-stating the ConnectionState.Open, true, false defaults inline. Remove the unused ChannelDbConnectionPool-only ConstructPool overload and its ConcurrencyLimiter/RateLimiting using from DbConnectionPoolInstrumentationTest.cs: every test call site already uses the PoolImplementation-parameterized overload added when WaitHandle coverage was introduced. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- .../Data/ProviderBase/DbConnectionInternal.cs | 6 +++++ .../Connection/SqlConnectionInternal.cs | 3 +-- .../ChannelDbConnectionPoolTest.cs | 3 +-- .../DbConnectionPoolInstrumentationTest.cs | 26 ------------------- 4 files changed, 8 insertions(+), 30 deletions(-) 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 3008f59c38..b15e066147 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/ProviderBase/DbConnectionInternal.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/ProviderBase/DbConnectionInternal.cs @@ -76,6 +76,12 @@ protected DbConnectionInternal() : this(ConnectionState.Open, true, false) { } + // Constructor for internal connections that report to a specific metrics sink, reusing + // the same defaults as the parameterless constructor above. + protected DbConnectionInternal(ISqlClientMetrics metrics) : this(ConnectionState.Open, true, false, metrics) + { + } + // Constructor for internal connections internal DbConnectionInternal(ConnectionState state, bool hidePassword, bool allowSetConnectionString) : this(state, hidePassword, allowSetConnectionString, metrics: null) 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 06fc89f201..e43c3ecebe 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 @@ -4,7 +4,6 @@ using System; using System.Collections.Generic; -using System.Data; using System.Data.Common; using System.Diagnostics; using System.Globalization; @@ -310,7 +309,7 @@ internal SqlConnectionInternal( Func> accessTokenCallback = null, SspiContextProvider sspiContextProvider = null, ISqlClientMetrics metrics = null) - : base(ConnectionState.Open, true, false, metrics) + : base(metrics) { Debug.Assert(connectionOptions is not null, "null connectionOptions"); diff --git a/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/ChannelDbConnectionPoolTest.cs b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/ChannelDbConnectionPoolTest.cs index a1fb11b9b1..c545685c9e 100644 --- a/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/ChannelDbConnectionPoolTest.cs +++ b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/ChannelDbConnectionPoolTest.cs @@ -4,7 +4,6 @@ using System; using System.Collections.Concurrent; -using System.Data; using System.Data.Common; using System.Threading; using System.Threading.RateLimiting; @@ -1432,7 +1431,7 @@ protected override DbConnectionInternal CreateConnection( internal class StubDbConnectionInternal : DbConnectionInternal { internal StubDbConnectionInternal(ISqlClientMetrics? metrics = null) - : base(ConnectionState.Open, true, false, metrics) + : base(metrics) { } diff --git a/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/DbConnectionPoolInstrumentationTest.cs b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/DbConnectionPoolInstrumentationTest.cs index 3a240ab5e9..2605c8c8b3 100644 --- a/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/DbConnectionPoolInstrumentationTest.cs +++ b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/DbConnectionPoolInstrumentationTest.cs @@ -7,7 +7,6 @@ using System.Data.Common; using System.Linq; using System.Threading; -using System.Threading.RateLimiting; using System.Transactions; using Microsoft.Data.Common; using Microsoft.Data.Common.ConnectionString; @@ -29,31 +28,6 @@ namespace Microsoft.Data.SqlClient.UnitTests.ConnectionPool /// public class DbConnectionPoolInstrumentationTest { - /// - /// Builds a pool for instrumentation tests. Defaults mirror - /// so behavior is comparable across suites. - /// - /// The factory used to create physical connections. - /// Connection string backing the pool group. Tests override - /// it to control the Pool Blocking Period. - /// Maximum pool size. - /// Minimum pool size. - /// Connection Idle Timeout, in seconds. - /// Optional limiter throttling physical creates. - private static ChannelDbConnectionPool ConstructPool( - SqlConnectionFactory connectionFactory, - string connectionString = "Data Source=localhost;", - int maxPoolSize = 50, - int minPoolSize = 0, - int idleTimeout = 0, - ConcurrencyLimiter? connectionCreationRateLimiter = null) - => new( - connectionFactory, - ConstructPoolGroup(connectionString, maxPoolSize, minPoolSize, idleTimeout), - DbConnectionPoolIdentity.NoIdentity, - new DbConnectionPoolProviderInfo(), - connectionCreationRateLimiter); - /// /// Builds the pool group shared by both pool implementations. /// From a970bdd61108256a04b1958c4eb30c4d93320edd Mon Sep 17 00:00:00 2001 From: Malcolm Daigle Date: Thu, 13 Aug 2026 12:06:55 -0700 Subject: [PATCH 12/19] Clean up test file structure. --- .../DbConnectionPoolInstrumentationTest.cs | 42 +++++++------------ 1 file changed, 15 insertions(+), 27 deletions(-) diff --git a/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/DbConnectionPoolInstrumentationTest.cs b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/DbConnectionPoolInstrumentationTest.cs index 2605c8c8b3..88d782a58f 100644 --- a/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/DbConnectionPoolInstrumentationTest.cs +++ b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/DbConnectionPoolInstrumentationTest.cs @@ -14,6 +14,7 @@ using Microsoft.Data.SqlClient.ConnectionPool; using Microsoft.Data.SqlClient.Diagnostics; using Microsoft.Data.SqlClient.Tests.Common; +using Microsoft.Extensions.Time.Testing; using Xunit; using static Microsoft.Data.SqlClient.UnitTests.ConnectionPool.ChannelDbConnectionPoolTest; @@ -28,6 +29,18 @@ namespace Microsoft.Data.SqlClient.UnitTests.ConnectionPool /// public class DbConnectionPoolInstrumentationTest { + /// + /// Identifies which pool implementation a parameterized metric test exercises. + /// + public enum PoolImplementation + { + /// The legacy . + WaitHandle, + + /// The . + Channel, + } + /// /// Builds the pool group shared by both pool implementations. /// @@ -52,29 +65,6 @@ private static DbConnectionPoolGroup ConstructPoolGroup( poolGroupOptions); } - #region Metric parity - - // Each test gives its pool its own metrics instance, so the counters observe only that - // pool's activity and can be asserted exactly. They run against both pool implementations - // so that any divergence in what the channel pool emits shows up as a failing test rather - // than as a silent telemetry gap. - // - // Counters emitted outside the pool are still process-wide: DbConnectionInternal reports - // active-connection and stasis counts against the global instance, so those are not - // asserted here. - - /// - /// Identifies which pool implementation a parameterized metric test exercises. - /// - public enum PoolImplementation - { - /// The legacy . - WaitHandle, - - /// The . - Channel, - } - /// /// Builds the requested pool implementation behind the shared pool interface, reporting to /// the supplied metrics instance. @@ -97,7 +87,7 @@ private static IDbConnectionPool ConstructPool( poolGroup, DbConnectionPoolIdentity.NoIdentity, new DbConnectionPoolProviderInfo(), - timeProvider: null, + timeProvider: new FakeTimeProvider(), metrics: metrics), PoolImplementation.Channel => new ChannelDbConnectionPool( @@ -106,7 +96,7 @@ private static IDbConnectionPool ConstructPool( DbConnectionPoolIdentity.NoIdentity, new DbConnectionPoolProviderInfo(), connectionCreationRateLimiter: null, - timeProvider: null, + timeProvider: new FakeTimeProvider(), metrics: metrics), _ => throw new ArgumentOutOfRangeException(nameof(implementation)), @@ -423,8 +413,6 @@ public void TransactionRollback_ReleasingParkedConnection_KeepsActiveConnectionC activeConnections: 0); } - #endregion - #region Test classes /// From 14dbff12be48b54ea4c47fc74185013d2b4d4971 Mon Sep 17 00:00:00 2001 From: Malcolm Daigle Date: Fri, 14 Aug 2026 09:12:07 -0700 Subject: [PATCH 13/19] Balance soft and hard disconnects when replacing a connection ReplaceConnection vends a new connection to the caller and destroys the one it displaced. Both pools counted the soft connect for the replacement but nothing for the retirement, so active-soft-connects drifted up by one per replacement and never came back down. The wait handle pool also disposed the old connection directly rather than through its destroy path, leaking active-hard-connections the same way. Emit a soft disconnect and a hard disconnect for the retired connection in both pools, and parameterize the instrumentation test over both implementations. The pooled-connection gauge still differs: the channel pool reuses the old slot, while the wait handle pool never emits the matching decrement. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- .../ConnectionPool/ChannelDbConnectionPool.cs | 5 ++- .../WaitHandleDbConnectionPool.cs | 6 ++++ .../DbConnectionPoolInstrumentationTest.cs | 32 ++++++++++++------- 3 files changed, 30 insertions(+), 13 deletions(-) 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 c9e0be819e..194e09d000 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 @@ -514,8 +514,11 @@ public DbConnectionInternal ReplaceConnection( oldConnection.Dispose(); // The replacement took over the old connection's slot, so the pooled gauge is - // already correct and only the hard-disconnect counter needs balancing. Traced as a + // already correct. The old connection was vended to the caller and is now destroyed + // rather than returned, so balance both the soft gauge (it was counted as a + // checkout) and the hard gauge (its physical connection is going away). Traced as a // destroy so the connection's exit is visible in the pooler trace stream. + Metrics.SoftDisconnectRequest(); Metrics.HardDisconnectRequest(); SqlClientEventSource.Log.TryPoolerTraceEvent( 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 311663721b..20d0549f7c 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 @@ -1193,6 +1193,12 @@ public DbConnectionInternal ReplaceConnection(DbConnection owningObject, DbConne PrepareConnection(owningObject, newConnection, oldConnection.EnlistedTransaction); oldConnection.DeactivateConnection(); oldConnection.Dispose(); + + // The old connection was vended to the caller and is now destroyed rather than + // returned to the pool, so balance both the soft gauge (it was counted as a + // checkout) and the hard gauge (its physical connection is going away). + Metrics.SoftDisconnectRequest(); + Metrics.HardDisconnectRequest(); } return newConnection; diff --git a/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/DbConnectionPoolInstrumentationTest.cs b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/DbConnectionPoolInstrumentationTest.cs index 88d782a58f..95786a1743 100644 --- a/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/DbConnectionPoolInstrumentationTest.cs +++ b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/DbConnectionPoolInstrumentationTest.cs @@ -280,21 +280,27 @@ public void Destroy_CountsHardDisconnect(PoolImplementation implementation) } /// - /// Verifies the counters emitted when a checked-out connection is replaced. The channel pool - /// swaps the new connection into the old connection's slot, so the pooled-connection gauge - /// is deliberately left untouched. + /// Verifies the counters emitted when a checked-out connection is replaced. Both pools swap + /// the new connection in for the old one, so the caller's checkout is unchanged: the + /// replacement is a soft connect and retiring the old connection is a soft disconnect plus + /// a hard disconnect. /// /// - /// This is not parameterized over the wait handle pool: that implementation disposes the - /// replaced connection directly rather than through its destroy path, so it emits neither - /// the hard disconnect nor the pooled-connection decrement. + /// The pooled-connection gauge differs by implementation. The channel pool reuses the old + /// connection's slot, so the gauge is deliberately left untouched. The wait handle pool + /// disposes the replaced connection directly rather than through its destroy path, so it + /// never emits the matching decrement. /// - [Fact] - public void ReplaceConnection_CountsHardDisconnectForDiscardedConnection() + [Theory] + [InlineData(PoolImplementation.WaitHandle, 2)] + [InlineData(PoolImplementation.Channel, 1)] + public void ReplaceConnection_CountsDisconnectsForDiscardedConnection( + PoolImplementation implementation, + int expectedPooledConnections) { // Arrange FakeSqlClientMetrics metrics = new(); - IDbConnectionPool pool = ConstructPool(PoolImplementation.Channel, metrics, new SuccessfulSqlConnectionFactory(metrics)); + IDbConnectionPool pool = ConstructPool(implementation, metrics, new SuccessfulSqlConnectionFactory(metrics)); SqlConnection owner = new(); Assert.True(pool.TryGetConnection(owner, null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out DbConnectionInternal? oldConnection)); Assert.NotNull(oldConnection); @@ -302,15 +308,17 @@ public void ReplaceConnection_CountsHardDisconnectForDiscardedConnection() // Act DbConnectionInternal newConnection = pool.ReplaceConnection(owner, oldConnection!, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15))); - // Assert - two physical connections were opened and one was retired, leaving the pooled - // count unchanged because the replacement inherited the slot. + // Assert - two physical connections were opened and one was retired. The caller still + // holds exactly one connection, so the soft connect for the replacement is balanced by + // a soft disconnect for the connection it displaced. Assert.NotSame(oldConnection, newConnection); AssertCounters( metrics, hardConnects: 2, hardDisconnects: 1, softConnects: 2, - pooledConnections: 1, + softDisconnects: 1, + pooledConnections: expectedPooledConnections, activeConnections: 1); } From 563543e04b82e459bdfe53878b331f0489853364 Mon Sep 17 00:00:00 2001 From: Malcolm Daigle Date: Fri, 14 Aug 2026 09:15:56 -0700 Subject: [PATCH 14/19] Balance the pooled-connection gauge when replacing a connection CreateObject swaps the replacement into the old connection's place in the pool's object list, but only incremented the pooled-connection gauge. The removal had no matching decrement, so number-of-pooled-connections drifted up by one per replacement. ReplaceConnection is the only caller that passes an old connection, so this is scoped to replacement. Both pools now report the same counters for a replacement, so the instrumentation test no longer needs a per-implementation expectation. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- .../WaitHandleDbConnectionPool.cs | 11 +++++++++-- .../DbConnectionPoolInstrumentationTest.cs | 17 +++++++---------- 2 files changed, 16 insertions(+), 12 deletions(-) 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 20d0549f7c..f15be73c96 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 @@ -549,7 +549,13 @@ private DbConnectionInternal CreateObject(DbConnection owningObject, DbConnectio { if ((oldConnection != null) && (oldConnection.Pool == this)) { - _objectList.Remove(oldConnection); + // The replacement takes over the old connection's place in the pool. The + // caller disposes the old connection once the replacement is in place, so + // account for its departure here rather than leaving the gauge inflated. + if (_objectList.Remove(oldConnection)) + { + Metrics.ExitPooledConnection(); + } } _objectList.Add(newObj); _totalObjects = _objectList.Count; @@ -1196,7 +1202,8 @@ public DbConnectionInternal ReplaceConnection(DbConnection owningObject, DbConne // The old connection was vended to the caller and is now destroyed rather than // returned to the pool, so balance both the soft gauge (it was counted as a - // checkout) and the hard gauge (its physical connection is going away). + // checkout) and the hard gauge (its physical connection is going away). The pooled + // gauge is settled in CreateObject, which removed it from the pool's object list. Metrics.SoftDisconnectRequest(); Metrics.HardDisconnectRequest(); } diff --git a/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/DbConnectionPoolInstrumentationTest.cs b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/DbConnectionPoolInstrumentationTest.cs index 95786a1743..6842e55a3a 100644 --- a/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/DbConnectionPoolInstrumentationTest.cs +++ b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/DbConnectionPoolInstrumentationTest.cs @@ -286,17 +286,14 @@ public void Destroy_CountsHardDisconnect(PoolImplementation implementation) /// a hard disconnect. /// /// - /// The pooled-connection gauge differs by implementation. The channel pool reuses the old - /// connection's slot, so the gauge is deliberately left untouched. The wait handle pool - /// disposes the replaced connection directly rather than through its destroy path, so it - /// never emits the matching decrement. + /// Neither pool changes the pooled-connection gauge: the channel pool reuses the old + /// connection's slot, and the wait handle pool swaps the replacement into the old + /// connection's place in its object list. /// [Theory] - [InlineData(PoolImplementation.WaitHandle, 2)] - [InlineData(PoolImplementation.Channel, 1)] - public void ReplaceConnection_CountsDisconnectsForDiscardedConnection( - PoolImplementation implementation, - int expectedPooledConnections) + [InlineData(PoolImplementation.WaitHandle)] + [InlineData(PoolImplementation.Channel)] + public void ReplaceConnection_CountsDisconnectsForDiscardedConnection(PoolImplementation implementation) { // Arrange FakeSqlClientMetrics metrics = new(); @@ -318,7 +315,7 @@ public void ReplaceConnection_CountsDisconnectsForDiscardedConnection( hardDisconnects: 1, softConnects: 2, softDisconnects: 1, - pooledConnections: expectedPooledConnections, + pooledConnections: 1, activeConnections: 1); } From 389d934de377265a969434bb282d33f800c2cd79 Mon Sep 17 00:00:00 2001 From: Malcolm Daigle Date: Fri, 14 Aug 2026 09:32:46 -0700 Subject: [PATCH 15/19] Address review feedback on metrics routing, sizing, and shared traces - Route the remaining DbConnectionInternal counters (hard disconnect, non-pooled exit, stasis enter/exit) through the instance metrics sink instead of the global one. This is a no-op in production, where the factory hands every connection the process-wide instance, but it lets a test observe them. - Emit a hard disconnect when ConnectionPoolSlots.Add fails after opening a connection. The connection was counted as a hard connect and then disposed without a matching decrement. - Stop marking the slot counters volatile and read them through Volatile.Read instead. They are only mutated through Interlocked, but they are also read outside it, including in the TryReserve spin loop. - Gate warmup on ReservationCount rather than Count, matching the max-pool-size gate and the pruner. Count excludes in-flight creations, so warmup created duplicates for connections other threads were already opening. - Restore the original trace format in TransactedConnectionPool and PoolPruner. Both are shared with the wait handle pool, so reformatting them would change v1's trace stream. PoolPruner is now unchanged from main. - Document why pools take a metrics sink independently of the connection factory, and note the Count vs ReservationCount convention. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- .../Data/ProviderBase/DbConnectionInternal.cs | 10 +++---- .../ConnectionPool/ChannelDbConnectionPool.cs | 26 +++++++++++++++---- .../ConnectionPool/ConnectionPoolSlots.cs | 14 +++++----- .../ConnectionPool/IDbConnectionPool.cs | 6 +++++ .../SqlClient/ConnectionPool/PoolPruner.cs | 2 +- .../TransactedConnectionPool.cs | 18 ++++++------- 6 files changed, 50 insertions(+), 26 deletions(-) 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 b15e066147..1b1c7b3e40 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/ProviderBase/DbConnectionInternal.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/ProviderBase/DbConnectionInternal.cs @@ -505,7 +505,7 @@ internal virtual void CloseConnection(DbConnection owningObject, SqlConnectionFa // and transactions may not get cleaned up... Deactivate(); - SqlClientDiagnostics.Metrics.HardDisconnectRequest(); + Metrics.HardDisconnectRequest(); // To prevent an endless recursion, we need to clear the owning object // before we call dispose so that we can't get here a second time... @@ -520,7 +520,7 @@ internal virtual void CloseConnection(DbConnection owningObject, SqlConnectionFa } else { - SqlClientDiagnostics.Metrics.ExitNonPooledConnection(); + Metrics.ExitNonPooledConnection(); Dispose(); } } @@ -606,7 +606,7 @@ internal virtual void DelegatedTransactionEnded() // once and for all, or the server will have fits about us // leaving connections open until the client-side GC kicks // in. - SqlClientDiagnostics.Metrics.ExitNonPooledConnection(); + Metrics.ExitNonPooledConnection(); Dispose(); } @@ -836,7 +836,7 @@ internal void SetInStasis() IsTxRootWaitingForTxEnd = true; SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Non-Pooled Connection has Delegated Transaction, waiting to Dispose.", ObjectID); - SqlClientDiagnostics.Metrics.EnterStasisConnection(); + Metrics.EnterStasisConnection(); } /// @@ -1022,7 +1022,7 @@ private void TerminateStasis(bool returningToPool) : "Delegated Transaction has ended, connection is closed/leaked. Disposing."; SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, {1}", ObjectID, message); - SqlClientDiagnostics.Metrics.ExitStasisConnection(); + Metrics.ExitStasisConnection(); IsTxRootWaitingForTxEnd = false; } 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 194e09d000..c5225d45b5 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 @@ -232,6 +232,10 @@ public ConcurrentDictionary< /// resolved instance name on the pool's provider info. Counting an in-flight open here sends /// the first caller down the cached branch instead, where it reads an instance name that /// nothing has set yet. + /// + /// Internal sizing decisions (the max-pool-size gate, warmup, and pruning) all use + /// instead, so that connections another + /// thread is currently opening count toward the pool's size. /// public int Count => _connectionSlots.ConnectionCount; @@ -1153,7 +1157,15 @@ _connectionCreationRateLimiter is not null && // If we fail to open a connection, we need to write a null to the idle channel to // wake up any waiters _idleChannel.TryWrite(null); - newConnection?.Dispose(); + + if (newConnection is not null) + { + // The connection opened, so a hard connect was counted for it. It never + // reached the pool, so balance the hard-connection gauge here rather + // than leaving it inflated for the lifetime of the pool. + newConnection.Dispose(); + Metrics.HardDisconnectRequest(); + } }); if (connection is not null) @@ -1672,8 +1684,12 @@ internal void RequestWarmup() // up. Return before scheduling a thread-pool work item. This keeps hot-path callers // (e.g. RemoveConnection on every return) cheap. The check is best-effort under // concurrency; a below-minimum condition missed here is still observed by the running - // loop, which re-reads Count on every iteration. - if (Count >= MinPoolSize) + // loop, which re-reads the count on every iteration. + // + // This gates on ReservationCount rather than Count so that connections another thread + // is currently opening count toward the minimum. Gating on Count would make warmup + // create duplicates for every creation already in flight. + if (_connectionSlots.ReservationCount >= MinPoolSize) { return; } @@ -1756,7 +1772,7 @@ private async Task RunWarmupLoopAsync() while (State == Running && !token.IsCancellationRequested && !ErrorOccurred - && Count < MinPoolSize) + && _connectionSlots.ReservationCount < MinPoolSize) { // Fresh per-attempt timeout budget based on the pool's CreationTimeout, since // warmup has no owning Open() call to inherit a budget from. Matches the @@ -1795,7 +1811,7 @@ private async Task RunWarmupLoopAsync() if (connection is null) { - // A slot is guaranteed available here (Count < MinPoolSize <= MaxPoolSize), + // A slot is guaranteed available here (ReservationCount < MinPoolSize <= MaxPoolSize), // and creation failures throw rather than return null, so a null return means // the shared rate limiter is currently saturated. Rather than bypassing the // limiter or spinning on it (Story 2), end this warmup pass. Saturation only diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/ConnectionPoolSlots.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/ConnectionPoolSlots.cs index 5eabf04cfe..b9465ec93c 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/ConnectionPoolSlots.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/ConnectionPoolSlots.cs @@ -59,8 +59,10 @@ internal void Keep() private readonly DbConnectionInternal?[] _connections; private readonly uint _capacity; - private volatile int _reservations; - private volatile int _connectionCount; + // Mutated only through Interlocked and read only through Volatile.Read, so the fields + // themselves do not need to be volatile. + private int _reservations; + private int _connectionCount; /// /// Constructs a ConnectionPoolSlots instance with the given fixed capacity. @@ -91,14 +93,14 @@ internal ConnectionPoolSlots(uint fixedCapacity) /// Gets the total number of reservations currently held. This includes reservations held on /// behalf of connections that are still being opened and are therefore not yet tracked. /// - internal int ReservationCount => _reservations; + internal int ReservationCount => Volatile.Read(ref _reservations); /// /// Gets the number of connections currently tracked by this collection. Unlike /// , this excludes reservations held for connections that are /// still being opened, so it reports connections that actually belong to the pool. /// - internal int ConnectionCount => _connectionCount; + internal int ConnectionCount => Volatile.Read(ref _connectionCount); /// /// Adds a connection to the collection. @@ -159,7 +161,7 @@ internal ConnectionPoolSlots(uint fixedCapacity) private void ReleaseReservation() { Interlocked.Decrement(ref _reservations); - Debug.Assert(_reservations >= 0, "Released a reservation that wasn't held"); + Debug.Assert(Volatile.Read(ref _reservations) >= 0, "Released a reservation that wasn't held"); } /// @@ -208,7 +210,7 @@ internal bool TryReplace(DbConnectionInternal oldConnection, DbConnectionInterna /// A Reservation if successful, otherwise returns null. private Reservation? TryReserve() { - for (var expected = _reservations; expected < _capacity; expected = _reservations) + for (var expected = Volatile.Read(ref _reservations); expected < _capacity; expected = Volatile.Read(ref _reservations)) { // Try to reserve a spot in the collection by incrementing _reservations. // If _reservations changed underneath us, then another thread already reserved the spot we were trying to take. diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/IDbConnectionPool.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/IDbConnectionPool.cs index 665d7b5038..ec30b4efa6 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/IDbConnectionPool.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/IDbConnectionPool.cs @@ -39,6 +39,12 @@ internal interface IDbConnectionPool /// In production this is the process-wide /// instance. Making it a pool property lets a test give a pool its own counters so /// assertions are not perturbed by unrelated connection activity elsewhere in the process. + /// + /// The pool takes its sink independently of + /// rather than reading it from the factory, so that a pool can be constructed and asserted + /// on without standing up a factory. Both default to the same process-wide instance, so + /// they agree in production; a test that asserts across both must pass the same instance to + /// the pool and to the factory it is given. /// ISqlClientMetrics Metrics { get; } diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/PoolPruner.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/PoolPruner.cs index 3611afda5e..9c6621f5f0 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/PoolPruner.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/PoolPruner.cs @@ -136,7 +136,7 @@ internal PoolPruner(ChannelDbConnectionPool pool, TimeSpan idleTimeout) // cadence so operators can tell why a very large Connection Idle Timeout samples less // frequently than the default 10-second interval. SqlClientEventSource.Log.TryPoolerTraceEvent( - "PoolPruner.PoolPruner | INFO | Idle timeout {0}s derived a pruning interval of {1}s with {2} samples (max {3}).", + " Idle timeout {0}s derived a pruning interval of {1}s with {2} samples (max {3}).", idleTimeoutSeconds, intervalSeconds, sampleSize, MaxSampleSize); } diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/TransactedConnectionPool.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/TransactedConnectionPool.cs index 9da6759a0b..32e6865efb 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/TransactedConnectionPool.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/TransactedConnectionPool.cs @@ -82,7 +82,7 @@ internal TransactedConnectionPool(IDbConnectionPool pool, ISqlClientMetrics metr Pool = pool; _metrics = metrics; TransactedConnections = new Dictionary(); - SqlClientEventSource.Log.TryPoolerTraceEvent("TransactedConnectionPool.TransactedConnectionPool | INFO | {0}, Constructed for connection pool {1}", Id, Pool.Id); + SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Constructed for connection pool {1}", Id, Pool.Id); } #region Properties @@ -156,7 +156,7 @@ internal TransactedConnectionPool(IDbConnectionPool pool, ISqlClientMetrics metr if (transactedObject != null) { - SqlClientEventSource.Log.TryPoolerTraceEvent("TransactedConnectionPool.GetTransactedObject | INFO | {0}, Transaction {1}, Connection {2}, Popped.", Id, transaction.GetHashCode(), transactedObject.ObjectID); + SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Transaction {1}, Connection {2}, Popped.", Id, transaction.GetHashCode(), transactedObject.ObjectID); } return transactedObject; } @@ -196,7 +196,7 @@ internal void PutTransactedObject(Transaction transaction, DbConnectionInternal { // TODO: validate that we're not adding the same connection twice? // Debug.Assert(0 > connections.IndexOf(transactedObject), "adding to pool a second time?"); - SqlClientEventSource.Log.TryPoolerTraceEvent("TransactedConnectionPool.PutTransactedObject | INFO | {0}, Transaction {1}, Connection {2}, Pushing.", Id, transaction.GetHashCode(), transactedObject.ObjectID); + SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Transaction {1}, Connection {2}, Pushing.", Id, transaction.GetHashCode(), transactedObject.ObjectID); connections.Add(transactedObject); } } @@ -230,13 +230,13 @@ internal void PutTransactedObject(Transaction transaction, DbConnectionInternal lock (connections) { Debug.Assert(0 > connections.IndexOf(transactedObject), "adding to pool a second time?"); - SqlClientEventSource.Log.TryPoolerTraceEvent("TransactedConnectionPool.PutTransactedObject | INFO | {0}, Transaction {1}, Connection {2}, Pushing.", Id, transaction.GetHashCode(), transactedObject.ObjectID); + SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Transaction {1}, Connection {2}, Pushing.", Id, transaction.GetHashCode(), transactedObject.ObjectID); connections.Add(transactedObject); } } else { - SqlClientEventSource.Log.TryPoolerTraceEvent("TransactedConnectionPool.PutTransactedObject | INFO | {0}, Transaction {1}, Connection {2}, Adding List to transacted pool.", Id, transaction.GetHashCode(), transactedObject.ObjectID); + SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Transaction {1}, Connection {2}, Adding List to transacted pool.", Id, transaction.GetHashCode(), transactedObject.ObjectID); // add the connection/transacted object to the list newConnections.Add(transactedObject); @@ -264,7 +264,7 @@ internal void PutTransactedObject(Transaction transaction, DbConnectionInternal } } } - SqlClientEventSource.Log.TryPoolerTraceEvent("TransactedConnectionPool.PutTransactedObject | INFO | {0}, Transaction {1}, Connection {2}, Added.", Id, transaction.GetHashCode(), transactedObject.ObjectID); + SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Transaction {1}, Connection {2}, Added.", Id, transaction.GetHashCode(), transactedObject.ObjectID); } _metrics.EnterFreeConnection(); @@ -288,7 +288,7 @@ internal void PutTransactedObject(Transaction transaction, DbConnectionInternal /// internal void TransactionEnded(Transaction transaction, DbConnectionInternal transactedObject) { - SqlClientEventSource.Log.TryPoolerTraceEvent("TransactedConnectionPool.TransactionEnded | INFO | {0}, Transaction {1}, Connection {2}, Transaction Completed", Id, transaction.GetHashCode(), transactedObject.ObjectID); + SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Transaction {1}, Connection {2}, Transaction Completed", Id, transaction.GetHashCode(), transactedObject.ObjectID); TransactedConnectionList? connections; int entry = -1; @@ -321,7 +321,7 @@ internal void TransactionEnded(Transaction transaction, DbConnectionInternal tra // safely remove the list from the transacted pool. if (0 >= connections.Count) { - SqlClientEventSource.Log.TryPoolerTraceEvent("TransactedConnectionPool.TransactionEnded | INFO | {0}, Transaction {1}, Removing List from transacted pool.", Id, transaction.GetHashCode()); + SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Transaction {1}, Removing List from transacted pool.", Id, transaction.GetHashCode()); TransactedConnections.Remove(transaction); // we really need to dispose our connection list; it may have @@ -337,7 +337,7 @@ internal void TransactionEnded(Transaction transaction, DbConnectionInternal tra } else { - SqlClientEventSource.Log.TryPoolerTraceEvent("TransactedConnectionPool.TransactionEnded | INFO | {0}, Transaction {1}, Connection {2}, Transacted pool not yet created prior to transaction completing. Connection may be leaked.", Id, transaction.GetHashCode(), transactedObject.ObjectID); + SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Transaction {1}, Connection {2}, Transacted pool not yet created prior to transaction completing. Connection may be leaked.", Id, transaction.GetHashCode(), transactedObject.ObjectID); } } From d36665e73d4f3085913d92dc2b385ff70f8dce66 Mon Sep 17 00:00:00 2001 From: Malcolm Daigle Date: Fri, 14 Aug 2026 09:35:44 -0700 Subject: [PATCH 16/19] Balance connection counters when activation fails Both pools activated a connection before counting the checkout, and DbConnectionInternal counted the active connection after calling Activate while DeactivateConnection counts before calling Deactivate. When activation failed, the pool returned the connection and deactivated it, emitting a soft disconnect and an active-connection exit with nothing to pair against. Both gauges went negative. Count the checkout before activating in both pools, and make ActivateConnection symmetric with DeactivateConnection. The wait handle pool also counted a soft connect when it vended no connection at all; that is now scoped to the branch that actually hands one out. Adds two tests, both parameterized over the two pools: - a failed activation leaves every counter balanced - concurrent checkout and return settles all gauges to a consistent resting state, with nothing outstanding and no connection leaked or double counted The failed-activation test is what surfaced the negative gauges. Replaces the dead FailingSqlConnectionFactory with a fake that opens successfully and fails to activate. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- .../Data/ProviderBase/DbConnectionInternal.cs | 8 +- .../ConnectionPool/ChannelDbConnectionPool.cs | 5 +- .../WaitHandleDbConnectionPool.cs | 7 +- .../DbConnectionPoolInstrumentationTest.cs | 116 +++++++++++++++++- 4 files changed, 126 insertions(+), 10 deletions(-) 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 1b1c7b3e40..338f0e65e9 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/ProviderBase/DbConnectionInternal.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/ProviderBase/DbConnectionInternal.cs @@ -390,9 +390,13 @@ internal void ActivateConnection(Transaction transaction) // the Activate method publicly. SqlClientEventSource.Log.TryPoolerTraceEvent(" {0}, Activating", ObjectID); - Activate(transaction); - + // Counted before Activate, mirroring DeactivateConnection, which counts before + // Deactivate. If Activate throws, the pool returns the connection and deactivates it, + // so counting afterwards would leave that exit unpaired and drive the + // active-connections gauge negative. Metrics.EnterActiveConnection(); + + Activate(transaction); } internal void AddWeakReference(object value, int tag) 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 c5225d45b5..09fe3a1c2d 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 @@ -1514,8 +1514,11 @@ private async Task GetInternalConnection( } } - PrepareConnection(owningConnection, connection, transaction); + // Counted before activation: if PrepareConnection fails it returns the connection to + // the pool, which emits the matching soft disconnect. Counting after would leave that + // disconnect unpaired and drive the active-soft-connects gauge negative. Metrics.SoftConnectRequest(); + PrepareConnection(owningConnection, connection, transaction); SqlClientEventSource.Log.TryPoolerTraceEvent( "ChannelDbConnectionPool.GetInternalConnection | INFO | {0}, Connection {1}, Obtained.", Id, connection.ObjectID); 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 f15be73c96..afaa827fce 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 @@ -1152,13 +1152,16 @@ private bool TryGetConnection(DbConnection owningObject, uint waitForMultipleObj if (obj != null) { + // Counted before activation: if PrepareConnection fails it returns the connection + // to the pool, which emits the matching soft disconnect. Counting after would leave + // that disconnect unpaired and drive the active-soft-connects gauge negative. + // Counted inside this branch so that no connection vended means no soft connect. + Metrics.SoftConnectRequest(); PrepareConnection(owningObject, obj, transaction); } connection = obj; - Metrics.SoftConnectRequest(); - return true; } diff --git a/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/DbConnectionPoolInstrumentationTest.cs b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/DbConnectionPoolInstrumentationTest.cs index 6842e55a3a..71711911f2 100644 --- a/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/DbConnectionPoolInstrumentationTest.cs +++ b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/DbConnectionPoolInstrumentationTest.cs @@ -7,6 +7,7 @@ using System.Data.Common; using System.Linq; using System.Threading; +using System.Threading.Tasks; using System.Transactions; using Microsoft.Data.Common; using Microsoft.Data.Common.ConnectionString; @@ -418,25 +419,130 @@ public void TransactionRollback_ReleasingParkedConnection_KeepsActiveConnectionC activeConnections: 0); } + /// + /// Verifies that a connection which opens successfully but fails to activate leaves the + /// counters balanced. The pool counts the checkout before activating, so the soft + /// disconnect emitted when the failed connection is returned has a matching soft connect + /// and the active-soft-connects gauge does not go negative. + /// + [Theory] + [InlineData(PoolImplementation.WaitHandle)] + [InlineData(PoolImplementation.Channel)] + public void FailedActivation_LeavesCountersBalanced(PoolImplementation implementation) + { + // Arrange + FakeSqlClientMetrics metrics = new(); + IDbConnectionPool pool = ConstructPool(implementation, metrics, new ActivationFailingConnectionFactory(metrics)); + SqlConnection owner = new(); + + // Act + Assert.Throws(() => + pool.TryGetConnection(owner, null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out _)); + + // Assert - the physical connection was opened and stays in the pool, and the checkout + // that failed is balanced by the return. + AssertCounters( + metrics, + hardConnects: 1, + softConnects: 1, + softDisconnects: 1, + pooledConnections: 1, + freeConnections: 1, + activeConnections: 0); + } + + /// + /// Drives concurrent checkouts and returns through the pool and verifies that every gauge + /// settles back to a consistent resting state. This is the broad safety net for the + /// counters: it does not assert a specific interleaving, only that nothing is leaked or + /// double-counted once all activity has stopped. + /// + [Theory] + [InlineData(PoolImplementation.WaitHandle)] + [InlineData(PoolImplementation.Channel)] + public void ConcurrentCheckoutAndReturn_SettlesAllGaugesToZero(PoolImplementation implementation) + { + // Arrange + const int Threads = 8; + const int IterationsPerThread = 50; + const int MaxPoolSize = 4; + + FakeSqlClientMetrics metrics = new(); + IDbConnectionPool pool = ConstructPool( + implementation, + metrics, + new SuccessfulSqlConnectionFactory(metrics), + maxPoolSize: MaxPoolSize); + + // Act + Task[] workers = Enumerable.Range(0, Threads).Select(_ => Task.Run(() => + { + for (int i = 0; i < IterationsPerThread; i++) + { + SqlConnection owner = new(); + Assert.True(pool.TryGetConnection(owner, null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(30)), out DbConnectionInternal? connection)); + Assert.NotNull(connection); + pool.ReturnInternalConnection(connection!, owner); + } + })).ToArray(); + + Assert.True(Task.WaitAll(workers, TimeSpan.FromSeconds(60)), "Concurrent checkout workers did not finish in time."); + + // Assert - every connection handed out came back, so no checkout is still outstanding. + long expectedCheckouts = Threads * IterationsPerThread; + Assert.Equal(expectedCheckouts, metrics.SoftConnects); + Assert.Equal(expectedCheckouts, metrics.SoftDisconnects); + Assert.Equal(0, metrics.ActiveConnections); + + // Every physical connection that was opened is either still pooled or was destroyed. + Assert.Equal(metrics.PooledConnections, metrics.HardConnects - metrics.HardDisconnects); + + // Nothing is checked out, so every pooled connection is sitting idle. + Assert.Equal(metrics.PooledConnections, metrics.FreeConnections); + + // The pool never grew past its configured ceiling. + Assert.InRange(metrics.PooledConnections, 0, MaxPoolSize); + } + #region Test classes /// /// Distinctive exception type used to prove that the exact failure recorded by the pool is - /// the one attached to the pooled-open timeout. + /// the one raised by the connection under test. /// internal sealed class TestConnectionCreateException : Exception { internal TestConnectionCreateException() - : base("Simulated physical connection failure.") + : base("Simulated connection activation failure.") + { + } + } + + /// + /// Stub connection whose activation always fails, so a test can exercise the pool's + /// behavior when a connection is successfully opened but cannot be handed to the caller. + /// + private sealed class ActivationFailingConnection : StubDbConnectionInternal + { + internal ActivationFailingConnection(ISqlClientMetrics metrics) + : base(metrics) { } + + protected override void Activate(Transaction transaction) + => throw new TestConnectionCreateException(); } /// - /// Connection factory that always fails with . + /// Connection factory whose connections open successfully but always fail to activate. /// - internal sealed class FailingSqlConnectionFactory : SqlConnectionFactory + private sealed class ActivationFailingConnectionFactory : SqlConnectionFactory { + internal ActivationFailingConnectionFactory(ISqlClientMetrics metrics) + : base(metrics) + { + } + /// protected override DbConnectionInternal CreateConnection( SqlConnectionOptions options, @@ -445,7 +551,7 @@ protected override DbConnectionInternal CreateConnection( IDbConnectionPool pool, DbConnection owningConnection, TimeoutTimer timeout) - => throw new TestConnectionCreateException(); + => new ActivationFailingConnection(Metrics); } #endregion From 37307b8d458a3a42ba0529c7a20b7b5dd6e2b277 Mon Sep 17 00:00:00 2001 From: Malcolm Daigle Date: Fri, 14 Aug 2026 09:37:16 -0700 Subject: [PATCH 17/19] Add coverage for the counters emitted when idle connections are pruned Pruning destroys a connection that no caller holds, so it must record a hard disconnect and decrement the pooled and free gauges while leaving the soft counters alone. Channel pool only: the wait handle pool reclaims idle connections through a different mechanism. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- .../DbConnectionPoolInstrumentationTest.cs | 56 +++++++++++++++++++ 1 file changed, 56 insertions(+) diff --git a/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/DbConnectionPoolInstrumentationTest.cs b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/DbConnectionPoolInstrumentationTest.cs index 71711911f2..c715c3a235 100644 --- a/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/DbConnectionPoolInstrumentationTest.cs +++ b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/DbConnectionPoolInstrumentationTest.cs @@ -504,6 +504,62 @@ public void ConcurrentCheckoutAndReturn_SettlesAllGaugesToZero(PoolImplementatio Assert.InRange(metrics.PooledConnections, 0, MaxPoolSize); } + /// + /// Verifies the counters emitted when idle connections are pruned out of the pool. Pruning + /// destroys the physical connection, so it must decrement both the pooled and free gauges + /// and record a hard disconnect, without touching the soft counters: pruning removes an + /// idle connection that no caller holds. + /// + [Fact] + public void PruneConnections_CountsHardDisconnectForEachEvictedConnection() + { + // Arrange - check out three connections so they are all open at once, then return them + // so they sit idle and are eligible for pruning. + FakeSqlClientMetrics metrics = new(); + ChannelDbConnectionPool pool = (ChannelDbConnectionPool)ConstructPool( + PoolImplementation.Channel, + metrics, + new SuccessfulSqlConnectionFactory(metrics)); + + List<(SqlConnection Owner, DbConnectionInternal Connection)> checkedOut = new(); + for (int i = 0; i < 3; i++) + { + SqlConnection owner = new(); + Assert.True(pool.TryGetConnection(owner, null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out DbConnectionInternal? connection)); + checkedOut.Add((owner, connection!)); + } + + foreach ((SqlConnection owner, DbConnectionInternal connection) in checkedOut) + { + pool.ReturnInternalConnection(connection, owner); + } + + AssertCounters( + metrics, + hardConnects: 3, + softConnects: 3, + softDisconnects: 3, + pooledConnections: 3, + freeConnections: 3, + activeConnections: 0); + + // Act - prune two of the three idle connections. + pool.PruneConnections(2); + + // Assert - the two evicted connections were destroyed, and pruning did not disturb the + // soft counters because nothing was checked out or returned. + Assert.Equal(1, pool.Count); + AssertCounters( + metrics, + hardConnects: 3, + hardDisconnects: 2, + softConnects: 3, + softDisconnects: 3, + pooledConnections: 1, + freeConnections: 1, + activeConnections: 0); + } + #region Test classes /// From b8ec7a3a7c95447a8fe14ea72f77bb73bbe82839 Mon Sep 17 00:00:00 2001 From: Malcolm Daigle Date: Fri, 14 Aug 2026 09:49:25 -0700 Subject: [PATCH 18/19] Keep the new trace format in PoolPruner PoolPruner is constructed only by ChannelDbConnectionPool and its constructor is typed to it, so it is not shared with the wait handle pool and reformatting its trace does not change v1's trace stream. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- .../src/Microsoft/Data/SqlClient/ConnectionPool/PoolPruner.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/PoolPruner.cs b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/PoolPruner.cs index 9c6621f5f0..3611afda5e 100644 --- a/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/PoolPruner.cs +++ b/src/Microsoft.Data.SqlClient/src/Microsoft/Data/SqlClient/ConnectionPool/PoolPruner.cs @@ -136,7 +136,7 @@ internal PoolPruner(ChannelDbConnectionPool pool, TimeSpan idleTimeout) // cadence so operators can tell why a very large Connection Idle Timeout samples less // frequently than the default 10-second interval. SqlClientEventSource.Log.TryPoolerTraceEvent( - " Idle timeout {0}s derived a pruning interval of {1}s with {2} samples (max {3}).", + "PoolPruner.PoolPruner | INFO | Idle timeout {0}s derived a pruning interval of {1}s with {2} samples (max {3}).", idleTimeoutSeconds, intervalSeconds, sampleSize, MaxSampleSize); } From c9dfe1cb24ea246ea300a790a04ae6fa4d8dbff2 Mon Sep 17 00:00:00 2001 From: Malcolm Daigle Date: Fri, 14 Aug 2026 09:59:15 -0700 Subject: [PATCH 19/19] Add unit coverage for the stasis connection counter The stasis gauge had no unit coverage. FakeSqlClientMetrics exposed it, but AssertCounters only ever asserted zero, and the existing stasis tests assert pool state rather than metrics. The only test asserting a non-zero value was MetricsTest.StasisCounters_Functional, which needs a live server and covers just the non-pooled CloseConnection path. Promotes stasisConnections to an AssertCounters parameter and covers all three ways a pool puts a connection in stasis, plus both ways it leaves: - a non-poolable transaction root on return, both pools - a transaction root returned to a shut down pool, both pools - the wait handle idle sweep aging out a free transaction root, which is the only case that exits stasis back into general circulation rather than being destroyed Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- .../DbConnectionPoolInstrumentationTest.cs | 219 +++++++++++++++++- 1 file changed, 217 insertions(+), 2 deletions(-) diff --git a/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/DbConnectionPoolInstrumentationTest.cs b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/DbConnectionPoolInstrumentationTest.cs index c715c3a235..25d98b351e 100644 --- a/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/DbConnectionPoolInstrumentationTest.cs +++ b/src/Microsoft.Data.SqlClient/tests/UnitTests/ConnectionPool/DbConnectionPoolInstrumentationTest.cs @@ -124,7 +124,8 @@ private static void AssertCounters( long pooledConnections = 0, long freeConnections = 0, long reclaimedConnections = 0, - long activeConnections = 0) + long activeConnections = 0, + long stasisConnections = 0) { (string Name, long Expected, long Actual)[] counters = { @@ -138,6 +139,7 @@ private static void AssertCounters( ("freeConnections", freeConnections, metrics.FreeConnections), ("reclaimedConnections", reclaimedConnections, metrics.ReclaimedConnections), ("activeConnections", activeConnections, metrics.ActiveConnections), + ("stasisConnections", stasisConnections, metrics.StasisConnections), // Not emitted through a pool's metrics instance, so any non-zero value here means a // counter has moved to the pool that the tests have not accounted for. @@ -146,7 +148,6 @@ private static void AssertCounters( ("inactiveConnectionPoolGroups", 0, metrics.InactiveConnectionPoolGroups), ("activeConnectionPools", 0, metrics.ActiveConnectionPools), ("inactiveConnectionPools", 0, metrics.InactiveConnectionPools), - ("stasisConnections", 0, metrics.StasisConnections), }; // Reported as a single message listing only the counters that differ. Asserting on a @@ -560,6 +561,178 @@ public void PruneConnections_CountsHardDisconnectForEachEvictedConnection() activeConnections: 0); } + /// + /// Verifies the counters emitted when a transaction root that cannot be pooled is returned: + /// the pool puts it in stasis rather than destroying it, because closing it would orphan the + /// root transaction with no way to commit or roll back. The stasis gauge must come back down + /// when the transaction ends, or every delegated transaction leaks a count. + /// + [Theory] + [InlineData(PoolImplementation.WaitHandle)] + [InlineData(PoolImplementation.Channel)] + public void NonPoolableTransactionRoot_CountsStasisEnterAndExit(PoolImplementation implementation) + { + // Arrange + FakeSqlClientMetrics metrics = new(); + IDbConnectionPool pool = ConstructPool(implementation, metrics, new TransactionRootConnectionFactory(metrics)); + + using (TransactionScope scope = new()) + { + SqlConnection owner = new(); + Assert.True(pool.TryGetConnection(owner, null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out DbConnectionInternal? connection)); + Assert.NotNull(connection); + + TransactionRootConnection root = Assert.IsType(connection); + root.MarkDoNotPool(); + Assert.False(root.CanBePooled); + Assert.False(root.IsConnectionDoomed); + + // Act + pool.ReturnInternalConnection(connection!, owner); + + // Assert - in stasis, not pooled and not destroyed. + Assert.True(root.IsTxRootWaitingForTxEnd); + AssertCounters( + metrics, + hardConnects: 1, + softConnects: 1, + softDisconnects: 1, + pooledConnections: 1, + stasisConnections: 1); + + scope.Complete(); + } + + // Assert - the transaction ended, so stasis terminated and the connection, still + // unpoolable, was destroyed on the way out. + AssertCounters( + metrics, + hardConnects: 1, + hardDisconnects: 1, + softConnects: 1, + softDisconnects: 1, + pooledConnections: 0, + stasisConnections: 0); + } + + /// + /// A shut-down pool destroys an ordinary connection on return, but a transaction root must + /// still go to stasis instead, or shutting a pool down would abort a live transaction. This + /// is the second way into stasis, and it must be counted and uncounted the same way. + /// + [Theory] + [InlineData(PoolImplementation.WaitHandle)] + [InlineData(PoolImplementation.Channel)] + public void TransactionRootReturnedToShutDownPool_CountsStasisEnterAndExit(PoolImplementation implementation) + { + // Arrange + FakeSqlClientMetrics metrics = new(); + IDbConnectionPool pool = ConstructPool(implementation, metrics, new TransactionRootConnectionFactory(metrics)); + + using (TransactionScope scope = new()) + { + SqlConnection owner = new(); + Assert.True(pool.TryGetConnection(owner, null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out DbConnectionInternal? connection)); + Assert.NotNull(connection); + + pool.Shutdown(); + + // Act + pool.ReturnInternalConnection(connection!, owner); + + // Assert + Assert.True(connection!.IsTxRootWaitingForTxEnd); + AssertCounters( + metrics, + hardConnects: 1, + softConnects: 1, + softDisconnects: 1, + pooledConnections: 1, + stasisConnections: 1); + + scope.Complete(); + } + + // Assert - the pool is not running, so the connection is destroyed on the way out of + // stasis rather than pooled, and the gauge returns to zero either way. + AssertCounters( + metrics, + hardConnects: 1, + hardDisconnects: 1, + softConnects: 1, + softDisconnects: 1, + pooledConnections: 0, + stasisConnections: 0); + } + + /// + /// The third way into stasis, and the only one that leaves by the other exit. When the idle + /// sweep ages out a free connection that happens to be a transaction root, it puts it in + /// stasis rather than destroying it. The connection is still pooled at that point, so when + /// the transaction ends it returns to general circulation instead of being disposed. This is + /// specific to ; the channel pool has no generational + /// sweep. + /// + [Fact] + public void IdleSweepOfTransactionRoot_CountsStasisExitOnReturnToPool() + { + // Arrange - checked out and returned with no ambient transaction, so the connection is + // filed in the general free pool rather than the transacted store, while still + // reporting itself as a transaction root. + FakeSqlClientMetrics metrics = new(); + WaitHandleDbConnectionPool pool = Assert.IsType( + ConstructPool( + PoolImplementation.WaitHandle, + metrics, + new TransactionRootConnectionFactory(metrics), + idleTimeout: 1)); + + SqlConnection owner = new(); + Assert.True(pool.TryGetConnection(owner, null, TimeoutTimer.StartNew(TimeSpan.FromSeconds(15)), out DbConnectionInternal? connection)); + Assert.NotNull(connection); + pool.ReturnInternalConnection(connection!, owner); + + AssertCounters( + metrics, + hardConnects: 1, + softConnects: 1, + softDisconnects: 1, + pooledConnections: 1, + freeConnections: 1); + + // Act - the first sweep ages the connection from the new stack to the old stack, the + // second pops it off the old stack and finds it is a transaction root. + pool.CleanupCallback(null); + pool.CleanupCallback(null); + + // Assert - in stasis rather than destroyed, and no longer counted as free. + Assert.True(connection!.IsTxRootWaitingForTxEnd); + AssertCounters( + metrics, + hardConnects: 1, + softConnects: 1, + softDisconnects: 1, + pooledConnections: 1, + freeConnections: 0, + stasisConnections: 1); + + // Act - the delegated transaction ends. Normally raised by System.Transactions through + // the connection's TransactionCompleted handler. + connection!.DelegatedTransactionEnded(); + + // Assert - the connection was still pooled, so it rejoins general circulation rather + // than being disposed, and the stasis gauge comes back down. + Assert.False(connection!.IsTxRootWaitingForTxEnd); + AssertCounters( + metrics, + hardConnects: 1, + softConnects: 1, + softDisconnects: 1, + pooledConnections: 1, + freeConnections: 1, + stasisConnections: 0); + } + #region Test classes /// @@ -610,6 +783,48 @@ protected override DbConnectionInternal CreateConnection( => new ActivationFailingConnection(Metrics); } + /// + /// Stub connection that reports itself as the root of a delegated transaction, which is what + /// makes a pool put it in stasis on return rather than pooling or destroying it. + /// + private sealed class TransactionRootConnection : StubDbConnectionInternal + { + internal TransactionRootConnection(ISqlClientMetrics metrics) + : base(metrics) + { + } + + internal override bool IsTransactionRoot => true; + + /// + /// Marks the connection unfit for pooling without dooming it. A doomed connection + /// short-circuits the return path before the stasis decision is ever reached, so a test + /// that wants stasis must use this instead. + /// + internal void MarkDoNotPool() => DoNotPoolThisConnection(); + } + + /// + /// Connection factory whose connections are all transaction roots. + /// + private sealed class TransactionRootConnectionFactory : SqlConnectionFactory + { + internal TransactionRootConnectionFactory(ISqlClientMetrics metrics) + : base(metrics) + { + } + + /// + protected override DbConnectionInternal CreateConnection( + SqlConnectionOptions options, + ConnectionPoolKey poolKey, + DbConnectionPoolGroupProviderInfo poolGroupProviderInfo, + IDbConnectionPool pool, + DbConnection owningConnection, + TimeoutTimer timeout) + => new TransactionRootConnection(Metrics); + } + #endregion } }