Why is my EntityFramework insert so slow?

Question

I've found a bottleneck in my application to be the insert operation for one particular entity (into three tables, through navigation properties). The classes are defined as follows:

public class TrackerState
{
    public int Id { get; set; }
    [Index]
    public int TrackerId { get; set; }

    [Index]
    public DateTime DateRecorded { get; set; }
    public DateTime DatePublished { get; set; }
    public DateTime DateReceived { get; set; }
    public LocationStatus LocationStatus { get; set; }
    public double Latitude { get; set; }
    public double Longitude { get; set; }
    public double Altitude { get; set; }
    public double Accuracy { get; set; }
    public string Source { get; set; }
    public double Speed { get; set; }
    public double Heading { get; set; }
    public int PrimaryOdometer { get; set; }
    public int SecondaryOdometer { get; set; }
    public int OperationalSeconds { get; set; }
    public virtual IList<AnalogState> AnalogStates { get; set; }
    public virtual IList<DigitalState> DigitalStates { get; set; }
}

public class AnalogState
{
    public int TrackerStateId { get; set; }
    public virtual TrackerState TrackerState { get; set; }
    public int Index { get; set; }
    public int Value { get; set; }
}

public class DigitalState
{
    public int TrackerStateId { get; set; }
    public virtual TrackerState TrackerState { get; set; }
    public int Index { get; set; }
    public bool Value { get; set; }
}

The AnalogState and DigitalState classes use the TrackerStateId and their Index as a composite primary key.

The tables are currently very small:

TrackerStates: 2719
AnalogStates: 0
DigitalStates: 32604

When I insert into the tables manually, through SQL management studio, the operation runs in a fraction of a second. When I insert through Entity Framework, using the following code, it can take up to 15 seconds, and the amount of time taken is very dependent on the number of digital values included in the tracker state - e.g. a tracker state with 0 digital values takes between 0.1 to 0.5 seconds, and a tracker state with 64 digital values takes between 10 and 15 seconds.

public async Task<int> AddAsync(TrackerState trackerState)
{
    using (var context = ContextFactory.CreateContext())
    {
        context.TrackerStates.Add(trackerState);
        await context.SaveChangesAsync();
        return trackerState.Id;
    }
}

Based on this, it seems like Entity Framework is doing something very slow in the background, but I can't figure out why. 0.5 seconds is pretty slow for a transaction, considering how often this is going to be done. 15 seconds is just too damn slow. Things I have tried so far, to no success:

Disabling change tracking. I didn't expect this to do much, as I am using a separate context for each transaction anyway.
Inserting the tracker state first, then the digital states in a separate step. Entity Framework is probably doing this internally anyway.

Update 1

I'm using EntityFramework 6.1.3. I couldn't figure out how to view the SQL being executed, but I updated the repository's store method to use SQL instead of EF:

context.Database.ExecuteSqlCommand("INSERT INTO DigitalStates ([TrackerStateId], [Index], [Value]) VALUES (@Id, @Index, @Value)",
                    new SqlParameter("Id", entity.Id),
                    new SqlParameter("Index", digital.Index),
                    new SqlParameter("Value", digital.Value));

This part alone is accounting for the majority of the time. It takes 3 seconds to insert 7 entries.

What if you try to open up SQL Server Profiler and see the query that EF is running that takes 15 seconds? — Camilo Terevinto, Jul 19 '17 at 22:43
As far as I'm aware, there's no validation on the input columns. What you see in the models above is exactly what was used to generate the tables (besides the composite keys). — Andrew Williamson, Jul 19 '17 at 22:46
Did you add a logger to queries and see what is being executed to SQL. Also what version are you running core or 6? — Filip Cordas, Jul 19 '17 at 22:58
I use [Express Profiler](https://expressprofiler.codeplex.com/) to see your queries - simple and easy to use. Highly recommended. — trailmax, Jul 19 '17 at 23:11
I removed that answer, I misread the issue as when updating multiple Trackers with multiple digital states, not single tracker with multiple. Have you hooked up a profiler to SQL to review the queries being sent to SQL? This would reveal if it's EF or what EF is sending to SQL. (# of statements during this operation, time to execute each) By "disabling change tracking" was this via context.Configuration.AutoDetectChangesEnabled = false;? I agree for 67 records though, I can't see how that would affect it by much... — Steve Py, Jul 20 '17 at 03:28

score 1 · Accepted Answer · answered Jul 20 '17 at 00:04

Saving all the digital states in one transaction made a huge difference:

if (trackerState.DigitalStates.Count > 0)
{
    var query = "INSERT INTO DigitalStates ([TrackerStateId], [Index], [Value]) VALUES "
        + string.Join(",", trackerState.DigitalStates.Select(state => String.Format("({0}, {1}, {2})", entity.Id, state.Index, state.Value ? 1 : 0)));
    context.Database.ExecuteSqlCommand(query);
}

For some reason, letting Entity Framework add the collection automatically seemed to be making a request to the database for each digital state that was added, although I was under the impression that it should have been one transaction, triggered by the context's SaveChanges() method. This fix has changed it from linear time to approximately constant time, relative to the size of the collection. Now my next question is, why?

Why is my EntityFramework insert so slow?

1 Answers1

Linked