Hibernating Rhinos

Zero friction databases

Nuget packages and an example use of the profiler

Recently, we started to provide a Nuget package for each of the following profilers:

In case that you wonder how frequently those packages are updated, well, we push new packages to Nuget repository each time that we have a new build. That means that you get a new Nuget package or update to an existing package as soon as we have a new build.

In this post I’ll show you a possible problem that you may encounter when using an ORM tool, which will be solved using the profiler and leverage the Nuget package of the profiler. For this example I’m going to use EF4 CTP5 as the ORM tool with Entity Framework Profiler, but the same example is applicable for all of the others ORM/Profilers that we support.

Let us consider the following application example, which makes a use of the Northwind sample database with the following domain model:

public class Customer
{
    public string CustomerId { get; set; }
    public string ContactName { get; set; }
    public string ContactTitle { get; set; }
    public string Address { get; set; }
    public string City { get; set; }
    public string Region { get; set; }
    public string PostalCode { get; set; }
    public string Country { get; set; }
    public string Phone { get; set; }
    public string Fax { get; set; }

    public virtual ICollection<Order> Orders { get; set; }
}
    
public class Order
{
    public int OrderId { get; set; }
    public string CustomerId { get; set; }
    public DateTime OrderDate { get; set; }
    public DateTime RequiredDate { get; set; }
    public DateTime ShippedDate { get; set; }
    public string ShipName { get; set; }
    public string ShipAddress { get; set; }
    public string ShipCity { get; set; }
    public string ShipRegion { get; set; }
    public string ShipPostalCode { get; set; }
    public string ShipCountry { get; set; }

    public virtual ICollection<OrderDetails> OrderDetails { get; set; }
}

public class OrderDetails
{
    public int OrderId { get; set; }
    public int ProductId { get; set; }
    public decimal? UnitPrice { get; set; }
    public Int16 Quantity { get; set; }
    public Single Discount { get; set; }

    public virtual Product Product { get; set; }
}

public class Product
{
    public int ProductId { get; set; }
    public int CategoryId { get; set; }
    public string ProductName { get; set; }
    public decimal? UnitPrice { get; set; }
    public bool Discontinued { get; set; }
}

public class Northwind : DbContext
{
    public DbSet<Order> Orders { get; set; }
    public DbSet<Customer> Customers { get; set; }

    protected override void OnModelCreating(DbModelBuilder modelBuilder)
    {
        modelBuilder.Conventions.Remove<IncludeMetadataConvention>();
        modelBuilder.Entity<OrderDetails>()
            .HasKey(x => new { x.OrderId, x.ProductId })
            .ToTable("Order Details");
    }
}

As you can see, we have here a Customer entity which has many Orders, which in turn have many OrderDetails, which has a product. We also have here a Northwind context class that we will use in order to query the database.

The main scenario that we are going examine is the Orders action which takes a customer ID and prints a list of all of the orders that the customer had made. Consider the following Orders controller action and Orders view:

public class CustomerController : Controller
{
    private readonly Northwind _northwind = new Northwind();

    public ActionResult Orders(string customerId)
    {
        var customer = GetCustomer(customerId);
        if (customer == null)
            return HttpNotFound();
            
        var viewModel = new CustomerOrdersViewModel
        {
            Customer = customer,
            Orders = GetCustomerOrders(customer)
        };
        return View(viewModel);
    }

    private Customer GetCustomer(string customerId)
    {
        var customers = from customer1 in _northwind.Customers
                        where customer1.CustomerId == customerId
                        select customer1;
        var customer = customers.SingleOrDefault();
        return customer;
    }

    private IList<Order> GetCustomerOrders(Customer customer)
    {
        return customer.Orders.OrderByDescending(o => o.OrderDate).ToList();
    }
}
Orders.cshtml:
model CustomerOrdersViewModel
@{
    ViewBag.Title = "Orders for " + @Model.Customer.ContactName;
}
<div><strong>Customer ID:</strong> @Model.Customer.CustomerId</div>
<div><strong>Customer Name:</strong> @Model.Customer.ContactName</div>
<div><strong>Orders:</strong>
    <div class="orders">
        @foreach (var order in Model.Orders)
        {
            <div><strong>Order ID:</strong> @order.OrderId</div>
            <div><strong>Order Date:</strong> @order.OrderDate</div>
            <div><strong>Products:</strong>
                <div class="products">
                    @foreach (var orderDetail in order.OrderDetails)
                    {
                        <div class="product">
                            <div><strong>Product Name:</strong> @orderDetail.Product.ProductName</div>
                            <div><strong>Quantity:</strong> @orderDetail.Quantity</div>
                            <div><strong>Unit Price:</strong> @String.Format("{0:c}", orderDetail.UnitPrice)</div>
                        </div>
                    }
                </div>
            </div>
        }
    </div>
