Lesson Learned #453:Optimizing Connection Pooling for Application Workloads: A single journey

Jose_Manuel_Jurado · ‎Nov 25 2023

In recent days, we have received several requests how to reduce the latency of a connection for an application designed to check database availability for receiving requests. I would like to share with you my experience, along with other articles that will be published shortly.

In this first article, our customer indicates that each time they establish a connection to a Basic type database, the connection time exceeds several seconds when using Active Directory authentication. Based on our script, which you can find below, we encountered the following connectivity time results:

Result of the connection.
Connection ID.
Client Machine Name.
How much took the connection.
How much time to the execution of SELECT 1.

2023-11-25 15:23:30.429: Trying the connection...
2023-11-25 15:23:33.513: Successful connection. - b0ebb64d-6558-4281-aeee-2fe74c276715 - testvm
2023-11-25 15:23:33.514: Connected - 00:00:03.19
2023-11-25 15:23:33.589: Executed - 00:00:00.07
2023-11-25 15:23:38.607: Trying the connection...
2023-11-25 15:23:38.609: Successful connection. - b0ebb64d-6558-4281-aeee-2fe74c276715 - testvm
2023-11-25 15:23:38.609: Connected - 00:00:00.00
2023-11-25 15:23:38.650: Executed - 00:00:00.04
2023-11-25 15:23:43.654: Trying the connection...
2023-11-25 15:23:43.656: Successful connection. - b0ebb64d-6558-4281-aeee-2fe74c276715 - testvm
2023-11-25 15:23:43.657: Connected - 00:00:00.00
2023-11-25 15:23:43.697: Executed - 00:00:00.03
2023-11-25 15:23:48.711: Trying the connection...
2023-11-25 15:23:48.712: Successful connection. - b0ebb64d-6558-4281-aeee-2fe74c276715 - testvm
2023-11-25 15:23:48.713: Connected - 00:00:00.00
2023-11-25 15:23:48.752: Executed - 00:00:00.03
2023-11-25 15:23:53.763: Trying the connection...
2023-11-25 15:23:53.764: Successful connection. - b0ebb64d-6558-4281-aeee-2fe74c276715 - testvm
2023-11-25 15:23:53.765: Connected - 00:00:00.00
2023-11-25 15:23:53.804: Executed - 00:00:00.03
2023-11-25 15:23:58.816: Trying the connection...
2023-11-25 15:23:58.818: Successful connection. - b0ebb64d-6558-4281-aeee-2fe74c276715 - testvm
2023-11-25 15:23:58.819: Connected - 00:00:00.00
2023-11-25 15:23:58.858: Executed - 00:00:00.03
2023-11-25 15:24:03.871: Trying the connection...
2023-11-25 15:24:03.872: Successful connection. - b0ebb64d-6558-4281-aeee-2fe74c276715 - testvm
2023-11-25 15:24:03.872: Connected - 00:00:00.00
2023-11-25 15:24:03.911: Executed - 00:00:00.03
2023-11-25 15:24:08.927: Trying the connection...
2023-11-25 15:24:08.928: Successful connection. - b0ebb64d-6558-4281-aeee-2fe74c276715 - testvm
2023-11-25 15:24:08.928: Connected - 00:00:00.00
2023-11-25 15:24:08.967: Executed - 00:00:00.03
2023-11-25 15:24:13.976: Trying the connection...
2023-11-25 15:24:13.977: Successful connection. - b0ebb64d-6558-4281-aeee-2fe74c276715 - testvm
2023-11-25 15:24:13.978: Connected - 00:00:00.00
2023-11-25 15:24:14.019: Executed - 00:00:00.04
2023-11-25 15:24:19.037: Trying the connection...
2023-11-25 15:24:19.038: Successful connection. - b0ebb64d-6558-4281-aeee-2fe74c276715 - testvm
2023-11-25 15:24:19.039: Connected - 00:00:00.00
2023-11-25 15:24:19.077: Executed - 00:00:00.03
2023-11-25 15:24:24.080: Trying the connection...
2023-11-25 15:24:24.082: Successful connection. - b0ebb64d-6558-4281-aeee-2fe74c276715 - testvm
2023-11-25 15:24:24.083: Connected - 00:00:00.00
2023-11-25 15:24:24.121: Executed - 00:00:00.03

Question 1: Why the first connection took 3 seconds?

Checking our file SqlClient.Log generated by our script, I have found several interesting topics.

Several activities that connection pooling needs to perform.
Send the Prelogin to the server.
Request the AAD token to AAD servers.
Send the Prelogin handshake to Azure SQL Databases with the AAD token included.
Received the ack from AAD
Create the pooled database connection.
Set the command.

