From 1b763f55b2f92690c7ef3844044c40d2a26e5614 Mon Sep 17 00:00:00 2001 From: Krzysztof Nozderko Date: Tue, 2 Jan 2024 12:34:44 +0100 Subject: [PATCH] debug info --- .../ConnectionMultiplePoolsIT.cs | 13 +++++++++---- Snowflake.Data/Core/Session/SessionPool.cs | 16 ++++++++++++---- 2 files changed, 21 insertions(+), 8 deletions(-) diff --git a/Snowflake.Data.Tests/IntegrationTests/ConnectionMultiplePoolsIT.cs b/Snowflake.Data.Tests/IntegrationTests/ConnectionMultiplePoolsIT.cs index abc384dc5..86f72497b 100644 --- a/Snowflake.Data.Tests/IntegrationTests/ConnectionMultiplePoolsIT.cs +++ b/Snowflake.Data.Tests/IntegrationTests/ConnectionMultiplePoolsIT.cs @@ -7,6 +7,7 @@ using NUnit.Framework; using Snowflake.Data.Client; using Snowflake.Data.Core.Session; +using Snowflake.Data.Log; using Snowflake.Data.Tests.Util; namespace Snowflake.Data.Tests.IntegrationTests @@ -16,6 +17,7 @@ namespace Snowflake.Data.Tests.IntegrationTests public class ConnectionMultiplePoolsIT: SFBaseTest { private readonly PoolConfig _previousPoolConfig = new PoolConfig(); + private static readonly SFLogger s_logger = SFLoggerFactory.GetLogger(); [SetUp] public new void BeforeTest() @@ -104,7 +106,7 @@ public void TestReuseSessionInConnectionPoolReachingMaxConnections() // old name public void TestWaitForTheIdleConnectionWhenExceedingMaxConnectionsLimit() { // arrange - var connectionString = ConnectionString; + var connectionString = ConnectionString + "application=TestWaitForMaxSize1"; var pool = SnowflakeDbConnectionPool.GetPool(connectionString); Assert.AreEqual(0, pool.GetCurrentPoolSize(), "expecting pool to be empty"); pool.SetMaxPoolSize(2); @@ -115,10 +117,13 @@ public void TestWaitForTheIdleConnectionWhenExceedingMaxConnectionsLimit() // act watch.Start(); + var start = DateTimeOffset.UtcNow.ToUnixTimeSeconds(); var thrown = Assert.Throws(() => OpenedConnection(connectionString)); + var stop = DateTimeOffset.UtcNow.ToUnixTimeSeconds(); watch.Stop(); - + // assert + s_logger.Debug($"TestWaitForTheIdleConnectionWhenExceedingMaxConnectionsLimit - start at: {start}, stop at: {stop}"); Assert.That(thrown.Message, Does.Contain("Unable to connect. Could not obtain a connection from the pool within a given timeout")); Assert.GreaterOrEqual(watch.ElapsedMilliseconds, 1000); Assert.LessOrEqual(watch.ElapsedMilliseconds, 1500); @@ -133,7 +138,7 @@ public void TestWaitForTheIdleConnectionWhenExceedingMaxConnectionsLimit() public void TestWaitForTheIdleConnectionWhenExceedingMaxConnectionsLimitAsync() { // arrange - var connectionString = ConnectionString; + var connectionString = ConnectionString + "application=TestWaitForMaxSize2"; var pool = SnowflakeDbConnectionPool.GetPool(connectionString); Assert.AreEqual(0, pool.GetCurrentPoolSize(), "expecting pool to be empty"); pool.SetMaxPoolSize(2); @@ -165,7 +170,7 @@ public void TestWaitForTheIdleConnectionWhenExceedingMaxConnectionsLimitAsync() public void TestWaitInAQueueForAnIdleSession() { // arrange - var connectionString = ConnectionString + "application=TestWaitInAQueueForAnIdleSession"; + var connectionString = ConnectionString + "application=TestWaitForMaxSize3"; var pool = SnowflakeDbConnectionPool.GetPool(connectionString); Assert.AreEqual(0, pool.GetCurrentPoolSize(), "the pool is expected to be empty"); pool.SetMaxPoolSize(2); diff --git a/Snowflake.Data/Core/Session/SessionPool.cs b/Snowflake.Data/Core/Session/SessionPool.cs index 5466f372e..1c3faa84e 100644 --- a/Snowflake.Data/Core/Session/SessionPool.cs +++ b/Snowflake.Data/Core/Session/SessionPool.cs @@ -171,6 +171,14 @@ private SFSession WaitForSession(string connStr) var timeout = _waitingQueue.GetWaitingTimeoutMillis(); s_logger.Debug($"SessionPool::WaitForSession for {timeout} millis timeout"); var beforeWaitingTime = DateTimeOffset.UtcNow.ToUnixTimeSeconds(); + string debugApplicationName = ""; + if (connStr.EndsWith("application=TestWaitForMaxSize1")) + debugApplicationName = "TestWaitForMaxSize1"; + if (connStr.EndsWith("application=TestWaitForMaxSize2")) + debugApplicationName = "TestWaitForMaxSize2"; + if (connStr.EndsWith("application=TestWaitForMaxSize3")) + debugApplicationName = "TestWaitForMaxSize3"; + s_logger.Debug($"Wait for session started at: {beforeWaitingTime} for: {debugApplicationName}"); long nowTime = beforeWaitingTime; while (nowTime < beforeWaitingTime + timeout) // we loop to handle the case if someone overtook us after being woken or session which we were promised has just expired { @@ -178,22 +186,22 @@ private SFSession WaitForSession(string connStr) var successful = _waitingQueue.Wait((int) timeoutLeft, CancellationToken.None); if (!successful) { - s_logger.Debug($"SessionPool::WaitForSession - woken without a session granted"); + s_logger.Debug($"SessionPool::WaitForSession - woken without a session granted for: {debugApplicationName}"); throw WaitingFailedException(); } - s_logger.Debug($"SessionPool::WaitForSession - woken with a session granted"); + s_logger.Debug($"SessionPool::WaitForSession - woken with a session granted for: {debugApplicationName}"); lock (_sessionPoolLock) { var session = ExtractIdleSession(connStr); if (session != null) { - s_logger.Debug($"SessionPool::WaitForSession - a session was extracted from idle sessions"); + s_logger.Debug($"SessionPool::WaitForSession - a session was extracted from idle sessions for: {debugApplicationName}"); return session; } } nowTime = DateTimeOffset.UtcNow.ToUnixTimeSeconds(); } - s_logger.Debug($"SessionPool::WaitForSession - could not find any idle session available withing a given timeout"); + s_logger.Debug($"SessionPool::WaitForSession - could not find any idle session available withing a given timeout for: {debugApplicationName} at: {nowTime}"); throw WaitingFailedException(); }