La operación asincrónica de Entity Framework tarda diez veces más en completarse

Tengo un sitio MVC que usa Entity Framework 6 para manejar la base de datos, y he estado experimentando con cambiarlo para que todo se ejecute como controladores asíncronos y las llamadas a la base de datos se ejecuten como sus contrapartes asíncronas (por ejemplo, ToListAsync () en lugar de ToList ())

El problema que tengo es que simplemente cambiar mis consultas a asíncrono ha provocado que sean increíblemente lentas.

El siguiente código obtiene una colección de objetos "Álbum" de mi contexto de datos y se traduce en una unión de base de datos bastante simple:

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

Aquí está el SQL que se crea:

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

Tal como están las cosas, no es una consulta enormemente complicada, pero el servidor SQL tarda casi 6 segundos en ejecutarla. SQL Server Profiler informa que tarda 5742 ms en completarse.

Si cambio mi código a:

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

Luego se genera exactamente el mismo SQL, pero esto se ejecuta en solo 474 ms según el SQL Server Profiler.

La base de datos tiene alrededor de 3500 filas en la tabla "Álbumes", que en realidad no son muchas, y tiene un índice en la columna "Artist_ID", por lo que debería ser bastante rápido.

Sé que async tiene gastos generales, ¡pero hacer que las cosas funcionen diez veces más lento me parece un poco caro! ¿Dónde me estoy equivocando aquí?

Encontré esta pregunta muy interesante, especialmente porque la estoy usando en asynctodas partes con Ado.Net y EF 6. Esperaba que alguien me diera una explicación, pero no sucedió. Así que intenté reproducir este problema de mi lado. Espero que algunos de ustedes lo encuentren interesante.

Primeras buenas noticias: lo reproduje :) Y la diferencia es enorme. Con un factor 8 ...

Primero sospechaba algo relacionado con esto CommandBehavior, ya que leí un artículo interesante sobre asyncAdo y decía esto:

"Dado que el modo de acceso no secuencial tiene que almacenar los datos para toda la fila, puede causar problemas si está leyendo una columna grande del servidor (como varbinary (MAX), varchar (MAX), nvarchar (MAX) o XML ) ".

Sospechaba que las ToList()llamadas eran CommandBehavior.SequentialAccessy las asíncronas eran CommandBehavior.Default(no secuenciales, lo que puede causar problemas). Así que descargué las fuentes de EF6 y puse puntos de interrupción en todas partes ( CommandBehaviordonde se usó, por supuesto).

Resultado: nada . Todas las llamadas se hacen con CommandBehavior.Default... Así que traté de entrar en el código EF para entender lo que sucede ... y ... ooouch ... Nunca veo un código tan delegante, todo parece perezoso ejecutado ...

Así que traté de hacer algunos perfiles para entender lo que sucede ...

Y creo que tengo algo ...

Aquí está el modelo para crear la tabla que comparé, con 3500 líneas dentro de ella y datos aleatorios de 256 Kb en cada uno 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; }
}

Y aquí está el código que usé para crear los datos de prueba, y el punto de referencia 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 la llamada EF normal ( .ToList()), el perfil parece "normal" y es fácil de leer:

Aquí encontramos los 8.4 segundos que tenemos con el cronómetro (el perfil ralentiza los resultados). También encontramos HitCount = 3500 a lo largo de la ruta de llamada, que es consistente con las 3500 líneas en la prueba. En el lado del analizador TDS, las cosas comienzan a empeorar ya que leemos 118 353 llamadas en el TryReadByteArray()método, que es donde ocurre el bucle de almacenamiento en búfer. (un promedio de 33.8 llamadas por cada byte[]256kb)

Para el asynccaso, es realmente muy diferente ... Primero, la .ToListAsync()llamada se programa en ThreadPool y luego se espera. Nada asombroso aquí. Pero, ahora, aquí está el asyncinfierno en ThreadPool:

Primero, en el primer caso teníamos solo 3500 recuentos de visitas a lo largo de la ruta de llamada completa, aquí tenemos 118 371. Además, debes imaginar todas las llamadas de sincronización que no puse en la captura de pantalla ...