2023-11-25 15:23:30.405: <prov.DbConnectionHelper.ConnectionString_Set|API> 1, 'Server=tcp:servername.database.windows.net,1433;User Id=username@microsoft.com;Initial Catalog=test;Persist Security Info=False;MultipleActiveResultSets=False;Encrypt=True;TrustServerCertificate=False;Connection Timeout=5;Pooling=true;Max Pool size=1;Min Pool Size=1;ConnectRetryCount=3;ConnectRetryInterval=10;Authentication=Active Directory Password;PoolBlockingPeriod=NeverBlock;Connection Lifetime=0;Application Name=ConnTest'
2023-11-25 15:23:30.455: <sc.SqlConfigurableRetryLogicManager.ConnectionProvider|INFO> Requested the ConnectionProvider value.
2023-11-25 15:23:30.658: <sc.AppConfigManager.FetchConfigurationSection|INFO>: Unable to load custom `SqlConfigurableRetryLogicConnection`. Default value of `T` type returns.
2023-11-25 15:23:30.658: <sc.AppConfigManager.FetchConfigurationSection|INFO>: Unable to load custom `SqlConfigurableRetryLogicCommand`. Default value of `T` type returns.
2023-11-25 15:23:30.716: <sc|SqlAuthenticationProviderManager|Ctor|Info>No SqlAuthProviders configuration section found.
2023-11-25 15:23:30.791: TdsParserStateObjectFactory.CreateTdsParserStateObject | Info | AppContext switch 'Switch.Microsoft.Data.SqlClient.UseManagedNetworkingOnWindows' not enabled, native networking implementation will be used.
2023-11-25 15:23:30.797: TdsParser.Connect | SEC | Connection Object Id 4, Authentication Mode: ActiveDirectoryPassword
2023-11-25 15:23:30.819: <sc.SqlConfigurableRetryLogicLoader.MakeFullPath|INFO> Looking for 'Microsoft.Data.SqlClient.resources' assembly in 'C:\AppTest\C#\HealthCheck\bin\Debug\netcoreapp3.1' directory.
2023-11-25 15:23:30.819: <sc.SqlConfigurableRetryLogicLoader.MakeFullPath|INFO> Looking for 'Microsoft.Data.SqlClient.resources' assembly by 'C:\AppTest\C#\HealthCheck\bin\Debug\netcoreapp3.1\Microsoft.Data.SqlClient.resources' full path.
2023-11-25 15:23:30.821: <sc.SqlConfigurableRetryLogicLoader.Default_Resolving|INFO> Looking for 'Microsoft.Data.SqlClient.resources, Version=5.0.0.0, Culture=en-US, PublicKeyToken=23ec7fc2d6eaa4a5' assembly that is requested by '"Default" System.Runtime.Loader.DefaultAssemblyLoadContext #0' ALC from 'null' path.
2023-11-25 15:23:30.822: <sc.SqlConfigurableRetryLogicLoader.MakeFullPath|INFO> Looking for 'Microsoft.Data.SqlClient.resources' assembly in 'C:\AppTest\C#\HealthCheck\bin\Debug\netcoreapp3.1' directory.
2023-11-25 15:23:30.823: <sc.SqlConfigurableRetryLogicLoader.MakeFullPath|INFO> Looking for 'Microsoft.Data.SqlClient.resources' assembly by 'C:\AppTest\C#\HealthCheck\bin\Debug\netcoreapp3.1\Microsoft.Data.SqlClient.resources' full path.
2023-11-25 15:23:30.823: <sc.SqlConfigurableRetryLogicLoader.Default_Resolving|INFO> Looking for 'Microsoft.Data.SqlClient.resources, Version=5.0.0.0, Culture=en, PublicKeyToken=23ec7fc2d6eaa4a5' assembly that is requested by '"Default" System.Runtime.Loader.DefaultAssemblyLoadContext #0' ALC from 'null' path.
2023-11-25 15:23:30.825: <sc.SqlConfigurableRetryLogicLoader.MakeFullPath|INFO> Looking for 'Microsoft.Data.SqlClient.resources' assembly in 'C:\AppTest\C#\HealthCheck\bin\Debug\netcoreapp3.1' directory.
2023-11-25 15:23:30.826: <sc.SqlConfigurableRetryLogicLoader.MakeFullPath|INFO> Looking for 'Microsoft.Data.SqlClient.resources' assembly by 'C:\AppTest\C#\HealthCheck\bin\Debug\netcoreapp3.1\Microsoft.Data.SqlClient.resources' full path.
2023-11-25 15:23:30.826: <sc.SqlConfigurableRetryLogicLoader.Default_Resolving|INFO> Looking for 'Microsoft.Data.SqlClient.resources, Version=5.0.0.0, Culture=en-US, PublicKeyToken=23ec7fc2d6eaa4a5' assembly that is requested by '"Default" System.Runtime.Loader.DefaultAssemblyLoadContext #0' ALC from 'null' path.
2023-11-25 15:23:30.827: <sc.SqlConfigurableRetryLogicLoader.MakeFullPath|INFO> Looking for 'Microsoft.Data.SqlClient.resources' assembly in 'C:\AppTest\C#\HealthCheck\bin\Debug\netcoreapp3.1' directory.
2023-11-25 15:23:30.828: <sc.SqlConfigurableRetryLogicLoader.MakeFullPath|INFO> Looking for 'Microsoft.Data.SqlClient.resources' assembly by 'C:\AppTest\C#\HealthCheck\bin\Debug\netcoreapp3.1\Microsoft.Data.SqlClient.resources' full path.
2023-11-25 15:23:30.829: <sc.SqlConfigurableRetryLogicLoader.Default_Resolving|INFO> Looking for 'Microsoft.Data.SqlClient.resources, Version=5.0.0.0, Culture=en, PublicKeyToken=23ec7fc2d6eaa4a5' assembly that is requested by '"Default" System.Runtime.Loader.DefaultAssemblyLoadContext #0' ALC from 'null' path.
2023-11-25 15:23:30.909: <sc.TdsParser.Connect|SEC> Sending prelogin handshake
2023-11-25 15:23:30.914: <sc.TdsParser.SendPreLoginHandshake|INFO> ClientConnectionID dad689d9-f823-4f03-9f72-528efbfc3dc4, ActivityID d1954e31-b051-42c3-b607-ed0d04ffa00a:1
2023-11-25 15:23:30.923: <sc.TdsParser.Connect|SEC> Consuming prelogin handshake
2023-11-25 15:23:31.047: <sc.TdsParser.Connect|SEC> Prelogin handshake successful
2023-11-25 15:23:31.056: <sc.TdsParser.TdsLogin|SEC> Sending federated authentication feature request
2023-11-25 15:23:31.057: <sc.TdsParser.TdsLogin|SEC> Sending federated authentication feature request
2023-11-25 15:23:31.094: <sc.TdsParser.TryRun|SEC> Received login acknowledgement token
2023-11-25 15:23:31.104: <sc.AppConfigManager.FetchConfigurationSection|INFO>: Unable to load custom `AppContextSwitchOverrides`. Default value of `T` type returns.
2023-11-25 15:23:31.105: <sc.SqlAppContextSwitchManager.ApplyContextSwitches|INFO> Entry point.
2023-11-25 15:23:31.105: <sc.SqlAppContextSwitchManager.ApplyContextSwitches|INFO> Exit point.
2023-11-25 15:23:31.107: <sc.SqlInternalConnectionTds.LoginNoFailover> Routed to tcp:servername.database.windows.net,1433
2023-11-25 15:23:31.109: TdsParserStateObjectFactory.CreateTdsParserStateObject | Info | AppContext switch 'Switch.Microsoft.Data.SqlClient.UseManagedNetworkingOnWindows' not enabled, native networking implementation will be used.
2023-11-25 15:23:31.109: TdsParser.Connect | SEC | Connection Object Id 4, Authentication Mode: ActiveDirectoryPassword
2023-11-25 15:23:31.145: <sc.TdsParser.Connect|SEC> Sending prelogin handshake
2023-11-25 15:23:31.146: <sc.TdsParser.SendPreLoginHandshake|INFO> ClientConnectionID b0ebb64d-6558-4281-aeee-2fe74c276715, ActivityID d1954e31-b051-42c3-b607-ed0d04ffa00a:2
2023-11-25 15:23:31.147: <sc.TdsParser.Connect|SEC> Consuming prelogin handshake
2023-11-25 15:23:31.257: <sc.TdsParser.Connect|SEC> Prelogin handshake successful
2023-11-25 15:23:31.258: <sc.TdsParser.TdsLogin|SEC> Sending federated authentication feature request
2023-11-25 15:23:31.259: <sc.TdsParser.TdsLogin|SEC> Sending federated authentication feature request
2023-11-25 15:23:31.299: <sc.TdsParser.TryProcessFedAuthInfo> Processed FEDAUTHINFO token stream: STSURL: https://login.windows.net/xxx, SPN: https://database.windows.net/
2023-11-25 15:23:31.301: <sc.SqlInternalConnectionTds.OnFedAuthInfo> 4, Generating federated authentication token
2023-11-25 15:23:31.408: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:31.409: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:31.410: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:31.412: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:31.412: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:31.413: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:31.415: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:31.417: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:31.419: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:31.421: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:31.431: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:31.449: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:31.454: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:31.462: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:31.472: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:31.473: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:32.386: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:32.387: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:32.387: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:32.388: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:32.389: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:32.389: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:32.390: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:32.391: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:32.392: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:32.393: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:32.395: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:32.396: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:32.397: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:32.398: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:32.399: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:32.400: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:33.394: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:33.395: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:33.396: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:33.397: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:33.397: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:33.398: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:33.399: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:33.400: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:33.401: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:33.402: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:33.403: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:33.404: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:33.406: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:33.407: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:33.408: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:33.408: System.Diagnostics.Tracing.EventPayload
2023-11-25 15:23:33.428: AcquireTokenAsync | Acquired access token for Active Directory Password auth mode. Expiry Time: 25/11/2023 15:41:48 +00:00
2023-11-25 15:23:33.431: <sc|ActiveDirectoryAuthenticationTimeoutRetryHelper|SetCachedToken|Info>CachedToken changed from null to TRxxxxxxxxxxxxxxxxxxxxxxxxxx=.
2023-11-25 15:23:33.431: <sc.SqlInternalConnectionTds.GetFedAuthToken> 4, Finished generating federated authentication token.
2023-11-25 15:23:33.432: <sc.TdsParser.SendFedAuthToken|SEC> Sending federated authentication token
2023-11-25 15:23:33.487: <sc.TdsParser.TryRun|SEC> Received login acknowledgement token
2023-11-25 15:23:33.508: <sc|ActiveDirectoryAuthenticationTimeoutRetryHelper|SetState|Info>State changed from NotStarted to HasLoggedIn.
2023-11-25 15:23:33.509: <prov.DbConnectionFactory.CreatePooledConnection|RES|CPOOL> 1, Pooled database connection created.
2023-11-25 15:23:33.518: SqlCommand.Set_CommandText | API | Object Id 1, String Value = 'SELECT 1', Client Connection Id null
2023-11-25 15:23:33.519: SqlCommand.Set_Connection | API | ObjectId 1, Client Connection Id b0ebb64d-6558-4281-aeee-2fe74c276715
2023-11-25 15:23:33.520: SqlCommand.Set_CommandTimeout | API | ObjectId 1, Command Timeout value 5, Client Connection Id b0ebb64d-6558-4281-aeee-2fe74c276715
2023-11-25 15:23:33.520: SqlCommand.Set_CommandTimeout | API | ObjectId 1, Command Timeout value 5, Client Connection Id b0ebb64d-6558-4281-aeee-2fe74c276715
2023-11-25 15:23:33.523: <sc.SqlConfigurableRetryLogicManager.CommandProvider|INFO> Requested the CommandProvider value.
2023-11-25 15:23:33.532: SqlCommand.RunExecuteReaderTds | Info | Object Id 1, Activity Id 99bb21f3-cf1f-4f28-b1fc-ba69cf4cb696:1, Client Connection Id b0ebb64d-6558-4281-aeee-2fe74c276715, Command executed as SQLBATCH, Command Text 'SELECT 1' 
2023-11-25 15:23:33.586: TdsParserStateObject.DecrementOpenResultCount | INFO | State Object Id 2, Processing Attention.

