Der asynchrone Vorgang von Entity Framework dauert zehnmal so lange

Ich habe eine MVC-Site, die Entity Framework 6 verwendet, um die Datenbank zu verwalten, und ich habe versucht, sie so zu ändern, dass alles als asynchrone Controller ausgeführt wird und Aufrufe der Datenbank als asynchrone Gegenstücke ausgeführt werden (z. B. ToListAsync () anstelle von ToList ())

Das Problem, das ich habe, ist, dass das einfache Ändern meiner Abfragen in asynchron dazu geführt hat, dass sie unglaublich langsam sind.

Der folgende Code ruft eine Sammlung von "Album" -Objekten aus meinem Datenkontext ab und wird in einen relativ einfachen Datenbank-Join übersetzt:

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

Hier ist die SQL, die erstellt wurde:

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

Es ist keine sehr komplizierte Abfrage, aber es dauert fast 6 Sekunden, bis SQL Server sie ausführt. SQL Server Profiler meldet, dass der Abschluss 5742 ms dauert.

Wenn ich meinen Code ändere in:

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

Dann wird genau das gleiche SQL generiert, das laut SQL Server Profiler jedoch nur in 474 ms ausgeführt wird.

Die Datenbank enthält ungefähr 3500 Zeilen in der Tabelle "Alben", was nicht wirklich sehr viele sind, und einen Index in der Spalte "Artist_ID", daher sollte sie ziemlich schnell sein.

Ich weiß, dass Async Overheads hat, aber zehnmal langsamer zu werden, scheint mir ein bisschen steil zu sein! Wo gehe ich hier falsch?

Ich fand diese Frage sehr interessant, zumal ich sie asyncüberall mit Ado.Net und EF 6 verwende. Ich hatte gehofft, dass jemand eine Erklärung für diese Frage gibt, aber es ist nicht passiert. Also habe ich versucht, dieses Problem auf meiner Seite zu reproduzieren. Ich hoffe, einige von Ihnen finden das interessant.

Erste gute Nachricht: Ich habe es reproduziert :) Und der Unterschied ist enorm. Mit einem Faktor 8 ...

Zuerst vermutete ich etwas, mit dem ich zu tun hatte CommandBehavior, da ich einen interessanten Artikel über asyncAdo las und Folgendes sagte:

"Da im nicht sequentiellen Zugriffsmodus die Daten für die gesamte Zeile gespeichert werden müssen, kann dies zu Problemen führen, wenn Sie eine große Spalte vom Server lesen (z. B. varbinary (MAX), varchar (MAX), nvarchar (MAX) oder XML ). "

Ich hatte den Verdacht, dass ToList()Anrufe CommandBehavior.SequentialAccessasynchron und asynchron sind CommandBehavior.Default(nicht sequentiell, was zu Problemen führen kann). Also habe ich die Quellen von EF6 heruntergeladen und überall Haltepunkte gesetzt (wo CommandBehaviornatürlich verwendet).

Ergebnis: nichts . Alle Anrufe werden mit getätigt CommandBehavior.Default... Also habe ich versucht, in den EF-Code einzusteigen, um zu verstehen, was passiert ... und ... ooouch ... ich sehe nie einen solchen delegierenden Code, alles scheint faul ausgeführt zu sein ...

Also habe ich versucht, ein Profil zu erstellen, um zu verstehen, was passiert ...

Und ich glaube ich habe etwas ...

Hier ist das Modell zum Erstellen der von mir verglichenen Tabelle mit 3500 Zeilen und 256 KB zufälligen Daten 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; }
}

Und hier ist der Code, mit dem ich die Testdaten erstellt und EF bewertet habe.

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);
    }
}

Für den regulären EF-Aufruf ( .ToList()) erscheint die Profilerstellung "normal" und ist leicht zu lesen:

Hier finden wir die 8,4 Sekunden, die wir mit der Stoppuhr haben (Profilierung verlangsamt die Leistung). Wir finden auch HitCount = 3500 entlang des Anrufpfads, was mit den 3500 Zeilen im Test übereinstimmt. Auf der TDS-Parser-Seite wird es immer schlimmer, seit wir 118 353 Aufrufe der TryReadByteArray()Methode gelesen haben , bei der die Pufferschleife auftritt. (durchschnittlich 33,8 Anrufe für jeweils byte[]256 KB)

Für den asyncFall ist es wirklich ganz anders ... Zuerst wird der .ToListAsync()Aufruf auf dem ThreadPool geplant und dann erwartet. Nichts Erstaunliches hier. Aber jetzt ist hier die asyncHölle auf dem ThreadPool:

Erstens hatten wir im ersten Fall nur 3500 Treffer auf dem gesamten Anrufpfad, hier haben wir 118 371. Außerdem müssen Sie sich alle Synchronisationsaufrufe vorstellen, die ich nicht in den Screenshoot aufgenommen habe ...

