EF Core diagnosis and features with MS SQL Server

This article shows how Entity Framework Core messages can be logged, and compared using the SQL Profiler and also some of the cool new 1.1 features, but not all. All information can be found on the links at the bottom and especially the excellent docs for EF Core.

Code: https://github.com/damienbod/EFCoreFeaturesAndDiag

project.json with EF Core packages and tools

When using EF Core, you need to add the correct packages and tools to the project file. EF Core 1.1 has a lot of changes compared to 1.0. You should not mix the different versions from EF Core. Use either the LTS or the current version, but not both. The Microsoft.EntityFrameworkCore.Tools.DotNet is a new package which came with 1.1.

{
    "dependencies": {
        "Microsoft.AspNetCore.Diagnostics.EntityFrameworkCore": "1.1.0",   
        "Microsoft.EntityFrameworkCore": "1.1.0",
        "Microsoft.EntityFrameworkCore.Relational": "1.1.0",
        "Microsoft.EntityFrameworkCore.SqlServer": "1.1.0",
        "Microsoft.EntityFrameworkCore.SqlServer.Design": {
            "version": "1.1.0",
            "type": "build"
        },
        "Microsoft.EntityFrameworkCore.Tools": "1.1.0-preview4-final",
        ...
    },

    "tools": {
        "Microsoft.EntityFrameworkCore.Tools.DotNet": "1.1.0-preview4",
        ...
    },

    ...

}

Startup ConfigureServices

The database and EF Core can be configured and usually is in the Startup ConfigureServices method for an ASP.NET Core application. The following code sets up EF Core to use a MS SQL server database and uses the new retry on failure method from version 1.1.

public void ConfigureServices(IServiceCollection services)
{
	var sqlConnectionString = Configuration.GetConnectionString("DataAccessMsSqlServerProvider");

	services.AddDbContext<DomainModelMsSqlServerContext>(
		options => options.UseSqlServer(
			sqlConnectionString,
			sqlServerOptions => sqlServerOptions.EnableRetryOnFailure()
		)
	);

	services.AddScoped<IDataAccessProvider, DataAccessMsSqlServerProvider>();

	services.AddMvc().AddJsonOptions(options =>
	{
		options.SerializerSettings.ReferenceLoopHandling = ReferenceLoopHandling.Ignore;
	});
}

Data Model

As with version 1.1, Entity Framework Core can now use backing fields to connect with the database and not just properties. This opens up a whole new world of possibilities of how entities can be designed or used. The _description field from the following DataEventRecord entity will be used for the database.

public class DataEventRecord
{
	private string _description;

	[Key]
	public long DataEventRecordId { get; set; }

	public string Name { get; set; }

	public string MadDescription {
		get { return _description; }
		set { _description = value;  }
	}

	public DateTime Timestamp { get; set; }

	[ForeignKey("SourceInfoId")]
	public SourceInfo SourceInfo { get; set; }

	public long SourceInfoId { get; set; }
}

DbContext with Field and Column mapping

In the OnModelCreating method from the DBContext, the description field is mapped to the column description for the MadDescription property. The context also configures shadow properties to add updated timestamps.

using System;
using System.Linq;
using Microsoft.EntityFrameworkCore;

namespace EFCoreFeaturesAndDiag.Model
{
    // >dotnet ef migration add testMigration
    public class DomainModelMsSqlServerContext : DbContext
    {
        public DomainModelMsSqlServerContext(DbContextOptions<DomainModelMsSqlServerContext> options) :base(options)
        { }
        
        public DbSet<DataEventRecord> DataEventRecords { get; set; }

        public DbSet<SourceInfo> SourceInfos { get; set; }

