Entity Framework 6 - Audit Log

audit-trail entity-framework-5 entity-framework-6

Question

I have a doubt regarding Audit Log under Entity Framework 6.0

I have implemented it but it really slows downs when I update or insert.

In other application (Not using EF), I used to create a memory XML with the audit information and then send it to a Stored Procedure in SQL Server in order to inserting the audit log and was amazing fast. You didn't realize that you were doing audit logging.

I would like to know if there is other way to do it or a best practice for it.

My actual code looks like this:

In my DbContext I override the SaveChanges() method:

public override int SaveChanges() {
    throw new InvalidOperationException("User ID and Session ID must be provided");
}

Then I implement my custon SaveChanges() method.

public int SaveChanges(int userId, Guid sessionId, bool saveAuditLog) {
    if (saveAuditLog && userId > 0) {
        // this list will exclude entities for auditing
        List < string > excludeEntities = new List < string > ();
        excludeEntities.Add("SecuritySession");
        excludeEntities.Add("SecurityUserActivityLog");

        this.ObjectContext = ((IObjectContextAdapter) this).ObjectContext;
        // Get all Added/Deleted/Modified entities (not Unmodified or Detached)
        foreach(var ent in this.ChangeTracker.Entries().Where(p => p.State == System.Data.Entity.EntityState.Added || p.State == System.Data.Entity.EntityState.Deleted || p.State == System.Data.Entity.EntityState.Modified)) {
            // security session is not Auditable 

            if (!excludeEntities.Contains(ent.Entity.GetType().Name)) {
                // For each changed record, get the audit record entries and add them
                foreach(AuditLog x in GetAuditRecordsForChange(ent, userId, sessionId)) {
                    this.AuditLogs.Add(x);
                }
            }

        }
    }

And finally I have a method GetAuditRecordsForChange() that will do the auditing job.

 private List < AuditLog > GetAuditRecordsForChange(DbEntityEntry dbEntry, int userId, Guid sessionId) {
        Type entityType = dbEntry.Entity.GetType();
        if (entityType.BaseType != null && entityType.Namespace == "System.Data.Entity.DynamicProxies")
            entityType = entityType.BaseType;

        string entityTypeName = entityType.Name;

        string[] keyNames;

        MethodInfo method = Data.Helpers.EntityKeyHelper.Instance.GetType().GetMethod("GetKeyNames");
        keyNames = (string[]) method.MakeGenericMethod(entityType).Invoke(Data.Helpers.EntityKeyHelper.Instance, new object[] {
            this
        });

        List < AuditLog > result = new List < AuditLog > ();

        DateTime changeTime = DateTime.Now;

        // Get table name (if it has a Table attribute, use that, otherwise get the pluralized name)
        string tableName = entityTypeName;

        if (dbEntry.State == System.Data.Entity.EntityState.Added) {
            // For Inserts, just add the whole record
            // If the entity implements IDescribableEntity, use the description from Describe(), otherwise use ToString()

            foreach(string propertyName in dbEntry.CurrentValues.PropertyNames) {
                result.Add(new AuditLog() {
                    AuditLogId = Guid.NewGuid(),
                        UserId = userId,
                        SessionId = sessionId,
                        EventDateUTC = changeTime,
                        EventType = "A", // Added
                        TableName = tableName,
                        RecordId = dbEntry.CurrentValues.GetValue < object > (keyNames[0]).ToString(),
                        ColumnName = propertyName,
                        NewValue = dbEntry.CurrentValues.GetValue < object > (propertyName) == null ? null : dbEntry.CurrentValues.GetValue < object > (propertyName).ToString()
                });
            }
        } else if (dbEntry.State == System.Data.Entity.EntityState.Deleted) {
            // Same with deletes, do the whole record, and use either the description from Describe() or ToString()
            result.Add(new AuditLog() {
                AuditLogId = Guid.NewGuid(),
                    UserId = userId,
                    SessionId = sessionId,
                    EventDateUTC = changeTime,
                    EventType = "D", // Deleted
                    TableName = tableName,
                    RecordId = dbEntry.OriginalValues.GetValue < object > (keyNames[0]).ToString(),
                    ColumnName = "*ALL",
                    NewValue = (dbEntry.OriginalValues.ToObject() is IDescribableEntity) ? (dbEntry.OriginalValues.ToObject() as IDescribableEntity).Describe() : dbEntry.OriginalValues.ToObject().ToString()
            });
        } else if (dbEntry.State == System.Data.Entity.EntityState.Modified) {
            foreach(string propertyName in dbEntry.OriginalValues.PropertyNames) {
                // For updates, we only want to capture the columns that actually changed
                if (!object.Equals(dbEntry.OriginalValues.GetValue < object > (propertyName), dbEntry.CurrentValues.GetValue < object > (propertyName))) {
                    result.Add(new AuditLog() {
                        AuditLogId = Guid.NewGuid(),
                            UserId = userId,
                            SessionId = sessionId,
                            EventDateUTC = changeTime,
                            EventType = "M", // Modified
                            TableName = tableName,
                            RecordId = dbEntry.OriginalValues.GetValue < object > (keyNames[0]).ToString(),
                            ColumnName = propertyName,
                            OriginalValue = dbEntry.OriginalValues.GetValue < object > (propertyName) == null ? null : dbEntry.OriginalValues.GetValue < object > (propertyName).ToString(),
                            NewValue = dbEntry.CurrentValues.GetValue < object > (propertyName) == null ? null : dbEntry.CurrentValues.GetValue < object > (propertyName).ToString()
                    });
                }
            }
        }
        // Otherwise, don't do anything, we don't care about Unchanged or Detached entities

        return result;
    }

    // Call the original SaveChanges(), which will save both the changes made and the audit records
    return base.SaveChanges();
}
1
1
9/27/2014 12:13:14 AM

Popular Answer

Your biggest performance problem appears to be that the calls to ChangeTracker.Entries() and DbSet.Add() both internally trigger the DetectChanges() method, which is slow proportional to the number of entities being actively tracked by the DbContext instance. I suspect that the call to .Add() in the foreach loop is the main culprit, because it is calling the method n times. Because you are adding AuditLog entities in a foreach loop, each call to DetectChanges() will be slower, because the DbContext instance is tracking more entities.

See http://blog.oneunicorn.com/2012/03/11/secrets-of-detectchanges-part-2-when-is-detectchanges-called-automatically/ for more details.

Calling DbSet.Add() or DbSet.Remove() sets the state of the entity appropriately (without a call to DetectChanges()), but the entity state of updated entities is not automatically updated (this is one thing that DetectChanges() accomplishes). You would need a single call (implicit or explicit) to DetectChanges() at the beginning of the method to ensure that all updated entities are marked as updated. Note that the base SaveChanges() method automatically calls DetectChanges() unless explicitly turned off.

Also, the repeated reflective calls probably don't help. I would suggest profiling this method by using System.Diagnostics.Stopwatch or something more sophisticated to specifically identify your bottleneck.

3
8/12/2014 11:30:26 PM


Related Questions





Related

Licensed under: CC-BY-SA with attribution
Not affiliated with Stack Overflow
Licensed under: CC-BY-SA with attribution
Not affiliated with Stack Overflow