【PostgreSQL】【EntityFramework Core】Debugging SQL 1

Masui Masanori - Oct 6 '20 - - Dev Community

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.

Image
The JavaScript community should focus on making AI/ML accessible to the language, just as it is with Python.

javascript, typescript, ai, webdev
Image
Glam up my markup

devchallenge, frontendchallenge, css, javascript
Image
Test Post
Image
My Experience with the MageGee 60% Compact Keyboard

keyboard, product, programming
Image
Today's Trending Projects: FTP Weak Password Scanner Using Python and More

labex, programming, projects
Image
Stetragy of Crafting Effective Calls to Action for Enhanced Conversions
Image
Embracing Surface-Level Understanding: A Key to Mastering Software Engineering
Image
Good opportunity for Blockchain Expert

blockchaindevelopment
Image
Need Help Blockchain experts

blockchain
Image
LangGraph.js Concept Guide

langchain, llm, openai, chatgpt
Image
Coding For Everyone: Accessibility in Web Development.

webdev, a11y, coding, testing
Image
Memory Management in Rust

webdev, javascript, beginners, programming
Image
Velo Credit App Customer. Care Helpline Number =(91)((+7864967O58-)) +/{+983117O35O Call Now.Velo

javascript
Image
REVENANT CYBER HACKER / CRYPTO SCAM RECOVERY SERVICES
Image
Velo Credit App Customer. Care Helpline Number =(91)((+7864967O58-)) +/{+983117O35O Call Now.

javascript, beginners, webdev
Image
Pre-Cloud Development Chatbot with Streamlit, Langchain, OpenAI and MongoDB Atlas Vector Search

rag, pdftextextraction, python, vectordatabase
Image
Velo Credit App Customer. Care Helpline Number =(91)((+7864967O58-)) +/{+983117O35O Call Now.

webdev
Image
[Game of Purpose] Day 72

gamedev
Image
Building a CRUD Application with Ruby on Rails: Step-by-Step Guide

rails, ruby, learning
. . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . .
Terabox Video Player