The method described by Jared Kells
does not work under Net Core, because, well it is not guaranteed that finalizers will be called. And, in fact, it is not called for the code above. Please, see:
Why does the Finalize/Destructor example not work in .NET Core?
https://github.com/dotnet/runtime/issues/16028
https://github.com/dotnet/runtime/issues/17836
https://github.com/dotnet/runtime/issues/24623
So, based on the great answer above, here is what I ended up doing (replace saving to file as necessary):
public class DatabaseCommandInterceptor : IDbCommandInterceptor
{
private static ConcurrentDictionary<DbCommand, DateTime> StartTime { get; } = new();
public void ReaderExecuted(DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext) => Log(command, interceptionContext);
public void NonQueryExecuted(DbCommand command, DbCommandInterceptionContext<int> interceptionContext) => Log(command, interceptionContext);
public void ScalarExecuted(DbCommand command, DbCommandInterceptionContext<object> interceptionContext) => Log(command, interceptionContext);
private static void Log<T>(DbCommand command, DbCommandInterceptionContext<T> interceptionContext)
{
var parameters = new StringBuilder();
foreach (DbParameter param in command.Parameters)
{
if (parameters.Length > 0) parameters.Append(", ");
parameters.Append($"{param.ParameterName}:{param.DbType} = {param.Value}");
}
var data = new DatabaseCommandInterceptorData
{
CommandText = command.CommandText,
CommandType = $"{command.CommandType}",
Parameters = $"{parameters}",
Duration = StartTime.TryRemove(command, out var startTime) ? DateTime.Now - startTime : TimeSpan.Zero,
Exception = interceptionContext.Exception,
};
DbInterceptorFixture.Current.LogDatabaseCall(data);
}
public void NonQueryExecuting(DbCommand command, DbCommandInterceptionContext<int> interceptionContext) => OnStart(command);
public void ReaderExecuting(DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext) => OnStart(command);
public void ScalarExecuting(DbCommand command, DbCommandInterceptionContext<object> interceptionContext) => OnStart(command);
private static void OnStart(DbCommand command) => StartTime.TryAdd(command, DateTime.Now);
}
public class DatabaseCommandInterceptorData
{
public string CommandText { get; set; }
public string CommandType { get; set; }
public string Parameters { get; set; }
public TimeSpan Duration { get; set; }
public Exception Exception { get; set; }
}
/// <summary>
/// All times are in milliseconds.
/// </summary>
public record DatabaseCommandStatisticalData
{
public string CommandText { get; }
public int CallCount { get; init; }
public int ExceptionCount { get; init; }
public double Min { get; init; }
public double Max { get; init; }
public double Mean { get; init; }
public double StdDev { get; init; }
public DatabaseCommandStatisticalData(string commandText)
{
CommandText = commandText;
CallCount = 0;
ExceptionCount = 0;
Min = 0;
Max = 0;
Mean = 0;
StdDev = 0;
}
/// <summary>
/// Calculates k-th moment for n + 1 values: M_k(n + 1)
/// based on the values of k, n, mkn = M_k(N), and x(n + 1).
/// The sample adjustment (replacement of n -> (n - 1)) is NOT performed here
/// because it is not needed for this function.
/// Note that k-th moment for a vector x will be calculated in Wolfram as follows:
/// Sum[x[[i]]^k, {i, 1, n}] / n
/// </summary>
private static double MknPlus1(int k, int n, double mkn, double xnp1) =>
(n / (n + 1.0)) * (mkn + (1.0 / n) * Math.Pow(xnp1, k));
public DatabaseCommandStatisticalData Updated(DatabaseCommandInterceptorData data) =>
CallCount == 0
? this with
{
CallCount = 1,
ExceptionCount = data.Exception == null ? 0 : 1,
Min = data.Duration.TotalMilliseconds,
Max = data.Duration.TotalMilliseconds,
Mean = data.Duration.TotalMilliseconds,
StdDev = 0.0,
}
: this with
{
CallCount = CallCount + 1,
ExceptionCount = ExceptionCount + (data.Exception == null ? 0 : 1),
Min = Math.Min(Min, data.Duration.TotalMilliseconds),
Max = Math.Max(Max, data.Duration.TotalMilliseconds),
Mean = MknPlus1(1, CallCount, Mean, data.Duration.TotalMilliseconds),
StdDev = Math.Sqrt(
MknPlus1(2, CallCount, Math.Pow(StdDev, 2) + Math.Pow(Mean, 2), data.Duration.TotalMilliseconds)
- Math.Pow(MknPlus1(1, CallCount, Mean, data.Duration.TotalMilliseconds), 2)),
};
public static string Header { get; } =
string.Join(TextDelimiter.VerticalBarDelimiter.Key,
new[]
{
nameof(CommandText),
nameof(CallCount),
nameof(ExceptionCount),
nameof(Min),
nameof(Max),
nameof(Mean),
nameof(StdDev),
});
public override string ToString() =>
string.Join(TextDelimiter.VerticalBarDelimiter.Key,
new[]
{
$"\"{CommandText.Replace("\"", "\"\"")}\"",
$"{CallCount}",
$"{ExceptionCount}",
$"{Min}",
$"{Max}",
$"{Mean}",
$"{StdDev}",
});
}
public class DbInterceptorFixture
{
public static readonly DbInterceptorFixture Current = new();
private bool _disposedValue;
private ConcurrentDictionary<string, DatabaseCommandStatisticalData> DatabaseCommandData { get; } = new();
private static IMasterLogger Logger { get; } = new MasterLogger(typeof(DbInterceptorFixture));
/// <summary>
/// Will run once at start up.
/// </summary>
private DbInterceptorFixture()
{
AssemblyLoadContext.Default.Unloading += Unloading;
}
/// <summary>
/// A dummy method to call in order to ensure that static constructor is called
/// at some more or less controlled time.
/// </summary>
public void Ping()
{
}
public void LogDatabaseCall(DatabaseCommandInterceptorData data) =>
DatabaseCommandData.AddOrUpdate(
data.CommandText,
_ => new DatabaseCommandStatisticalData(data.CommandText).Updated(data),
(_, d) => d.Updated(data));
private void Unloading(AssemblyLoadContext context)
{
if (_disposedValue) return;
GC.SuppressFinalize(this);
_disposedValue = true;
SaveData();
}
private void SaveData()
{
try
{
File.WriteAllLines(
@"C:\Temp\Test.txt",
DatabaseCommandData
.Select(e => $"{e.Value}")
.Prepend(DatabaseCommandStatisticalData.Header));
}
catch (Exception e)
{
Logger.LogError(e);
}
}
}
and then register DatabaseCommandInterceptor
once somewhere in the tests:
DbInterception.Add(new DatabaseCommandInterceptor());
I also prefer calling DbInterceptorFixture.Current.Ping()
in the base test class, though I don't think that this is needed.
The interface IMasterLogger
is just a strongly typed wrapper around log4net
, so just replace it with your favorite one.
The value of TextDelimiter.VerticalBarDelimiter.Key
is just '|'
and it sits in what we call a closed set.
PS If I screwed up with statistics, please, comment and I will update the answer.