Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fixed the timers to track proper DB execution duration. #2536

Merged
merged 2 commits into from
Jan 29, 2025
Merged

Fixed the timers to track proper DB execution duration. #2536

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
26644f8
fixed the timers issue
lingxiao-microsoft Jan 23, 2025
29a9edb
Merge branch 'main' into dev/lingxiao/graphql-fix-timer
abhishekkumams Jan 29, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
242 changes: 117 additions & 125 deletions src/Core/Resolvers/QueryExecutor.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -112,61 +112,51 @@ public QueryExecutor(DbExceptionParser dbExceptionParser,

SetManagedIdentityAccessTokenIfAny(conn, dataSourceName);

Stopwatch queryExecutionTimer = new();
queryExecutionTimer.Start();
TResult? result = default(TResult?);

try
lingxiao-microsoft marked this conversation as resolved.
Show resolved Hide resolved
result = _retryPolicy.Execute(() =>
{
result = _retryPolicy.Execute(() =>
retryAttempt++;
try
{
retryAttempt++;
try
// When IsLateConfigured is true we are in a hosted scenario and do not reveal query information.
if (!ConfigProvider.IsLateConfigured)
lingxiao-microsoft marked this conversation as resolved.
Show resolved Hide resolved
{
// When IsLateConfigured is true we are in a hosted scenario and do not reveal query information.
if (!ConfigProvider.IsLateConfigured)
{
string correlationId = HttpContextExtensions.GetLoggerCorrelationId(httpContext);
QueryExecutorLogger.LogDebug("{correlationId} Executing query: {queryText}", correlationId, sqltext);
}
string correlationId = HttpContextExtensions.GetLoggerCorrelationId(httpContext);
QueryExecutorLogger.LogDebug("{correlationId} Executing query: {queryText}", correlationId, sqltext);
}

TResult? result = ExecuteQueryAgainstDb(conn, sqltext, parameters, dataReaderHandler, httpContext, dataSourceName, args);
TResult? result = ExecuteQueryAgainstDb(conn, sqltext, parameters, dataReaderHandler, httpContext, dataSourceName, args);

if (retryAttempt > 1)
{
string correlationId = HttpContextExtensions.GetLoggerCorrelationId(httpContext);
int maxRetries = _maxRetryCount + 1;
// This implies that the request got successfully executed during one of retry attempts.
QueryExecutorLogger.LogInformation("{correlationId} Request executed successfully in {retryAttempt} attempt of {maxRetries} available attempts.", correlationId, retryAttempt, maxRetries);
}
if (retryAttempt > 1)
{
string correlationId = HttpContextExtensions.GetLoggerCorrelationId(httpContext);
int maxRetries = _maxRetryCount + 1;
// This implies that the request got successfully executed during one of retry attempts.
lingxiao-microsoft marked this conversation as resolved.
Show resolved Hide resolved
QueryExecutorLogger.LogInformation("{correlationId} Request executed successfully in {retryAttempt} attempt of {maxRetries} available attempts.", correlationId, retryAttempt, maxRetries);
}

return result;
return result;
}
catch (DbException e)
{
if (DbExceptionParser.IsTransientException((DbException)e) && retryAttempt < _maxRetryCount + 1)
lingxiao-microsoft marked this conversation as resolved.
Show resolved Hide resolved
{
throw;
}
catch (DbException e)
else
{
if (DbExceptionParser.IsTransientException((DbException)e) && retryAttempt < _maxRetryCount + 1)
{
throw;
}
else
{
QueryExecutorLogger.LogError(
exception: e,
message: "{correlationId} Query execution error due to:\n{errorMessage}",
HttpContextExtensions.GetLoggerCorrelationId(httpContext),
e.Message);

// Throw custom DABException
throw DbExceptionParser.Parse(e);
}
QueryExecutorLogger.LogError(
exception: e,
message: "{correlationId} Query execution error due to:\n{errorMessage}",
HttpContextExtensions.GetLoggerCorrelationId(httpContext),
e.Message);

// Throw custom DABException
throw DbExceptionParser.Parse(e);
}
});
}
finally
{
queryExecutionTimer.Stop();
AddDbExecutionTimeToMiddlewareContext(queryExecutionTimer.ElapsedMilliseconds);
}
}
});