Question 2: Why the second and successive connections took 0 ms?

As you could see, we are reusing the previous connection established. As we can observe, it is no longer necessary to perform the previous tasks. Moreover, if we set the Min Pool Size to 1, as in this case, and since we are always reusing the connection, this will ensure that the connection pooling always has one ready to receive requests. Additionally, our connection lifetime is set to 0, which indicates that the connection will never be destroyed. If there is a connectivity issue with the connection already established in the connection pool, ConnectRetryCount will assist in recovering it, and if not, our retry policy will help to reconnect. Finally, although we use PoolBlockingPeriod=NeverBlock by default, the Microsoft.Data.SqlClient library, when detecting that we are connecting to Azure SQL Database, will not apply any blocking

2023-11-25 15:23:38.606: <prov.DbConnectionHelper.ConnectionString_Set|API> 2, 'Server=tcp:servername.database.windows.net,1433;User Id=username@microsoft.com;Initial Catalog=test;Persist Security Info=False;MultipleActiveResultSets=False;Encrypt=True;TrustServerCertificate=False;Connection Timeout=5;Pooling=true;Max Pool size=1;Min Pool Size=1;ConnectRetryCount=3;ConnectRetryInterval=10;Authentication=Active Directory Password;PoolBlockingPeriod=NeverBlock;Connection Lifetime=0;Application Name=ConnTest'
2023-11-25 15:23:38.608: <sc.SqlConfigurableRetryLogicManager.ConnectionProvider|INFO> Requested the ConnectionProvider value.
2023-11-25 15:23:38.610: SqlCommand.Set_CommandText | API | Object Id 2, String Value = 'SELECT 1', Client Connection Id null
2023-11-25 15:23:38.610: SqlCommand.Set_Connection | API | ObjectId 2, Client Connection Id b0ebb64d-6558-4281-aeee-2fe74c276715
2023-11-25 15:23:38.611: SqlCommand.Set_CommandTimeout | API | ObjectId 2, Command Timeout value 5, Client Connection Id b0ebb64d-6558-4281-aeee-2fe74c276715
2023-11-25 15:23:38.611: <sc.SqlConfigurableRetryLogicManager.CommandProvider|INFO> Requested the CommandProvider value.
2023-11-25 15:23:38.613: SqlCommand.RunExecuteReaderTds | Info | Object Id 2, Activity Id 99bb21f3-cf1f-4f28-b1fc-ba69cf4cb696:1, Client Connection Id b0ebb64d-6558-4281-aeee-2fe74c276715, Command executed as SQLBATCH, Command Text 'SELECT 1' 
2023-11-25 15:23:38.650: TdsParserStateObject.DecrementOpenResultCount | INFO | State Object Id 2, Processing Attention.

