Operacja asynchroniczna Entity Framework trwa dziesięć razy dłużej

Mam witrynę MVC, która używa Entity Framework 6 do obsługi bazy danych i eksperymentowałem ze zmianą jej tak, aby wszystko działało jako kontrolery asynchroniczne, a wywołania bazy danych były uruchamiane jako ich odpowiedniki asynchroniczne (np. ToListAsync () zamiast ToList ())

Problem polega na tym, że po prostu zmiana zapytań na asynchroniczne spowodowała, że ​​były niewiarygodnie wolne.

Poniższy kod pobiera kolekcję obiektów „Album” z mojego kontekstu danych i jest tłumaczony na dość proste łączenie bazy danych:

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

Oto utworzony kod 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

Na razie nie jest to bardzo skomplikowane zapytanie, ale uruchomienie serwera SQL zajmuje prawie 6 sekund. SQL Server Profiler zgłasza, że ​​ukończenie go trwa 5742 ms.

Jeśli zmienię kod na:

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

Następnie generowany jest dokładnie ten sam kod SQL, ale zgodnie z SQL Server Profiler działa to w zaledwie 474 ms.

Baza danych ma około 3500 wierszy w tabeli „Albumy”, co nie jest zbyt wiele i ma indeks w kolumnie „Artist_ID”, więc powinno działać dość szybko.

Wiem, że asynchronizacja ma narzuty, ale dziesięciokrotne spowolnienie wydaje mi się nieco strome! Gdzie ja tu się mylę?

asyncWydało mi się to bardzo interesujące, zwłaszcza że używam wszędzie z Ado.Net i EF 6. Miałem nadzieję, że ktoś wyjaśni to pytanie, ale tak się nie stało. Próbowałem więc odtworzyć ten problem po swojej stronie. Mam nadzieję, że niektórzy z was uznają to za interesujące.

Pierwsza dobra wiadomość: odtworzyłem to :) A różnica jest ogromna. Przy współczynniku 8 ...

Najpierw podejrzewałem, że coś się z tym wiąże CommandBehavior, ponieważ przeczytałem ciekawy artykuł o asyncAdo, mówiąc o tym:

„Ponieważ tryb dostępu niesekwencyjnego musi przechowywać dane dla całego wiersza, może to powodować problemy, jeśli odczytujesz dużą kolumnę z serwera (na przykład varbinary (MAX), varchar (MAX), nvarchar (MAX) lub XML ). ”

Podejrzewałem, że ToList()połączenia mają być, CommandBehavior.SequentialAccessa asynchroniczne CommandBehavior.Default(niesekwencyjne, co może powodować problemy). Pobrałem więc źródła EF6 i umieściłem punkty przerwania wszędzie ( CommandBehavioroczywiście tam, gdzie są używane).

Wynik: nic . Wszystkie wywołania są wykonywane za pomocą CommandBehavior.Default.... Więc próbowałem wejść do kodu EF, aby zrozumieć, co się dzieje ... i ... ooouch ... Nigdy nie widziałem takiego kodu delegującego, wszystko wydaje się być wykonywane leniwie ...

Więc spróbowałem zrobić pewne profilowanie, aby zrozumieć, co się dzieje ...

I chyba coś mam ...

Oto model do utworzenia tabeli, którą przetestowałem, z 3500 wierszami w środku i 256 Kb losowymi danymi w każdej 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; }
}

A oto kod, którego użyłem do utworzenia danych testowych i testu porównawczego 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);
    }
}

W przypadku zwykłego wywołania EF ( .ToList()) profilowanie wydaje się „normalne” i jest łatwe do odczytania:

Tutaj znajdujemy 8,4 sekundy, które mamy ze stoperem (profilowanie spowalnia działanie). Znajdujemy również HitCount = 3500 wzdłuż ścieżki wywołania, co jest zgodne z 3500 liniami w teście. Po stronie parsera TDS sytuacja zaczyna się pogarszać, odkąd przeczytaliśmy 118 353 wywołań TryReadByteArray()metody, w której występuje pętla buforowania. (średnio 33,8 wywołań na każde byte[]256kb)

W tym asyncprzypadku jest naprawdę zupełnie inaczej ... Najpierw .ToListAsync()wywołanie jest zaplanowane w puli wątków, a następnie jest oczekiwane. Nie ma tu nic niesamowitego. Ale teraz, oto asyncpiekło w ThreadPool:

Po pierwsze, w pierwszym przypadku mieliśmy tylko 3500 zliczeń trafień na całej ścieżce wywołania, tutaj mamy 118 371. Co więcej, musisz sobie wyobrazić wszystkie wywołania synchronizacyjne, których nie wykonałem podczas zrzutu ekranu ...

