SqlCommand to T-SQL Printer

• Download LogExample.zip - 385.5 KB

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.

-- SQL executed in 1 ms:
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
-- 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 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]}'"; // 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 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}"));
}

// Same stuff for other -ed methods

The code snippet above will produce the following log message.

-- SQL executed in 1 ms:
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
-- Result: SqlDataReader

If the execution target is a stored procedure, the log message will be something like this:

-- SQL executed in 20 ms:
DECLARE @QueryString VarChar(200)  = '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 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.