Question 3: What does happen at database level?

Well, running a XEvent Profiler we could see that each time we see login,execution and logout.

Question 4: A simple review about the connection string parameters?

In our blog we have many articles, explaining details about connection timeout, pooling, ConnecRetryCount but in this case I would like to pay attention about:

Connection Lifetime: Discuss when to reset connections. Link to Connection Lifetime property. In order to know what is the impact if I changed the connection string the connection liftime to 5 seconds, I found that every time that we reached this threshold a previous connection is destroyed, creating a new one. At this time, more time is needed to prepare the new stuff, for example, request a new AAD token, pre-handshake with the database, etc.. In this situation, took around 500 ms.

2023-11-25 16:53:47.374: Trying the connection...
2023-11-25 16:53:47.912: Successful connection. - 14ae2a44-788c-4bb2-b330-1da189b718eb - testvm
2023-11-25 16:53:47.913: Connected - 00:00:00.54

2023-11-25 16:53:47.373: <prov.DbConnectionHelper.ConnectionString_Set|API> 108, 'Server=tcp:servername.database.windows.net,1433;User Id=username@microsoft.com;Initial Catalog=test;Persist Security Info=False;MultipleActiveResultSets=False;Encrypt=True;TrustServerCertificate=False;Connection Timeout=5;Pooling=true;Max Pool size=1;Min Pool Size=1;ConnectRetryCount=3;ConnectRetryInterval=10;Authentication=Active Directory Password;PoolBlockingPeriod=NeverBlock;Connection Lifetime=5;Application Name=ConnTest'
2023-11-25 16:53:47.372: TdsParserStateObjectFactory.CreateTdsParserStateObject | Info | AppContext switch 'Switch.Microsoft.Data.SqlClient.UseManagedNetworkingOnWindows' not enabled, native networking implementation will be used.
2023-11-25 16:53:47.375: <sc.SqlConfigurableRetryLogicManager.ConnectionProvider|INFO> Requested the ConnectionProvider value.
2023-11-25 16:53:47.375: TdsParser.Connect | SEC | Connection Object Id 7, Authentication Mode: ActiveDirectoryPassword
2023-11-25 16:53:47.432: <sc.TdsParser.Connect|SEC> Sending prelogin handshake
2023-11-25 16:53:47.433: <sc.TdsParser.SendPreLoginHandshake|INFO> ClientConnectionID 63f40765-f9cb-4ef8-9c28-ea6dc5bb99a6, ActivityID 0adb762f-b82a-4b4c-9acc-3bfe0fab47f0:3
2023-11-25 16:53:47.433: <sc.TdsParser.Connect|SEC> Consuming prelogin handshake
2023-11-25 16:53:47.613: <sc.TdsParser.Connect|SEC> Prelogin handshake successful
2023-11-25 16:53:47.614: <sc.TdsParser.TdsLogin|SEC> Sending federated authentication feature request
2023-11-25 16:53:47.615: <sc.TdsParser.TdsLogin|SEC> Sending federated authentication feature request
2023-11-25 16:53:47.671: <sc.TdsParser.TryRun|SEC> Received login acknowledgement token
2023-11-25 16:53:47.672: <sc.SqlInternalConnectionTds.LoginNoFailover> Routed to tcp:servername.database.windows.net,1433
2023-11-25 16:53:47.673: TdsParserStateObjectFactory.CreateTdsParserStateObject | Info | AppContext switch 'Switch.Microsoft.Data.SqlClient.UseManagedNetworkingOnWindows' not enabled, native networking implementation will be used.
2023-11-25 16:53:47.673: TdsParser.Connect | SEC | Connection Object Id 7, Authentication Mode: ActiveDirectoryPassword
2023-11-25 16:53:47.709: <sc.TdsParser.Connect|SEC> Sending prelogin handshake
2023-11-25 16:53:47.710: <sc.TdsParser.SendPreLoginHandshake|INFO> ClientConnectionID 14ae2a44-788c-4bb2-b330-1da189b718eb, ActivityID 0adb762f-b82a-4b4c-9acc-3bfe0fab47f0:4
2023-11-25 16:53:47.711: <sc.TdsParser.Connect|SEC> Consuming prelogin handshake
2023-11-25 16:53:47.823: <sc.TdsParser.Connect|SEC> Prelogin handshake successful
2023-11-25 16:53:47.824: <sc.TdsParser.TdsLogin|SEC> Sending federated authentication feature request
2023-11-25 16:53:47.825: <sc.TdsParser.TdsLogin|SEC> Sending federated authentication feature request
2023-11-25 16:53:47.862: <sc.TdsParser.TryProcessFedAuthInfo> Processed FEDAUTHINFO token stream: STSURL: https://login.windows.net/XXXXX, SPN: https://database.windows.net/
2023-11-25 16:53:47.864: <sc.SqlInternalConnectionTds.OnFedAuthInfo> 7, Generating federated authentication token
2023-11-25 16:53:47.869: <sc.TdsParser.SendFedAuthToken|SEC> Sending federated authentication token
2023-11-25 16:53:47.910: <sc.TdsParser.TryRun|SEC> Received login acknowledgement token
2023-11-25 16:53:47.910: <sc|ActiveDirectoryAuthenticationTimeoutRetryHelper|SetState|Info>State changed from NotStarted to HasLoggedIn.
2023-11-25 16:53:47.911: <prov.DbConnectionFactory.CreatePooledConnection|RES|CPOOL> 1, Pooled database connection created.
2023-11-25 16:53:47.913: SqlCommand.Set_CommandText | API | Object Id 108, String Value = 'SELECT 1', Client Connection Id null
2023-11-25 16:53:47.914: SqlCommand.Set_Connection | API | ObjectId 108, Client Connection Id 14ae2a44-788c-4bb2-b330-1da189b718eb
2023-11-25 16:53:47.915: SqlCommand.Set_CommandTimeout | API | ObjectId 108, Command Timeout value 5, Client Connection Id 14ae2a44-788c-4bb2-b330-1da189b718eb
2023-11-25 16:53:47.915: <sc.SqlConfigurableRetryLogicManager.CommandProvider|INFO> Requested the CommandProvider value.
2023-11-25 16:53:47.916: SqlCommand.RunExecuteReaderTds | Info | Object Id 108, Activity Id c61d0ed3-15e7-4d68-882b-9878b17fb915:1, Client Connection Id 14ae2a44-788c-4bb2-b330-1da189b718eb, Command executed as SQLBATCH, Command Text 'SELECT 1' 
2023-11-25 16:53:47.951: TdsParserStateObject.DecrementOpenResultCount | INFO | State Object Id 4, Processing Attention.

