In an attempt to log time spent on SQL Server queries in an ASP.NET Core web application I've been using the following code, having subscribed to all DiagnosticListeners
in some middleware and using the Observable
below.
I'm not sure this is the most optimal solution in terms of performance and wondered if there was a better way using the ASP.NET Core Logging API by capturing detailed logging objects directly from EFCore? Ideally I want to keep a total of the duration of all queries performed through a request and have the total in milliseconds at the end of a request which the Middleware can use.
public class QueryTimingObserver : IObserver<DiagnosticListener>
{
private readonly List<IDisposable> subscriptions = new List<IDisposable>();
private readonly AsyncLocal<Stopwatch> stopwatch = new AsyncLocal<Stopwatch>();
private double milliseconds = 0;
void IObserver<DiagnosticListener>.OnNext(DiagnosticListener diagnosticListener)
{
if (diagnosticListener.Name == "SqlClientDiagnosticListener")
{
IDisposable subscription = diagnosticListener.SubscribeWithAdapter(this);
subscriptions.Add(subscription);
}
}
void IObserver<DiagnosticListener>.OnError(Exception error)
{
}
void IObserver<DiagnosticListener>.OnCompleted()
{
subscriptions.ForEach(x => x.Dispose());
subscriptions.Clear();
}
[DiagnosticName("System.Data.SqlClient.WriteCommandBefore")]
public void OnCommandBefore()
{
stopwatch.Value = Stopwatch.StartNew();
}
[DiagnosticName("System.Data.SqlClient.WriteCommandAfter")]
public void OnCommandAfter(DbCommand command)
{
stopwatch.Value.Stop();
milliseconds += stopwatch.Value.Elapsed.TotalMilliseconds;
}
public double Milliseconds
{
get
{
return milliseconds;
}
}
}
Query performance should be done at two levels, timing the controller/service actions, and profiling at the database level. Performance issues crop up for a number of reasons, and might be detected only at the controller, or at the database, or both. Recording performance metrics at the code level should always be configurable to be able to turn it off and on easily because any performance capture represents a performance hit, plus resource space needed to record the results.
At the risk of being a bit off-topic I've outlined the typical performance pitfalls I come across and how I measure/detect them. The purpose would just be to outline why SQL-side profiling can be valuable along-side code-based timers to detect potential performance issues, as well as identify steps to resolve them.