El funcionamiento asincrónico de Entity Framework tarda diez veces más en completarse

Tengo un sitio de MVC que está utilizando 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 estoy teniendo es que el simple hecho de cambiar mis consultas a async ha hecho que sean increíblemente lentos.

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 creó:

 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 complicada, pero el servidor SQL tardará casi 6 segundos en ejecutarla. El Analizador de SQL Server informa que tarda 5742ms 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, sin embargo, esto se ejecuta en solo 474ms de acuerdo con 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 “ID de artista”, por lo que debería ser bastante rápido.

Sé que la sincronización tiene gastos generales, pero hacer que las cosas vayan diez veces más lento me parece un poco abrupto. ¿Dónde me estoy equivocando aquí?

Encontré esta pregunta muy interesante, especialmente porque estoy usando async todas partes con Ado.Net y EF 6. Esperaba que alguien me diera una explicación para esta pregunta, pero no sucede. Así que traté de reproducir este problema de mi lado. Espero que algunos de ustedes encuentren esto interesante.

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

primeros resultados

Primero estaba sospechando algo relacionado con CommandBehavior , ya que leí un artículo interesante sobre async con Ado, diciendo 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 ToList() llama a CommandBehavior.SequentialAccess y async para ser CommandBehavior.Default (no secuencial, lo que puede causar problemas). Así que descargué las fonts de EF6 y ubiqué puntos de interrupción en todas partes (donde CommandBehavior 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 de delegado, 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 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 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 utilicé para crear los datos de prueba y el benchmark 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 itemsWithAdo = new List(); 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 itemsWithAdo = new List(); 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 itemsWithAdo = new List(); 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 itemsWithAdo = new List(); 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 perfilado parece “normal” y es fácil de leer:

ToList trace

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

Para el caso async , es realmente muy diferente … Primero, la llamada .ToListAsync() está progtwigda en ThreadPool, y luego esperada. Nada sorprendente aquí. Pero, ahora, aquí está el infierno de asincronización en ThreadPool:

ToListAsync infierno

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

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

Además hay:

  • 120 000 instancias de Task creadas
  • 727 519 llamadas Interlocked
  • 290 569 Monitor llamadas
  • 98 283 instancias de ExecutionContext , con 264 481 Captures
  • 208 733 llamadas SpinLock

Mi suposición es que el almacenamiento en búfer se realiza de forma asíncrona (y no una buena), con tareas paralelas que intentan leer datos del TDS. Demasiadas tareas se crean solo para analizar los datos binarios.

Como conclusión preliminar, podemos decir que Async es genial, EF6 es genial, pero los usos de asincronización de EF6 en su implementación actual agregan una sobrecarga importante en el lado del rendimiento, el lado de Subprocesamiento y el lado de la CPU (12% de uso de CPU en el ToList() caso ToList() y el 20% en el caso de ToListAsync para un trabajo de 8 a 10 veces más largo … Lo ejecuto en un viejo i7 920).

Mientras realizo algunas pruebas, estaba pensando en este artículo nuevamente y noté algo que extraño:

“Para los nuevos métodos asíncronos en .Net 4.5, su comportamiento es exactamente el mismo que con los métodos sincrónicos, excepto por una excepción notable: 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! :

con adoración

¡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 CommandBehavior a SequentialAccess cuando se realiza una llamada asincrónica en una tabla que contiene una columna binary(max) . El problema de crear demasiadas Tareas, ralentizando el proceso, está en el lado Ado.Net. El problema de EF es que no usa Ado.Net como debería.

Ahora ya sabes, en lugar de utilizar los métodos asincrónicos EF6, será mejor que tengas que llamar a EF de una manera regular que no sea asincrónica, y luego usar TaskCompletionSource para devolver el resultado de una manera asíncrona.

Nota 1: edité mi publicación debido a un error vergonzoso … He hecho 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 caso ToList() es la CPU del 12% (1/8 de mi CPU = 1 núcleo lógico). Algo inusual es el máximo 20% para el caso ToListAsync() , como si el Progtwigdor no pudiera usar todas las Botas. Probablemente se deba a la demasiada tarea creada, o tal vez a un cuello de botella en el analizador TDS, no sé …