s_izumi
@s_izumi (ab cd)

Are you sure you want to delete the question?

Leaving a resolved question undeleted may help others!

EntityFrameworkでToList()が極端に遅くなる

解決したいこと

C# + Entity FrameworkアプリケーションでTake()をかまさないToList()が極端に遅い原因を知りたい。

プログラム作成中にリスト表示箇所が極端に遅かったため、VisualStudioのデバッグ機能にて問題個所を調べたところ
ToList()で極端に遅くなっていることに気づきました。

該当するソースコード

using (var db = new AppDbContext())
{
    Decimal pKey1 = XXX;
    Decimal pKey2 = XXXXX;
    Decimal pCode = XX;

    var r1 = db.V_DATA
        .Where(s => s.Key1 == pKey1)
        .Where(s => s.Key2 == pKey2)
        .Where(s => s.Code <= pCode)
        .ToList();  // ここで7,363ミリ秒(7秒程)かかる
}
============================
/// Entityクラス
public partial class V_DATA
{
    [Key]
    [Column(Order = 0, TypeName = "numeric")]
    public decimal Key1 { get; set; }

    [Key]
    [Column(Order = 1, TypeName = "numeric")]
    public decimal Key2 { get; set; }

    [Key]
    [Column(Order = 2, TypeName = "numeric")]
    public decimal Key3 { get; set; }

    [Key]
    [Column(Order = 3)]
    public string Column4 { get; set; } // 最大

    [Key]
    [Column(Order =4 , TypeName = "numeric")]
    public decimal Column5 { get; set; }

    [Key]
    [Column(Order = 5, TypeName = "numeric")]
    public decimal Column6 { get; set; }
}

ToList()で取得される件数は100件。試しにToList()直前に生成されたSQLをSSMSから実行しましたが
ほぼ0秒で結果が返ってきたためクエリチューニングの問題ではないように思えました。

var r1 = db.V_DATA
    .Where(s => s.Key1 == pKey1)
    .Where(s => s.Key2 == pKey2)
    .Where(s => s.Code <= pCode)
    .Selct(s => s); // デバッグモードで停止してSql文字列を取得

質問

以下の点についてご教示をお願い致します。
- Take()無しで速度を向上する方法を知りたい。
- ToList()のみで極端に遅くなる理由を知りたい。

なお、V_DATASQLServerデータベースにおいてViewとして定義されています。

検証したこと1(Take(100).ToList())⇒少し早くなる(及第点)

var r1 = db.V_DATA
    .Where(s => s.Key1 == pKey1)
    .Where(s => s.Key2 == pKey2)
    .Where(s => s.Code <= pCode)
    .Take(100)  // ToList()で取得される件数と同数の100を指定
    .ToList();  // 早くなった。⇒1,112ミリ秒(1秒程)

検証したこと2(ToArray)⇒遅い

var r1 = db.V_DATA
    .Where(s => s.Key1 == pKey1)
    .Where(s => s.Key2 == pKey2)
    .Where(s => s.Code <= pCode)
    .ToArray();  // ToArray化。同様に遅い。⇒7,576ミリ秒(7秒程)

検証したこと3(Any)⇒早い

var r1 = db.V_DATA
    .Where(s => s.Key1 == pKey1)
    .Where(s => s.Key2 == pKey2)
    .Where(s => s.Code <= pCode)
    .Any();  // Any()化。早い。⇒49ミリ秒(7秒程)

その他

V_DATAビューは概ね以下の定義になっています。
Column4の最大桁数は11桁、その他数値項目は12桁です。

[dbo].[V_DATA](
    [Key1] [numeric](6, 0) NOT NULL,
    [Key2] [numeric](7, 0) NOT NULL,
    [Key3] [numeric](3, 0) NOT NULL,
    [Column4] [nvarchar](max) NOT NULL,
    [Column5] [numeric](22, 0) NOT NULL,
    [Column6] [numeric](22, 0) NOT NULL,
)

利用バージョンなど

  • Windows 10
  • Windows Forms アプリケーション
  • .NET Framework 4.8
  • Entity Framework 6.2.0
  • SQL Server 2014

困っています。ご回答お待ちしております。

0

6Answer

SSMSのようなDBメンテナンスツールは、パフォーマンスの低下を防ぐために、クエリを実行した際、カーソルの先頭の一部だけを取り出して表示させ、残りはスクロールさせた際にオンデマンドで取り出すことをしたりしなかったりします。

SSMSで最後の結果が表示されるまでスクロールさせた場合どの程度時間がかかりますか?

もしかしたら最終行取得もいい感じに最適化していて速いかもしれません。
この場合、全体で何行取得できていますか?

全体の抽出件数が多ければ、ToList()で相応の時間がかかるのは必然かもしれません。

2Like