En segundo lugar, en el primer caso, teníamos "solo 118 353" llamadas al TryReadByteArray()método, ¡aquí tenemos 2 050 210 llamadas! Es 17 veces más ... (en una prueba con una gran matriz de 1Mb, es 160 veces más)

Además hay:

• 120 000 Taskinstancias creadas
• 727519 Interlockedllamadas
• 290 569 Monitorllamadas
• 98 283 ExecutionContextinstancias, con 264 481 capturas
• 208 733 SpinLockllamadas

Supongo que el almacenamiento en búfer se realiza de forma asíncrona (y no es buena), con Tareas paralelas que intentan leer datos del TDS. Se crean demasiadas tareas solo para analizar los datos binarios.

Como conclusión preliminar, podemos decir que Async es excelente, EF6 es excelente, pero los usos de EF6 de asíncrona en su implementación actual agrega una sobrecarga importante, en el lado del rendimiento, el lado de subprocesos y el lado de la CPU (12% de uso de CPU en el ToList()caso y 20% en el ToListAsynccaso para un trabajo de 8 a 10 veces más largo ... lo ejecuto en un viejo i7 920).

Mientras hacía algunas pruebas, estaba pensando en este artículo nuevamente y noto algo que extraño:

"Para los nuevos métodos asincrónicos en .Net 4.5, su comportamiento es exactamente el mismo que con los métodos síncronos, excepto por una notable excepción: ReadAsync en modo no secuencial".

Qué ?!!!

Así que extiendo mis puntos de referencia para incluir Ado.Net en llamadas regulares / asíncronas, y con CommandBehavior.SequentialAccess/ CommandBehavior.Default, ¡y aquí hay una gran sorpresa! :

Tenemos exactamente el mismo comportamiento con Ado.Net !!! Facepalm ...

Mi conclusión definitiva es : hay un error en la implementación de EF 6. Debe alternar CommandBehaviora SequentialAccesscuando se realiza una llamada asincrónica sobre una tabla que contiene una binary(max)columna. El problema de crear demasiadas Tareas, ralentizar el proceso, está en el lado de Ado.Net. El problema de EF es que no usa Ado.Net como debería.

Ahora sabe que en lugar de utilizar los métodos asíncronos EF6, será mejor que llame a EF de una manera no asíncrona regular y luego use a TaskCompletionSource<T>para devolver el resultado de forma asíncrona.

Nota 1: edité mi publicación debido a un error vergonzoso ... Hice mi primera prueba en la red, no localmente, y el ancho de banda limitado ha distorsionado los resultados. Aquí están los resultados actualizados.

Nota 2: No extendí mi prueba a otros casos de uso (por ejemplo, nvarchar(max)con muchos datos), pero hay posibilidades de que ocurra el mismo comportamiento.

Nota 3: Algo habitual para el ToList()caso, es el 12% de CPU (1/8 de mi CPU = 1 núcleo lógico). Algo inusual es el máximo del 20% para el ToListAsync()caso, como si el Programador no pudiera usar todas las pisadas. Probablemente se deba a la demasiada Tarea creada, o tal vez a un cuello de botella en el analizador TDS, no lo sé ...

Debido a que recibí un enlace a esta pregunta hace un par de días, decidí publicar una pequeña actualización. Pude reproducir los resultados de la respuesta original utilizando, actualmente, la versión más reciente de EF (6.4.0) y .NET Framework 4.7.2. Sorprendentemente, este problema nunca mejoró.

.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

Esto planteó la pregunta: ¿hay una mejora en el núcleo dotnet?

Copié el código de la respuesta original a un nuevo proyecto dotnet core 3.1.3 y agregué EF Core 3.1.3. Los resultados son:

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

Sorprendentemente, hay muchas mejoras. Todavía parece haber algún retraso debido a que se llama al conjunto de subprocesos pero es aproximadamente 3 veces más rápido que la implementación de .NET Framework.

Espero que esta respuesta ayude a otras personas que se envíen de esta manera en el futuro.