Мы заметили, что некоторые очень маленькие вызовы веб-сервисов занимают гораздо больше времени, чем мы ожидали. Мы провели некоторое расследование и поставили некоторые таймеры, и мы сузили его, чтобы создать экземпляр нашего Entity Framework 6 DbContext. Не сам запрос, а просто создание контекста. С тех пор я несколько раз регистрировал журнал, чтобы узнать, сколько времени он действительно занимает, чтобы создать экземпляр нашего DbContext, и, похоже, он составлял около 50 мс.
После того как приложение разогревается, создание контекста не замедляется. После перезагрузки приложения он начинается с 2-4 мс (что мы видим в наших средах разработчиков). С течением времени создание контекста замедляется. В течение следующих двух часов он будет ползать до диапазона 50-80 мс и выровняться.
Наш контекст - довольно большой контекст кода с примерно 300 объектами, включая некоторые довольно сложные отношения между некоторыми объектами. Мы запускаем EF 6.1.3. Мы делаем "один контекст за запрос", но для большинства наших веб-API он вызывает только один или два запроса. Создание контекста, принимающего 60 + ms, а затем выполнение запроса 1 мс немного недовольство. У нас около 10 тыс. Запросов в минуту, поэтому мы не легко используем сайт.
Вот снимок того, что мы видим. Время в MS, большое падение - это развертывание, которое перерабатывает домен приложения. Каждая строка является одним из четырех разных веб-серверов. Обратите внимание, что это не всегда один и тот же сервер.
Я взял свалку памяти, чтобы попытаться выяснить, что происходит, и вот статистика кучи:
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
Это похоже на немного метаданных и typeusage.
Что мы пробовали:
- Создание простого тестового жгута для репликации. Это не удалось, я предполагаю, что мы не меняем трафик или меняем тип запросов. Просто загрузка контекста и выполнение нескольких запросов снова и снова не приводили к увеличению времени.
- Мы значительно сократили контекст, это было 500 объектов, теперь 300. Не изменили скорость. Я предполагаю, что мы не использовали эти 200 объектов вообще.
- (Edit) Мы используем SimpleInjector для создания нашего "контекста за запрос". Чтобы проверить, что это не SimpleInjector, я создал экземпляр контекста, просто обновив его. То же самое медленное время создания.
- (Edit) У нас есть ngen'd EF. Не оказал никакого влияния.
Что мы можем исследовать дальше? Я понимаю, что кеш, используемый EF, обширен, чтобы ускорить работу. Чем больше вещей в кеше замедляет создание контекста? Есть ли способ увидеть, что именно в этом кеше можно найти в каких-нибудь странных вещах? Кто-нибудь знает, что конкретно мы можем сделать, чтобы ускорить создание контекста?
Обновление - 5/30/17
Я взял источник EF6 и скомпилировал нашу собственную версию, чтобы придерживаться некоторых таймингов. Мы запускаем довольно популярный сайт, поэтому собирать огромное количество информации о времени сложно, и я не получил столько, сколько хотел, но в основном мы обнаружили, что все замедление происходит от этот метод
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();
}
}
}
Каждая итерация этого foreach попадает для каждого из объектов, определенных DBSet в нашем контексте. Каждая итерация относительно короткая .1-.3 мс, но когда вы добавляете в 254 сущности, которые у нас есть, она складывается. Мы до сих пор не выяснили, почему это быстро в начале и замедляется.
