A operação assíncrona do Entity Framework leva dez vezes mais para ser concluída

Eu tenho um site MVC que usa o Entity Framework 6 para manipular o banco de dados e estou experimentando alterá-lo para que tudo seja executado como controladores assíncronos e as chamadas ao banco de dados sejam executadas como suas contrapartes assíncronas (por exemplo, ToListAsync () em vez de ToList ())

O problema que estou enfrentando é que simplesmente alterar minhas consultas para assíncronas fez com que elas fossem incrivelmente lentas.

O código a seguir obtém uma coleção de objetos "Álbum" do meu contexto de dados e é traduzido para uma junção ao banco de dados bastante simples:

// Get the albums
var albums = await this.context.Albums
    .Where(x => x.Artist.ID == artist.ID)
    .ToListAsync();

Aqui está o SQL criado:

exec sp_executesql N'SELECT 
[Extent1].[ID] AS [ID], 
[Extent1].[URL] AS [URL], 
[Extent1].[ASIN] AS [ASIN], 
[Extent1].[Title] AS [Title], 
[Extent1].[ReleaseDate] AS [ReleaseDate], 
[Extent1].[AccurateDay] AS [AccurateDay], 
[Extent1].[AccurateMonth] AS [AccurateMonth], 
[Extent1].[Type] AS [Type], 
[Extent1].[Tracks] AS [Tracks], 
[Extent1].[MainCredits] AS [MainCredits], 
[Extent1].[SupportingCredits] AS [SupportingCredits], 
[Extent1].[Description] AS [Description], 
[Extent1].[Image] AS [Image], 
[Extent1].[HasImage] AS [HasImage], 
[Extent1].[Created] AS [Created], 
[Extent1].[Artist_ID] AS [Artist_ID]
FROM [dbo].[Albums] AS [Extent1]
WHERE [Extent1].[Artist_ID] = @p__linq__0',N'@p__linq__0 int',@p__linq__0=134

No momento, não é uma consulta extremamente complicada, mas leva quase 6 segundos para o SQL Server executá-la. O SQL Server Profiler relata que está levando 5742ms para ser concluído.

Se eu mudar meu código para:

// Get the albums
var albums = this.context.Albums
    .Where(x => x.Artist.ID == artist.ID)
    .ToList();

Em seguida, o mesmo SQL é gerado, mas ele é executado em apenas 474ms, de acordo com o SQL Server Profiler.

O banco de dados possui cerca de 3500 linhas na tabela "Álbuns", que na verdade não são muitas, e possui um índice na coluna "Artist_ID", portanto deve ser bem rápido.

Eu sei que o assíncrono tem custos indiretos, mas tornar as coisas dez vezes mais lentas me parece um pouco íngreme! Onde estou errado aqui?

Achei essa pergunta muito interessante, principalmente porque estou usando em asynctodos os lugares o Ado.Net e o EF 6. Esperava que alguém desse uma explicação para essa pergunta, mas isso não aconteceu. Então, eu tentei reproduzir esse problema do meu lado. Espero que alguns de vocês achem isso interessante.

Primeira boa notícia: eu a reproduzi :) E a diferença é enorme. Com um fator 8 ...

Primeiro, eu suspeitava de algo relacionado CommandBehavior, pois li um artigo interessante sobre o asyncAdo, dizendo o seguinte:

"Como o modo de acesso não sequencial precisa armazenar os dados para toda a linha, isso pode causar problemas se você estiver lendo uma coluna grande do servidor (como varbinary (MAX), varchar (MAX), nvarchar (MAX) ou XML ). "

Eu suspeitava ToList()que fossem chamadas CommandBehavior.SequentialAccessassíncronas CommandBehavior.Default(não sequenciais, o que pode causar problemas). Então eu baixei as fontes do EF6 e coloquei pontos de interrupção em todos os lugares ( CommandBehavioronde usados, é claro).

Resultado: nada . Todas as chamadas são feitas com CommandBehavior.Default.... Então, eu tentei entrar no código EF para entender o que acontece ... e ... ooouch ... Eu nunca vejo esse código de delegação, tudo parece executado com preguiça ...

Então eu tentei fazer alguns perfis para entender o que acontece ...

E acho que tenho algo ...

Aqui está o modelo para criar a tabela que eu comparou, com 3500 linhas dentro dela e dados aleatórios de 256 Kb em cada uma 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; }
}

E aqui está o código que eu usei para criar os dados de teste e comparar a 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);
    }
}

Para a chamada EF normal ( .ToList()), o perfil parece "normal" e é fácil de ler:

Aqui encontramos os 8,4 segundos que temos com o cronômetro (a criação de perfil diminui o desempenho). Também encontramos HitCount = 3500 no caminho da chamada, o que é consistente com as 3500 linhas no teste. No lado do analisador TDS, as coisas começam a piorar desde que lemos as chamadas no TryReadByteArray()método, que é onde ocorre o loop de buffer. (uma média de 33,8 chamadas para cada um byte[]dos 256kb)

