DEV Community

Masui Masanori
Masui Masanori

Posted on • Updated on

【PostgreSQL】【EntityFramework Core】Debugging SQL 1

Intro

When my application causes performance problems, I should measure to find the bottle neck.
In this time, I try to measure codes what use EntityFramework 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>();
    }
}
Enter fullscreen mode Exit fullscreen mode

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; }
    }
}
Enter fullscreen mode Exit fullscreen mode

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; }
    }
}
Enter fullscreen mode Exit fullscreen mode

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>();
    }
}
Enter fullscreen mode Exit fullscreen mode

Generate sample data

To measure SQL performance, I generate sample data.

ISampleCreator.cs

using System.Threading.Tasks;

namespace BookStoreSample.Samples
{
    public interface ISampleCreator
    {
        Task CreateAsync();
    }
}
Enter fullscreen mode Exit fullscreen mode

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;
                }
            }
        }
    }
}
Enter fullscreen mode Exit fullscreen mode

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

}
Enter fullscreen mode Exit fullscreen mode

Output generated SQL

EntityFramework Core generates SQL from my C# codes.
To measure SQL, I want to get the generated SQL.

I can output them by "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"]);
            });
...
        }
...
Enter fullscreen mode Exit fullscreen mode

Because log level of outputting SQL is Information, so I must set Microsoft log level down.

appsettings.Development.json

{
  "Logging": {
    "LogLevel": {
      "Default": "Debug",
      "Microsoft": "Information",
      "Microsoft.Hosting.Lifetime": "Information"
    }
  }
}
Enter fullscreen mode Exit fullscreen mode

For example, when I execute this code,

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

I can get log like below.

...
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
...
Enter fullscreen mode Exit fullscreen mode

EXPLAIN, ANALYZE

To measure the SQL performance, I can use EXPLAIN and ANALYZE.

EXPLAIN ANALYZE SELECT c."Id", c."Name" FROM "Companies" AS c
Enter fullscreen mode Exit fullscreen mode

I add them before SQL queries and execute(For example on PgAdmin4), and I can get analyzed results.
The results includes execution time, what key is used for searching, etc.

This is the result on PgAdmin4.
Alt Text

Example

I try two examples and measure execution times.

Sample 1

SearchedCompany.cs

using BookStoreSample.Models;

namespace BookStoreSample.Books
{
    public class SearchedCompany
    {
        public Company? Company { get; set; }
        public Book? Book { get; set; }
    }
}
Enter fullscreen mode Exit fullscreen mode

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();
        }
    }
}
Enter fullscreen mode Exit fullscreen mode

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"
Enter fullscreen mode Exit fullscreen mode

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; }
    }
...
Enter fullscreen mode Exit fullscreen mode

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();
        }
...
Enter fullscreen mode Exit fullscreen mode

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"
Enter fullscreen mode Exit fullscreen mode

Planning Time

  • 0.341 ms

Execution Time

  • 2209.166 ms

In this case, I should choose Sample 2.
These differences are small. But the Sample 1's execution time is slower two times than Sample 2's.

Top comments (2)

Collapse
 
huseyinsimsek profile image
Huseyin Simsek

Thanks for post. I have a question. Is log output and explain, analyze query output same mean?
I understood to "explain, analyze query". Although, I didn't understand to clearly why you used log output.

Collapse
 
masanori_msl profile image
Masui Masanori

Thank you for reading my post.

Is log output and explain, analyze query output same mean?
I meant "log output" was outputting Entity Framework Core generated SQL as log, and "explain, analyze query output" was result of executing "EXPLAIN ANALYZE SELECT ~".

I want to analyze SQL and avoid writing slow queries. But I haven't understand "EXPLAIN" and "ANALYZE" result yet. So I just wrote execution times.