title: Creating instance of Entity Framework Context slows down under load
body: <p>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. </p>
  
  <p>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. </p>
  
  <p>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. </p>
  
  <p>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. </p>
  
  <p><a href="https://i.stack.imgur.com/s9PwI.png" rel="nofollow noreferrer"><img src="https://i.stack.imgur.com/s9PwI.png" alt="enter image description here"></a></p>
  
  <p>I did take a memory dump to try and flesh out what's going on and here is the heap stats:</p>
  
  <pre><code>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
  </code></pre>
  
  <p>That seems like quite a bit of metadata and typeusage. </p>
  
  <p>Things we've tried: </p>
  
  <ol>
  <li>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. </li>
  <li>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. </li>
  <li>(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. </li>
  <li>(Edit) We have ngen'd EF. Didn't make any impact. </li>
  </ol>
  
  <p>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?</p>
  
  <p><strong>Update - 5/30/17</strong> </p>
  
  <p>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 <a href="https://github.com/aspnet/EntityFramework6/blob/master/src/EntityFramework/Internal/InternalContext.cs#L1307" rel="nofollow noreferrer">this method</a></p>
  
  <pre><code>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();
              }
          }
      }
  </code></pre>
  
  <p>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.</p>