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.