Conclusion

The comprehensive analysis of connection string parameters in our discussion highlights their pivotal role in the efficiency and performance of database connectivity. These parameters, especially Connection Lifetime, and Min Pool Size, are integral to fine-tuning our application's interaction with the database, ensuring optimal use of resources.

The Min Pool Size parameter, in particular, plays a critical role when maintaining a persistent connection is desired. It defines the minimum number of connections that should always be available in the pool. Setting an appropriate Min Pool Size ensures that a baseline level of readiness is maintained, which can be crucial for applications that require a constant and immediate database connection, such as real-time data processing systems or high-availability services.

Adjusting the Connection Lifetime parameter can lead to significant differences in how connections are managed, reused, or recycled. These settings impact the connection setup times and the overall responsiveness of the application, especially in scenarios that involve complex authentication processes like token acquisition for Active Directory authentication.

It's vital for developers and database administrators to understand these parameters deeply and adjust them in response to the specific demands and workload patterns of their applications. Regular monitoring and fine-tuning of these parameters can lead to improved application performance and user experience.

Effective connection management is more than just establishing database connectivity; it's about optimizing these connections to align with the unique requirements of our application's landscape. By proactively managing parameters such as Min Pool Size, we not only ensure functional connectivity but also enhance the performance and scalability of our applications, leading to a more efficient and reliable user experience.

