91

According this thread, we can log the generated SQL via EF, but what about DbContext.SaveChanges()? Is there any easy way to do this job without any extra frameworks?

Community
  • 1
  • 1
Masoud
  • 8,020
  • 12
  • 62
  • 123
  • 1
    are you looking to do something like this ? http://stackoverflow.com/questions/11922552/logging-history-of-user-changes-in-ef-codefirst/11923762#11923762 – Kirsten Jun 02 '13 at 09:48
  • 1
    no, i want log the generated SQl statements by EF – Masoud Jun 02 '13 at 10:56
  • Check this link: http://jkowalski.com/2010/04/23/logging-sql-statements-in-entity-frameworkcode-first/ – Alaa Masoud Jun 02 '13 at 14:52

8 Answers8

142

In entity framework 6.0, the Database class has a property Action<string> Log. so setting up logging is as easy as:

context.Database.Log = Console.WriteLine;

For more advanced needs you can set up an interceptor.

emp
  • 4,926
  • 2
  • 38
  • 50
Lorentz Vedeler
  • 5,101
  • 2
  • 29
  • 40
  • 77
    or put it in DbContext ctor 'Database.Log = s => Debug.WriteLine(s);' – Søren Dec 28 '13 at 15:16
  • 2
    Public Sub New() Database.Log = Sub(s) Debug.WriteLine(s) End Sub End Sub – Bernhard Döbler Mar 17 '16 at 22:09
  • 10
    Checked all the answers and didn't see; how do we do this in EF Core? – Scott Fraley May 05 '17 at 21:31
  • See: Entity Framework Logging and Intercepting Database Operations (EF6 Onwards) here: https://msdn.microsoft.com/en-us/library/dn469464(v=vs.113).aspx – DeveloperDan Sep 21 '17 at 19:14
  • This log output gets jumbled when serving multiple concurrent web requests. So I created a new Q and found an A - see https://stackoverflow.com/questions/46984518/messages-are-being-mixed-up-through-database-log-by-multiple-threads/46984519#46984519 – Kind Contributor Oct 27 '17 at 23:07
  • 2
    It's just as easy for `Serilog` users, e.g.: `context.Database.Log = Log.Logger.Verbose;` (substitute your `Serilog.ILogger` instance). – Jonathan Lidbeck Jan 23 '19 at 01:22
  • Here's a Q&A for EFCore: https://stackoverflow.com/q/56310854 – DharmaTurtle Jan 03 '20 at 23:00
  • 1
    @ScottFraley please see this separate question for EF Core: https://stackoverflow.com/questions/56310854/get-generated-sql-for-a-dbcontext-savechanges-in-entity-framework-core – Qwertie Mar 04 '21 at 00:18
  • I have been searching for the .Log property for the Database, but there's no Log property under DatabaeFacade type...what am I missing? – Johnny Wu Dec 07 '22 at 17:50
15

See http://www.codeproject.com/Articles/499902/Profiling-Entity-Framework-5-in-code. I implemented Mr. Cook's idea in an asp.net mvc application using a Code First, POCO DbContext, Entity Framework 5.

The context class for the application derives from DbContext:

public class MyDbContext : DbContext

The constructor for the context hooks up the SavingChanges event (I only want to do the expensive reflection for debug builds):

public MyDbContext(): base("MyDbContext")
{
#if DEBUG
    ((IObjectContextAdapter)this).ObjectContext.SavingChanges += new EventHandler(objContext_SavingChanges);
#endif
}

The saving changes event writes the generated sql to the output window. The code I copied from Mr. Cook converts the DbParameter to a SqlParamter, which I leave as-is because I'm hitting a Sql Server, but I'm assuming that conversion would fail if you are hitting some other kind of database.

public void objContext_SavingChanges(object sender, EventArgs e)
    {
        var commandText = new StringBuilder();

        var conn = sender.GetType()
             .GetProperties(BindingFlags.Public | BindingFlags.Instance)
             .Where(p => p.Name == "Connection")
             .Select(p => p.GetValue(sender, null))
             .SingleOrDefault();
        var entityConn = (EntityConnection)conn;

        var objStateManager = (ObjectStateManager)sender.GetType()
              .GetProperty("ObjectStateManager", BindingFlags.Instance | BindingFlags.Public)
              .GetValue(sender, null);

        var workspace = entityConn.GetMetadataWorkspace();

        var translatorT =
            sender.GetType().Assembly.GetType("System.Data.Mapping.Update.Internal.UpdateTranslator");

        var translator = Activator.CreateInstance(translatorT, BindingFlags.Instance |
            BindingFlags.NonPublic, null, new object[] {objStateManager,workspace,
            entityConn,entityConn.ConnectionTimeout }, CultureInfo.InvariantCulture);

        var produceCommands = translator.GetType().GetMethod(
            "ProduceCommands", BindingFlags.NonPublic | BindingFlags.Instance);

        var commands = (IEnumerable<object>)produceCommands.Invoke(translator, null);

        foreach (var cmd in commands)
        {
            var identifierValues = new Dictionary<int, object>();
            var dcmd =
                (DbCommand)cmd.GetType()
                   .GetMethod("CreateCommand", BindingFlags.Instance | BindingFlags.NonPublic)
                   .Invoke(cmd, new[] { translator, identifierValues });

            foreach (DbParameter param in dcmd.Parameters)
            {
                var sqlParam = (SqlParameter)param;

                commandText.AppendLine(String.Format("declare {0} {1} {2}",
                                                        sqlParam.ParameterName,
                                                        sqlParam.SqlDbType.ToString().ToLower(),
                                                        sqlParam.Size > 0 ? "(" + sqlParam.Size + ")" : ""));

                commandText.AppendLine(String.Format("set {0} = '{1}'", sqlParam.ParameterName, sqlParam.SqlValue));
            }

            commandText.AppendLine();
            commandText.AppendLine(dcmd.CommandText);
            commandText.AppendLine("go");
            commandText.AppendLine();
        }

        System.Diagnostics.Debug.Write(commandText.ToString());
    }