Comments

  1. @s_izumi

    Questioner

    `SSMS`がビュー表示を最適化しているというのはまさに盲点でした。
    EntityFrameworkによって生成されたSQLを実行するのには時間がかかりませんでしたが、
    ビュー全体の`SELECT`だと22秒ほどかかりました。

    実はビューで分析関数`LAG()`を利用しています。
    試しにこのカラムをオンコードで`0`を返すように修正したところ、速度が改善しましたので、
    これが読み込みを遅延させている原因かもしれません。

    私としては`LAG()を使用しないビューに書き直すことで解決`となりそうですが
    他の解決案があるかも併せて知りたいため、今日一日だけ未解決のまま回答を募集したいと思います。

    皆様ご回答頂きありがとうございました。
  2. @s_izumi

    Questioner

    再度巻き込んで申し訳ありませんが、
    `コマンドプロンプト`から`sqlcmd`ユーティリティ(?)を利用してクエリを叩きましたが、
    応答はほぼノータイムに近いものでした。

    また、回答という形で下に追記したのですが、
    以下のようにSQLを直接実行すると`170ミリ秒``というはやさで応答がありました。

    困惑しております。
    お気づきの点ありましたらよろしくお願いします。

    ```c#
    var sql = "実行計画から取得したクエリ";
    db.Database.Sql<List<V_ZM>>(sql).ToList();
    ```

よく分かっていなくて、質問に質問を返すようで申し訳ありません。
以下の部分ですけど、

    var r1 = db.V_DATA
        .Where(s => s.Key1 == pKey1)
        .Where(s => s.Key2 == pKey2)
        .Where(s => s.Code <= pCode)
        .ToList(); 

(1) 以下のようにしてはまずいのでしょうか?

    var r1 = db.V_DATA
        .Where (s => s.Key1 == pKey1 && s.Key2 == pKey2 && s.Code <= pCode)
        .ToList(); 

(2) 以下のようにした場合、コンソールはどのような表示になるでしょうか?

    var startTime = DateTime.Now;
    var r0 = db.V_DATA
        .Where(s => s.Key1 == pKey1)
        .Where(s => s.Key2 == pKey2)
        .Where(s => s.Code <= pCode);
    var endTime = DateTime.Now;
    Console.WriteLine ($"Where ×3 に要した時間 {endTime - startTime}");
    startTime = DateTime.Now;
    var r1 = r0.ToList (); 
    endTime = DateTime.Now;
    Console.WriteLine ($"ToList に要した時間 {endTime - startTime}");
1Like

Comments

  1. @s_izumi

    Questioner

    回答ありがとうございます。

    (1)Whereの記述方法について
     特別意識してWhereを複数に分けていたわけではなかったので、
     (2)のコードのWhereをご指摘の1本に絞った版も載せます。
     

    ```cmd
    Where ×1 に要した時間 00:00:00.0010432
    ToList に要した時間 00:00:07.0930230
    ```

    (2)コンソール出力(回答して頂いたコードまま)

    ```cmd
    Where ×3 に要した時間 00:00:00.0021529
    ToList に要した時間 00:00:06.9929449
    ```

    (3)`Where().Take(100).ToList()とつなげた場合

    ```cmd
    Where ×1 に要した時間 00:00:00
    Take(100) に要した時間 00:00:00.0032364
    ToList に要した時間 00:00:00.8432526
    ```

    `ToList`がはやくなります。。
  2. ご回答いただきありがとうございます。
    お役に立てず申し訳ありませんでした。

    (3)で`Where`をまとめると`ToList`が短縮される現象は、ktz_aliasさんのご回答を読むと納得できます。
    `Where`では処理を終えずに制御が戻って(非同期)、`ToList`で終了待ち(同期)が発生するわけですね。
  3. @s_izumi

    Questioner

    (3)の場合ですが`Where`をまとめて短縮されたのではなく、
     `Take(100)`を入れたことにより短縮されたという認識です。謎は深まります。
  4. 正しく読めていませんでした。
    重ね重ね申し訳ありません。

やり取りを拝見して一点だけ。
SQL Serverはデータバッファのキャッシュやクエリプランのキャッシュを再利用します。
そのため1度実行したクエリを全く同じ条件で再度実行すると処理時間が短くなったりします。
従いまして処理時間を計測する場合はキャッシュをクリアして実行された方が宜しいかと思います。

DBCC DROPCLEANBUFFERS
1Like

Where()がデータベースクエリーとして処理されるようにTake()もデータベースクエリーとして処理されます。
Transact-SQLではオフセットとリミットの指定はORDER BYの一部なので、暗黙のORDER BYが指定されいる可能性があります。LAG()関数は非決定性なのでクエリーの内容によって結果が変化する可能性があります。Take()ありのログを確認すれば何かわかるかもしれません。

参考:
https://docs.microsoft.com/ja-jp/sql/t-sql/queries/select-order-by-clause-transact-sql?view=sql-server-ver15
https://docs.microsoft.com/ja-jp/sql/relational-databases/user-defined-functions/deterministic-and-nondeterministic-functions?view=sql-server-ver15