I would also like to point out that if the connection pool is created each time an application is executed or started, it's important to know if our applications have a stoppage after being in an idle state for a specific period of time.

Scripts

ClsCheck:

using System;
using Microsoft.Data.SqlClient;
using System.Threading;
using System.IO;
using System.Diagnostics;

namespace HealthCheck
{
    class ClsCheck
    {
        const string LogFolder = "c:\\temp\\Mydata";
        const string LogFilePath = LogFolder + "\\logCheck.log";

        public void Main(Boolean bSingle=true, Boolean bDifferentConnectionString=false)
        {
            int lMaxConn = 100;
            int lMinConn = 0;
            if(bSingle)
            {
                lMaxConn = 1;
                lMinConn = 1;
            }
            string connectionString = "Server=tcp:servername.database.windows.net,1433;User Id=username@microsoft.com;Password=Pwd!;Initial Catalog=test;Persist Security Info=False;MultipleActiveResultSets=False;Encrypt=True;TrustServerCertificate=False;Connection Timeout=5;Pooling=true;Max Pool size=" + lMaxConn.ToString() + ";Min Pool Size=" + lMinConn.ToString() + ";ConnectRetryCount=3;ConnectRetryInterval=10;Authentication=Active Directory Password;PoolBlockingPeriod=NeverBlock;Connection Lifetime=5;Application Name=ConnTest";
            Stopwatch stopWatch = new Stopwatch();
            SqlConnection[] oConnection = new SqlConnection[lMaxConn];
            int lActivePool = -1;
            string sConnectionStringDummy = connectionString;

            DeleteDirectoryIfExists(LogFolder);
            ClsEvents.EventCounterListener oClsEvents = new ClsEvents.EventCounterListener();
            ClsEvents.SqlClientListener olistener = new ClsEvents.SqlClientListener();
            while (true)
            {
                if (bSingle)
                {
                    lActivePool = 0;
                    sConnectionStringDummy = connectionString;
                }
                else
                {
                    lActivePool++;
                    if (lActivePool == (lMaxConn-1))
                    {
                        lActivePool = 0;

                        for (int i = 0; i < lMaxConn; i++)
                        {
                            if (oConnection[i].State == System.Data.ConnectionState.Open)
                            {
                                oConnection[i].Close();
                            }
                        }
                    }
                    sConnectionStringDummy = connectionString + " Pool# " + lActivePool.ToString();
                }

                stopWatch.Start();
                oConnection[lActivePool] = ConnectToDatabase(sConnectionStringDummy);
                LogExecutionTime(stopWatch, "Connected");
                stopWatch.Reset();

                stopWatch.Start();
                ExecuteQuery(oConnection[lActivePool]);
                LogExecutionTime(stopWatch, "Executed");
                if (bSingle)
                {
                    oConnection[lActivePool].Close();
                }
                stopWatch.Reset();
                Console.WriteLine("Waiting for a new round....");
                //Thread.Sleep(1000); // Wait for 5 minutes
            }
        }