        protected override void OnModelCreating(ModelBuilder builder)
        {
            builder.Entity<DataEventRecord>().HasKey(m => m.DataEventRecordId);
            builder.Entity<SourceInfo>().HasKey(m => m.SourceInfoId);

            // shadow properties
            builder.Entity<DataEventRecord>().Property<DateTime>("UpdatedTimestamp");
            builder.Entity<SourceInfo>().Property<DateTime>("UpdatedTimestamp");

            builder.Entity<DataEventRecord>()
                .Property(b => b.MadDescription)
                .HasField("_description")
                .HasColumnName("_description");

            base.OnModelCreating(builder);
        }

        public override int SaveChanges()
        {
            ChangeTracker.DetectChanges();

            updateUpdatedProperty<SourceInfo>();
            updateUpdatedProperty<DataEventRecord>();

            return base.SaveChanges();
        }

        private void updateUpdatedProperty<T>() where T : class
        {
            var modifiedSourceInfo =
                ChangeTracker.Entries<T>()
                    .Where(e => e.State == EntityState.Added || e.State == EntityState.Modified);

            foreach (var entry in modifiedSourceInfo)
            {
                entry.Property("UpdatedTimestamp").CurrentValue = DateTime.UtcNow;
            }
        }
    }
}

Logging and diagnosis

Logging for EF Core is configured for this application as described here in the Entity Framework Core docs.

The EfCoreFilteredLoggerProvider.

using Microsoft.Extensions.Logging;
using System;
using System.Linq;
using Microsoft.EntityFrameworkCore.Storage.Internal;

namespace EFCoreFeaturesAndDiag.Logging
{
    public class EfCoreFilteredLoggerProvider : ILoggerProvider
    {
        private static string[] _categories =
        {
            typeof(Microsoft.EntityFrameworkCore.Storage.Internal.RelationalCommandBuilderFactory).FullName,
            typeof(Microsoft.EntityFrameworkCore.Storage.Internal.SqlServerConnection).FullName
        };

        public ILogger CreateLogger(string categoryName)
        {
            if (_categories.Contains(categoryName))
            {
                return new MyLogger();
            }

            return new NullLogger();
        }

        public void Dispose()
        { }

        private class MyLogger : ILogger
        {
            public bool IsEnabled(LogLevel logLevel)
            {
                return true;
            }

            public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
            {
                Console.WriteLine(formatter(state, exception));
            }

            public IDisposable BeginScope<TState>(TState state)
            {
                return null;
            }
        }

        private class NullLogger : ILogger
        {
            public bool IsEnabled(LogLevel logLevel)
            {
                return false;
            }

            public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
            { }

            public IDisposable BeginScope<TState>(TState state)
            {
                return null;
            }
        }
    }
}

The EfCoreLoggerProvider class:

using Microsoft.Extensions.Logging;
using System;
using System.IO;

namespace EFCoreFeaturesAndDiag.Logging
{
    public class EfCoreLoggerProvider : ILoggerProvider
    {
        public ILogger CreateLogger(string categoryName)
        {
            return new MyLogger();
        }

        public void Dispose()
        { }

        private class MyLogger : ILogger
        {
            public bool IsEnabled(LogLevel logLevel)
            {
                return true;
            }

            public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
            {
                File.AppendAllText(@"C:\temp\log.txt", formatter(state, exception));
                Console.WriteLine(formatter(state, exception));
            }

            public IDisposable BeginScope<TState>(TState state)
            {
                return null;
            }
        }
    }
}

The EfCoreLoggerProvider logger is then added in the DataAccessMsSqlServerProvider constructor.

public class DataAccessMsSqlServerProvider : IDataAccessProvider
{
	private readonly DomainModelMsSqlServerContext _context;
	private readonly ILogger _logger;

