(EFCore Best Practices) Identify Slow Commands with Logging and Tags

Enable SQL Logs

In the previous tutorial we turned off all logs so that we can focus on SQL query logs only.

The first thing we do now is to configure logging for SQL commands. For this, open the program.cs file and locate the statement where we added our project context. Just add a LogTo call next to the UseSqlServer call. This call logs all information to the console output.

// enable SQL logging 
// program.cs file 

// --- pre code not shown ---// 

builder.Services.AddRazorPages();

builder.Services.AddDbContext<MyProjectContext>
  (

  opt => opt.UseSqlServer(
                "Data Source=(localdb)\\ProjectModels;" +
                "Initial Catalog=mydb;Integrated Security=True;"
                )
            .LogTo(Console.WriteLine, LogLevel.Information) <=== ADD THIS

  );

var app = builder.Build();

// --- post code not shown ---// 

Now the log messages will show the time in milliseconds alongwith the SQL syntax that was executed on the database side.

Video Explanation (see it happen!)

Please watch the following youtube video:

Measuring the Time taken by a SELECT Query

Now let's practically run a SQL select query and display the time taken for completion.

Open the solution explorer and locate the Index.cshtml file. Double click and open it!

Recall that we already have a link called "Click to Seed" for seeding the database. Add an anchor link called "Select All Items" just next to it so that we can click it to run a SELECT query. This link is connected to a handler called Select_1.

  // add this in index.cshtml file 
  // (see the first tutorial of this series) 

<p>
  <a asp-page="Index" asp-page-handler="Select_1">Select All Items</a>
</p>

Next, open the backing class and add a handler called OnGetSelect_1Async. Inside this handler we have fired a query await _ctx.Items.ToListAsync(). This query will bring all the columns of all the records of the Items table.

  // add this in index.cshtml.cs file 
  // (see the first tutorial of this series) 

public async Task OnGetSelect_1Async()
{

  var list = await _ctx.Items 
                       .ToListAsync();

  Message = "Query Run: _ctx.Items.ToListAsync()";

}

Run the Project

Run the project to open the home page.

We observe that some log items have appeared in the console window. These SQL commands are due to the initialization of DbContext.

Come to the home page and click on the "Select All Items" link to fire the SELECT query and allow the query to finish.

// log for SELECT query 
// time taken see below Executed DbCommand (23ms)  

info: 19-Sep-22 16:22:45.484 RelationalEventId.CommandExecuted[20101] 
(Microsoft.EntityFrameworkCore.Database.Command)
      Executed DbCommand (23ms) [Parameters=[], CommandType='Text']

      SELECT [i].[ID], [i].[Name], [i].[Price]
      FROM [Items] AS [i]

We observe that the log window shows a log for the SELECT query. The command execution time has been mentioned in the brackets with Executed Command (time in milliseconds)

This is how we can read the log and the time consumed by a query.

Use of Tags with SELECT Queries

As you must have seen, the console log is fairly bulky and if you run too many queries then it might be difficult to locate a specific query.

Another problem is that the final SQL queries might look very different from the LINQ query. So there could be some difficulty in determining the log entry that corresponds to a particular LINQ query.

1. Tags are a bookmark in a bulky log
2. Tags help us identify a LINQ to SQL Command

The above problem can be solved by using query tags with the SELECT queries.

Open the Index.cshtml.cs file and modify the handler for the SELECT query to add a tag to the select query - _ctx.Items.TagWith("My Sum_1 Query"). The tag is added by using a method called TagWith. A tag is any readable string.

public async Task OnGetSelect_1Async()
{

  var list = await _ctx.Items
                        .TagWith("My Select_1 Query")  < ==== ADD THIS
                        .ToListAsync();

  Message = "Query Run: _ctx.Items.ToListAsync()";

}

// 1. Tags are a bookmark in a bulky log 
// 2. Tags help us identify a LINQ to SQL Command 

Run the project again and this time notice that the tag appears in the log window.

      
info: 19-Sep-22 16:22:45.484 RelationalEventId.CommandExecuted[20101]
(Microsoft.EntityFrameworkCore.Database.Command)
      Executed DbCommand (23ms) [Parameters=[], CommandType='Text']
      -- My Select_1 Query

      SELECT [i].[ID], [i].[Name], [i].[Price]
      FROM [Items] AS [i]

This is how we can use tags. We'll close the tutorial now!