        static SqlConnection ConnectToDatabase(string connectionString)
        {
            int retries = 0;
            SqlConnection connection = new SqlConnection(connectionString);
            while (true)
            {

                try
                {
                    Log($"Trying the connection...");
                    connection.Open();
                    Log($"Successful connection. - {connection.ClientConnectionId.ToString()} - {connection.WorkstationId}");
                    return connection;
                }
                catch (Exception ex)
                {
                    retries++;
                    if (retries >= 5)
                    {
                        Log($"Maximum number of retries reached. Error: " + ex.Message);
                        break;
                    }
                    Log($"Error connecting to the database. Retrying in " + retries + " seconds...");
                    Thread.Sleep(retries * 1000);
                }
            }
            return connection;
        }

        static void Log(string message)
        {
            var ahora = DateTime.Now;
            string logMessage = $"{ahora.ToString("yyyy-MM-dd HH:mm:ss.fff")}: {message}";
            Console.WriteLine(logMessage);
            try
            {
                using (FileStream stream = new FileStream(LogFilePath, 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}");
            }
        }

        static void ExecuteQuery(SqlConnection connection)
        {
            int retries = 0;
            while (true)
            {
                try
                {
                    using (SqlCommand command = new SqlCommand("SELECT 1", connection))
                    {
                        command.CommandTimeout = 5;
                        object result = command.ExecuteScalar();
                    }
                    break;
                }
                catch (Exception ex)
                {
                    retries++;
                    if (retries >= 5)
                    {
                        Log($"Maximum number of retries reached. Error: " + ex.Message);
                        break;
                    }
                    Log($"Error executing the query. Retrying in " + retries + " seconds...");
                    Thread.Sleep(retries * 1000);
                }
            }
        }

        static void LogExecutionTime(Stopwatch stopWatch, string action)
        {
            stopWatch.Stop();
            TimeSpan ts = stopWatch.Elapsed;
            string elapsedTime = String.Format("{0:00}:{1:00}:{2:00}.{3:00}",
               ts.Hours, ts.Minutes, ts.Seconds,
               ts.Milliseconds / 10);
            Log($"{action} - {elapsedTime}");
            stopWatch.Reset();
        }

        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}");
            }
        }
    }

}

