Entity Framework DBInterception(Exception Handling+Optimizing Performance)

• Download source (ZIP) - 7.4 MB
• Download source (RAR) - 6.2 MB

Introduction

If you are using the EF6 and want to log the database operations, analyze them, then, this is the right place for you.

Background

When I was developing one WebApi project, what I was searching for is an output each query performed by Entity framework should be logged with time. Also, exception if there is any. So, in this section, you will learn how to log commands and queries to the database generated by Entity framework. 

Using the Code

There are two ways:

1) Simple Method

  using (MyDatabaseEntities context = new MyDatabaseEntities())
       {
           context.Database.Log = s => System.Diagnostics.Debug.WriteLine(s);

            // query the database using EF here.
        }

This will log the database operations in the output window. What it does is it writes the operations performed by EntityFramework to the output window. It gives awesome traces. 

Have a look:

2) IDbCommandInterceptor

This uses the IDbCommandInterceptor Interface. This is in-built in Entity framework 6.

Note: This Interface is available only in Entityframework 6 and later.

Have a look at Interface:

namespace System.Data.Entity.Infrastructure.Interception
{
  /// <summary>
  /// An object that implements this interface can be registered with 
  /// <see cref="T:System.Data.Entity.Infrastructure.Interception.DbInterception"/> to
  ///             receive notifications when Entity Framework executes commands.
  /// 
  /// </summary>
  /// 
  /// <remarks>
  /// Interceptors can also be registered in the config file of the application.
  ///             See http://go.microsoft.com/fwlink/?LinkId=260883 
  ///             for more information about Entity Framework configuration.
  /// 
  /// </remarks>
  public interface IDbCommandInterceptor : IDbInterceptor
  {
    /// <summary>
    /// This method is called before a call to 
    /// <see cref="M:System.Data.Common.DbCommand.ExecuteNonQuery"/> or
    ///             one of its async counterparts is made.
    /// 
    /// </summary>
    /// <param name="command">The command being executed.</param>
    /// <param name="interceptionContext">
    /// Contextual information associated with the call.</param>
    void NonQueryExecuting(DbCommand command, DbCommandInterceptionContext<int> interceptionContext);

    /// <summary>
    /// This method is called after a call to 
    /// <see cref="M:System.Data.Common.DbCommand.ExecuteNonQuery"/>  or
    /// one of its async counterparts is made. 
    /// The result used by Entity Framework can be changed by setting
    /// <see cref=
    /// "P:System.Data.Entity.Infrastructure.Interception.DbCommandInterceptionContext`1.Result"/>.
    /// 
    /// </summary>
    /// 
    /// <remarks>
    /// For async operations this method is not called until after the async task has completed
    ///             or failed.
    /// 
    /// </remarks>
    /// <param name="command">The command being executed.</param>
    /// <param name=
    /// "interceptionContext">Contextual information associated with the call.</param>
    void NonQueryExecuted(DbCommand command, DbCommandInterceptionContext<int> interceptionContext);

    /// <summary>
    /// This method is called before a call to 
    /// <see cref="M:System.Data.Common.DbCommand.ExecuteReader(System.Data.CommandBehavior)"/> or
    /// one of its async counterparts is made.
    /// 
    /// </summary>
    /// <param name="command">The command being executed.</param>
    /// <param name="interceptionContext">Contextual information associated with the call.
    /// </param>
    void ReaderExecuting(DbCommand command, 
	DbCommandInterceptionContext<DbDataReader> interceptionContext);

    /// <summary>
    /// This method is called after a call to 
    /// <see cref="M:System.Data.Common.DbCommand.ExecuteReader(System.Data.CommandBehavior)"/> or
    /// one of its async counterparts is made. 
    /// The result used by Entity Framework can be changed by setting
    /// <see cref=
    /// "P:System.Data.Entity.Infrastructure.Interception.DbCommandInterceptionContext`1.Result"/>.
    /// 
    /// </summary>
    /// 
    /// <remarks>
    /// For async operations this method is not called until after the async task has completed
    ///             or failed.
    /// 
    /// </remarks>
    /// <param name="command">The command being executed.</param>
    /// <param name="interceptionContext">
    /// Contextual information associated with the call.</param>
    void ReaderExecuted(DbCommand command, 
    	DbCommandInterceptionContext<DbDataReader> interceptionContext);