1Like

Comments

  1. @s_izumi

    Questioner

    おっしゃる通りでした。

    `Take()`がデータベースクリーではなく`Linq to Objects`(終端操作?)のメソッドだと勘違いしていました。
    `Take()`で取得するときには`SELECT文`に`TOP句`が追加されていることを確認できました。
    → `SELECT TOP(100) [columns..] FROM ...`

実行クエリをログ出力することができることを知りました。

db.Database.Log = Console.Write;

こんなに簡単にコンソール出力ができることは知りませんでした。
早速ログを確認しました。クエリはオーソドックスなものになりましたが、やはり7306ミリ秒かかりました。

 で接続を開きましたSELECT 
    [Extent1].[Key1] AS [Key1], 
    [Extent1].[Key2] AS [Key2], 
    [Extent1].[Key3] AS [Key3], 
    [Extent1].[Column4] AS [Column4], 
    [Extent1].[Column5] AS [Column5], 
    [Extent1].[Column6] AS [Column6]
    FROM [dbo].[V_DATA] AS [Extent1]
    WHERE ([Extent1].[Key1] = @p__linq__0) AND ([Extent1].[Key2] = @p__linq__1) AND ([Extent1].[Key3] <= cast(98 as decimal(18)))
-- p__linq__0: '201903' (Type = Decimal, IsNullable = false, Precision = 6)
-- p__linq__1: '160' (Type = Decimal, IsNullable = false, Precision = 3)
-- 2020/10/29 13:31:29 +09:00
 で実行しています-- 7306 ミリ秒で完了しました。結果: SqlDataReader

悩ましいことに、新しい質問が生まれました。
ログに吐かれたクエリをdb.Database.SqlQuery<List<V_DATA>>(/* ここにSQL文字列 */).ToList()で直接実行してみました。
すると170ミリ秒で結果が帰ってきたのです。

2020/10/29 13:40:23 +09:00
 で接続を閉じました2020/10/29 13:40:23 +09:00
 で接続を開きました SELECT /* 文字数のため省略 */
-- 2020/10/29 13:40:23 +09:00
 で実行しています-- 170 ミリ秒で完了しました。結果: SqlDataReader

内部での実行形式が全く違うのでしょうか?
改めてよろしくお願いします。

0Like

db.V_DATA.GetType().FullNamedb.Database.SqlQuery<List<V_ZM_DATA>>(/* SQL */).GetType().FullNameの結果を教えてください

0Like

Comments

  1. @s_izumi

    Questioner

    `FullName`の結果を記載します。

    ちなみに`V_DATA`ではない方のエンティティ名は修正漏れでございます。
    `V_DATA`と同義ですので、お忘れいただければ幸いです。

    - db.Database.SqlQuery<List<V_DATA>>("SQL").GetType().FullName
    `System.Data.Entity.Infrastructure.DbRawSqlQuery`1[[System.Collections.Generic.List`1[[appName.Apps.Entity.V_DATA, appName, Version=2020.8.18.1, Culture=neutral, PublicKeyToken=null]], mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089]]`

    - db.V_DATA.GetType().FullName;
    `System.Data.Entity.DbSet`1[[appName.Apps.Entity.V_DATA, appName, Version=2020.8.18.1, Culture=neutral, PublicKeyToken=null]]`
  2. クラス名を聞いたのは、全件を一度メモリに展開してから`Linq to Object`として実行されたのではと疑ったため。
    しかしクエリ作られてることがログから分かるから、さすがにそんなことはないと信じたい。

    しかし・・・

    [DbSet<TEntity> Class](https://docs.microsoft.com/en-us/dotnet/api/system.data.entity.dbset-1?view=entity-framework-6.2.0)のリファレンスの冒頭より引用
    > A DbSet represents the **collection of all entities in the context, or that can be queried from the database, of a given type.** (snip.)

    強調した部分が気になる・・・。
  3. (回答者コメント自体が引用構文だから、生のMarkdownがそのまま表示されるのか・・・うわぁ)
  4. @s_izumi

    Questioner

    英語はやんわりとしか把握できていませんが、
    `DbSet`であることがフルセット取ってきているのではとかそういう懸念でしょうか?

    ちなみにWhereを付与して型名を取るとこうなりました
    - `V_DATA.Where(条件).GetType().FullName;`
    System.Data.Entity.Infrastructure.DbQuery`1[[appName.Apps.Entity.V_DATA, appName, Version=2020.8.18.1, Culture=neutral, PublicKeyToken=null]]

    Take(100)の場合も同様(一致)でした
    - `db.V_DATA.Take(100).GetType().FullName;
    System.Data.Entity.Infrastructure.DbQuery`1[[appName.Apps.Entity.V_DATA, appName, Version=2020.8.18.1, Culture=neutral, PublicKeyToken=null]]

    GitHubのIssue案件ですかね。。

Your answer might help someone💌