ClsListener

using System;
using System.Collections.Generic;
using System.Text;
using System.Diagnostics.Tracing;
using System.Linq;
using System.Diagnostics;
using System.IO;

namespace HealthCheck
{
    class ClsEvents
    {
        const string LogFilePathSQLClient = "c:\\temp\\Mydata\\SqlClient.log";
        const string LogFilePathEvents = "c:\\temp\\Mydata\\logEvents.Log";

        public class SqlClientListener : EventListener
        {
            protected override void OnEventSourceCreated(EventSource eventSource)
            {
                // Only enable events from SqlClientEventSource.
                if (eventSource.Name.Equals("Microsoft.Data.SqlClient.EventSource"))
                {
                    // Use EventKeyWord 2 to capture basic application flow events.
                    // See the above table for all available keywords.
                    EnableEvents(eventSource, EventLevel.Informational, (EventKeywords)2);
                }
            }

            // This callback runs whenever an event is written by SqlClientEventSource.
            // Event data is accessed through the EventWrittenEventArgs parameter.
            protected override void OnEventWritten(EventWrittenEventArgs eventData)
            {
                // Print event data.
                Log($"{eventData.Payload[0].ToString()}", LogFilePathSQLClient);
            }
        }

        public class EventCounterListener : EventListener
        {
            protected override void OnEventSourceCreated(EventSource eventSource)
            {
                // Only enable events from SqlClientEventSource.
                if (eventSource.Name.Equals("Microsoft.Data.SqlClient.EventSource"))
                {
                    var options = new Dictionary<string, string>();
                    // define time interval 1 second
                    // without defining this parameter event counters will not enabled
                    options.Add("EventCounterIntervalSec", "1");
                    // enable for the None keyword
                    EnableEvents(eventSource, EventLevel.Informational, EventKeywords.None, options);
                }
            }

            // This callback runs whenever an event is written by SqlClientEventSource.
            // Event data is accessed through the EventWrittenEventArgs parameter.
            protected override void OnEventWritten(EventWrittenEventArgs eventData)
            {
                if (eventData.Payload.FirstOrDefault(p => p is IDictionary<string, object> x && x.ContainsKey("Name")) is IDictionary<string, object> counters)
                {
                    if (counters.TryGetValue("DisplayName", out object name) && name is string cntName
                        && counters.TryGetValue("Mean", out object value) && value is double cntValue)
                    {
                        // print event counter's name and mean value
                        Log($"{cntName}\t\t{cntValue}",LogFilePathEvents);
                    }
                }
            }
        }

        static void Log(string message, string LogFilePath)
        {
            var ahora = DateTime.Now;
            string logMessage = $"{ahora.ToString("yyyy-MM-dd HH:mm:ss.fff")}: {message}";
            Console.WriteLine(logMessage);
            try
            {
                using (FileStream stream = new FileStream(LogFilePath, 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}");
            }
        }
    }

}

Products (50)

Special Topics (27)

Video Hub (462)

Most Active Hubs

Most Active Hubs

Video Hub

Lesson Learned #453:Optimizing Connection Pooling for Application Workloads: A single journey

Conclusion

Scripts