    /// <summary>
    /// This method is called before a call to 
    /// <see cref="M:System.Data.Common.DbCommand.ExecuteScalar"/> or
    ///             one of its async counterparts is made.
    /// 
    /// </summary>
    /// <param name="command">The command being executed.</param>
    /// <param name="interceptionContext">
    /// Contextual information associated with the call.</param>
    void ScalarExecuting(DbCommand command, DbCommandInterceptionContext<object> interceptionContext);

    /// <summary>
    /// This method is called after a call to 
    /// <see cref="M:System.Data.Common.DbCommand.ExecuteScalar"/> or
    /// one of its async counterparts is made. 
    /// The result used by Entity Framework can be changed by setting
    /// <see cref=
    /// "P:System.Data.Entity.Infrastructure.Interception.DbCommandInterceptionContext`1.Result"/>.
    /// 
    /// </summary>
    /// 
    /// <remarks>
    /// For async operations this method is not called until after the async task has completed
    ///             or failed.
    /// 
    /// </remarks>
    /// <param name="command">The command being executed.
    /// </param><param name="interceptionContext">
    /// Contextual information associated with the call.</param>
    void ScalarExecuted(DbCommand command, DbCommandInterceptionContext<object> interceptionContext);
  }
}

Let’s derive this interface to the DatabaseLogger class.

FYI, I have added my log information into database. You may insert into file, Excel, anything you want.

You need not worry about the methods Interface itself is very self explanatory. It has 6 methods.

You can see that I have derived and check comments to understand each methods.

   //this file is used to log the database operations it checks 
   //the query execution time and than insert if it takes more than one second.
    //to disable it remove its registry from TeamPassDbContext default constructor
    public class DatabaseLogger : IDbCommandInterceptor
    {       
        static readonly ConcurrentDictionary<DbCommand, 
        DateTime> MStartTime = new ConcurrentDictionary<DbCommand, DateTime>();
        
        public void NonQueryExecuted(DbCommand command, 
        DbCommandInterceptionContext<int> interceptionContext)
        {
            //executed state
            Log(command, interceptionContext);
        }

        public void NonQueryExecuting(DbCommand command, 
        DbCommandInterceptionContext<int> interceptionContext)
        {
            //executing state
            OnStart(command);
        }

        public void ReaderExecuted(DbCommand command, 
        DbCommandInterceptionContext<DbDataReader> interceptionContext)
        {
            //reader executed state
            Log(command,interceptionContext);
        }

        public void ReaderExecuting(DbCommand command, 
        DbCommandInterceptionContext<DbDataReader> interceptionContext)
        {
            //reader executing state
            OnStart(command);
        }

        private static void Log<T>(DbCommand command, 
        DbCommandInterceptionContext<T> interceptionContext)
        {            
            DateTime startTime;
            TimeSpan duration;
            //Removing from dictionary and calculating time
            MStartTime.TryRemove(command, out startTime);
            if (startTime != default(DateTime))
            {
                duration = DateTime.Now - startTime;
            }
            else
                duration = TimeSpan.Zero;

            const int requestId = -1;

            var parameters = new StringBuilder();
            foreach (DbParameter param in command.Parameters)
            {
                parameters.AppendLine(param.ParameterName + " " + 
                param.DbType + " = " + param.Value);
            }
            
            var message = interceptionContext.Exception == null ? 
            $"Database call took {duration.TotalSeconds.ToString("N3")} sec. 
            RequestId {requestId} \r\nCommand:\r\n{parameters + command.CommandText}" : 
            $"EF Database call failed after {duration.TotalSeconds.ToString("N3")} sec. 
            RequestId {requestId} \r\nCommand:\r\n{parameters.ToString() + 
            command.CommandText}\r\nError:{interceptionContext.Exception} ";

            //Ignoring some queries which runs perfectly
            if (duration.TotalSeconds>1 || message.Contains("EF Database call failed after "))
            {
                //The time taken is more or it contains error so adding that to database
                using (DbContext dbContext = new DbContext())
                {
                    //using error model class
                    Error error = new Error
                    {
                        TotalSeconds = (decimal)duration.TotalSeconds,
                        Active = true,
                        CommandType = Convert.ToString(command.CommandType),
                        CreateDate = DateTime.Now,
                        Exception = Convert.ToString(interceptionContext.Exception),
                        FileName = "",
                        InnerException = interceptionContext.Exception == null ? 
                        "" : Convert.ToString(interceptionContext.Exception.InnerException),
                        Parameters = parameters.ToString(),
                        Query = command.CommandText,
                        RequestId = 0
                    };
                    //Adding to database
                    dbContext.Errors.Add(error);
                    dbContext.SaveChanges();
                }               
                
                //var errorFileUrl = ;
                //File.WriteAllLines(, message);
            }            
        }

        public void ScalarExecuted
        (DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
        {
            //Log and calculate after executed
            Log(command, interceptionContext);
        }

        public void ScalarExecuting
        (DbCommand command, DbCommandInterceptionContext<object> interceptionContext)
        {
            //adding to dictionary when executing
            OnStart(command);
        }
        private static void OnStart(DbCommand command)
        {
            //adding to dictionary when executing
            MStartTime.TryAdd(command, DateTime.Now);
        }
    }

Now, I am registering this class to dbcontext.

Explanation: It tells entity framework to use this class for Logging database operations.

 public DbContext(): base("name=connectionstring")
        {
            //TODO remove this when don't need to log anything
            DbInterception.Add(new DatabaseLogger());
        }

Everything is set up now. You can make an Error model class like this. (This is the code-first model class.)

  public class Error
    {
        [Key]
        [Required]
        public int ErrorId { get; set; }

        public string Query { get; set; }

        public string Parameters { get; set; }

        public string CommandType { get; set; }

        public decimal TotalSeconds { get; set; }

        public string Exception { get; set; }

        public string InnerException { get; set; }
        public int RequestId { get; set; }
        public string FileName { get; set; }
        public DateTime CreateDate { get; set; }

        public bool Active { get; set; }
    }

Have a look at Error logs here:

Technically, there are many approaches to log your Database operations. This is the easiest way I saw.

Credits

• Idea of using time intervals: http://stackoverflow.com/a/27365855/2630817
• Resharper for decompiling Interface: https://www.jetbrains.com/resharper/
• Have a look at https://msdn.microsoft.com/en-us/library/dd287191(v=vs.110).aspx for ConcurrentDictionary

Bonus

I just used this so thought about sharing it here too :)

