webentwicklung-frage-antwort-db.com.de

Der asynchrone Vorgang von Entity Framework dauert zehnmal so lange

Ich habe eine MVC-Site, die Entity Framework 6 für die Verwaltung der Datenbank verwendet, und ich habe versucht, diese so zu ändern, dass alle asynchronen Controller ausgeführt werden 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 erstellte SQL:

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

Nach wie vor handelt es sich nicht um eine sehr komplizierte Abfrage, aber es dauert fast 6 Sekunden, bis SQL Server sie ausführt. SQL Server Profiler meldet, dass der Vorgang 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 dieselbe SQL generiert, die laut SQL Server Profiler jedoch nur 474 ms dauert.

Die Datenbank enthält ungefähr 3500 Zeilen in der Tabelle "Alben", was nicht wirklich sehr viele sind, und verfügt über einen Index in der Spalte "Artist_ID". Daher sollte dieser Index ziemlich schnell sein.

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

133
Dylan Parry

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

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

first results

Zuerst hatte ich den Verdacht, dass etwas mit CommandBehavior zu tun hat, da ich einen interessanten Artikel gelesen habe über async mit Ado und sagte Folgendes:

"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() Aufrufe CommandBehavior.SequentialAccess Und asynchrone CommandBehavior.Default Sind (nicht sequenziell, was zu Problemen führen kann). Also habe ich die Quellen von EF6 heruntergeladen und überall Haltepunkte gesetzt (wobei CommandBehavior natürlich verwendet wurde).

Ergebnis: nichts . Alle Aufrufe werden mit CommandBehavior.Default Getätigt. Also habe ich versucht, in den EF-Code einzusteigen, um zu verstehen, was passiert ...

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 getesteten Tabelle mit 3500 Zeilen darin und 256 Kb Zufallsdaten in jeder 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 habe, und der Referenz-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);
    }
}

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

ToList trace

Hier finden wir die 8,4 Sekunden, die wir mit der Stoppuhr haben (das Profilieren verlangsamt die Perfs). Wir finden auch HitCount = 3500 im Aufrufpfad, was mit den 3500 Zeilen im Test übereinstimmt. Auf der Seite des TDS-Parsers wurde es schlimmer, seit wir 118 353 Aufrufe der TryReadByteArray() -Methode gelesen haben, in der die Pufferschleife auftritt. (durchschnittlich 33,8 Aufrufe für jeden byte[] von 256 KB)

Für den Fall async ist es wirklich ganz anders .... Zuerst wird der Aufruf von .ToListAsync() im ThreadPool geplant und dann abgewartet. Nichts Erstaunliches hier. Aber jetzt ist hier die async Hölle im ThreadPool:

ToListAsync hell

Erstens hatten wir im ersten Fall nur 3500 Treffer auf dem gesamten Anrufpfad, hier sind es 118 371. Außerdem müssen Sie sich alle Synchronisierungsanrufe vorstellen, die ich nicht auf dem Bildschirm 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 großem 1-MB-Array sind es 160-mal mehr)

Darüber hinaus gibt es:

  • 120 000 Task Instanzen erstellt
  • 727 519 Interlocked Anrufe
  • 290 569 Monitor Anrufe
  • 98 283 ExecutionContext Instanzen mit 264 481 Captures
  • 208.733 SpinLock Anrufe

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

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

Während ich einige Tests durchführte, dachte ich über diesen Artikel noch einmal nach und mir fällt etwas auf, das ich vermisse:

"Für die neuen asynchronen Methoden in .Net 4.5 ist ihr Verhalten bis auf eine bemerkenswerte Ausnahme genau dasselbe wie für die synchronen Methoden: ReadAsync im nicht-sequentiellen Modus."

Was? !!!

Deshalb erweitere ich meine Benchmarks, um Ado.Net in reguläre/asynchrone Aufrufe und mit CommandBehavior.SequentialAccess/CommandBehavior.Default Einzubeziehen, und hier ist eine große Überraschung! :

with ado

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

Meine endgültige Schlussfolgerung ist : Es gibt einen Fehler in der EF 6-Implementierung. Es sollte die CommandBehavior auf SequentialAccess umschalten, wenn ein asynchroner Aufruf über eine Tabelle mit einer binary(max) -Spalte erfolgt. Das Problem, zu viele Aufgaben zu erstellen, verlangsamt den Prozess und ist auf der Ado.Net-Seite. Das EF-Problem ist, dass es Ado.Net nicht so verwendet, wie es sollte.

Anstatt die asynchronen EF6-Methoden zu verwenden, sollten Sie EF jetzt auf normale, nicht asynchrone Weise aufrufen und anschließend mit TaskCompletionSource<T> Das Ergebnis asynchron zurückgeben.

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 (z. B. nvarchar(max) mit vielen Daten) ausgedehnt, aber es besteht die Möglichkeit, dass dasselbe Verhalten auftritt.

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

267
rducom