Often, when we write complex entity framework queries we would want to check how the translated query looks like or simply we would want to monitor the efficiency of it.
If we have SQL Server Management Studio, we can leverage SQL Profiler to track all the queries on a specific database:
This is not very convenient because you need to find the query in a bunch of others queries executed on the database.
Fortunately we have others options that we can have with entity framework:
– Database log
– Command interceptor
We’ll see how we can configure these two options and pros and cons of these two solutions.
Database Log
For this implementation I’ll use the factory that we have seen in this post.
First of all I implement a Logger Service that I’ll use later:
public class LoggerService : ILoggerService
{
private readonly string _filePath;
public LoggerService(string filepath)
{
var directorypath = filepath.Substring(0, filepath.LastIndexOf(@"\"));
if (!Directory.Exists(directorypath))
Directory.CreateDirectory(directorypath);
_filePath = filepath;
}
public void Debug(string message)
{
#if DEBUG
using (var streamWriter = new StreamWriter(_filePath, true))
{
streamWriter.WriteLine(message);
}
#endif
}
}
The logger service has a constructor with the filepath parameter and it deal with the checks about if the directory exists. Then there is an implementation of the Debug method, that simply write the message to the file.
In my case this is only for debug mode, so I disable the file write for release configuration with the a pragma directive.
Now I can modify the factory:
public class ContextFactory
{
private Type _dbContextType;
private DbContext _dbContext;
public void Register<TDbContext>(TDbContext dbContext) where TDbContext : DbContext, new()
{
_dbContextType = typeof(TDbContext);
_dbContext = dbContext;
}
public TDbContext Get<TDbContext>(ILoggerService loggerService = null) where TDbContext : DbContext, IContext, new()
{
if (_dbContext == null || _dbContextType != typeof(TDbContext) || loggerService != null)
{
var db = new TDbContext();
if (loggerService != null)
db.Database.Log = (string message) => loggerService.Debug(message);
return db;
}
return (TDbContext)_dbContext;
}
}
When I ask the factory to give me the context with the Get method, I can specify the logger service as parameter. Then in the method, when I create the context I setup the entity framework database log property with a delegate that invoke the debug method of the logger.
Now I can use the method like this:
using (var db = _contextFactory.Get<Context>(new LoggerService(@"c:\temp\log.txt")))
{
.....
}
Once the queries execution is completed, I can see the sql queries in the txt file:
Opened connection asynchronously at 28/09/2018 12:41:43 +02:00 Context 'Context' is executing command 'SELECT TOP (1) [c].[TaxCode] AS [TaxCode], [c].[Firstname] AS [Firstname], [c].[Surname] AS [Surname] FROM [dbo].[Persons] AS [c]' -- Completed in 14 ms with result: SqlDataReader Closed connection at 28/09/2018 12:41:43 +02:00
As you can see the format of the informations is understandable, thanks to the default comments written by Entity Framework. If you prefer, you can customize the log format by creating a log formatter class which inherit from the DatabaseLogFormatter:
public class LogFormatter : DatabaseLogFormatter
{
public LogFormatter(Action<string> writeAction) : base(writeAction) {}
public LogFormatter(DbContext context, Action<string> writeAction) : base(context, writeAction) {}
public override void LogCommand<TResult>(DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext)
{
Write($"Context '{Context.GetType().Name}' is executing command '{command.CommandText}'{Environment.NewLine}");
}
}
By overriding the LogCommand method I have access to the command text and I can customize the format. I need to register this formatter as well and I can do that with the Entity Framework database configuration:
public class DatabaseConfiguration : DbConfiguration
{
public DatabaseConfiguration()
{
SetDatabaseLogFormatter((context, writeAction) => new LogFormatter(context, writeAction));
}
}
Now the log will be written with the format specified.
Command interceptor
The other option is implement a command interceptor and in order to do that I need to add two properties to the dbContext class:
public class Context : DbContext, IContext
{
public virtual DbSet<Person> Persons { get; set; }
public string LogPath { get; set; }
public bool LogEnabled { get; set; }
.....
}
Then I manage the properties in the Get method of the context factory. Differently from the previous solution I can pass two different parameters, a boolean to specify if I want to log the queries and the path of the logger file:
public TDbContext Get<TDbContext>(bool log = false, string filepath = "") where TDbContext : DbContext, IContext, new()
{
if (log && string.IsNullOrEmpty(filepath))
throw new ArgumentNullException(nameof(filepath));
if (log && _loggerService == null)
_loggerService = new LoggerService(filepath);
if (_dbContext == null || _dbContextType != typeof(TDbContext))
{
var db = new TDbContext();
if (log)
{
db.LogEnabled = true;
db.LogPath = filepath;
}
return db;
}
return (TDbContext)_dbContext;
}
Now I can use these properties in the command interceptor that it have to implement the IDbCommandInterceptor interface:
public class CommandInterceptor : IDbCommandInterceptor
{
private static LoggerService _loggerService;
public void NonQueryExecuted(DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
{
if (ToBeLogged(interceptionContext))
_loggerService.Debug(command.CommandText);
}
public void NonQueryExecuting(DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
{
if (ToBeLogged(interceptionContext))
_loggerService.Debug(command.CommandText);
}
public void ReaderExecuted(DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)
{
if (ToBeLogged(interceptionContext))
_loggerService.Debug(command.CommandText);
}
public void ReaderExecuting(DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)
{
if (ToBeLogged(interceptionContext))
_loggerService.Debug(command.CommandText);
}
public void ScalarExecuted(DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
{
if (ToBeLogged(interceptionContext))
_loggerService.Debug(command.CommandText);
}
public void ScalarExecuting(DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
{
if (ToBeLogged(interceptionContext))
_loggerService.Debug(command.CommandText);
}
private bool ToBeLogged<TContext>(TContext interceptionContext) where TContext : DbCommandInterceptionContext
{
var context = interceptionContext.DbContexts.FirstOrDefault();
if (context != null && context is IContext && ((IContext)context).LogEnabled && !string.IsNullOrEmpty(((IContext)context).LogPath))
{
if (_loggerService == null)
_loggerService = new LoggerService(((IContext)context).LogPath);
return true;
}
return false;
}
}
All the public methods uses the ToBeLogged method to understand if the command/query needs to be logged. Like the formatter, the interceptor must be registered in the database configuration as well:
public class DatabaseConfiguration : DbConfiguration
{
public DatabaseConfiguration()
{
SetDatabaseLogFormatter((context, writeAction) => new LogFormatter(context, writeAction));
AddInterceptor(new CommandInterceptor());
}
}
Comparing this approach with the Log delegate, here we have to implement an interface with some methods and in order to pass the parameters to the interceptors we have added two custom properties to the context. In conclusion I prefer the first approach, that is less invasive, faster to implement and easier to understand.
You can find the source code of the command interceptor implementation on a GitHub project.
Summary
We have seen what is the common way to track entity framework sql queries, with SQL profiler. We have understanded why this is not comfortable and that by writing some code we have two different options: database log delegate and command interceptor. With the first one we have only added a delegate that uses a logger service. With the second one, we need to write some more code, add two properties to the context and implement the interceptor class.
You can find more details on Microsoft documentation and the source code about the database log implementation on a GitHub project.
Mirko Maggioni 
Leave a Reply