An Entity Framework log printer that converts SQL commands to executable T-SQL statement
Introduction
In this article, we are going to see a log printer working with Entity Framework that converts SqlCommand to a completely executable T-SQL statement, including all parameter declarations and write to log file. Once a command is executed, You will see following message like this in your log file.
-- SQL executed in 1 ms: DECLARE @p__linq__0 VarChar = 'Cloudie'; SELECT [Extent1].[StudentID] AS [StudentID], [Extent1].[StudentName] AS [StudentName], FROM [dbo].[Student] AS [Extent1] WHERE [Extent1].[StudentName] = @p__linq__0 -- Result: SqlDataReader
The log message will also show the time taken by the command. This can help us debug and test every SQL command executed by DbContext.
The example in this article is based on .Net Framework 4.7 and Entity Framework 6.2.0.
Create an Interceptor
The first thing to do is to create a class that implements IDbCommandInterceptor interface. In this article, we name it SqlLogInterceptor
.
public class SqlLogInterceptor : IDbCommandInterceptor { #region Fields private static readonly TraceSource _traceSource = new TraceSource(nameof(SqlLogInterceptor)); #endregion #region Constructor public SqlLogInterceptor() { } #endregion #region Implementations public void NonQueryExecuting(DbCommand cmd, DbCommandInterceptionContext<int> interceptionContext) { interceptionContext.SetUserState(nameof(Stopwatch), Stopwatch.StartNew()); } public void NonQueryExecuted(DbCommand cmd, DbCommandInterceptionContext<int> interceptionContext) { var stopwatch = interceptionContext.FindUserState(nameof(Stopwatch)) as Stopwatch; // TODO: print T-SQL statement. } public void ReaderExecuting(DbCommand cmd, DbCommandInterceptionContext<DbDataReader> interceptionContext) { interceptionContext.SetUserState(nameof(Stopwatch), Stopwatch.StartNew()); } public void ReaderExecuted(DbCommand cmd, DbCommandInterceptionContext<DbDataReader> interceptionContext) { var stopwatch = interceptionContext.FindUserState(nameof(Stopwatch)) as Stopwatch; // TODO: print T-SQL statement. } public void ScalarExecuting(DbCommand cmd, DbCommandInterceptionContext<object> interceptionContext) { interceptionContext.SetUserState(nameof(Stopwatch), Stopwatch.StartNew()); } public void ScalarExecuted(DbCommand cmd, DbCommandInterceptionContext<object> interceptionContext) { var stopwatch = interceptionContext.FindUserState(nameof(Stopwatch)) as Stopwatch; // TODO: print T-SQL statement. } #endregion }
From the naming of these methods, you can already tell their purpose and execution order. For example, NonQueryExecuting()
will be invoked when a non-query command is about to run. And NonQueryExecuted()
method will be invoked once the command is done. In each -ing
method, we initialize a Stopwatch
instance and assign it to interceptionContext
, and retrieve it later in corresponding -ed
method. This allows us to measure the time taken by the command and include it to log message.
To enable the interceptor, we need to add a piece of configuration to <entityFramework>
section in our Web.config, as following snippet shows.
<entityFramework> <interceptors> <interceptor type="LogExample.Logging.SqlLogInterceptor, LogExample"></interceptor> </interceptors> </entityFramework>
Note that we have a TraceSource field which is to be used to accept log messages. You can replace it with whatever you desire to use.
Format Basic Type Parameters
Next thing to do is to handle every parameter used by the SqlCommand
instance and format it in a T-SQL Statement. In order to achieve that, we need to figure out its SqlDbType and choose correct string format accordingly.
private static string FormatParameters(DbParameterCollection parameters) { return string.Join(Environment.NewLine, parameters.OfType<SqlParameter>().Select(FormatParameter)); } private static string FormatParameter(SqlParameter param) { switch (param.SqlDbType) { case SqlDbType.BigInt: case SqlDbType.Binary: case SqlDbType.Decimal: case SqlDbType.Float: case SqlDbType.Int: case SqlDbType.SmallMoney: case SqlDbType.TinyInt: case SqlDbType.SmallInt: case SqlDbType.Money: case SqlDbType.DateTimeOffset: case SqlDbType.Timestamp: return $"DECLARE @{param.ParameterName.TrimStart('@')} {param.SqlDbType} {FormatNumericParameter(param)};"; case SqlDbType.Bit: return $"DECLARE @{param.ParameterName.TrimStart('@')} {param.SqlDbType} {FormatBooleanParameter(param)};"; case SqlDbType.Char: case SqlDbType.VarChar: case SqlDbType.NChar: case SqlDbType.NText: case SqlDbType.NVarChar: case SqlDbType.Text: case SqlDbType.Time: case SqlDbType.Xml: case SqlDbType.UniqueIdentifier: return $"DECLARE @{param.ParameterName.TrimStart('@')} {param.SqlDbType} {FormatStringParameter(param)};"; case SqlDbType.Date: case SqlDbType.DateTime: case SqlDbType.DateTime2: case SqlDbType.SmallDateTime: return $"DECLARE @{param.ParameterName.TrimStart('@')} {param.SqlDbType} {FormatDateTimeParameter(param)};"; case SqlDbType.Structured: // We will discuss this later return $"DECLARE @{param.ParameterName.TrimStart('@')} {param.TypeName} {FormatDataTableParameter(param)};"; default: return $"DECLARE @{param.ParameterName.TrimStart('@')} {param.SqlDbType} {FormatNumericParameter(param)};"; } } private static string FormatNumericParameter(SqlParameter param) { if (param.Direction == ParameterDirection.Input) return " = " + (Convert.IsDBNull(param.Value) ? "NULL" : Convert.ToString(param.Value)); else return string.Empty; } private static string FormatBooleanParameter(SqlParameter param) { if (param.Direction == ParameterDirection.Input) return " = " + (Convert.IsDBNull(param.Value) ? "NULL" : Convert.ToString(Convert.ToByte(param.Value))); else return string.Empty; } private static string FormatStringParameter(SqlParameter param) { if (param.Direction == ParameterDirection.Input) return " = " + (Convert.IsDBNull(param.Value) ? "NULL" : $"'{param.Value}'"); else return string.Empty; } private static string FormatDateTimeParameter(SqlParameter param) { if (param.Direction == ParameterDirection.Input) return " = " + (Convert.IsDBNull(param.Value) ? "NULL" : $"'{param.Value:yyyy-MM-ddTHH:mm:ss}'"); else return string.Empty; }
This will produce a DECLARE statement for each SqlCommand
instance in the log message. A couple of examples is shown below.
DECLARE @QueryString VarChar = 'string'; DECLARE @BeginDate DateTime = '1970-01-01T08:00:00'; DECLARE @PageNumber Int = 0;
Format Structured Type Parameters
Structured type parameters are a bit complicated to handle. Structured type is defined in SQL Server, and is usually used to pass array to stored procedure. On application side, we need to create a DataTable
instance and add one or more DataRow
instances to it. In T-SQL, the statement consists of a DECLARE statement and one or more INSERT statements. In order to print structured type parameters, we need to obtain all columns and row, then choose correct format for each cell by its data type. In this article, we use GetTypeCode
method.
private static string FormatDataTableParameter(SqlParameter param) { if (param.Direction == ParameterDirection.Input) { var table = param.Value as DataTable; if (table.Rows.Count == 0) return string.Empty; var columns = table.Columns.OfType<DataColumn>().ToArray(); var rows = table.Rows.OfType<DataRow>().Select(row => $"({string.Join(", ", FormatDataRowColumns(columns, row))})"); var sb = new StringBuilder(Environment.NewLine); sb.AppendLine($"INSERT INTO @{param.ParameterName.TrimStart('@')} ({string.Join(", ", columns.Select(col => col.ColumnName))}) VALUES"); sb.Append(string.Join("," + Environment.NewLine, rows)); return sb.ToString(); } return string.Empty; } private static IEnumerable<string> FormatDataRowColumns(DataColumn[] columns, DataRow row) { foreach (var col in columns) { var value = row[col]; switch (Type.GetTypeCode(col.DataType)) { case TypeCode.Empty: yield return string.Empty; break; case TypeCode.Object: yield return $"{row[col]}"; break; case TypeCode.DBNull: yield return $"NULL"; break; case TypeCode.Boolean: yield return $"{(Convert.ToBoolean(row[col]) ? 1 : 0)}"; break; case TypeCode.Char: case TypeCode.String: yield return $"N'{row[col]}'"; // TODO: Add your logic to remove prefix N break; case TypeCode.SByte: case TypeCode.Byte: case TypeCode.Int16: case TypeCode.UInt16: case TypeCode.Int32: case TypeCode.UInt32: case TypeCode.Int64: case TypeCode.UInt64: case TypeCode.Single: case TypeCode.Double: case TypeCode.Decimal: yield return $"{row[col]}"; break; case TypeCode.DateTime: yield return $"'{row[col]:yyyy-MM-ddTHH:mm:ss}'"; break; default: yield return string.Empty; break; } } }
The code snippet above will produce following statement.
DECLARE @YourParamter dbo.YourStructuredType INSERT INTO @YourParamter (Column1Name, Column2Name) VALUES (10001001, N'Robert'), (20002001, N'Cloudie'), (30003001, N'Rachel');
Produce Complete SQL Statement
In SqlLogInterceptor
, now we can produce complete SQL statement as well as execution time, exception and result in every -ed
method, and write the log message. Apart from log message, we also check Exception
property to decide message level.
public void ScalarExecuted(DbCommand cmd, DbCommandInterceptionContext<object> interceptionContext) { var stopwatch = interceptionContext.FindUserState(nameof(Stopwatch)) as Stopwatch; var type = interceptionContext.Exception == null ? TraceEventType.Information : TraceEventType.Error; _traceSource.TraceEvent(type, 1, string.Join(Environment.NewLine, $"-- SQL executed in {stopwatch.ElapsedMilliseconds} ms:", $"USE {cmd.Connection.Database};", FormatParameters(cmd.Parameters), $"{cmd.CommandText};", interceptionContext.Exception, $"-- Result: {interceptionContext.Result}")); } // Same stuff for other -ed methods
The code snippet above will produce following log message.
-- SQL executed in 1 ms: DECLARE @p__linq__0 VarChar = 'Robert'; SELECT [Extent1].[StudentID] AS [StudentID], [Extent1].[StudentName] AS [StudentName], [Extent1].[StandardId] AS [StandardId] FROM [dbo].[Student] AS [Extent1] WHERE [Extent1].[StudentName] = @p__linq__0 -- Result: SqlDataReader
If the execution target is stored procedure, the log message will be something like this.
-- SQL executed in 20 ms: DECLARE @QueryString VarChar = 'string'; DECLARE @BeginDate DateTime = '1970-01-01T08:00:00'; DECLARE @PageNumber Int = 0; EXEC [dbo].[YourStoredProcedure] @QueryString, @BeginDate, @PageNumber; -- Result: 1
Conclusion
Entity Framework provides an accessible way to monitor each command. The code in this article takes advantage of it and produces executable T-SQL statements in log file. We can directly copy them, and debug them on SQL Server Management Studio, which saves our time of debugging.