【PostgreSQL】【EntityFramework Core】SQL クエリのデバッグ 1

はじめに
とりあえずサンプルのデータを生成する
生成された SQL クエリをログ出力する
EXPLAIN, ANALYZE
実行例
Raw SQL クエリの実行

はじめに

作ったアプリにパフォーマンス上の問題が発生している場合、ボトルネックを探索する必要があるわけなんですが、今回は Entity Framework Core の処理を計測してみたいと思います。

Environments

.NET ver.5.0.100-rc.1.20452.10
Microsoft.EntityFrameworkCore ver.5.0.0-rc.1.20451.13
Npgsql.EntityFrameworkCore.PostgreSQL ver.5.0.0-rc1
NLog.Web.AspNetCore ver.4.9.3
Microsoft.AspNetCore.Mvc.NewtonsoftJson ver.5.0.0-rc.1.20451.17

Base Project

Company.cs

using System.ComponentModel.DataAnnotations;
using System.ComponentModel.DataAnnotations.Schema;

namespace BookStoreSample.Models
{
    public class Company
    {
        [Key]
        [DatabaseGenerated(DatabaseGeneratedOption.Identity)]
        public int Id { get; set; }
        [Required]
        public string Name { get; set; }
        
        public List<Book> Books { get; set; } = new List<Book>();
    }
}

Genre.cs

using System.ComponentModel.DataAnnotations;
using System.ComponentModel.DataAnnotations.Schema;

namespace BookStoreSample.Models
{
    public class Genre
    {
        [Key]
        [DatabaseGenerated(DatabaseGeneratedOption.Identity)]
        public int Id { get; set; }
        [Required]
        public string Name { get; set; }
    }
}

Book.cs

using System;
using System.ComponentModel.DataAnnotations;
using System.ComponentModel.DataAnnotations.Schema;

namespace BookStoreSample.Models
{
    public class Book
    {
        [Key]
        [DatabaseGenerated(DatabaseGeneratedOption.Identity)]
        public int Id { get; set; }
        [Required]
        public string Name { get; set; }
        [Column(TypeName = "timestamp with time zone")]
        public DateTime? PublishDate { get; set; }
        [ForeignKey(nameof(Company))]
        public int CompanyId { get; set; }
        [ForeignKey(nameof(Genre))]
        public int GenreId { get; set; }        
        public Company Company { get; set; }
        public Genre Genre { get; set; }
    }
}

BookStoreContext.cs

using Microsoft.EntityFrameworkCore;

namespace BookStoreSample.Models
{
    public class BookStoreContext: DbContext
    {
        public BookStoreContext(DbContextOptions<BookStoreContext> options)
            : base(options)
        {
        }
        public DbSet<Company> Companies => Set<Company>();
        public DbSet<Genre> Genres => Set<Genre>();
        public DbSet<Book> Books => Set<Book>();
    }
}

とりあえずサンプルのデータを生成する

ISampleCreator.cs

using System.Threading.Tasks;

namespace BookStoreSample.Samples
{
    public interface ISampleCreator
    {
        Task CreateAsync();
    }
}

SampleCreator.cs

using System;
using System.Threading.Tasks;
using BookStoreSample.Models;

namespace BookStoreSample.Samples
{
    public class SampleCreator: ISampleCreator
    {
        private readonly BookStoreContext _context;
        public SampleCreator(BookStoreContext context)
        {
            _context = context;
        }
        public async Task CreateAsync()
        {
            using(var transaction = _context.Database.BeginTransaction())
            {
                try
                {
                    for(var i = 0; i < 1000; i++)
                    {
                        _context.Companies.Add(new Company
                        {
                            Name = $"Company: {i}",
                        });
                    }
                    for(var i = 0; i < 1000; i++)
                    {
                        _context.Genres.Add(new Genre
                        {
                            Name = $"Genre: {i}",
                        });
                    }
                    await _context.SaveChangesAsync();
                    var random = new Random();
                    for(var i = 0; i < 1000000; i++)
                    {
                        _context.Books.Add(new Book
                        {
                            Name = $"Book: {i}",
                            PublishDate = DateTime.Now,
                            CompanyId = random.Next(999) + 1,
                            GenreId = random.Next(999) + 1,
                            Price = 600,
                        });
                    }
                    await _context.SaveChangesAsync();
                    transaction.Commit();
                }
                catch(Exception ex)
                {
                    transaction.Rollback();
                    throw ex;
                }
            }
        }
    }
}

