I created a SqlMonitorInterceptor that will check the execution time of queries and log errors. The main idea is to log queries in such a way that they can be easily copied into SQL Server Management Studio and executed.
SqlMonitorInterceptor:
using System;
using System.Data;
using System.Data.Common;
using System.Linq;
using System.Text;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.Data.SqlClient;
using Microsoft.EntityFrameworkCore.Diagnostics;
using Microsoft.Extensions.Logging;
namespace WebApplication.Data
{
public class SqlMonitorInterceptor : DbCommandInterceptor
{
private readonly ILogger<SqlMonitorInterceptor> logger;
public SqlMonitorInterceptor(ILogger<SqlMonitorInterceptor> logger)
{
this.logger = logger;
}
public override void CommandFailed(DbCommand command, CommandErrorEventData eventData)
{
if (eventData.Exception is not null)
{
logger.LogError(eventData.Exception, "Command:\r\n{Command}\r\nfailed with Exception.", GetGeneratedQuery(command));
}
}
public override Task CommandFailedAsync(DbCommand command, CommandErrorEventData eventData, CancellationToken cancellationToken = default)
{
CommandFailed(command, eventData);
return Task.CompletedTask;
}
public override int NonQueryExecuted(DbCommand command, CommandExecutedEventData eventData, int result)
{
CommandExecuted(eventData);
return result;
}
public override ValueTask<int> NonQueryExecutedAsync(DbCommand command, CommandExecutedEventData eventData, int result, CancellationToken cancellationToken = default)
{
CommandExecuted(eventData);
return new ValueTask<int>(result);
}
public override DbDataReader ReaderExecuted(DbCommand command, CommandExecutedEventData eventData, DbDataReader result)
{
CommandExecuted(eventData);
return result;
}
public override ValueTask<DbDataReader> ReaderExecutedAsync(DbCommand command, CommandExecutedEventData eventData, DbDataReader result, CancellationToken cancellationToken = default)
{
CommandExecuted(eventData);
return new ValueTask<DbDataReader>(result);
}
public override object ScalarExecuted(DbCommand command, CommandExecutedEventData eventData, object result)
{
CommandExecuted(eventData);
return result;
}
public override ValueTask<object> ScalarExecutedAsync(DbCommand command, CommandExecutedEventData eventData, object result, CancellationToken cancellationToken = default)
{
CommandExecuted(eventData);
return new ValueTask<object>(result);
}
private void CommandExecuted(CommandExecutedEventData eventData)
{
// Log command if non-async.
if (!eventData.IsAsync)
{
logger.LogWarning("Non-async command used:\r\n{Command}", GetGeneratedQuery(eventData.Command));
}
// Log command if too slow.
if (eventData.Duration > AppConfiguration.SqlPerformance_WarningThreshold)
{
logger.LogDebug("Query time ({Duration}ms) exceeded the threshold of {Threshold}ms. Command:\r\n{Command}",
eventData.Duration.TotalMilliseconds,
AppConfiguration.SqlPerformance_WarningThreshold.TotalMilliseconds,
GetGeneratedQuery(eventData.Command));
}
}
private static string GetGeneratedQuery(DbCommand command)
{
var quotedParameterTypes = new DbType[] {
DbType.Date, DbType.DateTime, DbType.DateTime2, DbType.DateTimeOffset,
DbType.Guid, DbType.AnsiString, DbType.String,
DbType.AnsiStringFixedLength, DbType.StringFixedLength
};
var sb = new StringBuilder();
foreach (DbParameter p in command.Parameters)
{
sb.Append($"DECLARE {p.ParameterName}");
sb.Append(' ');
if (p is SqlParameter sqlParameter)
{
sb.Append(sqlParameter.SqlDbType.ToString().ToLower());
}
else
{
sb.Append(p.DbType.ToString().ToLower());
}
if (p.Size > 0)
{
sb.Append("(" + (p.Size > 4000 ? "max" : p.Size.ToString()) + ")");
}
else if (p.Precision > 0)
{
sb.Append("(" + p.Precision.ToString() + (p.Scale > 0 ? "," + p.Scale.ToString() : "") + ")");
}
sb.Append(' ');
string pValStr = quotedParameterTypes.Contains(p.DbType) ? $"'{p.Value}'" : p.Value.ToString();
sb.Append($"= {pValStr};");
sb.AppendLine();
}
sb.AppendLine();
sb.Append(command.CommandText);
return sb.ToString();
}
}
}
Example of generated log:
Query time (878.28ms) exceeded the threshold of 500ms. Command:
DECLARE @__8__locals1_entityDB_Id_0 int = 1094610;
DECLARE @__8__locals1_entityDB_CustomerId_1 uniqueidentifier = 'f47253a5-d660-4faf-408d-08d833e8e27b';
DECLARE @__phone_2 nvarchar(63) = '+79991111111';
SELECT COUNT(*)
FROM [Leads] AS [l]
WHERE (([l].[Id] <> @__8__locals1_entityDB_Id_0) AND ([l].[CustomerId] = @__8__locals1_entityDB_CustomerId_1)) AND ((@__phone_2 LIKE N'') OR (CHARINDEX(@__phone_2, [l].[PhoneNumbers]) > 0))
Do you see any improvement / issue?