Skip to content

Commit

Permalink
SQL Connection Logging (#4625)
Browse files Browse the repository at this point in the history
  • Loading branch information
@LTA-Thinking
LTA-Thinking authored Sep 17, 2024
1 parent d6793b9 commit ebe218f
Showing 1 changed file with 40 additions and 15 deletions.
55 changes: 40 additions & 15 deletions src/Microsoft.Health.Fhir.SqlServer/Features/Storage/SqlRetry/SqlRetryService.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,7 @@
using System.Collections.Generic;
using System.Data;
using System.Diagnostics;
using System.Text;
using System.Threading;
using System.Threading.Tasks;
using EnsureThat;
Expand Down Expand Up @@ -441,23 +442,28 @@ public async Task<SqlConnection> GetConnection<TLogger>(ISqlConnectionBuilder sq
{
SqlConnection conn;
var sw = Stopwatch.StartNew();
var logSB = new StringBuilder("Long running retrieve SQL connection");
var isReadOnlyConnection = isReadOnly ? "read-only " : string.Empty;

if (!isReadOnly)
{
conn = await sqlConnectionBuilder.GetSqlConnectionAsync(initialCatalog: null, cancellationToken: cancel).ConfigureAwait(false);
logSB.AppendLine("Not read only");
conn = await sqlConnectionBuilder.GetSqlConnectionAsync(initialCatalog: null, cancellationToken: cancel);
}
else
{
var replicaTrafficRatio = GetReplicaTrafficRatio(sqlConnectionBuilder);
logSB.AppendLine("Checking read only");
var replicaTrafficRatio = GetReplicaTrafficRatio(sqlConnectionBuilder, logger);
logSB.AppendLine($"Got replica traffic ratio in {sw.Elapsed.TotalSeconds} seconds. Ratio is {replicaTrafficRatio}");

if (replicaTrafficRatio < 0.5) // it does not make sense to use replica less than master at all
{
isReadOnlyConnection = string.Empty;
conn = await sqlConnectionBuilder.GetSqlConnectionAsync(initialCatalog: null, cancellationToken: cancel).ConfigureAwait(false);
conn = await sqlConnectionBuilder.GetSqlConnectionAsync(initialCatalog: null, cancellationToken: cancel);
}
else if (replicaTrafficRatio > 0.99)
{
conn = await sqlConnectionBuilder.GetReadOnlySqlConnectionAsync(initialCatalog: null, cancellationToken: cancel).ConfigureAwait(false);
conn = await sqlConnectionBuilder.GetReadOnlySqlConnectionAsync(initialCatalog: null, cancellationToken: cancel);
}
else
{
Expand All @@ -468,15 +474,20 @@ public async Task<SqlConnection> GetConnection<TLogger>(ISqlConnectionBuilder sq
}

conn = useWriteConnection
? await sqlConnectionBuilder.GetSqlConnectionAsync(initialCatalog: null, cancellationToken: cancel).ConfigureAwait(false)
: await sqlConnectionBuilder.GetReadOnlySqlConnectionAsync(initialCatalog: null, cancellationToken: cancel).ConfigureAwait(false);
? await sqlConnectionBuilder.GetSqlConnectionAsync(initialCatalog: null, cancellationToken: cancel)
: await sqlConnectionBuilder.GetReadOnlySqlConnectionAsync(initialCatalog: null, cancellationToken: cancel);
}
}

// Connection is never opened by the _sqlConnectionBuilder but RetryLogicProvider is set to the old, deprecated retry implementation. According to the .NET spec, RetryLogicProvider
// must be set before opening connection to take effect. Therefore we must reset it to null here before opening the connection.
conn.RetryLogicProvider = null; // To remove this line _sqlConnectionBuilder in healthcare-shared-components must be modified.
logger.LogInformation($"Retrieved {isReadOnlyConnection}connection to the database in {sw.Elapsed.TotalSeconds} seconds.");
if (sw.Elapsed.TotalSeconds > 1)
{
logSB.AppendLine($"Retrieved {isReadOnlyConnection}connection to the database in {sw.Elapsed.TotalSeconds} seconds.");
logger.LogWarning(logSB.ToString());
}

sw = Stopwatch.StartNew();
await conn.OpenAsync(cancel);
Expand All @@ -485,29 +496,42 @@ public async Task<SqlConnection> GetConnection<TLogger>(ISqlConnectionBuilder sq
return conn;
}

private double GetReplicaTrafficRatio(ISqlConnectionBuilder sqlConnectionBuilder)
private double GetReplicaTrafficRatio(ISqlConnectionBuilder sqlConnectionBuilder, ILogger logger)
{
const int trafficRatioCacheDurationSec = 600;
if (_lastUpdated.HasValue && (DateTime.UtcNow - _lastUpdated.Value).TotalSeconds < trafficRatioCacheDurationSec)
{
return _replicaTrafficRatio;
}

lock (_databaseAccessLocker)
if (Monitor.TryEnter(_databaseAccessLocker, new TimeSpan(0, 0, 5)))
{
if (_lastUpdated.HasValue && (DateTime.UtcNow - _lastUpdated.Value).TotalSeconds < trafficRatioCacheDurationSec)
try
{
return _replicaTrafficRatio;
}
if (_lastUpdated.HasValue && (DateTime.UtcNow - _lastUpdated.Value).TotalSeconds < trafficRatioCacheDurationSec)
{
logger.LogInformation("Waited, but used replica traffic cache");
return _replicaTrafficRatio;
}

_replicaTrafficRatio = GetReplicaTrafficRatioFromDatabase(sqlConnectionBuilder);
_lastUpdated = DateTime.UtcNow;
logger.LogInformation("Updating replica traffic ratio");
_replicaTrafficRatio = GetReplicaTrafficRatioFromDatabase(sqlConnectionBuilder, logger);
_lastUpdated = DateTime.UtcNow;
}
finally
{
Monitor.Exit(_databaseAccessLocker);
}
}
else
{
logger.LogInformation("Timed out waiting for replica traffic, using cached value");
}

return _replicaTrafficRatio;
}

private static double GetReplicaTrafficRatioFromDatabase(ISqlConnectionBuilder sqlConnectionBuilder)
private static double GetReplicaTrafficRatioFromDatabase(ISqlConnectionBuilder sqlConnectionBuilder, ILogger logger)
{
try
{
Expand All @@ -518,8 +542,9 @@ private static double GetReplicaTrafficRatioFromDatabase(ISqlConnectionBuilder s
var value = cmd.ExecuteScalar();
return value == null ? 0 : (double)value;
}
catch (SqlException)
catch (SqlException ex)
{
logger.LogInformation(ex, "Failed to get replica traffic ratio from the database.");
return 0;
}
}
Expand Down

0 comments on commit ebe218f

Please sign in to comment.