Lesson Learned #455:Optimizing Connection Pooling for Application Workloads: Exploring Login Rates

Posted November 27, 20231 yr

We have a client asking us what the login rate per second is that I can achieve on a S0, S1, S2, and S3 database. It's a complicated question but I'd like to share my experiences using a connection pooler.

The three previous articles we focus on optimizing connection pooling for application workloads, each addressing different aspects of this challenge:

Optimizing Connection Pooling - Thread Contention (Lesson Learned #455): - Lesson Learned #455:Optimizing Connection Pooling for Application Workloads: Thread Contention - Microsoft Community Hub
- Issue Addressed: A client experienced a 5-second delay in database connectivity while launching 50-100 concurrent processes. This delay was traced back to thread contention and not directly related to establishing database connections.
- Key Lessons:
  - Connection Pool Optimization: Adjusting the pool size to match concurrency needs and database server capabilities.
  - Improving Retry Logic: Implementing exponential backoff in retry logic.
  - Limiting Concurrent Connections: Using semaphores or a task queue to control connection concurrency.
  - Profiling and Monitoring: Utilizing tools to identify where contention occurs and understanding application behavior.

[*]Performance Measurement: Utilizing .NET CLR LocksAndThreads counters and external profiling tools to monitor thread behavior and database interactions.

[*]

Optimizing Connection Pooling - Active Connections (Lesson Learned #454): - Lesson Learned #454:Optimizing Connection Pooling for Application Workloads: Active Connections - Microsoft Community Hub

Exploration: The focus was on understanding active connections in connection pooling, including the number of pools, active connections, and how they fluctuate during open/close operations.
Findings: By opening and closing 100 connections, the dynamics of connection pooling were observed. Counters such as the number of active connections, connections managed by the pool, and connections waiting for readiness provided insights into the pool's performance.
Connection Pool Management: Key aspects included the removal of idle connections after 4-8 minutes and the implications of setting the 'Min Pool Size' in the connection string. If this value is greater than zero, the pool remains active as long as the minimum size is maintained.

[*]

Optimizing Connection Pooling - A Single Journey (Lesson Learned #453): Lesson Learned #453:Optimizing Connection Pooling for Application Workloads: A single journey - Microsoft Community Hub

Scenario: The customer reported high latency in establishing connections to a Basic type database using Active Directory authentication.
Investigation Results: The first connection took 3 seconds due to several steps like sending prelogin requests, requesting AAD tokens, and creating pooled database connections.
Connection Reuse Benefits: Subsequent connections were faster (0 ms) because the previously established connection was reused, avoiding the need for initial setup steps. The setup included a minimum pool size of 1 and a connection lifetime set to 0, ensuring constant availability and recovery in case of connectivity issues.

Each article contributes to a comprehensive understanding of the nuances and best practices in optimizing connection pooling, emphasizing the importance of configuration, monitoring, and understanding the behavior of connection pools in varying workloads and scenarios.

In this new article my idea is to know how using a subcore databases we could know how many logins per second we could have. So, the test will be the same for all databases: I'm going to run 50000 operations of Connect/Run a Select 1/Disconnect using 200 process at the same time, connection from home, in the North Europe database, using Redirect:

I'm going to start with Standard 0 database with 10 DTUs (0,10 of a vCore):

Well, as we saw in our article Lesson Learned #455:Optimizing Connection Pooling for Application Workloads: Thread Contention - Microsoft Community Hub we could have a thread contention and for this reason, as I know that I'm going to have at least 200 threads operations running at the same time. I'm going to cache first the connection, reducing the thread contention opening a new connection and leaving the connection ready to use.
We could see that the first operation 5 seconds to create the connection pooler stuff, but, the rest is taking few milliseconds to complete. The whole process take 1 minute and 33 seconds for opening and closing all.

2023-11-27 13:58:36.730: Pre-Warm - Done 0 - 02c6745e-c5eb-49be-8926-90d12fe7717e

2023-11-27 13:58:37.108: Pre-Warm - Done 1 - e0d8fb5b-bac3-4b9e-8076-53f92cd3b627

2023-11-27 13:58:37.490: Pre-Warm - Done 2 - f5085f5c-3abb-42f6-adf0-d28838dcc3e6

2023-11-27 13:58:38.005: Pre-Warm - Done 3 - fece89fd-4aa5-41ec-a21f-147e5472d547

2023-11-27 13:58:38.494: Pre-Warm - Done 4 - 50250745-249e-40a5-937e-90a5a1b70cf2

2023-11-27 13:58:39.063: Pre-Warm - Done 5 - fe880650-eb40-460a-aff2-133319f6906d

2023-11-27 13:58:39.549: Pre-Warm - Done 6 - d2383f0f-85c1-4b52-b9a4-76d61e353b08

2023-11-27 13:58:40.047: Pre-Warm - Done 7 - fe1e359d-7b5b-4e89-b4a5-f0b26c18ef6f

2023-11-27 13:58:40.514: Pre-Warm - Done 8 - 2483c7dd-e364-4e79-a511-73b685d4bcb6

2023-11-27 13:58:40.883: Pre-Warm - Done 9 - cb4309c2-03b2-476f-9efc-b32bb6197ef7

2023-11-27 13:58:41.340: Pre-Warm - Done 10 - 4ebb57ec-5255-42a2-a75e-b67fba1ef0a9

2023-11-27 13:58:41.706: Pre-Warm - Done 11 - d94c0ac3-7d32-4206-8092-0e68ea2b780e

2023-11-27 13:58:42.200: Pre-Warm - Done 12 - 1a6804a0-a1b7-464e-b9c3-62a2139992d4

2023-11-27 13:58:42.671: Pre-Warm - Done 13 - 75ab1eaf-04df-4888-85a4-88a8480996e4

2023-11-27 13:58:43.159: Pre-Warm - Done 14 - 16e8057d-af87-4ddc-ad1f-dc268caeb27d

2023-11-27 13:58:43.642: Pre-Warm - Done 15 - cd178928-fe09-4bc7-be49-cec3c8c7d96a

2023-11-27 13:58:44.005: Pre-Warm - Done 16 - e4768733-f58a-4a6a-8e21-9d9bbf5ef475

2023-11-27 13:58:44.493: Pre-Warm - Done 17 - 607b8cc9-471c-4cef-89db-ba41d5ca6a4c

2023-11-27 13:58:44.881: Pre-Warm - Done 18 - a5eb1d8d-43a2-4537-8f51-1c55ec739ac0

2023-11-27 13:58:45.253: Pre-Warm - Done 19 - 5d9e8443-ae15-4df1-86ce-0c468c861124

2023-11-27 13:58:45.679: Pre-Warm - Done 20 - b0cb4431-7f27-4690-ab21-e475586b5675

During this pre-process, I've created a Extended Event to capture all the logins

CREATE EVENT SESSION [LoginLogoutTracking] ON DATABASE

ADD EVENT sqlserver.login(

ACTION(sqlserver.client_app_name,sqlserver.client_connection_id,sqlserver.session_id))

ADD TARGET package0.event_file(SET filename=N'https://blobstorage.blob.core.windows.net/xevents/LoginLogoutTracking.xel')

WITH (MAX_MEMORY=8096 KB,EVENT_RETENTION_MODE=NO_EVENT_LOSS,MAX_DISPATCH_LATENCY=15 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=ON,STARTUP_STATE=OFF)

If we check the login extended event collected, we could see every second we have three connections made. Why? well connecting from home will take around aprox. 300 ms each time. So, running in Azure Environment, this time will be less.

name timestamp client_app_name client_connection_id session_id

Once we have this one, let's see how it went. More than 200 operations from 2023-11-27 10:46:00.5605246 to 2023-11-27 10:46:00.8593112 with CPU < 50% and 34.66% of session percent.

name timestamp client_app_name client_connection_id session_id

[ATTACH=full]56821[/ATTACH]

What happens when the database is S3 ( 1vCore):
- The Pre-Warm time was the same.
- But, executing the process take less, CPU and MaxSession usage.

[ATTACH=full]56822[/ATTACH]

Code

using System;

using Polly;

using Microsoft.Data.SqlClient;

using System.Diagnostics;

using System.Threading;

using System.Threading.Tasks;

using System.IO;

using System.Collections;

namespace HealthCheck

{

class Program

{

const string LogFolder = "c:\\temp\\Mydata";

const string LogFilePath = LogFolder + "\\log";

const string LogExtPath = ".log";

static async Task Main(string[] args)

{

DeleteDirectoryIfExists(LogFolder);

int numberOfThreads = 50000; //Nr Threads

int maxDegreeOfParallelism = 200; //Nr Threads to run concurrent

string connectionString = "data source=tcp:servername.database.windows.net,1433;initial catalog=test;User Id=username@microsoft.com;Password=Pwd1!;ConnectRetryCount=3;ConnectRetryInterval=10;Connection Timeout=5;Max Pool Size=200;MultipleActiveResultSets=false;Min Pool Size=0;Pooling=true;Authentication=Active Directory Password;PoolBlockingPeriod=NeverBlock;Connection Lifetime=0;Application Name=Testing by JMJD - SQL Unique";

/*Pre-Warm*/

Log($"Pre-Warm - Opening connection",-1);

SqlConnection[] oConnection = new SqlConnection[maxDegreeOfParallelism];

for (int i = 0; i < maxDegreeOfParallelism; i++)

{

Log($"Pre-Warm - Starting {i}", -1);

oConnection = new SqlConnection(connectionString);

oConnection.Open();

Log($"Pre-Warm - Done {i} - {oConnection.ClientConnectionId.ToString()}", -1);

}

Log($"Pre-Warm - Closing connection", -1);

for (int i = 0; i < maxDegreeOfParallelism; i++)

{

if (oConnection.State == System.Data.ConnectionState.Open)

{

Log($"Pre-Warm - Closing {i}", -1);

oConnection.Close();

}

Log($"Pre-Warm - Starting the process", -1);

var semaphore = new SemaphoreSlim(maxDegreeOfParallelism);

var tasks = new Task[numberOfThreads];

for (int i = 0; i < numberOfThreads; i++)

{

tasks = Task.Run(async () =>

{

await semaphore.WaitAsync();

try

{

await ExecuteQueryAsync(connectionString, false);

}

finally

{

semaphore.Release();

}

});

}

await Task.WhenAll(tasks);

}

static async Task ExecuteQueryAsync(string connectionString, Boolean bDifferentConnString=false)

{

int threadId = Thread.CurrentThread.ManagedThreadId;

TimeSpan ts;

string elapsedTime;

string sConnectionStringDummy = "";

try

{

Log($"Thread {threadId}: Opening the connection",threadId);

if (bDifferentConnString)

{

sConnectionStringDummy = sConnectionStringDummy + connectionString + " T# " + threadId.ToString();

}

else

{

sConnectionStringDummy = sConnectionStringDummy + connectionString;

}

Stopwatch stopWatch = new Stopwatch();

stopWatch.Start();

SqlConnection connection = await ConnectWithRetriesAsync(sConnectionStringDummy, threadId);

ts = stopWatch.Elapsed;

elapsedTime = String.Format("{0:00}:{1:00}:{2:00}.{3:00}",

ts.Hours, ts.Minutes, ts.Seconds,

ts.Milliseconds / 10);

Log($"Thread {threadId}: Connected - {elapsedTime} " + connection.ClientConnectionId.ToString(),threadId);

//Log($"Thread {threadId}: Executing the command",threadId);

SqlCommand command = new SqlCommand("SELECT 1", connection);

command.CommandTimeout = 5;

stopWatch.Reset();

stopWatch.Start();

object result = await ExecuteCommandWithRetriesAsync(command);

stopWatch.Stop();

ts = stopWatch.Elapsed;

elapsedTime = String.Format("{0:00}:{1:00}:{2:00}.{3:00}",

ts.Hours, ts.Minutes, ts.Seconds,

ts.Milliseconds / 10);

Log($"Thread {threadId}: Executed the command - {elapsedTime} - Result: {result}", threadId);

//Log($"Thread {threadId}: Closing the connection");

connection.Close();

}

catch (OperationCanceledException canc)

{

Log($"Thread {threadId}: Error (Cancelation): {canc.Message}", threadId);

}

catch (Exception ex)

{

Log($"Thread {threadId}: - Error (Exception): {ex.Message}", threadId);

}

static async Task<SqlConnection> ConnectWithRetriesAsync(string connectionString, int threadId)

{

Log($"Thread {threadId}: Calling", threadId);

SqlConnection connection = new SqlConnection(connectionString);

connection.StatisticsEnabled = true;

Log($"Thread {threadId}: End Calling", threadId);

var policy = Policy

.Handle<Exception>()

.WaitAndRetryAsync(5, retryAttempt => TimeSpan.FromSeconds(connection.ConnectionTimeout * 1.05),

(exception, timespan, retryCount, context) =>

{

Log($"Thread {threadId}: Retry {retryCount} due to {exception.Message}. Will retry in {timespan.TotalSeconds} seconds.", threadId);

});

await policy.ExecuteAsync(async () =>

{

try

{

await connection.OpenAsync();

IDictionary currentStatistics = connection.RetrieveStatistics();

if (currentStatistics["ExecutionTime"].ToString() != "0" || currentStatistics["ConnectionTime"].ToString() != "0")

{

Log("Thread "+ threadId.ToString() + ": " + connection.ClientConnectionId.ToString() + " ExecutionTime: " + currentStatistics["ExecutionTime"] + " ConnectionTime:" + currentStatistics["ConnectionTime"], threadId);

}

catch (Exception ex)

{

throw;

}

});

return connection;

}

static async Task<object> ExecuteCommandWithRetriesAsync(SqlCommand command)

{

var policy = Policy

.Handle<Exception>()

.WaitAndRetryAsync(5, retryAttempt => TimeSpan.FromSeconds(command.CommandTimeout * 1.05),

(exception, timespan, retryCount, context) =>

{

Log($"Retry {retryCount} due to {exception.Message}. Will retry in {timespan.TotalSeconds} seconds.");

});

object result = null;

await policy.ExecuteAsync(async () =>

{

try

{

result = await command.ExecuteScalarAsync();

}

catch (Exception ex)

{

throw;

}

});

return result;

}

static void Log(string message, int iThread = 0)

{

var ahora = DateTime.Now;

string logMessage = $"{ahora.ToString("yyyy-MM-dd HH:mm:ss.fff")}: {message}";

string sLogFile = LogFolder + "\\log" + iThread.ToString() + LogExtPath;

//Console.WriteLine(logMessage);

try

{

using (FileStream stream = new FileStream(sLogFile, FileMode.Append, FileAccess.Write, FileShare.ReadWrite))

{

using (StreamWriter writer = new StreamWriter(stream))

{

writer.WriteLine(logMessage);

}

catch (IOException ex)

{

Console.WriteLine($"Error writing in the log file: {ex.Message}");

}

public static void DeleteDirectoryIfExists(string path)

{

try

{

if (Directory.Exists(path))

{

Directory.Delete(path, true);

}

Directory.CreateDirectory(path);

}

catch (Exception ex)

{

Console.WriteLine($"Error deleting the folder: {ex.Message}");

}

Enjoy!

Continue reading...

Quote

Sign In

Lesson Learned #455:Optimizing Connection Pooling for Application Workloads: Exploring Login Rates

Featured Replies

Join the conversation

Account

Navigation

Search