Tom Regan
  • 3,580
  • 4
  • 42
  • 71
  • There is a bug in this code, the sqlParam.SqlValue isn't escaped, so any value with a single quote will generate invalid SQL.. and will also leave you open to SQL injection. – Rocklan Jan 10 '16 at 23:12
  • I disagree with your use of the word "bug" @LachlanB, but yes you are correct, it does not generate perfect sql, the sql has to be edited. Or you could add a bit more logic and get perfect sql. – Tom Regan Jan 11 '16 at 03:22
  • How is it not a bug? It's generating invalid SQL in certain conditions, and it's trying to generate valid SQL, so it's a bug by any definition of the word. – Rocklan Jan 12 '16 at 05:54
  • It is not trying to generate valid SQL, it is trying to show a software engineer the sql generated by Entity Framework 5 so that said engineer can debug problems. Note the #DEBUG preprocessor directive, and that the text is written to the IDE output window. The text must be must be manually copied and pasted into SSMS or something similar, and in some cases the developer will need to edit the sq before executing. That is not a bug, that is simply what the code is designed to do. – Tom Regan Jan 12 '16 at 13:57
  • Ok, can't argue with that, I'm using it for a different purpose. BTW there is another problem (not a bug), sqlParam.Size is -1 for nvarchar(max) data type, and the generated SQL will truncate your text down to one character. – Rocklan Jan 13 '16 at 00:07
12

For short-term logging, I just put into DbContext constructor:

Database.Log = x => Debug.WriteLine(x);

Pretty fast to add/remove logging of SQL. For long-use term, can be wrapped in checks with

#IFDEF DEBUG // or something similar
TPAKTOPA
  • 2,462
  • 1
  • 19
  • 26
8

If you want to capture the actual SQL that has been generated using EF6 (maybe to play back later) using an interceptor, you can do the following.

Create your interceptor

