Асинхронная операция Entity Framework занимает в десять раз больше времени

Ответ 1

Я нашел этот вопрос очень интересным, тем более, что я использую async везде с Ado.Net и EF 6. Я надеялся, что кто-то объяснит этот вопрос, но этого не произошло. Поэтому я попытался воспроизвести эту проблему на моей стороне. Надеюсь, некоторые из вас найдут это интересным.

Первые хорошие новости: я воспроизвел это :) И разница огромна. С коэффициентом 8...

Сначала я подозревал что-то, что CommandBehavior, так как я прочитал интересную статью об async Ado, сказав следующее:

"Поскольку режим не последовательного доступа должен хранить данные для всей строки, это может вызвать проблемы, если вы читаете большой столбец с сервера (например, varbinary (MAX), varchar (MAX), nvarchar (MAX) или XML ) ".

Я подозревал, что ToList() вызывает CommandBehavior.SequentialAccess и async, которые должны быть CommandBehavior.Default (не последовательные, что может вызвать проблемы). Поэтому я загрузил источники EF6 и поставил точки останова везде (где, конечно, CommandBehavior).

Результат: ничего. Все вызовы сделаны с CommandBehavior.Default.... Поэтому я попытался войти в EF-код, чтобы понять, что происходит... и.. ooouch... Я никогда не вижу такой делегирующий код, все кажется ленивым исполненным...

Поэтому я попытался сделать некоторые профилирования, чтобы понять, что происходит...

И я думаю, что у меня есть что-то...

Здесь модель для создания таблицы, в которой я сравнивал, с 3500 строк внутри нее и 256 Кб случайных данных в каждой varbinary(MAX). (EF 6.1 - CodeFirst - CodePlex):

public class TestContext : DbContext
{
    public TestContext()
        : base(@"Server=(localdb)\\v11.0;Integrated Security=true;Initial Catalog=BENCH") // Local instance
    {
    }
    public DbSet<TestItem> Items { get; set; }
}

public class TestItem
{
    public int ID { get; set; }
    public string Name { get; set; }
    public byte[] BinaryData { get; set; }
}

И вот код, который я использовал для создания тестовых данных, и бенчмарк EF.

using (TestContext db = new TestContext())
{
    if (!db.Items.Any())
    {
        foreach (int i in Enumerable.Range(0, 3500)) // Fill 3500 lines
        {
            byte[] dummyData = new byte[1 << 18];  // with 256 Kbyte
            new Random().NextBytes(dummyData);
            db.Items.Add(new TestItem() { Name = i.ToString(), BinaryData = dummyData });
        }
        await db.SaveChangesAsync();
    }
}

using (TestContext db = new TestContext())  // EF Warm Up
{
    var warmItUp = db.Items.FirstOrDefault();
    warmItUp = await db.Items.FirstOrDefaultAsync();
}

Stopwatch watch = new Stopwatch();
using (TestContext db = new TestContext())
{
    watch.Start();
    var testRegular = db.Items.ToList();
    watch.Stop();
    Console.WriteLine("non async : " + watch.ElapsedMilliseconds);
}

using (TestContext db = new TestContext())
{
    watch.Restart();
    var testAsync = await db.Items.ToListAsync();
    watch.Stop();
    Console.WriteLine("async : " + watch.ElapsedMilliseconds);
}

using (var connection = new SqlConnection(CS))
{
    await connection.OpenAsync();
    using (var cmd = new SqlCommand("SELECT ID, Name, BinaryData FROM dbo.TestItems", connection))
    {
        watch.Restart();
        List<TestItem> itemsWithAdo = new List<TestItem>();
        var reader = await cmd.ExecuteReaderAsync(CommandBehavior.SequentialAccess);
        while (await reader.ReadAsync())
        {
            var item = new TestItem();
            item.ID = (int)reader[0];
            item.Name = (String)reader[1];
            item.BinaryData = (byte[])reader[2];
            itemsWithAdo.Add(item);
        }
        watch.Stop();
        Console.WriteLine("ExecuteReaderAsync SequentialAccess : " + watch.ElapsedMilliseconds);
    }
}

using (var connection = new SqlConnection(CS))
{
    await connection.OpenAsync();
    using (var cmd = new SqlCommand("SELECT ID, Name, BinaryData FROM dbo.TestItems", connection))
    {
        watch.Restart();
        List<TestItem> itemsWithAdo = new List<TestItem>();
        var reader = await cmd.ExecuteReaderAsync(CommandBehavior.Default);
        while (await reader.ReadAsync())
        {
            var item = new TestItem();
            item.ID = (int)reader[0];
            item.Name = (String)reader[1];
            item.BinaryData = (byte[])reader[2];
            itemsWithAdo.Add(item);
        }
        watch.Stop();
        Console.WriteLine("ExecuteReaderAsync Default : " + watch.ElapsedMilliseconds);
    }
}

