Creating instance of Entity Framework Context slows down under load

Question

We noticed that some very small web service calls were taking much longer than we expected. We did some investigation and put some timers in place and we narrowed it down to creating an instance of our Entity Framework 6 DbContext. Not the query itself, just the creation of the context. I've since put some logging to see on average how long it actually takes to create an instance of our DbContext and it seems it was around 50ms.

After the application is warmed up context creation is not slow. After an app recycle it starts out at 2-4ms (which is what we see in our dev environments). Context creation seems to slow down over time. Over the next couple hours it will creep up to the 50-80ms range and level off.

Our context is a fairly large code-first context with around 300 entities - including some pretty complex relationships between some of the entities. We are running EF 6.1.3. We are doing a "one context per request", but for most of our web API calls it's only doing one or two queries. Creating a context taking 60+ms, and then execute a 1ms query is a bit dissatisfying. We have about 10k requests per minute, so we aren't a lightly used site.

Here is a snapshot of what we see. Times are in MS, the big dip is a deploy which recycled the app domain. Each line is one of 4 different web servers. Notice it's not always the same server either.

I did take a memory dump to try and flesh out what's going on and here is the heap stats:

00007ffadddd1d60    70821      2266272 System.Reflection.Emit.GenericFieldInfo
00007ffae02e88a8    29885      2390800 System.Linq.Enumerable+WhereSelectListIterator`2[[NewRelic.Agent.Core.WireModels.MetricDataWireModel, NewRelic.Agent.Core],[System.Single, mscorlib]]
00007ffadda7c1a0     1462      2654992 System.Collections.Concurrent.ConcurrentDictionary`2+Node[[System.Object, mscorlib],[System.Object, mscorlib]][]
00007ffadd4eccf8    83298      2715168 System.RuntimeType[]
00007ffadd4e37c8    24667      2762704 System.Reflection.Emit.DynamicMethod
00007ffadd573180    30013      3121352 System.Web.Caching.CacheEntry
00007ffadd2dc5b8    35089      3348512 System.String[]
00007ffadd6734b8    35233      3382368 System.RuntimeMethodInfoStub
00007ffadddbf0a0    24667      3749384 System.Reflection.Emit.DynamicILGenerator
00007ffae04491d8    67611      4327104 System.Data.Entity.Core.Metadata.Edm.MetadataProperty
00007ffadd4edaf0    57264      4581120 System.Signature
00007ffadd4dfa18   204161      4899864 System.RuntimeMethodHandle
00007ffadd4ee2c0    41900      5028000 System.Reflection.RuntimeParameterInfo
00007ffae0c9e990    21560      5346880 System.Data.SqlClient._SqlMetaData
00007ffae0442398    79504      5724288 System.Data.Entity.Core.Metadata.Edm.TypeUsage
00007ffadd432898    88807      8685476 System.Int32[]
00007ffadd433868     9985      9560880 System.Collections.Hashtable+bucket[]
00007ffadd4e3160    92105     10315760 System.Reflection.RuntimeMethodInfo
00007ffadd266668   493622     11846928 System.Object
00007ffadd2dc770    33965     16336068 System.Char[]
00007ffadd26bff8   121618     17335832 System.Object[]
00007ffadd2df8c0   168529     68677312 System.Byte[]
00007ffadd2d4d08   581057    127721734 System.String
0000019cf59e37d0   166894    143731666      Free
Total 5529765 objects
Fragmented blocks larger than 0.5 MB:
            Addr     Size      Followed by