public class InsertUpdateInterceptor : IDbCommandInterceptor
{
    public virtual void NonQueryExecuting(
        DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
    {
        logCommand(command);
    }

    public virtual void ReaderExecuting(
        DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)
    {
        // this will capture all SELECT queries if you care about them..
        // however it also captures INSERT statements as well 
        logCommand(command);
    }

    public virtual void ScalarExecuting(
     DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
    {
        logCommand(command);
    }


    private void logCommand(DbCommand dbCommand)
    {
        StringBuilder commandText = new StringBuilder();

        commandText.AppendLine("-- New statement generated: " + System.DateTime.Now.ToString());
        commandText.AppendLine();

        // as the command has a bunch of parameters, we need to declare
        // those parameters here so the SQL will execute properly

        foreach (DbParameter param in dbCommand.Parameters)
        {
            var sqlParam = (SqlParameter)param;

            commandText.AppendLine(String.Format("DECLARE {0} {1} {2}",
                                                    sqlParam.ParameterName,
                                                    sqlParam.SqlDbType.ToString().ToLower(),
                                                    getSqlDataTypeSize(sqlParam));

            var escapedValue = sqlParam.SqlValue.replace("'", "''");
            commandText.AppendLine(String.Format("SET {0} = '{1}'", sqlParam.ParameterName, escapedValue ));
            commandText.AppendLine();
        }

        commandText.AppendLine(dbCommand.CommandText);
        commandText.AppendLine("GO");
        commandText.AppendLine();
        commandText.AppendLine();

        System.IO.File.AppendAllText("outputfile.sql", commandText.ToString());
    }

    private string getSqlDataTypeSize(SqlParameter param)
    {
        if (param.Size == 0)
        {
            return "";
        }

        if (param.Size == -1)
        {
            return "(MAX)";
        }

        return "(" + param.Size + ")";
    }


    // To implement the IDbCommandInterceptor interface you need to also implement these methods like so

    public void NonQueryExecuted(
        DbCommand command, DbCommandInterceptionContext<int> interceptionContext)
    {
    }

    public void ReaderExecuted(
        DbCommand command, DbCommandInterceptionContext<DbDataReader> interceptionContext)
    {
    }

    public void ScalarExecuted(
        DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
    {
    }
}

And you also need to register your interceptor. If you're doing this within an ASP.NET application make sure you only do it once, otherwise you'll end up intercepting the same request multiple times.

Example DAO

public class MyDataDAO
{
    private static bool isDbInterceptionInitialised = false;

    public MyDataDAO()
    {
        if (!isDbInterceptionInitialised)
        {
            DbInterception.Add(new InsertUpdateInterceptor());
            isDbInterceptionInitialised = true;
        }
    }

    public void Insert(string dataToInsert)
    {
        using (myentities context = new myentities())
        {
            MyData myData = new MyData();
            myData.data = dataToInsert;

            // this will trigger the interceptor
            context.SaveChanges();
        }
    }
}
Rocklan
  • 7,888
  • 3
  • 34
  • 49
  • `NLogCommandInterceptor` for EF6 https://blog.oneunicorn.com/2013/05/14/ef6-sql-logging-part-3-interception-building-blocks , any `SerilogCommandInterceptor` using ***Serilog***? – Kiquenet Mar 06 '17 at 08:49
  • I find your example great, thanks! However it seems not working because the property SqlValue of the Object SqlParameter is Object type so it doen't know the method "replace". `sqlParam.SqlValue.replace("'", "''");` – Mister Q Apr 12 '17 at 12:29
4

This does the same thing, but for every time you use your context it will write the sql query in the output window. The difference is that it does not compile in release.

public MyEntitities()
    : base()
{
    Database.Log = s => System.Diagnostics.Trace.WriteLine(s);
}

This StackOverflow Explains the Difference between Trace and Debug.

Community
  • 1
  • 1
Travis Peterson
  • 373
  • 3
  • 15
3

Tom Regan's code updated for EF6.

    public void objContext_SavingChanges(object sender, EventArgs e)
    {
        var commandText = new StringBuilder();

        var conn = sender.GetType()
             .GetProperties(BindingFlags.Public | BindingFlags.Instance)
             .Where(p => p.Name == "Connection")
             .Select(p => p.GetValue(sender, null))
             .SingleOrDefault();
        var entityConn = (EntityConnection)conn;

        var objStateManager = (System.Data.Entity.Core.Objects.ObjectStateManager)sender.GetType()
              .GetProperty("ObjectStateManager", BindingFlags.Instance | BindingFlags.Public)
              .GetValue(sender, null);

        var workspace = entityConn.GetMetadataWorkspace();

        var translatorT =
            sender.GetType().Assembly.GetType("System.Data.Entity.Core.Mapping.Update.Internal.UpdateTranslator");

        var entityAdapterT =
            sender.GetType().Assembly.GetType("System.Data.Entity.Core.EntityClient.Internal.EntityAdapter");
        var entityAdapter = Activator.CreateInstance(entityAdapterT, BindingFlags.Instance |
            BindingFlags.NonPublic | BindingFlags.Public, null, new object[] { sender }, System.Globalization.CultureInfo.InvariantCulture);

        entityAdapterT.GetProperty("Connection").SetValue(entityAdapter, entityConn);

        var translator = Activator.CreateInstance(translatorT, BindingFlags.Instance |
            BindingFlags.NonPublic | BindingFlags.Public, null, new object[] { entityAdapter }, System.Globalization.CultureInfo.InvariantCulture);

        var produceCommands = translator.GetType().GetMethod(
            "ProduceCommands", BindingFlags.NonPublic | BindingFlags.Instance);

        var commands = (IEnumerable<object>)produceCommands.Invoke(translator, null);

        foreach (var cmd in commands)
        {
            var identifierValues = new Dictionary<int, object>();
            var dcmd =
                (System.Data.Common.DbCommand)cmd.GetType()
                   .GetMethod("CreateCommand", BindingFlags.Instance | BindingFlags.NonPublic)
                   .Invoke(cmd, new[] { identifierValues });

            foreach (System.Data.Common.DbParameter param in dcmd.Parameters)
            {
                var sqlParam = (SqlParameter)param;

                commandText.AppendLine(String.Format("declare {0} {1} {2}",
                                                        sqlParam.ParameterName,
                                                        sqlParam.SqlDbType.ToString().ToLower(),
                                                        sqlParam.Size > 0 ? "(" + sqlParam.Size + ")" : ""));

                commandText.AppendLine(String.Format("set {0} = '{1}'", sqlParam.ParameterName, sqlParam.SqlValue));
            }

            commandText.AppendLine();
            commandText.AppendLine(dcmd.CommandText);
            commandText.AppendLine("go");
            commandText.AppendLine();
        }

        System.Diagnostics.Debug.Write(commandText.ToString());
    }
Brandon Barkley
  • 720
  • 6
  • 21
2

You can use SQL Server Profiler and run it against the database server you are connecting to.

Jay Jay Jay
  • 1,970
  • 2
  • 25
  • 47
  • 7
    While that is a way to log SQL, it's a last resort. It requires special permissions on the server, doesn't integrate with application logging, logs more than what you're looking for, and has no way to associate your EF statements to the generated SQL. – Gabe Jun 02 '13 at 18:19
1

This should help, the EFTracingProvider

http://code.msdn.microsoft.com/EFProviderWrappers

Wiktor Zychla
  • 47,367
  • 6
  • 74
  • 106