Let's have a quick look at logging the time taken by each controller. Same table's structure, same queries.

1. Add a new class named ExecutionTimeFilter like I have added:

    public class ExecutionTimeFilter : ActionFilterAttribute
       {
           public override void OnActionExecuting(HttpActionContext actionContext)
           {
               //Method executing
               base.OnActionExecuting(actionContext);
               //Adding new key stopwatch which will be added to the current request properties
               actionContext.Request.Properties.Add("Time", Stopwatch.StartNew());
   
           }
   
           public override void OnActionExecuted(HttpActionExecutedContext actionContext)
           {
               //Executed
               base.OnActionExecuted(actionContext);
               try
               {
   
                   //retriving the stopwatch which we added in Executing method
                   var stopwatch = (Stopwatch)actionContext.Request.Properties["Time"];
                   //removing the key
                   actionContext.Request.Properties.Remove("Time");
   
                   //get the time Elapese means time take to execute the request
                   var elapsedTime = stopwatch.Elapsed;
                   if (!(elapsedTime.TotalSeconds > 10)) return;
                   //Ignoring controllers took seconds <10 so not inserting them into database
                   using (DbContext dbContext = new DbContext())
                   {
                       Error error = new Error
                       {
                           TotalSeconds = (decimal)elapsedTime.TotalSeconds,
                           Active = true,
                           CommandType = "Action Context",
                           CreateDate = DateTime.Now,
                           Exception = Convert.ToString(actionContext.Request),
                           FileName = "",
                           InnerException = actionContext.Response.ToString(),
                           Parameters = "",
                           Query = "",
                           RequestId = 0
                       };
                       dbContext.Errors.Add(error);
                       dbContext.SaveChanges();
                   }
               }
               catch
               {
                   // ignored
               }
           }
       }

2. Register it to the config in my case I am using it in web API so in App_Start/WebApiConfig.cs:

    public static void Register(HttpConfiguration config)
           {
              
               config.Filters.Add(new ExecutionTimeFilter());
   
           }

   Done! now, every action executed and took more than 10 seconds will log that entry to the database.