	public DataAccessMsSqlServerProvider(DomainModelMsSqlServerContext context, ILoggerFactory loggerFactory)
	{
		_context = context;
		loggerFactory.AddProvider(new EfCoreLoggerProvider());
		_logger = loggerFactory.CreateLogger("DataAccessMsSqlServerProvider");

	}

The EF Core logs

Here’s the logs produced for an insert command:

Executing action method AspNet5MultipleProject.Controllers.DataEventRecordsController.AddTest (EFCoreFeaturesAndDiag) with arguments ((null)) - ModelState is ValidOpening connection to database 'EfcoreTest' on server 'N275\MSSQLSERVER2014'.Beginning transaction with isolation level 'Unspecified'.Executed DbCommand (60ms) [Parameters=[@p0='?' (Size = 4000), @p1='?' (Size = 4000), @p2='?', @p3='?'], CommandType='Text', CommandTimeout='30']
SET NOCOUNT ON;
INSERT INTO [SourceInfos] ([Description], [Name], [Timestamp], [UpdatedTimestamp])
VALUES (@p0, @p1, @p2, @p3);
SELECT [SourceInfoId]
FROM [SourceInfos]
WHERE @@ROWCOUNT = 1 AND [SourceInfoId] = scope_identity();Executed DbCommand (1ms) [Parameters=[@p4='?' (Size = 4000), @p5='?' (Size = 4000), @p6='?', @p7='?', @p8='?'], CommandType='Text', CommandTimeout='30']
SET NOCOUNT ON;
INSERT INTO [DataEventRecords] ([_description], [Name], [SourceInfoId], [Timestamp], [UpdatedTimestamp])
VALUES (@p4, @p5, @p6, @p7, @p8);
SELECT [DataEventRecordId]
FROM [DataEventRecords]
WHERE @@ROWCOUNT = 1 AND [DataEventRecordId] = scope_identity();Committing transaction.Closing connection to database 'EfcoreTest' on server 'N275\MSSQLSERVER2014'.Executed action method AspNet5MultipleProject.Controllers.DataEventRecordsController.AddTest (EFCoreFeaturesAndDiag), returned result Microsoft.AspNetCore.Mvc.OkObjectResult.No information found on request to perform content negotiation.Selected output formatter 'Microsoft.AspNetCore.Mvc.Formatters.StringOutputFormatter' and content type 'text/plain; charset=utf-8' to write the response.Executing ObjectResult, writing value Microsoft.AspNetCore.Mvc.ControllerContext.Executed action AspNet5MultipleProject.Controllers.DataEventRecordsController.AddTest (EFCoreFeaturesAndDiag) in 1181.5083msConnection id "0HL13KIK3Q7QG" completed keep alive response.Request finished in 1259.1888ms 200 text/plain; charset=utf-8Request starting HTTP/1.1 GET http://localhost:46799/favicon.ico  The request path /favicon.ico does not match an existing fileRequest did not match any routes.Connection id "0HL13KIK3Q7QG" completed keep alive response.Request finished in 36.2143ms 404 

MS SQL Profiler

And here’s the corresponding insert request in the SQL Profiler from MS SQL Server.

sqlprofiler_efcore_01

EF Core Find

One feature which was also implemented in EF Core 1.1 is the Find method, which is very convenient to use.

public DataEventRecord GetDataEventRecord(long dataEventRecordId)
{
	return _context.DataEventRecords.Find(dataEventRecordId);
}

EF Core is looking really good and with the promise of further features and providers, this is becoming really exciting.

Links:

https://docs.microsoft.com/en-us/ef/

https://docs.microsoft.com/en-us/ef/core/miscellaneous/logging

https://blogs.msdn.microsoft.com/dotnet/2016/11/16/announcing-entity-framework-core-1-1/

https://msdn.microsoft.com/en-us/library/ms181091.aspx

https://github.com/aspnet/EntityFramework/releases/tag/rel%2F1.1.0

https://damienbod.com/2016/01/07/experiments-with-entity-framework-7-and-asp-net-5-mvc-6/

https://damienbod.com/2016/01/11/asp-net-5-with-postgresql-and-entity-framework-7/

https://damienbod.com/2015/12/05/asp-net-5-mvc-6-file-upload-with-ms-sql-server-filetable/

https://damienbod.com/2016/09/22/setting-the-nlog-database-connection-string-in-the-asp-net-core-appsettings-json/

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

%d bloggers like this: