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 the following message like this in your log file.
DECLARE @p__linq__0 VarChar(100) = 'Cloudie';
SELECT
[Extent1].[StudentID] AS [StudentID],
[Extent1].[StudentName] AS [StudentName],
FROM [dbo].[Student] AS [Extent1]
WHERE [Extent1].[StudentName] = @p__linq__0
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;
}
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;
}
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;
}
#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 the 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
The 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 the 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.Float:
case SqlDbType.Int:
case SqlDbType.TinyInt:
case SqlDbType.SmallInt:
case SqlDbType.DateTimeOffset:
case SqlDbType.Timestamp:
return $"DECLARE @{param.ParameterName.TrimStart('@')} {param.SqlDbType} {FormatNumericParameter(param)};";
case SqlDbType.Decimal:
case SqlDbType.Money:
case SqlDbType.SmallMoney:
return $"DECLARE @{param.ParameterName.TrimStart('@')} {param.SqlDbType} {FormatNumericParameterSize(param)} {FormatNumericParameter(param)};";
case SqlDbType.Bit:
return $"DECLARE @{param.ParameterName.TrimStart('@')} {param.SqlDbType} {FormatBooleanParameter(param)};";
case SqlDbType.NText:
case SqlDbType.Text:
case SqlDbType.Time:
case SqlDbType.Xml:
case SqlDbType.UniqueIdentifier:
return $"DECLARE @{param.ParameterName.TrimStart('@')} {param.SqlDbType} {FormatStringParameter(param)};";
case SqlDbType.Char:
case SqlDbType.NChar:
case SqlDbType.VarChar:
case SqlDbType.NVarChar:
return $"DECLARE @{param.ParameterName.TrimStart('@')} {param.SqlDbType} {FormatStringParameterSize(param)} {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:
return $"DECLARE @{param.ParameterName.TrimStart('@')} {param.TypeName} {FormatDataTableParameter(param)};";
case SqlDbType.Udt:
return $"DECLARE @{param.ParameterName.TrimStart('@')} {param.UdtTypeName} -- {param.Value};";
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 FormatNumericParameterSize(SqlParameter param)
{
if (param.Direction == ParameterDirection.Input || !Convert.IsDBNull(param.Value))
return string.Empty;
return $"({param.Precision}, {param.Scale})";
}
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 FormatStringParameterSize(SqlParameter param)
{
if (Convert.IsDBNull(param.SqlValue)) return string.Empty;
if (param.Size < 0) return "(MAX)";
if (param.Size > 0) return $"({param.Size})";
return $"({Convert.ToString(param.SqlValue).Length})";
}
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 are shown below:
DECLARE @QueryString VarChar(200) = '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 the 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 rows, 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]}'";
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 the 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 a 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}"));
}
The code snippet above will produce the following log message.
DECLARE @p__linq__0 VarChar(200) = '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
If the execution target is a stored procedure, the log message will be something like this:
DECLARE @QueryString VarChar(200) = 'string';
DECLARE @BeginDate DateTime = '1970-01-01T08:00:00';
DECLARE @PageNumber Int = 0;
EXEC [dbo].[YourStoredProcedure] @QueryString, @BeginDate, @PageNumber;
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 debugging time.
History
- 2018-03-16 Initial post
- 2018-03-22 Fix a bug where
CHAR, VARCHAR, NCHAR, VARCHAR data size is not present in DECLARE statement. - 2018-03-23 Fix a bug where
CHAR, VARCHAR, NCHAR, VARCHAR data size is not present correctly. Add precision and scale to DECIMAL, MONEY and SMALLMONEY declaration.
