[解決済み] Entity Frameworkの非同期処理には10倍の時間がかかる

質問

私は、データベースを処理するためにEntity Framework 6を使用しているMVCサイトを持っています。私は、すべてが非同期コントローラとして実行され、データベースへの呼び出しがそれらの非同期対応として実行されるようにそれを変更して試してきました（例：ToList（）ではなく、ToListAsync（））。

私が抱えている問題は、単にクエリを非同期に変更するだけで、信じられないほど遅くなることです。

次のコードは、データコンテキストから "Album" オブジェクトのコレクションを取得し、かなり単純なデータベース結合に変換されます。

// 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 によると、これはわずか 474ms で実行されます。

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

非同期にはオーバーヘッドがあることは知っていますが、物事を10倍遅くすることは、私には少し急なことのように思えます! 私はどこで間違っているのでしょうか?

どのように解決するのですか？

私はこの質問が非常に興味深いものであると感じました。 async をAdo.NetとEF 6でいたるところで使用しているからです。私は誰かがこの質問に対する説明を与えることを期待していましたが、それは起こりませんでした。そこで、私の側でこの問題を再現してみました。私はあなたの何人かがこれを面白いと思うことを願っています。

最初の良いニュースは：私はそれを再現した：）。そして、その差は非常に大きいです。ファクター8で ...

最初に、私は何か CommandBehavior を扱っているのではないかと疑いました。 面白い記事を読んだので について async をアドで、こう言っています。

"非シーケンシャルアクセスモードは行全体のデータを保存しなければならないので、サーバから大きな列（varbinary(MAX), varchar(MAX), nvarchar(MAX) or XMLなど）を読み込む場合は問題を起こす可能性があります)"。

私が疑っていたのは ToList() の呼び出しは CommandBehavior.SequentialAccess で、非同期呼び出しは CommandBehavior.Default (にする必要があります（非シーケンシャル、これは問題を引き起こす可能性があります）。そこで、EF6のソースをダウンロードして、あちこちにブレークポイントを置いてみました（ここで CommandBehavior が使われているところ）。

結果: 何もない . すべての呼び出しは CommandBehavior.Default .... そこで、何が起こっているのかを理解するためにEFのコードに踏み込もうとしたところ...うーん......。私はこのような委譲されたコードを見たことがありません、すべてが怠惰に実行されているようです...

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

そして、何かわかったような気がします...

私がベンチマークしたテーブルを作成するためのモデルです。その中には3500行があり、それぞれに256Kbのランダムデータがあります varbinary(MAX) . (EF6.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() ) では、プロファイリングは "normal" のように見え、読みやすくなっています。

ここでは、ストップウォッチで得られた8.4秒を見つけることができます（プロファイリングによってperfsが遅くなります）。また、呼び出しパスに沿って HitCount = 3500 が見つかり、これはテストでの 3500 行と一致しています。TDSパーサ側では、118 353の呼び出しがあり、事態は悪化し始めました。 TryReadByteArray() メソッドで 118 353 回の呼び出しがあり、バッファリング ループが発生したためです。(各 byte[] に対して平均 33.8 回の呼び出し)。

については async の場合、本当に本当に違います......。まず .ToListAsync() の呼び出しは ThreadPool 上でスケジュールされ、その後待機します。ここでは何も驚くことはありません。しかし、今度は async の地獄は、ThreadPool にあります。

まず、最初のケースでは、完全な呼び出しパスに沿ってちょうど 3500 のヒット カウントがありましたが、ここでは 118 371 です。さらに、スクリーンショットに載せていないすべての同期呼び出しを想像してください...

次に、最初のケースで、私たちは "ちょうど 118 353" の呼び出しを持っていました。 TryReadByteArray() メソッドへの呼び出しが 2,050 210 回もありました。これは17倍です... (大きな 1Mb の配列を使用したテストでは、160 倍になります)

さらに、次のようなこともあります。

• 120 000 Task 作成されたインスタンス
• 727 519 Interlocked コール
• 290 569 Monitor コール
• 98 283 ExecutionContext インスタンス、264 481 キャプチャーを含む
• 208 733 SpinLock コール

私の推測では、バッファリングは、TDSからデータを読もうとする並列タスクで、非同期方法（そして良いものではない）で作られていると思います。バイナリ データを解析するために、あまりにも多くのタスクが作成されます。

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

いくつかのテストを行っている間、私は次のことを考えていました。 この記事をもう一度 について考えていて、見落としていることに気づきました。

.Net 4.5 の新しい非同期メソッドについては、1 つの顕著な例外を除いて、その動作は同期メソッドとまったく同じです。非シーケンシャル モードでの ReadAsync です。

なんだ!

そこで、ベンチマークを拡張して、Ado.Netを通常/非同期呼び出しに含め、さらに CommandBehavior.SequentialAccess / CommandBehavior.Default そして、ここで大きな驚きが ! :

Ado.Netで全く同じ動作をしています !!! 顔面蒼白です...

私の決定的な結論は : EF 6 の実装にバグがある。これは CommandBehavior を SequentialAccess を含むテーブルに対して非同期呼び出しが行われた場合、そのテーブルには binary(max) カラムを含むテーブルに対して非同期呼び出しが行われた場合です。Taskを作りすぎて処理が遅くなるという問題は、Ado.Net側にあります。EFの問題は、Ado.Netを本来の意味で使えていないことです。

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

注1 : 恥ずかしい間違いがあったので、投稿を編集しました...。最初のテストはローカルではなくネットワーク上で行ったので、帯域が制限されているために結果が歪んでしまいました。以下は更新された結果です。

注2 : 私は自分のテストを他のユースケースに拡張しませんでした (例 : nvarchar(max) など）には拡張していませんが、同じ挙動が起こる可能性はあります。

注3 : 何か通常の ToList() の場合、12%の CPU (1/8 of my CPU = 1 logical core) です。通常と異なるのは ToListAsync() の場合、まるでスケジューラがすべてのトレッドを使用できないかのようです。これはおそらく、作成されたタスクが多すぎるか、TDS パーサーのボトルネックによるものだと思いますが、私は知りません...