</div>

Running the code for customer ID “KOENE” will produce the following output (In order to save some space, I’m attaching here just part of the output):

Customer ID: KOENE
Customer Name: Philip Cramer
Orders:
Order ID: 11028
Order Date: 4/16/1998 12:00:00 AM
Products:
Product Name: Pâté chinois
Quantity: 35
Unit Price: $24.00
Product Name: Raclette Courdavault
Quantity: 24
Unit Price: $55.00
Order ID: 10893
Order Date: 2/18/1998 12:00:00 AM
Products:
Product Name: Northwoods Cranberry Sauce
Quantity: 30
Unit Price: $40.00
Product Name: Guaraná Fantástica
Quantity: 10
Unit Price: $4.50
Product Name: Thüringer Rostbratwurst
Quantity: 24
Unit Price: $123.79
Product Name: Nord-Ost Matjeshering
Quantity: 35
Unit Price: $25.89
Product Name: Inlagd Sill
Quantity: 20
Unit Price: $19.00
Order ID: 10849
Order Date: 1/23/1998 12:00:00 AM
Products:
Product Name: Aniseed Syrup
Quantity: 49
Unit Price: $10.00
Product Name: Gumbär Gummibärchen
Quantity: 18
Unit Price: $31.23
Order ID: 10817
Order Date: 1/6/1998 12:00:00 AM
Products:
Product Name: Gumbär Gummibärchen
Quantity: 40
Unit Price: $31.23
Product Name: Côte de Blaye
Quantity: 30
...

You may execute this code against a local database without notice any problem with it, because this code does what it supposed to. But as soon as you’ll use this code in production environment when you have to use a remote database, you’ll find that this method is very slow. Why? And how can I make this method run faster?

The way to solve these kinds of problems is to look on the actual SQL queries that the ORM was generated for you. This way you can have a better idea of what is going on under the scene which is important step before you can make your code to be more efficient. In this example, we have to look on the actual queries that EF4 generated for us. We’ll make a use of the Entity Framework Profiler, which will let you to see the generated SQL code in a very convenient way and will also produce warnings if it encounters any problem in the way that you use the ORM.

The easy way to start using the profiler is to add a NuGet Package Reference to your project:

NugetPackages

When you click on Install button, you’ll be asked to accept the End User License Agreement:

LicenseAcceptance

When you do so, the following actions will be take place:

  • A new assembly reference is added to your project: HibernatingRhinos.Profiler.Appender.dll or HibernatingRhinos.Profiler.Appender.v4.0.dll depending on the .net framework version target of you project.
  • A new file will be added to your code, which will be called on the startup of your application.
  • The profiler is now running on your computer.

If this is the first time that you are running the profiler on your computer, you will get the following screen:

LicensePromote

If you do, than you have to provide your license file or if you don’t have a license file you can start a 30 days trial, as described in this blog post. In short, when you’ll start a 30 days trial, you’ll be able to use the profiler immediately for 15 minutes, then you’ll be asked to provide the trial license file that we have sent to your email address.

Now that the Entity Framework Profiler is running, we run the project again but this time the profiler will catch every query that the ORM made to the database:

ProfilerResult

As we can see, the ORM generated for us 45 queries!. A query for each OrderDetail and a query for each product. I highlighted all the statements, and you can see that it took us 10 seconds! to query the database. (As I noted before, we are using an external database).

In addition, as you can see in the right side of the statements, the profiler is warning us that something is wrong with these queries. Let’s click on one of the red warnings and look in the Alerts pane:

NPlustOne

As you can see, there is a SELECT N+1 alert here. If you click on the read more link you’ll forwarded to a detailed explanation of this common error and a suggestion of how to solve it. Following the suggestion, now we are eager loading the OrderDetails and Products entities using the Include method:

private IList<Order> GetCustomerOrders(string customerId)
{
    var orders = from order in _northwind.Orders.Include("OrderDetails").Include("OrderDetails.Product")
                 where order.CustomerId == customerId
                 orderby order.OrderDate descending
                 select order;
    return orders.ToList();
}

Now, if we run the code again and look in the profiler, we can see that we generate now just two SQL queries, instead of 45, which is much faster.

ProfilerSolutionOutput

Let’s summarize what we did here. We got a problem in our application when one of our methods run slower than expected. We install the profiler using NuGet and were quickly been able to see that there is a SELECT N+1 issue in our code. We find out very quickly that we have to eager load some of our entities and that we can make use of the .Include() method in order to do so. Now that we have the NuGet packages of the profilers, getting the profiler running in order to solve a similar problem is quick and easy.

Posted By: Fitzchak Yitzchaki

Comments

No comments posted yet.

Comments have been closed on this topic.