return result;
}
Expand Down Expand Up @@ -198,61 +188,51 @@ public QueryExecutor(DbExceptionParser dbExceptionParser,

await SetManagedIdentityAccessTokenIfAnyAsync(conn, dataSourceName);

Stopwatch queryExecutionTimer = new();
queryExecutionTimer.Start();
TResult? result = default(TResult);

try
result = await _retryPolicyAsync.ExecuteAsync(async () =>
{
result = await _retryPolicyAsync.ExecuteAsync(async () =>
retryAttempt++;
try
{
retryAttempt++;
try
// When IsLateConfigured is true we are in a hosted scenario and do not reveal query information.
if (!ConfigProvider.IsLateConfigured)
{
// When IsLateConfigured is true we are in a hosted scenario and do not reveal query information.
if (!ConfigProvider.IsLateConfigured)
{
string correlationId = HttpContextExtensions.GetLoggerCorrelationId(httpContext);
QueryExecutorLogger.LogDebug("{correlationId} Executing query: {queryText}", correlationId, sqltext);
}
string correlationId = HttpContextExtensions.GetLoggerCorrelationId(httpContext);
QueryExecutorLogger.LogDebug("{correlationId} Executing query: {queryText}", correlationId, sqltext);
}

TResult? result = await ExecuteQueryAgainstDbAsync(conn, sqltext, parameters, dataReaderHandler, httpContext, dataSourceName, args);
TResult? result = await ExecuteQueryAgainstDbAsync(conn, sqltext, parameters, dataReaderHandler, httpContext, dataSourceName, args);

if (retryAttempt > 1)
{
string correlationId = HttpContextExtensions.GetLoggerCorrelationId(httpContext);
int maxRetries = _maxRetryCount + 1;
// This implies that the request got successfully executed during one of retry attempts.
QueryExecutorLogger.LogInformation("{correlationId} Request executed successfully in {retryAttempt} attempt of {maxRetries} available attempts.", correlationId, retryAttempt, maxRetries);
}
if (retryAttempt > 1)
{
string correlationId = HttpContextExtensions.GetLoggerCorrelationId(httpContext);
int maxRetries = _maxRetryCount + 1;
// This implies that the request got successfully executed during one of retry attempts.
QueryExecutorLogger.LogInformation("{correlationId} Request executed successfully in {retryAttempt} attempt of {maxRetries} available attempts.", correlationId, retryAttempt, maxRetries);
}

return result;
return result;
}
catch (DbException e)
{
if (DbExceptionParser.IsTransientException((DbException)e) && retryAttempt < _maxRetryCount + 1)
{
throw;
}
catch (DbException e)
else
{
if (DbExceptionParser.IsTransientException((DbException)e) && retryAttempt < _maxRetryCount + 1)
{
throw;
}
else
{
QueryExecutorLogger.LogError(
exception: e,
message: "{correlationId} Query execution error due to:\n{errorMessage}",
HttpContextExtensions.GetLoggerCorrelationId(httpContext),
e.Message);

// Throw custom DABException
throw DbExceptionParser.Parse(e);
}
QueryExecutorLogger.LogError(
exception: e,
message: "{correlationId} Query execution error due to:\n{errorMessage}",
HttpContextExtensions.GetLoggerCorrelationId(httpContext),
e.Message);

// Throw custom DABException
throw DbExceptionParser.Parse(e);
}
});
}
finally
{
queryExecutionTimer.Stop();
AddDbExecutionTimeToMiddlewareContext(queryExecutionTimer.ElapsedMilliseconds);
}
}
});

