Sunday, 20 December 2020

Outputting runnable SQL from Entity Framework 6.x

This article will describe how you can output runnable SQL from Entity Framework. The output will be sent to the Console and Debug. You can easily modify this to output to other output sources, such as tracing or files for that matter. What is important is that we need to interpolate the parameters from Entity Framework so that we get a runnable SQL. Entity Framework parameterizes the SQL queries such that SQL injection is avoided. Where conditions and similar are inserted into parameters, notably with the p__linq naming convention. We will interpolate these parameters into runnable SQL such that you can paste SQL into SQL Server Management Studio (SMSMS). Or you could save the runnable SQL to a .sql file and let SQLCMD run it from command line. Either way, we must set up the DbContext to do this. I am using Entity Framework 6.2.0. It should be possible to use this technique with all EF 6.x version. In Entity Framework Core and Entity Framework Core 2, the techniques will be similar. First define a DbConfiguration and attribute the DbContext class you are using like this with the DbConfigurationType (we are not considering ObjectContext in this article, but DbContext is a wrapper around this class anyways, so you should be apply to techniques taught here to other scenarios).
SomeAcmeDbContext.cs
namespace SomeAcme.Data.EntityFramework { [DbConfigurationType(typeof(SomeAcmeDataContextConfiguration))] public partial class SomeAcmeDataContext : System.Data.Entity.DbContext, ISomeAcmeDataContext { ..
Ok, so our DbConfiguration just inherits from DbConfiguration and sets up a custom DatabaseLogFormatter like this:
  
SomeAcmeDataContextConfiguration.cs
using System.Data.Entity; namespace SomeAcme.Data.EntityFramework.DbContext { public class SomeAcmeDataContextConfiguration : DbConfiguration { public SomeAcmeDataContextConfiguration() { SetDatabaseLogFormatter((context, logAction) => new SomeAcmeDbLogFormatter(context, logAction)); } } }
SetDatabaseLogFormatter is a protected method o DbConfiguration. Our DatabaseLogFormatter implementation then looks like this:
 
SomeAcmeDbLogFormatter.cs
using System; using System.Data.Common; using System.Data.Entity.Infrastructure.Interception; using SomeAcme.Data.EntityFramework.DbContext.Extensions; namespace SomeAcme.Data.EntityFramework.DbContext { public class SomeAcmeDbLogFormatter : DatabaseLogFormatter { public SomeAcmeDbLogFormatter(System.Data.Entity.DbContext dbContext, Action<string> loggingAction) : base(dbContext, loggingAction) { } public override void LogCommand<TResult>(DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext) { string cmdText = command.CommandText; if (string.IsNullOrEmpty(cmdText)) return; if (cmdText.StartsWith("Openend connection", StringComparison.InvariantCultureIgnoreCase) || cmdText.StartsWith("Closed connection", StringComparison.InvariantCultureIgnoreCase)) return; Write($"--DbContext {Context.GetType().Name} is executing command against DB {Context.Database.Connection.Database}: {Environment.NewLine}{command.GetGeneratedQuery().Replace(Environment.NewLine, "")} {Environment.NewLine}"); } public override void LogResult<TResult>(DbCommand command, DbCommandInterceptionContext<TResult> interceptionContext) { //empty by intention } } }
We also have a helper extension method called GetGeneratedQuery on DbCommand objects to help us get the cruft of this article - the interpolated runnable query. From my testing we can just interpolate the parameters as is in most use cases. However, some datatypes in the T-SQL world must be quoted (like, strings) and we need to adjust the date and time data types to a runnable format too. In case you find this helper method should be interpolated, please let me know. Our helper method GetGeneratedQuery looks like this:
  
SomeAcmeDbCommandExtensions.cs
using System; using System.Data; using System.Data.Common; using System.Data.SqlClient; using System.Linq; using System.Text; namespace SomeAcme.Data.EntityFramework.DbContext.Extensions { public static class DbCommandExtensions { /// <summary> /// Returns the generated sql string where parameters are replaced by value. Generated a runnable /// SQL script. Note that this is an approximation anwyays, but gives us a runnable query. The database server query engine optimizer will possible rewrite /// even simple queries if it sees it possible to rearrange the query to predictively create a more efficient query. /// </summary> /// <param name="dbCommand"></param> /// <returns></returns> public static string GetGeneratedQuery(this DbCommand dbCommand) { DbType[] quotedParameterTypes = new DbType[] { DbType.AnsiString, DbType.Date, DbType.DateTime, DbType.DateTime2, DbType.Guid, DbType.String, DbType.AnsiStringFixedLength, DbType.StringFixedLength }; var sb = new StringBuilder(); sb.AppendLine(dbCommand.CommandText); var arrParams = new SqlParameter[dbCommand.Parameters.Count]; dbCommand.Parameters.CopyTo(arrParams, 0); //copy dbCommand parameters into another collection to avoid //mutating the query and be able to run a foreach loop foreach (SqlParameter p in arrParams.OrderByDescending(p => p.ParameterName.Length)) { string value = p.Value.ToString(); if (p.DbType == DbType.Date || p.DbType == DbType.DateTime || p.DbType == DbType.DateTime2) { value = DateTime.Parse(value).ToString("yyyy-MM-dd HH:mm:ss.fff"); } if (quotedParameterTypes.Contains(p.DbType)) value = "'" + value + "'"; sb.Replace("@" + p.ParameterName, value); } return sb.ToString(); } } }
We also need to activate database logging in the first place. Database logging to the console and debug should be avoided in production in ordinary cases, as they make a performance impact. Instead, it is handy to turn it on or off via an app setting. I have decided to only allow it while debugging so my constructors of my DbContext where I have tested it calls this method:
SomeAcmeDbContext.cs
(once more need to add some code) private void SetupDbContextBehavior() { Configuration.AutoDetectChangesEnabled = true; Configuration.LazyLoadingEnabled = true; ObjectContext.CommandTimeout = 10 * 60; #if DEBUG //To enable outputting database traffic to the console, set the app setting OutputDatabaseTrafficLogging in web.config to true //this must not be activated in production. To safe guard this, //this block below is wrapped in the debug preprocessor directive. bool outputDatabaseTrafficLogging = ConfigurationManagerWrapper.GetAppsetting(SomeAcme.Common.Constants.OutputDatabaseTrafficLogging); if (outputDatabaseTrafficLogging) { Database.Log = s => { if (s.StartsWith("Opened connection", StringComparison.InvariantCultureIgnoreCase) || s.StartsWith("Closed connection", StringComparison.InvariantCultureIgnoreCase)) return; Console.WriteLine(s); Debug.WriteLine(s); }; } #endif
Never mind the first three lines, they are just added here as tips for additional settings you CAN set if you want to. The important bit is the Database.Log delegate property, which acceps a lambda for example where you set up what to do with the logging. Here we just tell the DbContext that if the app setting OutputDatabaseTrafficLogging is set to true, we output the runnable SQL from Entity Framework to the console. That's all there is to it! You can now activate the app setting and see in the debug output (or in console) runnable SQL. And you can paste the SQL into SMSS for example to check for performance issues such as missing indexes and similar or tune up the size of the result sets and alter the SQL. You should also consider making your DbContext runnable in Linqpad for easier tuning of EF queries, but that is for another article. Happy coding!
Share this article on LinkedIn.

No comments:

Post a comment