From 0dfd9f2a83ca4395269a1116785d63f02a478bb5 Mon Sep 17 00:00:00 2001 From: Krzysztof Nozderko Date: Fri, 26 Apr 2024 09:55:51 +0000 Subject: [PATCH] SNOW-986233 Logging pool status --- .../ConnectionMultiplePoolsAsyncIT.cs | 5 +- Snowflake.Data/Core/Session/IWaitingQueue.cs | 2 + .../Core/Session/NonWaitingQueue.cs | 5 + Snowflake.Data/Core/Session/SessionPool.cs | 142 +++++++++++------- .../Core/Session/SessionPoolState.cs | 29 ++++ Snowflake.Data/Core/Session/WaitingQueue.cs | 9 +- 6 files changed, 132 insertions(+), 60 deletions(-) create mode 100644 Snowflake.Data/Core/Session/SessionPoolState.cs diff --git a/Snowflake.Data.Tests/IntegrationTests/ConnectionMultiplePoolsAsyncIT.cs b/Snowflake.Data.Tests/IntegrationTests/ConnectionMultiplePoolsAsyncIT.cs index 8f7d3c0ab..9089cc996 100644 --- a/Snowflake.Data.Tests/IntegrationTests/ConnectionMultiplePoolsAsyncIT.cs +++ b/Snowflake.Data.Tests/IntegrationTests/ConnectionMultiplePoolsAsyncIT.cs @@ -1,4 +1,3 @@ -using System; using System.Data.Common; using System.Threading; using System.Threading.Tasks; @@ -7,6 +6,7 @@ using Snowflake.Data.Client; using Snowflake.Data.Core; using Snowflake.Data.Core.Session; +using Snowflake.Data.Log; using Snowflake.Data.Tests.Mock; using Snowflake.Data.Tests.Util; @@ -17,6 +17,7 @@ namespace Snowflake.Data.Tests.IntegrationTests public class ConnectionMultiplePoolsAsyncIT: SFBaseTestAsync { private readonly PoolConfig _previousPoolConfig = new PoolConfig(); + private readonly SFLogger logger = SFLoggerFactory.GetLogger(); [SetUp] public new void BeforeTest() @@ -65,6 +66,8 @@ public async Task TestDoNotAddToPoolInvalidConnectionAsync() // assert var pool = SnowflakeDbConnectionPool.GetPool(connection.ConnectionString); + var poolState = pool.GetCurrentState(); + logger.Warn($"Pool state: {poolState}"); Assert.Less(pool.GetCurrentPoolSize(), SFSessionHttpClientProperties.DefaultMinPoolSize); // for invalid connection string it is used default min pool size // cleanup diff --git a/Snowflake.Data/Core/Session/IWaitingQueue.cs b/Snowflake.Data/Core/Session/IWaitingQueue.cs index 6759e9a0d..5cc895026 100644 --- a/Snowflake.Data/Core/Session/IWaitingQueue.cs +++ b/Snowflake.Data/Core/Session/IWaitingQueue.cs @@ -10,6 +10,8 @@ internal interface IWaitingQueue bool IsAnyoneWaiting(); + int WaitingCount(); + bool IsWaitingEnabled(); } } diff --git a/Snowflake.Data/Core/Session/NonWaitingQueue.cs b/Snowflake.Data/Core/Session/NonWaitingQueue.cs index 5604ea4a8..1e7f9ee64 100644 --- a/Snowflake.Data/Core/Session/NonWaitingQueue.cs +++ b/Snowflake.Data/Core/Session/NonWaitingQueue.cs @@ -18,6 +18,11 @@ public bool IsAnyoneWaiting() return false; } + public int WaitingCount() + { + return 0; + } + public bool IsWaitingEnabled() { return false; diff --git a/Snowflake.Data/Core/Session/SessionPool.cs b/Snowflake.Data/Core/Session/SessionPool.cs index 401e435f6..c1b5ccd1a 100644 --- a/Snowflake.Data/Core/Session/SessionPool.cs +++ b/Snowflake.Data/Core/Session/SessionPool.cs @@ -81,7 +81,7 @@ internal static ISessionFactory SessionFactory private void CleanExpiredSessions() { - s_logger.Debug("SessionPool::CleanExpiredSessions"); + s_logger.Debug("SessionPool::CleanExpiredSessions" + PoolIdentification()); lock (_sessionPoolLock) { var timeNow = DateTimeOffset.UtcNow.ToUnixTimeMilliseconds(); @@ -114,7 +114,7 @@ private static ConnectionPoolConfig ExtractConfig(string connectionString, Secur internal SFSession GetSession(string connStr, SecureString password) { - s_logger.Debug("SessionPool::GetSession"); + s_logger.Debug("SessionPool::GetSession" + PoolIdentification()); if (!GetPooling()) return NewNonPoolingSession(connStr, password); var sessionOrCreateTokens = GetIdleSession(connStr); @@ -129,7 +129,7 @@ internal SFSession GetSession(string connStr, SecureString password) internal async Task GetSessionAsync(string connStr, SecureString password, CancellationToken cancellationToken) { - s_logger.Debug("SessionPool::GetSessionAsync"); + s_logger.Debug("SessionPool::GetSessionAsync" + PoolIdentification()); if (!GetPooling()) return await NewNonPoolingSessionAsync(connStr, password, cancellationToken).ConfigureAwait(false); var sessionOrCreateTokens = GetIdleSession(connStr); @@ -160,7 +160,7 @@ private void WarnAboutOverridenConfig() { if (IsConfigOverridden() && GetPooling() && IsMultiplePoolsVersion()) { - s_logger.Warn("Providing a connection from a pool for which technical configuration has been overriden by the user"); + s_logger.Warn("Providing a connection from a pool for which technical configuration has been overriden by the user"); // TODO: + PoolIdentification()); } } @@ -178,22 +178,22 @@ internal void SetSessionPoolEventHandler(ISessionPoolEventHandler sessionPoolEve private SessionOrCreationTokens GetIdleSession(string connStr) { - s_logger.Debug("SessionPool::GetIdleSession"); + s_logger.Debug("SessionPool::GetIdleSession" + PoolIdentification()); lock (_sessionPoolLock) { if (_waitingForIdleSessionQueue.IsAnyoneWaiting()) { - s_logger.Debug("SessionPool::GetIdleSession - someone is already waiting for a session, request is going to be queued"); + s_logger.Debug("SessionPool::GetIdleSession - someone is already waiting for a session, request is going to be queued" + PoolIdentification()); } else { var session = ExtractIdleSession(connStr); if (session != null) { - s_logger.Debug("SessionPool::GetIdleSession - no thread was waiting for a session, an idle session was retrieved from the pool"); + s_logger.Debug("SessionPool::GetIdleSession - no thread was waiting for a session, an idle session was retrieved from the pool" + PoolIdentification()); return new SessionOrCreationTokens(session); } - s_logger.Debug("SessionPool::GetIdleSession - no thread was waiting for a session, but could not find any idle session available in the pool"); + s_logger.Debug("SessionPool::GetIdleSession - no thread was waiting for a session, but could not find any idle session available in the pool" + PoolIdentification()); var sessionsCount = AllowedNumberOfNewSessionCreations(1); if (sessionsCount > 0) { @@ -232,10 +232,10 @@ private int AllowedNumberOfNewSessionCreations(int atLeastCount) var maxSessionsToCreate = _poolConfig.MaxPoolSize - currentSize; var sessionsNeeded = Math.Max(_poolConfig.MinPoolSize - currentSize, atLeastCount); var sessionsToCreate = Math.Min(sessionsNeeded, maxSessionsToCreate); - s_logger.Debug($"SessionPool - allowed to create {sessionsToCreate} sessions, current pool size is {currentSize} out of {_poolConfig.MaxPoolSize}"); + s_logger.Debug($"SessionPool - allowed to create {sessionsToCreate} sessions, current pool size is {currentSize} out of {_poolConfig.MaxPoolSize}" + PoolIdentification()); return sessionsToCreate; } - s_logger.Debug($"SessionPool - not allowed to create a session, current pool size is {currentSize} out of {_poolConfig.MaxPoolSize}"); + s_logger.Debug($"SessionPool - not allowed to create a session, current pool size is {currentSize} out of {_poolConfig.MaxPoolSize}" + PoolIdentification()); return 0; } @@ -245,7 +245,7 @@ private SFSession WaitForSession(string connStr) { if (TimeoutHelper.IsInfinite(_poolConfig.WaitingForIdleSessionTimeout)) throw new Exception("WaitingForIdleSessionTimeout cannot be infinite"); - s_logger.Info($"SessionPool::WaitForSession for {(long) _poolConfig.WaitingForIdleSessionTimeout.TotalMilliseconds} ms timeout"); + s_logger.Info($"SessionPool::WaitForSession for {(long) _poolConfig.WaitingForIdleSessionTimeout.TotalMilliseconds} ms timeout" + PoolIdentification()); _sessionPoolEventHandler.OnWaitingForSessionStarted(this); var beforeWaitingTimeMillis = DateTimeOffset.UtcNow.ToUnixTimeMilliseconds(); long nowTimeMillis = beforeWaitingTimeMillis; @@ -256,25 +256,25 @@ private SFSession WaitForSession(string connStr) var successful = _waitingForIdleSessionQueue.Wait((int) timeoutLeftMillis, CancellationToken.None); if (successful) { - s_logger.Debug($"SessionPool::WaitForSession - woken with a session granted"); + s_logger.Debug($"SessionPool::WaitForSession - woken with a session granted" + PoolIdentification()); _sessionPoolEventHandler.OnWaitingForSessionSuccessful(this); lock (_sessionPoolLock) { var session = ExtractIdleSession(connStr); if (session != null) { - s_logger.Debug($"SessionPool::WaitForSession - provided an idle session"); + s_logger.Debug("SessionPool::WaitForSession - provided an idle session" + PoolIdentification()); return session; } } } else { - s_logger.Debug($"SessionPool::WaitForSession - woken without a session granted"); + s_logger.Debug("SessionPool::WaitForSession - woken without a session granted" + PoolIdentification()); } nowTimeMillis = DateTimeOffset.UtcNow.ToUnixTimeMilliseconds(); } - s_logger.Info($"SessionPool::WaitForSession - could not find any idle session available withing a given timeout"); + s_logger.Info("SessionPool::WaitForSession - could not find any idle session available withing a given timeout" + PoolIdentification()); throw WaitingFailedException(); } @@ -291,12 +291,12 @@ private SFSession ExtractIdleSession(string connStr) var timeNow = DateTimeOffset.UtcNow.ToUnixTimeMilliseconds(); if (session.IsExpired(_poolConfig.ExpirationTimeout, timeNow)) { - Task.Run(() => session.close()); // TODO: cherry-pick SNOW-984600 + Task.Run(() => session.close()); i--; } else { - s_logger.Debug($"reuse pooled session with sid {session.sessionId}"); + s_logger.Debug($"reuse pooled session with sid {session.sessionId}" + PoolIdentification()); _busySessionsCounter.Increase(); return session; } @@ -310,18 +310,20 @@ private SFSession NewNonPoolingSession(String connectionString, SecureString pas private SFSession NewSession(String connectionString, SecureString password, SessionCreationToken sessionCreationToken) { - s_logger.Debug("SessionPool::NewSession"); + s_logger.Debug("SessionPool::NewSession" + PoolIdentification()); try { var session = s_sessionFactory.NewSession(connectionString, password); session.Open(); - s_logger.Debug("SessionPool::NewSession - opened"); + s_logger.Debug("SessionPool::NewSession - opened" + PoolIdentification()); if (GetPooling()) { lock (_sessionPoolLock) { _sessionCreationTokenCounter.RemoveToken(sessionCreationToken); _busySessionsCounter.Increase(); + var poolState = GetCurrentState(); + s_logger.Debug($"Pool state after creating a session {poolState}" + PoolIdentification()); } } _sessionPoolEventHandler.OnNewSessionCreated(this); @@ -332,6 +334,14 @@ private SFSession NewSession(String connectionString, SecureString password, Ses { // Otherwise when Dispose() is called, the close request would timeout. _sessionCreationTokenCounter.RemoveToken(sessionCreationToken); + if (GetPooling()) + { + lock (_sessionPoolLock) + { + var poolState = GetCurrentState(); + s_logger.Debug($"Failed to create a new session {poolState}" + PoolIdentification()); + } + } if (e is SnowflakeDbException) throw; throw new SnowflakeDbException( @@ -350,7 +360,7 @@ private Task NewNonPoolingSessionAsync( private Task NewSessionAsync(String connectionString, SecureString password, SessionCreationToken sessionCreationToken, CancellationToken cancellationToken) { - s_logger.Debug("SessionPool::NewSessionAsync"); + s_logger.Debug("SessionPool::NewSessionAsync" + PoolIdentification()); var session = s_sessionFactory.NewSession(connectionString, password); return session .OpenAsync(cancellationToken) @@ -359,6 +369,14 @@ private Task NewSessionAsync(String connectionString, SecureString pa if (previousTask.IsFaulted || previousTask.IsCanceled) { _sessionCreationTokenCounter.RemoveToken(sessionCreationToken); + if (GetPooling()) + { + lock (_sessionPoolLock) + { + var poolState = GetCurrentState(); + s_logger.Debug($"Failed to create a new session {poolState}" + PoolIdentification()); + } + } } if (previousTask.IsFaulted && previousTask.Exception != null) @@ -378,6 +396,8 @@ private Task NewSessionAsync(String connectionString, SecureString pa { _sessionCreationTokenCounter.RemoveToken(sessionCreationToken); _busySessionsCounter.Increase(); + var poolState = GetCurrentState(); + s_logger.Debug($"Pool state after creating a session {poolState}" + PoolIdentification()); } } @@ -390,18 +410,14 @@ private Task NewSessionAsync(String connectionString, SecureString pa internal void ReleaseBusySession(SFSession session) { - s_logger.Debug("SessionPool::ReleaseBusySession"); - int currentPoolSize; + s_logger.Debug("SessionPool::ReleaseBusySession" + PoolIdentification()); + SessionPoolState poolState; lock (_sessionPoolLock) { _busySessionsCounter.Decrease(); - currentPoolSize = GetCurrentPoolSize(); + poolState = GetCurrentState(); } - var currentSizeMessageOldPool = $"After releasing a busy session from the pool, the pool size is: {currentPoolSize}"; - var poolSizeMessage = IsMultiplePoolsVersion() - ? $"{currentSizeMessageOldPool} - pool identified by: {ConnectionString}" - : currentSizeMessageOldPool; - s_logger.Debug(poolSizeMessage); + s_logger.Debug($"After releasing a busy session from the pool {poolState}" + PoolIdentification()); } internal bool AddSession(SFSession session, bool ensureMinPoolSize) @@ -413,11 +429,7 @@ internal bool AddSession(SFSession session, bool ensureMinPoolSize) ReleaseBusySession(session); return false; } - const string AddSessionMessage = "SessionPool::AddSession"; - var addSessionMessage = IsMultiplePoolsVersion() - ? $"{AddSessionMessage} - returning session to pool identified by connection string: {ConnectionString}" - : AddSessionMessage; - s_logger.Debug(addSessionMessage); + s_logger.Debug("SessionPool::AddSession" + PoolIdentification()); var result = ReturnSessionToPool(session, ensureMinPoolSize); var wasSessionReturnedToPool = result.Item1; var sessionCreationTokens = result.Item2; @@ -433,9 +445,12 @@ private Tuple> ReturnSessionToPool(SFSession se lock (_sessionPoolLock) { _busySessionsCounter.Decrease(); - return ensureMinPoolSize - ? Tuple.Create(false, RegisterSessionCreationsWhenReturningSessionToPool()) - : Tuple.Create(false, SessionOrCreationTokens.s_emptySessionCreationTokenList); + var sessionCreationTokens = ensureMinPoolSize + ? RegisterSessionCreationsWhenReturningSessionToPool() + : SessionOrCreationTokens.s_emptySessionCreationTokenList; + var poolState = GetCurrentState(); + s_logger.Debug($"Could not return session to pool {poolState}" + PoolIdentification()); + return Tuple.Create(false, sessionCreationTokens); } } @@ -445,34 +460,33 @@ private Tuple> ReturnSessionToPool(SFSession se CleanExpiredSessions(); if (session.IsExpired(_poolConfig.ExpirationTimeout, DateTimeOffset.UtcNow.ToUnixTimeMilliseconds())) // checking again because we could have spent some time waiting for a lock { - return ensureMinPoolSize - ? Tuple.Create(false, RegisterSessionCreationsWhenReturningSessionToPool()) - : Tuple.Create(false, SessionOrCreationTokens.s_emptySessionCreationTokenList); + var sessionCreationTokens = ensureMinPoolSize + ? RegisterSessionCreationsWhenReturningSessionToPool() + : SessionOrCreationTokens.s_emptySessionCreationTokenList; + var poolState = GetCurrentState(); + s_logger.Debug($"Could not return session to pool {poolState}" + PoolIdentification()); + return Tuple.Create(false, sessionCreationTokens); } - if (GetCurrentPoolSize() >= _poolConfig.MaxPoolSize) + var poolStateBeforeReturningToPool = GetCurrentState(); + if (poolStateBeforeReturningToPool.Count() >= _poolConfig.MaxPoolSize) { - s_logger.Warn($"Pool is full - unable to add session with sid {session.sessionId}"); + s_logger.Warn($"Pool is full - unable to add session with sid {session.sessionId} {poolStateBeforeReturningToPool}");// TODO: + PoolIdentification()); return Tuple.Create(false, SessionOrCreationTokens.s_emptySessionCreationTokenList); } - s_logger.Debug($"pool connection with sid {session.sessionId}"); _idleSessions.Add(session); _waitingForIdleSessionQueue.OnResourceIncrease(); - return ensureMinPoolSize - ? Tuple.Create(true, RegisterSessionCreationsWhenReturningSessionToPool()) - : Tuple.Create(true, SessionOrCreationTokens.s_emptySessionCreationTokenList); + var sessionCreationTokensAfterReturningToPool = ensureMinPoolSize + ? RegisterSessionCreationsWhenReturningSessionToPool() + : SessionOrCreationTokens.s_emptySessionCreationTokenList; + var poolStateAfterReturningToPool = GetCurrentState(); + s_logger.Debug($"returned session with sid {session.sessionId} to pool {poolStateAfterReturningToPool}" + PoolIdentification()); + return Tuple.Create(true, sessionCreationTokensAfterReturningToPool); } } internal void ClearSessions() { - if (IsMultiplePoolsVersion()) - { - s_logger.Debug($"SessionPool::ClearSessions for connection string: {ConnectionString}"); - } - else - { - s_logger.Debug("SessionPool::ClearSessions"); - } + s_logger.Debug("SessionPool::ClearSessions" + PoolIdentification()); lock (_sessionPoolLock) { _busySessionsCounter.Reset(); @@ -482,7 +496,7 @@ internal void ClearSessions() internal void ClearIdleSessions() { - s_logger.Debug("SessionPool::ClearIdleSessions"); + s_logger.Debug("SessionPool::ClearIdleSessions" + PoolIdentification()); lock (_sessionPoolLock) { foreach (SFSession session in _idleSessions) @@ -495,7 +509,7 @@ internal void ClearIdleSessions() internal async void ClearAllPoolsAsync() { - s_logger.Debug("SessionPool::ClearAllPoolsAsync"); + s_logger.Debug("SessionPool::ClearAllPoolsAsync" + PoolIdentification()); IEnumerable idleSessionsCopy; lock (_sessionPoolLock) { @@ -536,9 +550,20 @@ public int GetCurrentPoolSize() return _idleSessions.Count + _busySessionsCounter.Count() + _sessionCreationTokenCounter.Count(); } + public SessionPoolState GetCurrentState() + { + return new SessionPoolState( + _idleSessions.Count, + _busySessionsCounter.Count(), + _sessionCreationTokenCounter.Count(), + _waitingForIdleSessionQueue.WaitingCount(), + IsMultiplePoolsVersion() + ); + } + public bool SetPooling(bool isEnable) { - s_logger.Info($"SessionPool::SetPooling({isEnable})"); + s_logger.Info($"SessionPool::SetPooling({isEnable})" + PoolIdentification()); if (_poolConfig.PoolingEnabled == isEnable) return false; _poolConfig.PoolingEnabled = isEnable; @@ -567,5 +592,10 @@ internal List GetIdleSessionsStartTimes() return _idleSessions.Select(s => s.GetStartTime()).ToList(); } } + + private String PoolIdentification() => + IsMultiplePoolsVersion() + ? " [pool identified by " + ConnectionString + "]" + : ""; } } diff --git a/Snowflake.Data/Core/Session/SessionPoolState.cs b/Snowflake.Data/Core/Session/SessionPoolState.cs new file mode 100644 index 000000000..4f29858c3 --- /dev/null +++ b/Snowflake.Data/Core/Session/SessionPoolState.cs @@ -0,0 +1,29 @@ +namespace Snowflake.Data.Core.Session +{ + public class SessionPoolState + { + private readonly int _idleSessionsCount; + private readonly int _busySessionsCount; + private readonly int _sessionCreationsCount; + private readonly int _waitingCount; + private readonly bool _extensiveFormat; + + public SessionPoolState(int idleSessionsCount, int busySessionsCount, int sessionCreationsCount, int waitingCount, bool extensiveFormat) + { + _idleSessionsCount = idleSessionsCount; + _busySessionsCount = busySessionsCount; + _sessionCreationsCount = sessionCreationsCount; + _waitingCount = waitingCount; + _extensiveFormat = extensiveFormat; + } + + public int Count() => _idleSessionsCount + _busySessionsCount + _sessionCreationsCount; + + public override string ToString() + { + return _extensiveFormat + ? $"[pool size: {Count()} (idle sessions: {_idleSessionsCount}, busy sessions: {_busySessionsCount}, sessions under creation: {_sessionCreationsCount}), waiting sessions: {_waitingCount}]" + : $"[pool size: {Count()}]"; + } + } +} diff --git a/Snowflake.Data/Core/Session/WaitingQueue.cs b/Snowflake.Data/Core/Session/WaitingQueue.cs index c8cd23390..bdd64b9f5 100644 --- a/Snowflake.Data/Core/Session/WaitingQueue.cs +++ b/Snowflake.Data/Core/Session/WaitingQueue.cs @@ -8,7 +8,7 @@ internal class WaitingQueue: IWaitingQueue { private readonly ReaderWriterLockSlim _lock = new ReaderWriterLockSlim(); private readonly List _queue = new List(); - + public bool Wait(int millisecondsTimeout, CancellationToken cancellationToken) { var semaphore = new SemaphoreSlim(0, 1); @@ -67,11 +67,14 @@ public void OnResourceIncrease() semaphore?.Release(); } - public bool IsAnyoneWaiting() { + public bool IsAnyoneWaiting() => WaitingCount() > 0; + + public int WaitingCount() + { _lock.EnterReadLock(); try { - return _queue.Count > 0; + return _queue.Count; } finally {