Entity Framework の非同期操作は完了までに 10 倍の時間がかかります 質問する

Entity Framework の非同期操作は完了までに 10 倍の時間がかかります 質問する

私は Entity Framework 6 を使用してデータベースを処理する MVC サイトを持っており、すべてが非同期コントローラーとして実行され、データベースへの呼び出しが非同期の対応として実行されるように変更する実験を行っています (例: ToList() ではなく ToListAsync())

私が抱えている問題は、クエリを非同期に変更しただけで、クエリが非常に遅くなることです。

次のコードは、データ コンテキストから「アルバム」オブジェクトのコレクションを取得し、非常に単純なデータベース結合に変換されます。

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

作成された 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

実際のところ、これはそれほど複雑なクエリではありませんが、SQL サーバーがこれを実行するのに約 6 秒かかります。SQL Server Profiler は、完了までに 5742 ミリ秒かかると報告しています。

コードを次のように変更すると:

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

すると、まったく同じ SQL が生成されますが、SQL Server Profiler によると、これはわずか 474 ミリ秒で実行されます。

データベースの「Albums」テーブルには約 3500 行ありますが、これはそれほど多くはなく、「Artist_ID」列にインデックスがあるため、かなり高速になるはずです。

非同期にはオーバーヘッドがあることはわかっていますが、処理速度が 10 倍遅くなるのはちょっと高すぎる気がします。どこが間違っているのでしょうか?

ベストアンサー1

私はこの質問に非常に興味を持ちました。特に、私はasyncどこでも Ado.Net と EF 6 を使用しているからです。誰かがこの質問について説明してくれることを期待していましたが、それはありませんでした。そこで、私は自分の側でこの問題を再現しようとしました。皆さんの中にも、これが興味深いと感じてくれる人がいることを願っています。

最初の朗報:再現できました :) 違いは甚大です。8 倍です...

最初の結果

まず、私は何かが関係しているのではないかと疑っていましたCommandBehavior、 以来興味深い記事を読みましたasyncアドーについてこう言った。

「非シーケンシャル アクセス モードでは行全体のデータを格納する必要があるため、サーバーから大きな列 (varbinary(MAX)、varchar(MAX)、nvarchar(MAX)、XML など) を読み取る場合に問題が発生する可能性があります。」

ToList()呼び出しが be でCommandBehavior.SequentialAccess、非同期呼び出しが be CommandBehavior.Default(非連続で、問題を引き起こす可能性がある) であるのではないかと疑っていました。そこで、EF6 のソースをダウンロードし、あらゆる場所に (CommandBehaviorもちろん、使用されている場所に) ブレークポイントを設定しました。

結果 :何もないすべての呼び出しはCommandBehavior.Default... で行われます。そこで、何が起こるかを理解するために EF コードにステップインしようとしました...そして...ああ...このような委任コードは見たことがなく、すべてが遅延実行されているようです...

そこで、何が起こるかを理解するためにプロファイリングをしてみました...

そして、私は何かを持っていると思う...

これは私がベンチマークしたテーブルを作成するためのモデルです。テーブルには 3500 行あり、各行には 256 Kb のランダム データが含まれていますvarbinary(MAX)。(EF 6.1 - CodeFirst -コードプレックス) :

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

以下は、テスト データを作成し、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);
    }
}

通常の EF 呼び出し ( .ToList()) の場合、プロファイリングは「正常」に見え、読みやすいです。

ToList トレース

ここで、ストップウォッチで 8.4 秒がかかっていることがわかります (プロファイリングによりパフォーマンスが低下します)。また、呼び出しパスに沿って HitCount = 3500 も見つかりました。これは、テストの 3500 行と一致しています。TDS パーサー側では、TryReadByteArray()メソッドで 118 353 回の呼び出しが読み取られたため、状況が悪化し始めています。ここでバッファリング ループが発生します ( byte[]256kb ごとに平均 33.8 回の呼び出し)。

このasync場合、それは本当にまったく異なります.... まず、.ToListAsync()呼び出しが ThreadPool でスケジュールされ、その後待機されます。ここでは驚くべきことはありません。しかし、ここでasyncThreadPool の地獄が起こります:

ToListAsync 地獄

まず、最初のケースでは、完全な呼び出しパスに沿ってヒット数が 3500 だけでしたが、ここでは 118,371 です。さらに、スクリーンショットに載せなかったすべての同期呼び出しを想像する必要があります...

2 番目に、最初のケースでは、メソッドの呼び出しは「わずか 118,353」でしたがTryReadByteArray()、ここでは 2,050,210 回の呼び出しがあります。これは 17 倍です... (1 MB の大きな配列を使用したテストでは、160 倍になります)

さらに、次のものがあります:

  • 120,000Taskインスタンス作成
  • 727 519Interlocked通話
  • 290 569Monitor通話
  • 98,283ExecutionContextインスタンス、264,481 キャプチャ
  • 208 733SpinLock通話

私の推測では、バッファリングは非同期方式(良い方法ではない)で行われ、並列タスクが TDS からデータを読み取ろうとしています。バイナリ データを解析するためだけに作成されるタスクが多すぎます。

予備的な結論としては、非同期は素晴らしい、EF6 は素晴らしいと言えますが、EF6 の現在の実装での非同期の使用は、パフォーマンス面、スレッド面、CPU 面に大きなオーバーヘッドを追加します (この場合、CPU 使用率は 12% ToList()、8 ~ 10 倍の作業時間の場合は 20% になりますToListAsync...私は古い i7 920 で実行しています)。

いくつかのテストをしながら、私は考えていましたこの記事をもう一度そして、私は何か見逃していることに気づきました。

「.Net 4.5 の新しい非同期メソッドの動作は、非シーケンシャル モードの ReadAsync という 1 つの注目すべき例外を除いて、同期メソッドとまったく同じです。」

何 ?!!!

そこで、ベンチマークを拡張して、通常の / 非同期呼び出しとCommandBehavior.SequentialAccess/に Ado.Net を含めてみたところCommandBehavior.Default、大きな驚きがありました。

前置き

Ado.Net でもまったく同じ動作をします!!! 顔面を手で覆う...

私の最終的な結論は: EF 6 の実装にバグがあります。列を含むテーブルに対して非同期呼び出しが行われると、CommandBehaviorが切り替わる必要があります。タスクが多すぎるとプロセスが遅くなるという問題は、Ado.Net 側にあります。EF の問題は、Ado.Net が適切に使用されていないことです。SequentialAccessbinary(max)

これで、EF6 の非同期メソッドを使用する代わりに、通常の非同期の方法で EF を呼び出し、その後 を使用してTaskCompletionSource<T>非同期の方法で結果を返す方がよいことがわかりました。

注 1: 恥ずかしい間違いがあったため、投稿を編集しました。最初のテストはローカルではなくネットワーク経由で実行しましたが、帯域幅が限られているため結果が歪んでしまいました。更新された結果は次のとおりです。

注 2: テストを他のユースケース (例:nvarchar(max)大量のデータ) に拡張していませんが、同じ動作が発生する可能性があります。

注 3: このToList()場合、CPU が 12% であるのが普通です (CPU の 1/8 = 1 論理コア)。通常と異なるのは、このToListAsync()ケースで最大 20% であり、これはスケジューラがすべてのスレッドを使用できなかったかのようです。これは、作成されたタスクが多すぎるか、TDS パーサーのボトルネックによるものかもしれません。よくわかりません...

おすすめ記事