7

I'm consistently getting the results shown in the graph below. I'm wondering if there is anything I can do to increase predictability. I'm not using SqlBulkCopy since I need to leverage the validation capabilities of EFv5.

It would be great if someone could verify/refute my findings. My objective is to get rid of both kind of spikes. I'm providing the source code below to make it quick for you. All you need is a class library project in VS, with references to EFv5 and NUnit, both available through NuGet. Just paste this code in Class1, modify the connection string, and run it. You can use the sql script below to recreate the table.

I'm using .Net 4.5, EF 5, NUnit 2.6.1, running the code in Release mode, with no debugger attached. The db is SqlServer 2008 R2. I run the test with NUnit.exe in 64-bit mode, which shows 'Net 4.0' as the framework version.

EFv5 simple entity insert. 1000 batches of 100 entities

The X axis is the batch number (1000 batches total), and the Y axis is milliseconds. You can see the first batch takes about 30 seconds, which is expected since the dbContext is 'cold'. Each batch saves 100 entities.

Please note that this question is looking for a bit of information missing in this answer, it being the jitter in EF saves.

Here is the code I'm using:

The table:

CREATE TABLE [dbo].[Entity1](
    [Id] [int] IDENTITY(1,1) NOT NULL,
    [IntField] [int] NOT NULL,
    [StrField] [nvarchar](50) NOT NULL,
    [DateField] [datetimeoffset](7) NOT NULL,
CONSTRAINT [PK_Entity1] PRIMARY KEY CLUSTERED 
(
    [Id] ASC
)WITH (PAD_INDEX  = OFF, STATISTICS_NORECOMPUTE  = OFF, IGNORE_DUP_KEY = OFF,
    ALLOW_ROW_LOCKS  = ON, ALLOW_PAGE_LOCKS  = ON) ON [PRIMARY]
) ON [PRIMARY]

The classes:

using System;
using System.Collections.Generic;
using System.Data.Entity;
using System.Diagnostics;
using NUnit.Framework;

namespace ClassLibrary1
{
    public class Entity1
    {
        public int Id { get; protected set; }
        public int IntField { get; set; }
        public string StrField { get; set; }
        public DateTimeOffset DateField { get; set; }
    }

    public class MyContext : DbContext
    {
        public MyContext(string connStr) : base(connStr) { }
        public virtual DbSet<Entity1> Entities { get { return base.Set<Entity1>(); } }
    }

    [TestFixture]
    public class Class1
    {
        [Test]
        public void EfPerf()
        {
            var entities = buildEntities(100000);
            int batchSize = 100;
            var batchTimes = new List<Stopwatch>();

            for (int i = 0; i < entities.Length; i += batchSize)
            {
                var sw = Stopwatch.StartNew();
                using (var ctx = buildCtx())
                {
                    for (int j = i; j < i + batchSize; j++)
                        ctx.Entities.Add(entities[j]);
                    ctx.SaveChanges();
                }
                sw.Stop();
                batchTimes.Add(sw);
            }

            batchTimes.ForEach(sw => Console.Out.WriteLine("Elapsed ms: " + 
                sw.ElapsedMilliseconds));
        }

        private MyContext buildCtx()
        {
            var cs = "Data Source=your db server;" +
                    "Initial Catalog=your db;" +
                    "Persist Security Info=True;" +
                    "User ID=your user;" + 
                    "Password=your pwd";
            var ctx = new MyContext(cs);
            //ctx.Configuration.ProxyCreationEnabled = false;
            return ctx;
        }

        private Entity1[] buildEntities(int count)
        {
            var entities = new Entity1[count];
            for (int i = 0; i < count; i++)
                entities[i] = new Entity1 { IntField = i, StrField = "str" + i, 
                    DateField = DateTimeOffset.UtcNow };
            return entities;
        }
    }
}
Community
  • 1
  • 1
esegura
  • 473
  • 4
  • 12
  • Can you exaggerate the problem by increasing the batch size? That might allow you to break in the debugger. You could also start a timer after each batch calling Debugger.Break after 8s into the batch. – usr Sep 02 '12 at 21:20
  • Also run SQL Profiler to see if the spikes happen at the SQL level. Look at the duration column. – usr Sep 02 '12 at 21:20
  • 1
    I'm purposefully not attaching the debugger so I can make sure that is not a factor. Also, I did run Sql Profiler and all the inserts take '0' duration, and only one in a few dozens take more than '0' cpu (and only about '15' in that case). – esegura Sep 02 '12 at 21:33
  • did you change target framework version after adding ef 5 nuget package, or it was already 4.5 before that? – Goran Obradovic Sep 02 '12 at 21:34
  • Ok not attaching the debugger makes sense, but if you don't have any other ideas, I'd try it. You can first determine if the debugger changes behavior by comparing the two runs. You could also run a profiler. Or xperf to see if those spikes are GC events (very unlikely with that high duration). – usr Sep 02 '12 at 21:38
  • 3
    Looks like issue is on your computer. I just run your code and except the first batch which took about 8s I have all other batches running between 28-32ms. I'm using Resharper 7 as NUnit test runner. – Ladislav Mrnka Sep 02 '12 at 21:54
  • 1
    Could you time adding entities and saving changes separately? Maybe it'll give us more context. Adding entities to the context also performs some checks and I seem to remember they could get quite slow with a lot of entities attached to a context. The spikes could be (totally talking out of my a**, I'm sure) some buffer allocations once they're full or something like that. – Alex Paven Sep 02 '12 at 23:28
  • 1
    Use SQL Profiler to determine if the spikes are resulting from the database. If so, check to see if the SQL generated is the same. If it is not the same, then post the results here, and we'll go from there. – An00bus Jan 04 '13 at 23:17

1 Answers1

1

I have a feeling you are running into an issue with deadlocking in your DB. EF places all saveChanges() calls in a transaction. By default, transactions in SQL Server run as Read Committed which is highly restrictive. Perhaps you can try changing the isolation level as so:

 using (var scope = new TransactionScope(TransactionScopeOption.Required, new 
 2: TransactionOptions { IsolationLevel= IsolationLevel.Snapshot }))
 3: {
 4: // do something with EF here
 5: scope.Complete();
 6: }
Scott Stevens
  • 390
  • 1
  • 7