Viewing the SQL statements Entity Framework produces with interceptors
Recently I was involved in improving the performance and stability of a new, important, application at a client. The usage of Kendo MVC Grid was a great addition to the application but became notecable slower when the amount of data increased in turn of records in the database. In a later blog post I’ll explain more of the circumstances and the remedies that were put in place.
Meten is weten
as we like to say it in Dutch, or in English: to measure is to know (or to get insight).
I needed a baseline and measure what was being sent to the database. As the project was built with the usages of Entity Framework (6) I wanted to have a better debugging experience than only trust on watch windows and the like.
Bring in interceptors… With turning these on one can easily get to see the generated SQL statements by Entity Framework and, that was a nice addtion for my work at that moment, the amount of milliseconds spent to complete the SQL statement.
For this blog post I created a new ASP.NET MVC application by using the regular template and changing the authentication mode in the setup process to make use of a database to store users and roles in. You’re welcome to follow along and try it yourself 
.
Now open the web.config file that was generated by the template and scroll down to the Entity Framework settings:
<entityFramework>
<defaultConnectionFactory type="System.Data.Entity.Infrastructure.LocalDbConnectionFactory, EntityFramework">
<parameters>
<parameter value="mssqllocaldb" />
</parameters>
</defaultConnectionFactory>
<providers>
<provider invariantName="System.Data.SqlClient" type="System.Data.Entity.SqlServer.SqlProviderServices, EntityFramework.SqlServer" />
</providers>
</entityFramework>
To inject our interceptor simply add this after the closing </providers> element:
<interceptors>
<interceptor type="System.Data.Entity.Infrastructure.Interception.DatabaseLogger, EntityFramework">
<parameters>
<parameter value="C:\temp\SQLOutput.txt"/>
</parameters>
</interceptor>
</interceptors>
So now that part will look like
<entityFramework>
<defaultConnectionFactory type="System.Data.Entity.Infrastructure.LocalDbConnectionFactory, EntityFramework">
<parameters>
<parameter value="mssqllocaldb" />
</parameters>
</defaultConnectionFactory>
<providers>
<provider invariantName="System.Data.SqlClient" type="System.Data.Entity.SqlServer.SqlProviderServices, EntityFramework.SqlServer" />
</providers>
<interceptors>
<interceptor type="System.Data.Entity.Infrastructure.Interception.DatabaseLogger, EntityFramework">
<parameters>
<parameter value="C:\temp\SQLOutput.txt"/>
</parameters>
</interceptor>
</interceptors>
</entityFramework>
Simply run the application and login in (I already ran the application before and created a user account). Now open the file C:\temp\SQLOutput.txt in your favorite editor and notice the following information:
Opened connection at 4/26/2018 9:01:19 PM +02:00
select cast(serverproperty('EngineEdition') as int)
-- Executing at 4/26/2018 9:01:19 PM +02:00
-- Completed in 153 ms with result: SqlDataReader
Closed connection at 4/26/2018 9:01:19 PM +02:00
Opened connection at 4/26/2018 9:01:20 PM +02:00
IF db_id(N'aspnet-WebApplication4-20180426050117') IS NOT NULL SELECT 1 ELSE SELECT Count(*) FROM sys.databases WHERE [name]=N'aspnet-WebApplication4-20180426050117'
-- Executing at 4/26/2018 9:01:20 PM +02:00
-- Completed in 216 ms with result: 1
Closed connection at 4/26/2018 9:01:20 PM +02:00
Opened connection at 4/26/2018 9:01:20 PM +02:00
SELECT Count(*)
FROM INFORMATION_SCHEMA.TABLES AS t
WHERE t.TABLE_SCHEMA + '.' + t.TABLE_NAME IN ('dbo.AspNetRoles','dbo.AspNetUserRoles','dbo.AspNetUsers','dbo.AspNetUserClaims','dbo.AspNetUserLogins')
OR t.TABLE_NAME = 'EdmMetadata'
-- Executing at 4/26/2018 9:01:20 PM +02:00
-- Completed in 101 ms with result: 5
Closed connection at 4/26/2018 9:01:20 PM +02:00
Opened connection at 4/26/2018 9:01:20 PM +02:00
SELECT
[GroupBy1].[A1] AS [C1]
FROM ( SELECT
COUNT(1) AS [A1]
FROM [dbo].[__MigrationHistory] AS [Extent1]
WHERE [Extent1].[ContextKey] = @p__linq__0
) AS [GroupBy1]
-- p__linq__0: 'WebApplication4.Models.ApplicationDbContext' (Type = String, Size = 4000)
-- Executing at 4/26/2018 9:01:20 PM +02:00
-- Completed in 91 ms with result: SqlDataReader
Closed connection at 4/26/2018 9:01:21 PM +02:00
Opened connection at 4/26/2018 9:01:21 PM +02:00
SELECT TOP (1)
[Project1].[C1] AS [C1],
[Project1].[MigrationId] AS [MigrationId],
[Project1].[Model] AS [Model],
[Project1].[ProductVersion] AS [ProductVersion]
FROM ( SELECT
[Extent1].[MigrationId] AS [MigrationId],
[Extent1].[Model] AS [Model],
[Extent1].[ProductVersion] AS [ProductVersion],
1 AS [C1]
FROM [dbo].[__MigrationHistory] AS [Extent1]
WHERE [Extent1].[ContextKey] = @p__linq__0
) AS [Project1]
ORDER BY [Project1].[MigrationId] DESC
-- p__linq__0: 'WebApplication4.Models.ApplicationDbContext' (Type = String, Size = 4000)
-- Executing at 4/26/2018 9:01:21 PM +02:00
-- Completed in 84 ms with result: SqlDataReader
Closed connection at 4/26/2018 9:01:21 PM +02:00
Opened connection asynchronously at 4/26/2018 9:01:21 PM +02:00
SELECT TOP (1)
[Extent1].[Id] AS [Id],
[Extent1].[Email] AS [Email],
[Extent1].[EmailConfirmed] AS [EmailConfirmed],
[Extent1].[PasswordHash] AS [PasswordHash],
[Extent1].[SecurityStamp] AS [SecurityStamp],
[Extent1].[PhoneNumber] AS [PhoneNumber],
[Extent1].[PhoneNumberConfirmed] AS [PhoneNumberConfirmed],
[Extent1].[TwoFactorEnabled] AS [TwoFactorEnabled],
[Extent1].[LockoutEndDateUtc] AS [LockoutEndDateUtc],
[Extent1].[LockoutEnabled] AS [LockoutEnabled],
[Extent1].[AccessFailedCount] AS [AccessFailedCount],
[Extent1].[UserName] AS [UserName]
FROM [dbo].[AspNetUsers] AS [Extent1]
WHERE ((UPPER([Extent1].[UserName])) = (UPPER(@p__linq__0))) OR ((UPPER([Extent1].[UserName]) IS NULL) AND (UPPER(@p__linq__0) IS NULL))
-- p__linq__0: 'kris@azug.be' (Type = String, Size = 4000)
-- Executing asynchronously at 4/26/2018 9:01:21 PM +02:00
-- Completed in 24 ms with result: SqlDataReader
Closed connection at 4/26/2018 9:01:21 PM +02:00
Opened connection asynchronously at 4/26/2018 9:01:21 PM +02:00
SELECT
[Extent1].[Id] AS [Id],
[Extent1].[UserId] AS [UserId],
[Extent1].[ClaimType] AS [ClaimType],
[Extent1].[ClaimValue] AS [ClaimValue]
FROM [dbo].[AspNetUserClaims] AS [Extent1]
WHERE [Extent1].[UserId] = @p__linq__0
-- p__linq__0: 'd1a5811c-c43a-45c7-b971-64f3e876c739' (Type = String, Size = 4000)
-- Executing asynchronously at 4/26/2018 9:01:21 PM +02:00
-- Completed in 15 ms with result: SqlDataReader
Closed connection at 4/26/2018 9:01:21 PM +02:00
Opened connection asynchronously at 4/26/2018 9:01:21 PM +02:00
SELECT
[Extent1].[LoginProvider] AS [LoginProvider],
[Extent1].[ProviderKey] AS [ProviderKey],
[Extent1].[UserId] AS [UserId]
FROM [dbo].[AspNetUserLogins] AS [Extent1]
WHERE [Extent1].[UserId] = @p__linq__0
-- p__linq__0: 'd1a5811c-c43a-45c7-b971-64f3e876c739' (Type = String, Size = 4000)
-- Executing asynchronously at 4/26/2018 9:01:21 PM +02:00
-- Completed in 14 ms with result: SqlDataReader
Closed connection at 4/26/2018 9:01:21 PM +02:00
Opened connection asynchronously at 4/26/2018 9:01:21 PM +02:00
SELECT
[Extent1].[UserId] AS [UserId],
[Extent1].[RoleId] AS [RoleId]
FROM [dbo].[AspNetUserRoles] AS [Extent1]
WHERE [Extent1].[UserId] = @p__linq__0
-- p__linq__0: 'd1a5811c-c43a-45c7-b971-64f3e876c739' (Type = String, Size = 4000)
-- Executing asynchronously at 4/26/2018 9:01:21 PM +02:00
-- Completed in 14 ms with result: SqlDataReader
Closed connection at 4/26/2018 9:01:21 PM +02:00
Opened connection asynchronously at 4/26/2018 9:01:21 PM +02:00
SELECT
[Extent2].[Name] AS [Name]
FROM [dbo].[AspNetUserRoles] AS [Extent1]
INNER JOIN [dbo].[AspNetRoles] AS [Extent2] ON [Extent1].[RoleId] = [Extent2].[Id]
WHERE [Extent1].[UserId] = @p__linq__0
-- p__linq__0: 'd1a5811c-c43a-45c7-b971-64f3e876c739' (Type = String, Size = 4000)
-- Executing asynchronously at 4/26/2018 9:01:21 PM +02:00
-- Completed in 17 ms with result: SqlDataReader
Closed connection at 4/26/2018 9:01:21 PM +02:00
Now that’s a mighty lot of great information.
Note that with every run the file gets overwritten so if you want to keep some history of former sessions better rename the file to something meaningful to you before starting another run of your application.
Kris.
Leave a Comment