Para o asynccaso, é realmente muito diferente ... Primeiro, a .ToListAsync()chamada é agendada no ThreadPool e depois aguardada. Nada incrível aqui. Mas agora, aqui está o asyncinferno no ThreadPool:

Primeiro, no primeiro caso, tínhamos apenas 3500 contagens de hits ao longo do caminho completo da chamada, aqui temos 118 371. Além disso, você deve imaginar todas as chamadas de sincronização que não fiz na sessão de tela ...

Segundo, no primeiro caso, estávamos tendo "apenas 118 353" chamadas para o TryReadByteArray()método, aqui temos 2 050 210 chamadas! É 17 vezes mais ... (em um teste com uma grande matriz de 1Mb, é 160 vezes mais)

Além disso, existem:

• 120 000 Taskinstâncias criadas
• 727 519 Interlockedchamadas
• 290 569 Monitorchamadas
• 98 283 ExecutionContextinstâncias, com 264 481 capturas
• 208 733 SpinLockchamadas

Meu palpite é que o buffer é feito de maneira assíncrona (e não boa), com tarefas paralelas tentando ler dados do TDS. Muitas tarefas são criadas apenas para analisar os dados binários.

Como conclusão preliminar, podemos dizer que o Async é ótimo, o EF6 é ótimo, mas o uso de assíncrono do EF6 em sua implementação atual acrescenta uma grande sobrecarga, no lado do desempenho, no lado do Threading e no lado da CPU (12% de uso da CPU no ToList()caso e 20% no ToListAsynccaso de um trabalho de 8 a 10 vezes mais ... eu corro em um i7 920 antigo).

Enquanto fazia alguns testes, eu estava pensando neste artigo novamente e noto algo que sinto falta:

"Para os novos métodos assíncronos no .Net 4.5, o comportamento deles é exatamente o mesmo dos métodos síncronos, exceto por uma exceção notável: ReadAsync no modo não sequencial".

O que ?!!!

Então, estendo meus benchmarks para incluir o Ado.Net em chamadas regulares / assíncronas e com CommandBehavior.SequentialAccess/ CommandBehavior.Default, e aqui está uma grande surpresa! :

Temos exatamente o mesmo comportamento com o Ado.Net !!! Facepalm ...

Minha conclusão definitiva é : há um erro na implementação do EF 6. Ele deve alternar CommandBehaviorpara SequentialAccessquando uma chamada assíncrona é feita sobre uma tabela que contém uma binary(max)coluna. O problema de criar muitas tarefas, retardando o processo, está no lado do Ado.Net. O problema da EF é que ele não usa o Ado.Net como deveria.

Agora você sabe que, em vez de usar os métodos assíncronos EF6, seria melhor chamar EF de maneira não assíncrona regular e, em seguida, usar a TaskCompletionSource<T>para retornar o resultado de maneira assíncrona.

Nota 1: editei minha postagem devido a um erro vergonhoso ... fiz meu primeiro teste pela rede, não localmente, e a largura de banda limitada distorceu os resultados. Aqui estão os resultados atualizados.

Nota 2: Eu não estendi meu teste para outros casos de uso (ex: nvarchar(max)com muitos dados), mas há chances de o mesmo comportamento acontecer.

Nota 3: Algo comum para o ToList()caso, é a CPU de 12% (1/8 da minha CPU = 1 núcleo lógico). Algo incomum é o máximo de 20% para o ToListAsync()caso, como se o Agendador não pudesse usar todos os Treads. Provavelmente é devido às muitas tarefas criadas, ou talvez a um gargalo no analisador TDS, não sei ...

Como recebi um link para essa pergunta há alguns dias, decidi postar uma pequena atualização. Consegui reproduzir os resultados da resposta original usando a atual versão mais recente do EF (6.4.0) e do .NET Framework 4.7.2. Surpreendentemente, esse problema nunca foi aprimorado.

.NET Framework 4.7.2 | EF 6.4.0 (Values in ms. Average of 10 runs)

non async : 3016
async : 20415
ExecuteReaderAsync SequentialAccess : 2780
ExecuteReaderAsync Default : 21061
ExecuteReader SequentialAccess : 3467
ExecuteReader Default : 3074

Isso gerou a pergunta: Existe uma melhoria no núcleo do dotnet?

Copiei o código da resposta original para um novo projeto do dotnet core 3.1.3 e adicionei o EF Core 3.1.3. Os resultados são:

dotnet core 3.1.3 | EF Core 3.1.3 (Values in ms. Average of 10 runs)

non async : 2780
async : 6563
ExecuteReaderAsync SequentialAccess : 2593
ExecuteReaderAsync Default : 6679
ExecuteReader SequentialAccess : 2668
ExecuteReader Default : 2315

Surpreendentemente, há muitas melhorias. Ainda parece haver algum atraso, porque o pool de threads é chamado, mas é cerca de três vezes mais rápido que a implementação do .NET Framework.

Espero que esta resposta ajude outras pessoas que são enviadas dessa maneira no futuro.