return result;
}
Expand All @@ -279,39 +259,42 @@ public QueryExecutor(DbExceptionParser dbExceptionParser,
{
Stopwatch queryExecutionTimer = new();
queryExecutionTimer.Start();
await conn.OpenAsync();
DbCommand cmd = PrepareDbCommand(conn, sqltext, parameters, httpContext, dataSourceName);
TResult? result = default(TResult);
try
{
using DbDataReader dbDataReader = ConfigProvider.GetConfig().MaxResponseSizeLogicEnabled() ?
await cmd.ExecuteReaderAsync(CommandBehavior.SequentialAccess) : await cmd.ExecuteReaderAsync(CommandBehavior.CloseConnection);
if (dataReaderHandler is not null && dbDataReader is not null)
await conn.OpenAsync();
DbCommand cmd = PrepareDbCommand(conn, sqltext, parameters, httpContext, dataSourceName);
TResult? result = default(TResult);
try
{
result = await dataReaderHandler(dbDataReader, args);
using DbDataReader dbDataReader = ConfigProvider.GetConfig().MaxResponseSizeLogicEnabled() ?
await cmd.ExecuteReaderAsync(CommandBehavior.SequentialAccess) : await cmd.ExecuteReaderAsync(CommandBehavior.CloseConnection);
if (dataReaderHandler is not null && dbDataReader is not null)
{
result = await dataReaderHandler(dbDataReader, args);
}
else
{
result = default(TResult);
lingxiao-microsoft marked this conversation as resolved.
Show resolved Hide resolved
}
}
else
catch (DbException e)
{
result = default(TResult);
string correlationId = HttpContextExtensions.GetLoggerCorrelationId(httpContext);
QueryExecutorLogger.LogError(
exception: e,
message: "{correlationId} Query execution error due to:\n{errorMessage}",
correlationId,
e.Message);
throw DbExceptionParser.Parse(e);
}
}
catch (DbException e)
{
string correlationId = HttpContextExtensions.GetLoggerCorrelationId(httpContext);
QueryExecutorLogger.LogError(
exception: e,
message: "{correlationId} Query execution error due to:\n{errorMessage}",
correlationId,
e.Message);
throw DbExceptionParser.Parse(e);

return result;
}
finally
{
queryExecutionTimer.Stop();
AddDbExecutionTimeToMiddlewareContext(queryExecutionTimer.ElapsedMilliseconds);
}

return result;
}

/// <summary>
Expand Down Expand Up @@ -365,31 +348,40 @@ public virtual DbCommand PrepareDbCommand(
{
Stopwatch queryExecutionTimer = new();
queryExecutionTimer.Start();
conn.Open();
DbCommand cmd = PrepareDbCommand(conn, sqltext, parameters, httpContext, dataSourceName);

try
{
using DbDataReader dbDataReader = ConfigProvider.GetConfig().MaxResponseSizeLogicEnabled() ?
cmd.ExecuteReader(CommandBehavior.SequentialAccess) : cmd.ExecuteReader(CommandBehavior.CloseConnection);
if (dataReaderHandler is not null && dbDataReader is not null)
conn.Open();
DbCommand cmd = PrepareDbCommand(conn, sqltext, parameters, httpContext, dataSourceName);

try
{
return dataReaderHandler(dbDataReader, args);
using DbDataReader dbDataReader = ConfigProvider.GetConfig().MaxResponseSizeLogicEnabled() ?
cmd.ExecuteReader(CommandBehavior.SequentialAccess) : cmd.ExecuteReader(CommandBehavior.CloseConnection);
if (dataReaderHandler is not null && dbDataReader is not null)
{
return dataReaderHandler(dbDataReader, args);
}
else
{
return default(TResult);
}
}
else
catch (DbException e)
{
return default(TResult);
string correlationId = HttpContextExtensions.GetLoggerCorrelationId(httpContext);
QueryExecutorLogger.LogError(
exception: e,
message: "{correlationId} Query execution error due to:\n{errorMessage}",
correlationId,
e.Message);
throw DbExceptionParser.Parse(e);
}
}
catch (DbException e)
finally
{
string correlationId = HttpContextExtensions.GetLoggerCorrelationId(httpContext);
QueryExecutorLogger.LogError(
exception: e,
message: "{correlationId} Query execution error due to:\n{errorMessage}",
correlationId,
e.Message);
throw DbExceptionParser.Parse(e);
queryExecutionTimer.Stop();
AddDbExecutionTimeToMiddlewareContext(queryExecutionTimer.ElapsedMilliseconds);
}
}

Expand Down
39 changes: 29 additions & 10 deletions src/Service.Tests/Unittests/SqlQueryExecutorUnitTests.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,7 @@
using System.Collections.Generic;
using System.Data;
using System.Data.Common;
using System.Diagnostics;
using System.IO.Abstractions;
using System.IO.Abstractions.TestingHelpers;
using System.Linq;
Expand Down Expand Up @@ -32,6 +33,10 @@ public class SqlQueryExecutorUnitTests
{
// Error code for semaphore timeout in MsSql.
private const int ERRORCODE_SEMAPHORE_TIMEOUT = 121;

// The key of the item stored in http context
private const string TOTAL_DB_EXECUTION_TIME = "TotalDbExecutionTime";

/// <summary>
/// Validates managed identity token issued ONLY when connection string does not specify
/// User, Password, and Authentication method.
Expand Down Expand Up @@ -355,22 +360,36 @@ Mock<MsSqlQueryExecutor> queryExecutor
queryExecutor.Setup(x => x.ConnectionStringBuilders).Returns(new Dictionary<string, DbConnectionStringBuilder>());

// Call the actual ExecuteQueryAsync method.
queryExecutor.Setup(x => x.ExecuteQueryAsync(
queryExecutor.Setup(x => x.ExecuteQueryAgainstDbAsync(
It.IsAny<SqlConnection>(),
It.IsAny<string>(),
It.IsAny<IDictionary<string, DbConnectionParam>>(),
It.IsAny<Func<DbDataReader, List<string>, Task<object>>>(),
It.IsAny<string>(),
It.IsAny<HttpContext>(),
It.IsAny<string>(),
It.IsAny<List<string>>())).CallBase();

await queryExecutor.Object.ExecuteQueryAsync<object>(
sqltext: string.Empty,
parameters: new Dictionary<string, DbConnectionParam>(),
dataReaderHandler: null,
dataSourceName: String.Empty,
httpContext: null,
args: null);
Assert.IsTrue(context.Items.ContainsKey("TotalDbExecutionTime"), "HttpContext object must contain the total db execution time after execution of a query");
Stopwatch stopwatch = Stopwatch.StartNew();
try
{
await queryExecutor.Object.ExecuteQueryAgainstDbAsync<object>(
conn: null,
sqltext: string.Empty,
parameters: new Dictionary<string, DbConnectionParam>(),
dataReaderHandler: null,
dataSourceName: String.Empty,
httpContext: null,
args: null);
}
catch (Exception)
{
// as the SqlConnection object is a sealed class and can't be mocked, ignore any exceptions caused to bypass
}

stopwatch.Stop();

Assert.IsTrue(context.Items.ContainsKey(TOTAL_DB_EXECUTION_TIME), "HttpContext object must contain the total db execution time after execution of a query");
Assert.IsTrue(stopwatch.ElapsedMilliseconds >= (long)context.Items[TOTAL_DB_EXECUTION_TIME], "The execution time stored in http context must be valid.");
lingxiao-microsoft marked this conversation as resolved.
Show resolved Hide resolved
}

/// <summary>
Expand Down