Po drugie, w pierwszym przypadku mieliśmy „tylko 118 353” wywołań TryReadByteArray()metody, tutaj mamy 2 050 210 wywołań! To 17 razy więcej ... (w teście z dużą macierzą 1Mb to 160 razy więcej)

Ponadto są:

• TaskUtworzono 120 000 instancji
• 727 519 Interlockedpołączeń
• 290 569 Monitorwezwań
• 98 283 ExecutionContextinstancji, z 264 481 przechwyceniami
• 208 733 SpinLockpołączeń

Domyślam się, że buforowanie odbywa się w sposób asynchroniczny (i niezbyt dobry), z równoległymi zadaniami próbującymi odczytać dane z TDS. Utworzono zbyt wiele zadań tylko po to, aby przeanalizować dane binarne.

Na wstępny wniosek możemy powiedzieć, że Async jest świetny, EF6 jest świetny, ale użycie async przez EF6 w jego bieżącej implementacji dodaje znaczny narzut po stronie wydajności, po stronie wątkowości i po stronie procesora (12% użycie procesora w ToList()przypadku i 20% w ToListAsyncprzypadku 8 do 10 razy dłuższej pracy ... uruchamiam go na starym i7 920).

Robiąc kilka testów, ponownie myślałem o tym artykule i zauważyłem coś, czego mi brakuje:

„W przypadku nowych metod asynchronicznych w .Net 4.5 ich zachowanie jest dokładnie takie samo, jak w przypadku metod synchronicznych, z wyjątkiem jednego ważnego wyjątku: ReadAsync w trybie niesekwencyjnym”.

Co ?!!!

Więc rozszerzam moje testy porównawcze, aby uwzględnić Ado.Net w zwykłym / asynchronicznym połączeniu, a także z CommandBehavior.SequentialAccess / CommandBehavior.Default, a oto wielka niespodzianka! :

Dokładnie tak samo postępujemy z Ado.Net !!! Facepalm ...

Mój ostateczny wniosek jest taki : w implementacji EF 6 jest błąd. Powinien przełączyć się CommandBehaviornaSequentialAccess gdy wywołanie asynchroniczne jest wykonywane w tabeli zawierającej binary(max)kolumnę. Problem z utworzeniem zbyt wielu zadań, spowalniających proces, leży po stronie Ado.Net. Problem z EF polega na tym, że nie używa Ado.Net tak, jak powinien.

Teraz wiesz, że zamiast używać metod asynchronicznych EF6, lepiej byłoby wywołać EF w zwykły sposób inny niż asynchroniczny, a następnie użyć TaskCompletionSource<T> aby zwrócić wynik w sposób asynchroniczny.

Uwaga 1: Edytowałem swój post z powodu wstydliwego błędu ... Pierwszy test wykonałem przez sieć, a nie lokalnie, a ograniczona przepustowość zniekształciła wyniki. Oto zaktualizowane wyniki.

Uwaga 2: Nie rozszerzyłem mojego testu na inne przypadki zastosowań (np. nvarchar(max) Przy dużej ilości danych), ale są szanse, że wystąpi to samo zachowanie.

Uwaga 3: Coś zwykle w tym ToList()przypadku to 12% procesor (1/8 mojego procesora = 1 rdzeń logiczny). Coś niezwykłego to maksymalne 20% dla ToListAsync()sprawy, tak jakby planista nie mógł wykorzystać wszystkich stopni. Prawdopodobnie jest to spowodowane zbyt dużą liczbą utworzonych zadań, a może wąskim gardłem w parserze TDS, nie wiem ...

Ponieważ kilka dni temu dostałem link do tego pytania, postanowiłem opublikować małą aktualizację. Udało mi się odtworzyć wyniki oryginalnej odpowiedzi, korzystając z obecnie najnowszej wersji EF (6.4.0) i .NET Framework 4.7.2. Zaskakujące jest, że ten problem nigdy nie został rozwiązany.

.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

To zrodziło pytanie: czy istnieje poprawa w rdzeniu dotnet?

Skopiowałem kod z oryginalnej odpowiedzi do nowego projektu dotnet core 3.1.3 i dodałem EF Core 3.1.3. Wyniki są następujące:

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

Zaskakujące jest wiele ulepszeń. Wydaje się, że nadal istnieje pewne opóźnienie, ponieważ pula wątków jest wywoływana, ale jest około 3 razy szybsza niż implementacja .NET Framework.

Mam nadzieję, że ta odpowiedź pomoże innym osobom, które zostaną wysłane w ten sposób w przyszłości.