using (var connection = new SqlConnection(CS))
{
    await connection.OpenAsync();
    using (var cmd = new SqlCommand("SELECT ID, Name, BinaryData FROM dbo.TestItems", connection))
    {
        watch.Restart();
        List<TestItem> itemsWithAdo = new List<TestItem>();
        var reader = cmd.ExecuteReader(CommandBehavior.SequentialAccess);
        while (reader.Read())
        {
            var item = new TestItem();
            item.ID = (int)reader[0];
            item.Name = (String)reader[1];
            item.BinaryData = (byte[])reader[2];
            itemsWithAdo.Add(item);
        }
        watch.Stop();
        Console.WriteLine("ExecuteReader SequentialAccess : " + watch.ElapsedMilliseconds);
    }
}

using (var connection = new SqlConnection(CS))
{
    await connection.OpenAsync();
    using (var cmd = new SqlCommand("SELECT ID, Name, BinaryData FROM dbo.TestItems", connection))
    {
        watch.Restart();
        List<TestItem> itemsWithAdo = new List<TestItem>();
        var reader = cmd.ExecuteReader(CommandBehavior.Default);
        while (reader.Read())
        {
            var item = new TestItem();
            item.ID = (int)reader[0];
            item.Name = (String)reader[1];
            item.BinaryData = (byte[])reader[2];
            itemsWithAdo.Add(item);
        }
        watch.Stop();
        Console.WriteLine("ExecuteReader Default : " + watch.ElapsedMilliseconds);
    }
}

Для обычного вызова EF (.ToList()) профилирование кажется "нормальным" и легко читается:

Здесь мы находим 8,4 секунды у нас с секундомером (профилирование замедляет функционал). Мы также находим HitCount = 3500 по пути вызова, что согласуется с 3500 строк в тесте. На стороне анализатора TDS все начинает ухудшаться, поскольку мы читаем 118 353 вызовов TryReadByteArray(), который представляет собой цикл буферизации. (в среднем 33,8 вызова для каждого byte[] из 256 КБ)

Для async случая это действительно действительно отличается. Во-первых, на .ToListAsync() запланирован вызов .ToListAsync(), а затем ожидаемый. Ничего удивительного здесь. Но теперь, здесь async ад на ThreadPool:

Во-первых, в первом случае у нас было всего 3500 очков хитов по полному пути вызова, здесь у нас есть 118 371. Кроме того, вы должны представить все вызовы синхронизации, которые я не ставил на скриншоты...

Во-вторых, в первом случае у нас было "всего 118 353" вызовов метода TryReadByteArray(), здесь у нас есть 2 050 210 звонков! Это в 17 раз больше... (при тестировании с большим массивом 1 Мб, он в 160 раз больше)

Кроме того, есть:

• 120 000 Созданные экземпляры Task
• 727 519 Interlocked вызовы
• 290 569 Monitor вызовов
• 98 283 ExecutionContext экземпляры, с 264 481 Captures
• 208 733 звонки SpinLock

Я предполагаю, что буферизация выполняется асинхронным способом (а не хорошим), с параллельными задачами, пытающимися считывать данные из TDS. Слишком много задач создаются только для анализа двоичных данных.

Как предварительный вывод, мы можем сказать, что Async велик, EF6 велик, но EF6 использует асинхронную в нем текущую реализацию, добавляет основные накладные расходы, на стороне производительности, стороне Threading и стороне процессора (12% использования ЦП в ToList() и 20% в случае ToListAsync для работы в 8-10 раз больше... Я запускаю его на старом i7 920).

Пока делал несколько тестов, я снова думал об этой статье, и я замечаю что-то, чего я пропустил:

"Для новых асинхронных методов в.Net 4.5 их поведение точно такое же, как и с синхронными методами, за исключением одного заметного исключения: ReadAsync в несекретном режиме".

Какие?!!!

Поэтому я расширяю свои тесты, чтобы включить Ado.Net в обычный/асинхронный вызов, а также с CommandBehavior.SequentialAccess/CommandBehavior.Default, и здесь большой сюрприз! :

У нас такое же поведение с Ado.Net !!! Facepalm...

Мой окончательный вывод: есть ошибка в реализации EF 6. Он должен переключать CommandBehavior на SequentialAccess когда асинхронный вызов выполняется по таблице, содержащей binary(max) столбец. Проблема создания слишком большого количества задач, замедляющих процесс, находится на стороне Ado.Net. Проблема EF заключается в том, что он не использует Ado.Net, как должен.

Теперь вы знаете вместо использования асинхронных методов EF6, вам лучше будет вызывать EF обычным неасинхронным способом, а затем использовать TaskCompletionSource<T> чтобы вернуть результат асинхронным способом.

Примечание 1: я отредактировал свой пост из-за позорной ошибки.... Я сделал свой первый тест по сети, а не локально, и ограниченная полоса пропускания исказила результаты. Вот обновленные результаты.

Примечание 2: Я не расширил свой тест на другие случаи использования (например: nvarchar(max) с большим количеством данных), но есть вероятность, что такое же поведение происходит.

Примечание 3: Что-то обычное для ToList() - это 12% -ный процессор (1/8 моего CPU = 1 логического ядра). Что-то необычное - это максимум 20% для ToListAsync(), как если бы Планировщик не мог использовать все Протесты. Вероятно, из-за слишком большого количества созданных задач или, может быть, узкого места в парсере TDS, я не знаю...