L'opération asynchrone d'Entity Framework prend dix fois plus de temps à se terminer

J'ai un site MVC qui utilise Entity Framework 6 pour gérer la base de données, et j'ai essayé de le changer pour que tout fonctionne comme des contrôleurs asynchrones et que les appels à la base de données soient exécutés comme leurs homologues asynchrones (par exemple. ToListAsync () au lieu de ToList ())

Le problème que j'ai est que le simple fait de changer mes requêtes en asynchrones les a rendues incroyablement lentes.

Le code suivant récupère une collection d'objets "Album" à partir de mon contexte de données et est traduit en une jointure de base de données assez simple:

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

Voici le SQL créé:

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

Dans l'état actuel des choses, ce n'est pas une requête extrêmement compliquée, mais il faut presque 6 secondes au serveur SQL pour l'exécuter. SQL Server Profiler signale qu'il prend 5742 ms pour se terminer.

Si je change mon code en:

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

Ensuite, exactement le même SQL est généré, mais cela s'exécute en seulement 474 ms selon SQL Server Profiler.

La base de données a environ 3500 lignes dans la table "Albums", ce qui n'est pas vraiment très grand, et a un index sur la colonne "Artist_ID", donc ça devrait être assez rapide.

Je sais que l'async a des frais généraux, mais rendre les choses dix fois plus lentes me semble un peu raide! Où vais-je mal ici?

J'ai trouvé cette question très intéressante, d'autant plus que j'utilise asyncpartout avec Ado.Net et EF 6. J'espérais que quelqu'un donne une explication à cette question, mais cela ne s'est pas produit. J'ai donc essayé de reproduire ce problème de mon côté. J'espère que certains d'entre vous trouveront cela intéressant.

Première bonne nouvelle: je l'ai reproduite :) Et la différence est énorme. Avec un facteur 8 ...

D'abord, je soupçonnais quelque chose à propos CommandBehavior, depuis que j'ai lu un article intéressant sur asyncAdo, en disant ceci:

"Étant donné que le mode d'accès non séquentiel doit stocker les données pour la ligne entière, il peut entraîner des problèmes si vous lisez une colonne volumineuse à partir du serveur (comme varbinary (MAX), varchar (MAX), nvarchar (MAX) ou XML ). "

Je soupçonnais que les ToList()appels étaient CommandBehavior.SequentialAccesset les appels asynchrones CommandBehavior.Default(non séquentiels, ce qui peut causer des problèmes). J'ai donc téléchargé les sources d'EF6 et mis des points d'arrêt partout (là CommandBehavioroù ils sont utilisés, bien sûr).

Résultat: rien . Tous les appels sont effectués avec CommandBehavior.Default.... J'ai donc essayé d'entrer dans le code EF pour comprendre ce qui se passe ... et ... ooouch ... je ne vois jamais un tel code de délégation, tout semble exécuté paresseusement ...

J'ai donc essayé de faire du profilage pour comprendre ce qui se passe ...

Et je pense que j'ai quelque chose ...

Voici le modèle pour créer la table que j'ai comparée, avec 3500 lignes à l'intérieur et 256 Ko de données aléatoires dans chacune 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; }
}

Et voici le code que j'ai utilisé pour créer les données de test et comparer 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);
    }
}

Pour l'appel EF normal ( .ToList()), le profilage semble "normal" et est facile à lire:

Nous retrouvons ici les 8,4 secondes dont nous disposons avec le chronomètre (le profilage ralentit les performances). Nous trouvons également HitCount = 3500 le long du chemin d'appel, ce qui est cohérent avec les 3500 lignes du test. Du côté de l'analyseur TDS, les choses commencent à empirer depuis que nous avons lu 118 353 appels à la TryReadByteArray()méthode, c'est-à-dire où la boucle de mise en mémoire tampon se produit. (une moyenne de 33,8 appels pour chacun byte[]de 256 Ko)

Pour le asynccas, c'est vraiment très différent ... Tout d'abord, l' .ToListAsync()appel est planifié sur le ThreadPool, puis attendu. Rien d'extraordinaire ici. Mais, maintenant, voici l' asyncenfer sur le ThreadPool:

Premièrement, dans le premier cas, nous n'avions que 3500 comptages d'appels le long du chemin d'appel complet, ici nous avons 118 371. De plus, vous devez imaginer tous les appels de synchronisation que je n'ai pas mis sur la capture d'écran ...