HomeController.cs

using System.Threading.Tasks;
using Microsoft.AspNetCore.Mvc;
using Microsoft.Extensions.Logging;
using BookStoreSample.Samples;

namespace BookStoreSample.Controllers
{
    public class HomeController: Controller
    {
        private readonly ILogger<HomeController> _logger;
        private readonly ISampleCreator _sample;
        public HomeController(ILogger<HomeController> logger,
            ISampleCreator sample)
        {
            _logger = logger;
            _sample = sample;
        }
        [Route("Sample")]
        public async Task CreateSamples()
        {
            await _sample.CreateAsync();
        }
    }

}

生成された SQL クエリをログ出力する

EntityFramework Core は内部的に C# のコードから SQL クエリを生成するわけですが、実際どのようなものが生成されているのかが知りたいところ。

そのために「EnableSensitiveDataLogging」を使います。

Startup.cs

using Microsoft.AspNetCore.Builder;
using Microsoft.AspNetCore.Hosting;
using Microsoft.EntityFrameworkCore;
using Microsoft.Extensions.Configuration;
using Microsoft.Extensions.DependencyInjection;
using Newtonsoft.Json;
...

namespace BookStoreSample
{
    public class Startup
    {
        private readonly IConfiguration configuration;
        public Startup(IConfiguration config)
        {
            configuration = config;
        }
        public void ConfigureServices(IServiceCollection services)
        {
            services.AddControllers()
                .AddNewtonsoftJson(options =>
                    options.SerializerSettings.ReferenceLoopHandling = ReferenceLoopHandling.Ignore);
            services.AddDbContext<BookStoreContext>(options =>
            {
                options.EnableSensitiveDataLogging();
                options.UseNpgsql(configuration["ConnectionStrings"]);
            });
...
        }
...

この SQL クエリ出力のログレベルは Information なので、 Microsoft のログレベルを Information 以下にしておく必要があります(デフォルトだと Warning )。

appsettings.Development.json

{
  "Logging": {
    "LogLevel": {
      "Default": "Debug",
      "Microsoft": "Information",
      "Microsoft.Hosting.Lifetime": "Information"
    }
  }
}

で、例えばこのようなコードを実行すると。。。

public async Task<List<SearchedCompany>> SearchCompaniesAsync()
{
    return await _context.Companies
        .ToListAsync();
}

こんなログが出力されるわけです。

...
2020-10-06 18:20:17.1528|20101|INFO|Microsoft.EntityFrameworkCore.Database.Command|Executed DbCommand (9ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
SELECT c."Id", c."Name"
FROM "Companies" AS c |url: http://localhost/Company/Search|action: SearchCompany
...

EXPLAIN, ANALYZE

出力された SQL クエリのパフォーマンスを見たい場合に使えるのが「EXPLAIN」と「ANALYZE」。

EXPLAIN ANALYZE SELECT c."Id", c."Name" FROM "Companies" AS c

SQL クエリの前につけて(例えば) PgAdmin4 で実行してやると下記のような結果が得られます。

実行時間やどのキーを使って検索しているかなどの情報が得られます(今回は触れませんが)。

f:id:mslGt:20201010215559p:plain

PostgreSQL: Documentation: 13: 14.1. Using EXPLAIN

実行例

試しにいくつか実行してみます。

Sample 1

SearchedCompany.cs

using BookStoreSample.Models;

namespace BookStoreSample.Books
{
    public class SearchedCompany
    {
        public Company? Company { get; set; }
        public Book? Book { get; set; }
    }
}

BookSearchSample.cs

using System.Collections.Generic;
using System.Linq;
using System.Threading.Tasks;
using BookStoreSample.Models;
using Microsoft.EntityFrameworkCore;

namespace BookStoreSample.Books
{
    public class BookSearchSample: IBookSearchSample
    {
        private readonly BookStoreContext _context;
        public BookSearchSample(BookStoreContext context)
        {
            _context = context;
        }
        public async Task<List<SearchedCompany>> SearchCompaniesAsync()
        {
            return await _context.Companies
                .Include(c => c.Books)
                .Select(c => new SearchedCompany
                {
                    Company = c,
                    Book = c.Books
                        .OrderByDescending(b => b.Id).First(),
                })
                .ToListAsync();
        }
    }
}

Generated SQL

SELECT c."Id", c."Name", t0."Id", t0."CompanyId", t0."GenreId", t0."Name", t0."Price", t0."PublishDate", b0."Id", b0."CompanyId", b0."GenreId", b0."Name", b0."Price", b0."PublishDate"
FROM "Companies" AS c
LEFT JOIN (
    SELECT t."Id", t."CompanyId", t."GenreId", t."Name", t."Price", t."PublishDate"
    FROM (
        SELECT b."Id", b."CompanyId", b."GenreId", b."Name", b."Price", b."PublishDate", ROW_NUMBER() OVER(PARTITION BY b."CompanyId" ORDER BY b."Id" DESC) AS row
        FROM "Books" AS b
    ) AS t
    WHERE t.row <= 1
) AS t0 ON c."Id" = t0."CompanyId"
LEFT JOIN "Books" AS b0 ON c."Id" = b0."CompanyId"
ORDER BY c."Id", t0."Id", b0."Id"

Planning Time

0.942 ms

Execution Time

4941.233 ms

Sample 2

...
    public class SearchedCompany
    {
        public int CompanyId { get; set; }
        public string CompanyName { get; set; } = "";
        public Book? Book { get; set; }
    }
...

BookSearchSample.cs

...
        public async Task<List<SearchedCompany>> SearchCompaniesAsync()
        {
            return await _context.Companies
                .Include(c => c.Books)
                .Select(c => new SearchedCompany
                {
                    CompanyId = c.Id,
                    CompanyName = c.Name,
                    Book = c.Books
                        .OrderByDescending(b => b.Id).First(),
                })
                .ToListAsync();
        }
...

Generated SQL

SELECT c."Id", c."Name", t0."Id", t0."CompanyId", t0."GenreId", t0."Name", t0."Price", t0."PublishDate"
FROM "Companies" AS c
LEFT JOIN (
    SELECT t."Id", t."CompanyId", t."GenreId", t."Name", t."Price", t."PublishDate"
    FROM (
        SELECT b."Id", b."CompanyId", b."GenreId", b."Name", b."Price", b."PublishDate", ROW_NUMBER() OVER(PARTITION BY b."CompanyId" ORDER BY b."Id" DESC) AS row
        FROM "Books" AS b
    ) AS t
    WHERE t.row <= 1
) AS t0 ON c."Id" = t0."CompanyId"

Planning Time

0.341 ms

Execution Time

2209.166 ms

データの渡し方が変わるだけで結構実行時間が変わってくるあたり、面白くも怖くもありますね(パフォーマンスの問題がでなければそこまで気にしなくても良さそうですが)。

Raw SQL クエリの実行

上記の例でいくと、どちらかというとこんな SQL クエリを作りたい。

SELECT c."Id", c."Name" AS "CompanyName", b."Id" AS "BookId", b."Name" AS "BookName", 
b."PublishDate", b."GenreId", b."Price" FROM "Companies" c 
    INNER JOIN LATERAL(SELECT * FROM "Books" innerb
        WHERE innerb."CompanyId" = c."Id" ORDER BY innerb."Id" DESC LIMIT 1) b
    ON c."Id" = b."CompanyId"

EXPLAIN, ANALYZE の実行時間は 350.582 ms で、SQL の実行時間としては一番短くなりました。

ただ、 C＃からの生成だと実現がちょっと難しそうです。

となると SQL クエリをそのまま書いて実行してほしくなります。

ASP.NET Framework(Entity Framework 6) なら下記のように書けますが、 Entity Framework Core では存在しません。

using (var context = new BloggingContext())
{
    context.Database.ExecuteSqlCommand(
        "UPDATE dbo.Blogs SET Name = 'Another Name' WHERE BlogId = 1");
}

生の SQL クエリ-EF6 | Microsoft Docs

ではどうするか。

Entity Framework Core で Raw SQL を実行する

Raw SQL を実行するには「DbSet」を通す必要があります。

...
var blogs = context.Blogs
    .FromSqlRaw("EXECUTE dbo.GetMostPopularBlogsForUser {0}", user)
    .ToList();

生 SQL クエリ - EF Core | Microsoft Docs

それは良いのですが、下記のようにテーブルに紐づいていないクラスを扱いたい場合はどうするの？という疑問がわきます。

SELECT c."Id", c."Name" AS "CompanyName", b."Id" AS "BookId", b."Name" AS "BookName", 
b."PublishDate", b."GenreId", b."Price" FROM "Companies" c 
    INNER JOIN LATERAL(SELECT * FROM "Books" innerb
        WHERE innerb."CompanyId" = c."Id" ORDER BY innerb."Id" DESC LIMIT 1) b
    ON c."Id" = b."CompanyId"

SearchedCompany.cs

using System;
using System.ComponentModel.DataAnnotations;

namespace BookStoreSample.Books
{
    public class SearchedCompany
    {
        [Key]
        public int CompanyId { get; set; }
        public string CompanyName { get; set; } = "";
        public int BookId { get; set; }
        public string BookName { get; set; } = "";
        public DateTime? PublishDate { get; set; }
        public int GenreId { get; set; }
        public decimal? Price { get; set; }
    }
}

ずっと「DbSet」はテーブルに紐づくクラスに対してだけ使えるものだと思っていたのですが、実は上記のようなクラスも扱うことができます。

BookStoreContext.cs

using BookStoreSample.Books;
using Microsoft.EntityFrameworkCore;

namespace BookStoreSample.Models
{
    public class BookStoreContext: DbContext
    {
...
        public DbSet<SearchedCompany>  SearchedCompanies => Set<SearchedCompany>();
    }
}

これで、下記のような SQL から値を取得できるようになります。

BookSearchSample.cs

...
        public async Task<List<SearchedCompany>> SearchCompaniesAsync()
        {
            var sql = "SELECT c.\"Id\", c.\"Name\" AS \"CompanyName\", " +
                "b.\"Id\" AS \"BookId\", b.\"Name\" AS \"BookName\", " +
                "b.\"PublishDate\", b.\"GenreId\", b.\"Price\" FROM \"Companies\" c " +
                "INNER JOIN LATERAL(SELECT * FROM \"Books\" innerb " +
                "WHERE innerb.\"CompanyId\" = c.\"Id\" ORDER BY innerb.\"Id\" DESC LIMIT 1) b " +
                "ON c.\"Id\" = b.\"CompanyId\" ";
            return await _context.SearchedCompanies.FromSqlRaw(sql)
                .ToListAsync();
        }
...

重要なポイントとしては、「DbSet」に渡すクラスは「Key」属性か「Id」という名前を持つプロパティが必要で、これがないと実行時に例外が発生します。

Raw SQL を省いた場合は？

先ほどのサンプルから「FromSqlRaw」を省くと、空のデータが返るのでしょうか。

...
    public async Task<List<SearchedCompany>> SearchCompaniesAsync()
    {
        // Don't do this
        return await _context.SearchedCompanies
            .ToListAsync();
    }
...

答えとしては例外が発生します。

2020-10-10 07:04:17.1997|13|ERROR|Microsoft.AspNetCore.Server.Kestrel|Connection id "0HM3CJT1I07AV", Request id "0HM3CJT1I07AV:00000002": An unhandled exception was thrown by the application. Npgsql.PostgresException (0x80004005): 42P01: relation "SearchedCompanies" does not exist
   at Npgsql.NpgsqlConnector.<>c__DisplayClass160_0.<<DoReadMessage>g__ReadMessageLong|0>d.MoveNext()
...

気になるところとしては、下記の２例で例外が発生するかどうかを判別するには、クラスの中身を知っている、または名前くらいしか材料がない、というところ。

この辺良い解決方法はあるものなのでしょうか。

// OK
var companies = await _context.Companies
    .ToListAsync();
// Exception
var searchedCompanies = await _context.SearchedCompanies
    .ToListAsync();

Where 句

当然 Raw SQL クエリに Where ～を入れても良いわけですが、 SQL インジェクション対策などを考えなければならないわけです。

パラメータを渡す方法などもいくつかあるわけなのですが、「FromSqlRaw」は Linq と併用できるため、あまり複雑な条件でないのであれば下記のように Where 句は C# の世界に戻してしまうのが良さそうです。

BookSearchSample.cs

...
        public async Task<List<SearchedCompany>> SearchCompaniesAsync()
        {
            var sql = "SELECT c.\"Id\", c.\"Name\" AS \"CompanyName\", " +
                "b.\"Id\" AS \"BookId\", b.\"Name\" AS \"BookName\", " +
                "b.\"PublishDate\", b.\"GenreId\", b.\"Price\" FROM \"Companies\" c " +
                "INNER JOIN LATERAL(SELECT * FROM \"Books\" innerb " +
                "WHERE innerb.\"CompanyId\" = c.\"Id\" ORDER BY innerb.\"Id\" DESC LIMIT 1) b " +
                "ON c.\"Id\" = b.\"CompanyId\" ";
            return await _context.SearchedCompanies.FromSqlRaw(sql)
                .Where(c => c.CompanyId == 1)
                .ToListAsync();
        }
...

出力されたログによれば、 Linq の部分もちゃんと SQL に変換されています。

Generated SQL queries

SELECT s."Id", s."BookId", s."BookName", s."CompanyName", s."GenreId", s."Price", s."PublishDate"
FROM (
    SELECT c."Id", c."Name" AS "CompanyName", b."Id" AS "BookId", b."Name" AS "BookName", b."PublishDate", b."GenreId", b."Price" FROM "Companies" c INNER JOIN LATERAL(SELECT * FROM "Books" innerb WHERE innerb."CompanyId" = c."Id" ORDER BY innerb."Id" DESC LIMIT 1) b ON c."Id" = b."CompanyId" 
) AS s
WHERE s."Id" = 1

vaguely

和歌山に戻りました。ふらふらと色々なものに手を出す毎日。

【PostgreSQL】【EntityFramework Core】SQL クエリのデバッグ 1

はじめに

Environments

Base Project

Company.cs

Genre.cs

Book.cs

BookStoreContext.cs

とりあえずサンプルのデータを生成する

ISampleCreator.cs

SampleCreator.cs

HomeController.cs

生成された SQL クエリをログ出力する

Startup.cs

appsettings.Development.json

EXPLAIN, ANALYZE

実行例

Sample 1

SearchedCompany.cs

BookSearchSample.cs

Generated SQL

Planning Time

Execution Time

Sample 2

BookSearchSample.cs

Generated SQL

Planning Time

Execution Time

Raw SQL クエリの実行

Entity Framework Core で Raw SQL を実行する

SearchedCompany.cs

BookStoreContext.cs

BookSearchSample.cs

Raw SQL を省いた場合は？

Where 句

BookSearchSample.cs

Generated SQL queries