Click here to Skip to main content
14,447,096 members

Entity Framework DBInterception(Exception Handling+Optimizing Performance)

Rate this:
4.82 (11 votes)
Please Sign up or sign in to vote.
4.82 (11 votes)
8 Feb 2016CPOL
Logging database operations in Entity Framework and handling Exceptions

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:

Image 1

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:

Image 2

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

Credits

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.

License

This article, along with any associated source code and files, is licensed under The Code Project Open License (CPOL)

Share

About the Author

Dholakiya Ankit
Web Developer
India India
No Biography provided

Comments and Discussions

 
QuestionIs it possible to turn on or turn off EFInterceptor from config file? Pin
Member 769743829-Mar-17 22:48
MemberMember 769743829-Mar-17 22:48 
AnswerRe: Is it possible to turn on or turn off EFInterceptor from config file? Pin
Dholakiya Ankit4-Oct-17 23:36
MemberDholakiya Ankit4-Oct-17 23:36 
QuestionEF extension Pin
Ehsan Sajjad22-Jan-16 3:41
professionalEhsan Sajjad22-Jan-16 3:41 
AnswerRe: EF extension Pin
Dholakiya Ankit22-Jan-16 18:26
MemberDholakiya Ankit22-Jan-16 18:26 
GeneralRe: EF extension Pin
Ehsan Sajjad24-Jan-16 2:04
professionalEhsan Sajjad24-Jan-16 2:04 
GeneralRe: EF extension Pin
Dholakiya Ankit26-Jan-16 18:38
MemberDholakiya Ankit26-Jan-16 18:38 
SuggestionUse consistent formatting Pin
Jochen Arndt18-Jan-16 2:03
professionalJochen Arndt18-Jan-16 2:03 
GeneralRe: Use consistent formatting Pin
Dholakiya Ankit18-Jan-16 2:24
MemberDholakiya Ankit18-Jan-16 2:24 
GeneralMessage Closed Pin
18-Jan-16 3:19
MemberMember 1089184818-Jan-16 3:19 
GeneralRe: Use consistent formatting Pin
Dholakiya Ankit18-Jan-16 6:43
MemberDholakiya Ankit18-Jan-16 6:43 

General General    News News    Suggestion Suggestion    Question Question    Bug Bug    Answer Answer    Joke Joke    Praise Praise    Rant Rant    Admin Admin   

Use Ctrl+Left/Right to switch messages, Ctrl+Up/Down to switch threads, Ctrl+Shift+Left/Right to switch pages.

Tip/Trick
Posted 17 Jan 2016

Stats

36.2K views
375 downloads
44 bookmarked