Zweitens hatten wir im ersten Fall "nur 118 353" Aufrufe der TryReadByteArray()Methode, hier haben wir 2 050 210 Aufrufe! Es ist 17-mal mehr ... (bei einem Test mit einem großen 1-MB-Array sind es 160-mal mehr)

Darüber hinaus gibt es:

• 120 000 TaskInstanzen erstellt
• 727 519 InterlockedAnrufe
• 290 569 MonitorAnrufe
• 98 283 ExecutionContextInstanzen mit 264 481 Erfassungen
• 208 733 SpinLockAnrufe

Ich vermute, die Pufferung erfolgt asynchron (und nicht gut), wobei parallele Aufgaben versuchen, Daten aus dem TDS zu lesen. Es werden zu viele Aufgaben erstellt, um die Binärdaten zu analysieren.

Als vorläufige Schlussfolgerung können wir sagen, dass Async großartig ist, EF6 ist großartig, aber die Verwendung von Async durch EF6 in der aktuellen Implementierung erhöht den Overhead auf der Leistungsseite, der Threading-Seite und der CPU-Seite erheblich (12% CPU-Auslastung in der ToList()Fall und 20% in derToListAsync Fall für eine 8 bis 10 mal längere Arbeit ... Ich führe es auf einem alten i7 920).

Während ich einige Tests durchführte, dachte ich wieder über diesen Artikel nach und bemerkte etwas, das ich vermisse:

"Bei den neuen asynchronen Methoden in .Net 4.5 ist ihr Verhalten bis auf eine bemerkenswerte Ausnahme genau das gleiche wie bei den synchronen Methoden: ReadAsync im nicht sequentiellen Modus."

Was? !!!

Daher erweitere ich meine Benchmarks um Ado.Net in regulären / asynchronen Aufrufen und mit CommandBehavior.SequentialAccess/ CommandBehavior.Default, und hier ist eine große Überraschung! ::

Wir haben genau das gleiche Verhalten mit Ado.Net !!! Gesichtspalme ...

Meine endgültige Schlussfolgerung lautet : Es gibt einen Fehler in der EF 6-Implementierung. Es sollte das umschalten CommandBehavior, SequentialAccesswenn ein asynchroner Aufruf über eine Tabelle mit einer binary(max)Spalte ausgeführt wird. Das Problem, zu viele Aufgaben zu erstellen und den Prozess zu verlangsamen, liegt auf der Ado.Net-Seite. Das EF-Problem ist, dass Ado.Net nicht ordnungsgemäß verwendet wird.

Anstatt die asynchronen EF6-Methoden zu verwenden, sollten Sie EF besser regelmäßig nicht asynchron aufrufen und dann a verwenden TaskCompletionSource<T>, um das Ergebnis asynchron zurückzugeben.

Hinweis 1: Ich habe meinen Beitrag aufgrund eines beschämenden Fehlers bearbeitet. Ich habe meinen ersten Test über das Netzwerk durchgeführt, nicht lokal, und die begrenzte Bandbreite hat die Ergebnisse verzerrt. Hier sind die aktualisierten Ergebnisse.

Hinweis 2: Ich habe meinen Test nicht auf andere Anwendungsfälle ausgedehnt (z. B. nvarchar(max)mit vielen Daten), aber es besteht die Möglichkeit, dass dasselbe Verhalten auftritt.

Anmerkung 3: Etwas Übliches für den ToList()Fall ist die 12% CPU (1/8 meiner CPU = 1 logischer Kern). Etwas Ungewöhnliches ist das Maximum von 20% für den ToListAsync()Fall, als ob der Scheduler nicht alle Treads verwenden könnte. Es liegt wahrscheinlich an den zu vielen erstellten Aufgaben oder an einem Engpass im TDS-Parser, ich weiß nicht ...

Da ich vor ein paar Tagen einen Link zu dieser Frage bekommen habe, habe ich beschlossen, ein kleines Update zu veröffentlichen. Ich konnte die Ergebnisse der ursprünglichen Antwort mit der aktuell neuesten Version von EF (6.4.0) und .NET Framework 4.7.2 reproduzieren. Überraschenderweise wurde dieses Problem nie verbessert.

.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

Dies warf die Frage auf: Gibt es eine Verbesserung des Dotnet-Kerns?

Ich habe den Code aus der ursprünglichen Antwort in ein neues Dotnet Core 3.1.3-Projekt kopiert und EF Core 3.1.3 hinzugefügt. Die Ergebnisse sind:

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

Überraschenderweise gibt es viele Verbesserungen. Es scheint immer noch eine gewisse Zeitverzögerung zu geben, da der Threadpool aufgerufen wird, aber er ist ungefähr dreimal schneller als die .NET Framework-Implementierung.

Ich hoffe, diese Antwort hilft anderen Menschen, die in Zukunft auf diese Weise gesendet werden.