0000019ef63f2140    2.9MB 0000019ef66cfb40 Free
0000019f36614dc8    2.8MB 0000019f368d6670 System.Data.Entity.Core.Query.InternalTrees.SimpleColumnMap[]
0000019f764817f8    0.8MB 0000019f76550768 Free
0000019fb63a9ca8    0.6MB 0000019fb644eb38 System.Data.Entity.Core.Common.Utils.Set`1[[System.Data.Entity.Core.Metadata.Edm.EntitySet, EntityFramework]]
000001a0f6449328    0.7MB 000001a0f64f9b48 System.String
000001a0f65e35e8    0.5MB 000001a0f666e2a0 System.Collections.Hashtable+bucket[]
000001a1764e8ae0    0.7MB 000001a17659d050 System.RuntimeMethodHandle
000001a3b6430fd8    0.8MB 000001a3b6501aa0 Free
000001a4f62c05c8    0.7MB 000001a4f636e8a8 Free
000001a6762e2300    0.6MB 000001a676372c38 System.String
000001a7761b5650    0.6MB 000001a776259598 System.String
000001a8763c4bc0    2.3MB 000001a8766083a8 System.String
000001a876686f48    1.4MB 000001a8767f9178 System.String
000001a9f62adc90    0.7MB 000001a9f63653c0 System.String
000001aa362b8220    0.6MB 000001aa36358798 Free

That seems like quite a bit of metadata and typeusage.

Things we've tried:

1. Creating a simple test harness to replicate. It failed, my guess is because we weren't varying traffic, or varying the type of queries run. Just loading the context and executing a couple queries over and over didn't result in the timing increase.
2. We've reduced the context significantly, it was 500 entities, now 300. Didn't make a difference in speed. My guess is because we weren't using those 200 entities at all.
3. (Edit) We use SimpleInjector to create our "context per request". To validate it isn't SimpleInjector I have spun up an instance of the Context by just new'in it up. Same slow create times.
4. (Edit) We have ngen'd EF. Didn't make any impact.

What can we investigate further? I understand the cache used by EF is extensive to speed things up. Does more things in the cache, slow down the context creation? Is there a way to see exactly what's in that cache to flesh out any weird things in there? Does anyone know what specifically we can do to speed up context creation?

Update - 5/30/17

I took the EF6 source and compiled our own version to stick in some timings. We run a pretty popular site so collecting huge amount of timing info is tricky and I didn't get as far as I wanted, but basically we found that all of the slowdown is coming from this method

public void ForceOSpaceLoadingForKnownEntityTypes()
    {
        if (!_oSpaceLoadingForced)
        {
            // Attempting to get o-space data for types that are not mapped is expensive so
            // only try to do it once.
            _oSpaceLoadingForced = true;

            Initialize();
            foreach (var set in _genericSets.Values.Union(_nonGenericSets.Values))
            {
                set.InternalSet.TryInitialize();
            }
        }
    }

Each iteration of that foreach hits for each one of the entities defined by a DBSet in our context. Each iteration is relatively short .1-.3 ms, but when you add in the 254 entities we had it adds up. We still haven't figured out why it's fast at the beginning and slows down.

Answer 1

Here is where I would start to solving the problem, sans moving to a more enterprise friendly solution.

Our context is a fairly large code-first context with around 300 entities  

While EF has greatly improved over time, I still would start seriously looking at chopping things up once you get to 100 entities (actually I would start well before that, but that seems to be a magic number many people have stated - concensus?). Think of it as designing for "contexts", but use the word "domain" instead? That way you can sell your execs that you are applying "domain driven design" to fix the application? Maybe you are designing for future "microservices", then you use two buzz words in a single paragraph. ;-)

I am not a huge fan of EF in the Enterprise space, so I tend to avoid it for high scale or high performance applications. Your mileage may vary. For SMB, it is probably perfectly fine. I do run into clients that use it, however.

I am not sure the following ideas are completely up to date, but they are some other things I would consider, based on experience.

• Pre-gen your views. They are the most expensive part of the query. This will help even more with large models.
• Move your model to a separate assembly. Not so much a perf thing than a pet peeve of mine in code organization.
• Examine your application, model, for caching possibilities. Query plan caching can often shave quite a bit of time off.
• Use CompileQuery.
• When feasible, use NoTracking. This is a huge savings, if you do not need the feature.

It looks like you are already running some type of profiler on the application, so I am going to assume you also looked at your SQL queries and possible performance gains. Yes, I know that is not the problem you are looking to solve, but it is something that can contribute to the entire issue from the user perspective.

In response to @WiktorZichia's comment about not answering the question about the performance problem, the best way to get rid of these types of problems in an Enterprise System is to get rid of Entity Framework. There are trade offs in every decision. EF is a great abstraction and speeds up development. But it comes with some unnecessary overhead that can hurt systems at scale. Now, technically, I still did not answer the "how do I solve this problem they way I am trying to solve it" question, so this might still be seen as a fail.