Deuxièmement, dans le premier cas, nous n'avions "que 118 353" appels à la TryReadByteArray()méthode, ici nous avons 2 050 210 appels! C'est 17 fois plus ... (sur un test avec une grande baie de 1 Mo, c'est 160 fois plus)

De plus, il y a:

• 120000 Taskinstances créées
• 727519 Interlockedappels
• 290569 Monitorappels
• 98283 ExecutionContextinstances, avec 264481 captures
• 208733 SpinLockappels

Je suppose que la mise en mémoire tampon est effectuée de manière asynchrone (et non pas bonne), avec des tâches parallèles essayant de lire les données du TDS. Trop de tâches sont créées uniquement pour analyser les données binaires.

En guise de conclusion préliminaire, nous pouvons dire qu'Async est génial, EF6 est génial, mais l'utilisation de l'async par EF6 dans son implémentation actuelle ajoute une surcharge majeure, du côté des performances, du côté Threading et du côté CPU (12% d'utilisation du processeur dans le ToList()cas et 20% dans le ToListAsynccas pour un travail 8 à 10 fois plus long ... je le lance sur un ancien i7 920).

En faisant quelques tests, je repensais à cet article et je remarque quelque chose qui me manque:

"Pour les nouvelles méthodes asynchrones de .Net 4.5, leur comportement est exactement le même que celui des méthodes synchrones, à l'exception d'une exception notable: ReadAsync en mode non séquentiel."

Quelle ?!!!

J'étends donc mes benchmarks pour inclure Ado.Net dans les appels réguliers / asynchrones, et avec CommandBehavior.SequentialAccess/ CommandBehavior.Default, et voici une grosse surprise! :

Nous avons exactement le même comportement avec Ado.Net !!! Facepalm ...

Ma conclusion définitive est la suivante : il y a un bogue dans l'implémentation d'EF 6. Il doit basculer sur CommandBehaviorà SequentialAccesslorsqu'un appel asynchrone est effectué sur une table contenant une binary(max)colonne. Le problème de la création d'un trop grand nombre de tâches, ralentissant le processus, est du côté d'Ado.Net. Le problème EF est qu'il n'utilise pas Ado.Net comme il se doit.

Maintenant, vous savez qu'au lieu d'utiliser les méthodes asynchrones EF6, vous feriez mieux d'appeler EF de manière non asynchrone normale, puis d'utiliser a TaskCompletionSource<T>pour renvoyer le résultat de manière asynchrone.

Note 1: J'ai édité mon article à cause d'une erreur honteuse .... J'ai fait mon premier test sur le réseau, pas localement, et la bande passante limitée a déformé les résultats. Voici les résultats mis à jour.

Note 2: Je n'ai pas étendu mon test à d'autres cas d'utilisation (ex: nvarchar(max)avec beaucoup de données), mais il y a des chances que le même comportement se produise.

Note 3: quelque chose d'habituel pour le ToList()cas, c'est le CPU à 12% (1/8 de mon CPU = 1 cœur logique). Quelque chose d'inhabituel est le maximum de 20% pour le ToListAsync()cas, comme si le planificateur ne pouvait pas utiliser toutes les marches. C'est probablement dû au trop grand nombre de tâches créées, ou peut-être à un goulot d'étranglement dans l'analyseur TDS, je ne sais pas ...

Parce que j'ai eu un lien vers cette question il y a quelques jours, j'ai décidé de publier une petite mise à jour. J'ai pu reproduire les résultats de la réponse originale à l' aide de la dernière version actuellement d'EF (6.4.0) et .NET Framework 4.7.2. Étonnamment, ce problème ne s'est jamais amélioré.

.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

Cela a soulevé la question: y a-t-il une amélioration dans dotnet core?

J'ai copié le code de la réponse originale dans un nouveau projet dotnet core 3.1.3 et ajouté EF Core 3.1.3. Les résultats sont:

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

Étonnamment, il y a beaucoup d'amélioration. Il semble qu'il y ait encore un certain décalage car le threadpool est appelé, mais il est environ 3 fois plus rapide que l'implémentation .NET Framework.

J'espère que cette réponse aidera d'autres personnes qui seront envoyées de cette façon à l'avenir.