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

Tags:

Published at

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

Tags:

Published at

Don’t leave the profiler. Start your trial right from it.

As you may already know, you can try any of the profilers for a 30 days period. This is out there, so anyone can start experiencing with the profiler right away.

Last week we improved the process of starting a trial, so now you can register for a trial right from the application, no need to go to the profiler website anymore. In addition for that, when you register for a trial, you get a period of time that you can use the application right away, before you even need to go to your email and download the provided trial license.

Let me summarize to you how this work right now:

You started the application. If you didn’t provided yet a license, a dialog screen will appear, asking you to provide a valid license:

LicensePromote

 

In case that you want to try the profiler, you can get a free 30 trial license. Just click on “Click here to register for a 30 days trial” link. If you do so, the following dialog will appear, asking you to provide your full name, email address, and optionally the company name:

TrialRegistration

When you click on start trial, two things happen:

  1. You send a request for a trial license. You should get this license to the your email address (that you provided in the dialog).
  2. You get initial trial period of time to use the application without providing the license.

After the period of the initial trial is passed (it is 15 minutes), you’ll be asked again to provide a license file. This time, you should check your email for a trial license file, download the license file and locate it from the “Browse for Your License” dialog.

This is one of steps that we doing in order to make the application easier to start with. The next step is to provide you a Nuget package of the profiler, which will make starting using the profiler even easier.

Posted By: Fitzchak Yitzchaki

Tags:

Published at

Don’t leave the profiler. Start your trial right from it.

As you may already know, you can try any of the profilers for a 30 days period. This is out there, so anyone can start experiencing with the profiler right away.

Last week we improved the process of starting a trial, so now you can register for a trial right from the application, no need to go to the profiler website anymore. In addition for that, when you register for a trial, you get a period of time that you can use the application right away, before you even need to go to your email and download the provided trial license.

Let me summarize to you how this work right now:

You started the application. If you didn’t provided yet a license, a dialog screen will appear, asking you to provide a valid license:

LicensePromote

 

In case that you want to try the profiler, you can get a free 30 trial license. Just click on “Click here to register for a 30 days trial” link. If you do so, the following dialog will appear, asking you to provide your full name, email address, and optionally the company name:

TrialRegistration

When you click on start trial, two things happen:

  1. You send a request for a trial license. You should get this license to the your email address (that you provided in the dialog).
  2. You get initial trial period of time to use the application without providing the license.

After the period of the initial trial is passed (it is 15 minutes), you’ll be asked again to provide a license file. This time, you should check your email for a trial license file, download the license file and locate it from the “Browse for Your License” dialog.

This is one of steps that we doing in order to make the application easier to start with. The next step is to provide you a Nuget package of the profiler, which will make starting using the profiler even easier.

Posted By: Fitzchak Yitzchaki

Tags:

Published at

How do NHibernate Profiler support NHibernate 3 logging

Recently we added support for NHibernate 3 Internal Logger, which is exciting because it means that if you use NHibernate 3 then:

  • You don’t have to be depended on log4net anymore when you use the profiler appender.
  • The profiler appender now compatible with client profile apps.

When we started to look on how we can support NHibernate 3 Internal Logger, we found that this is pretty simple task to do: you would just have to provide an implementation of IInternalLogger and ILoggerFactory, and tell NHibernate to use your own custom logger, using the config file:

<appSettings>
     <add key="nhibernate-logger" value="MyApp.CustomLogger, MyApp"/>
</appSettings>

Well this is all nice and good for you, as a user of NHibernate, but for us things are more complicated. Let me start with what we did already before with NHibernate 2 and than I’ll show you the problem that we faced when we tried to support NHibernate 3 Internal Logger and how we solved it.

When you execute the NHibernateProfiler.Initialize(), what it basically does is to wrap the current NHibernate logger with our own logger. This way the profiler can get noticed when something interesting happens in you application, and act accordingly.

This is all good, and as I noted, was done before with NHibernate 2 too. Actually it was done too with NHibernate 3, as we do have already NHibernate 3 support in production for a week, so what new now? Well, until now in order to support NHibernate 3 we wrapped just the most important loggers that we need for the profiler to do it’s work, but not all of them. Why? because that we couldn’t do so easily. Consider the following line of code which you can find all around in NHibernate 3:

private static readonly IInternalLogger logger = LoggerProvider.LoggerFor(typeof(AbstractSessionImpl));

As you can see, this code initialized a logger at the startup of the application, way before you get the chance to call NHibernateProfiler.Initialize(). That means that when we get to set our own logger factory it’s already too late, because all of the static loggers are already initialized using the user’s logger. So how do we solved this issue and what did we do to replace all those static loggers with our own logger?

In order to solve this what we decided to do, is to generate a list of all the static loggers that NHibernate 3 has, it’s 144 loggers to be exact, and replace them at runtime (using reflection) with our own logger. In case you wonder how we inspect the NHibernate code and generate this list, I’ll give here the steps that we took:

In order to replace a particular NHibernate logger using reflection, we need 3 pieces of information about each logger:

  1. The class that contains the logger. It's any class that has a static field with the IInternalLogger type.
  2. The name of the field. This is the actually logger that we want to replace.
  3. The logger name. This value is the distinction between loggers, and when we ask the LoggerProvider for a logger, we have to provide this value.

For example, consider the code bellow taken from NHibernate. In this example the values are:

  1. ClassName:  NHibernate.Transaction.AdoNetWithDistributedTransactionFactory
  2. FieldName: logger
  3. LoggerName: NHibernate.Impl.AbstractSessionImpl

 

Logger

 

So, how do we get this values?

Our first take was to use NRefactory on the source code of NHibernate. Taking this approach I was able to easily take the ClassName and the FieldName of each logger but I couldn’t take the LoggerName. This is because that using NRefactory I couldn’t tell what AbstractSessionImpl full type name is actually is, as NRefactory looks on each file on their own. But what we actually need to look at is the NHibernate compiled assembly. This way we can tell what is exactly the actual logger type is.

In order to get those values from the compiled assembly, I can just use plain reflection. But in order to have more fun, I decided to use Mono.Cecil which was written specifically to inspect compiled assemblies. Using this approach I could just easily generate a list of all the static loggers in NHibernate.

But I did had one more problem though. Using this approach alone I couldn’t get the LoggerName easily, since this value is in the code that instantiate the logger. How would I get this value using reflection? Well, there is a way actually. If you think about it, what the C# compiler actually does when you instantiate a variable in the class level is to put the variable-initializer code in the default contactor. Take a look on the static constructor of the AdoNetWithDistributedTransactionFactory class using reflector, and you’ll see the following IL code:

ConstructorILCode

What it does here is fairly simple, it loads the token “NHibernate.Impl.AbstractSessionImpl” to the stack and than call the LoggerFor method of the LoggerProvider with this value. Well, I do can parse this IL code, and get the LoggerName. But it’s too complicated. I wished there is a better way to handle this.

Then we came up with a better idea. We can run NHibernate and just ask the logger instance what type is it. Well, I couldn’t do it with the default implementation of IInternalLogger as it don’t have a field with this value. But what I can do is to provide a custom logger, that will do just this task: provide the logger name. The code of this logger is fairly simple:

LoggerImplementation

So now we got a list of all the static loggers that we can now replace at runtime with our own logger. This was an easy task to do, and it means that we now fully supporting NHibernate 3. But what does it all means to you as the user of the profiler?

This is means that from now on, if you using NHibernate 3 and the latest build of the profiler, the NHibernate Profiler will catch every warn or error that NHibernate producing, and show you them. (One of the features that we’re considering to add to the next main version of the profiler is to add a detailed explanation of how to solve a common problems). We’re sure that this will help you a lot next time when you’ll need to debug your NHibernate 3 applications.

Posted by: Fitzchak Yitzchaki

Tags:

Published at

How do NHibernate Profiler support NHibernate 3 logging

Recently we added support for NHibernate 3 Internal Logger, which is exciting because it means that if you use NHibernate 3 then:

  • You don’t have to be depended on log4net anymore when you use the profiler appender.
  • The profiler appender now compatible with client profile apps.

When we started to look on how we can support NHibernate 3 Internal Logger, we found that this is pretty simple task to do: you would just have to provide an implementation of IInternalLogger and ILoggerFactory, and tell NHibernate to use your own custom logger, using the config file:

<appSettings>
     <add key="nhibernate-logger" value="MyApp.CustomLogger, MyApp"/>
</appSettings>

Well this is all nice and good for you, as a user of NHibernate, but for us things are more complicated. Let me start with what we did already before with NHibernate 2 and than I’ll show you the problem that we faced when we tried to support NHibernate 3 Internal Logger and how we solved it.

When you execute the NHibernateProfiler.Initialize(), what it basically does is to wrap the current NHibernate logger with our own logger. This way the profiler can get noticed when something interesting happens in you application, and act accordingly.

This is all good, and as I noted, was done before with NHibernate 2 too. Actually it was done too with NHibernate 3, as we do have already NHibernate 3 support in production for a week, so what new now? Well, until now in order to support NHibernate 3 we wrapped just the most important loggers that we need for the profiler to do it’s work, but not all of them. Why? because that we couldn’t do so easily. Consider the following line of code which you can find all around in NHibernate 3:

private static readonly IInternalLogger logger = LoggerProvider.LoggerFor(typeof(AbstractSessionImpl));

As you can see, this code initialized a logger at the startup of the application, way before you get the chance to call NHibernateProfiler.Initialize(). That means that when we get to set our own logger factory it’s already too late, because all of the static loggers are already initialized using the user’s logger. So how do we solved this issue and what did we do to replace all those static loggers with our own logger?

In order to solve this what we decided to do, is to generate a list of all the static loggers that NHibernate 3 has, it’s 144 loggers to be exact, and replace them at runtime (using reflection) with our own logger. In case you wonder how we inspect the NHibernate code and generate this list, I’ll give here the steps that we took:

In order to replace a particular NHibernate logger using reflection, we need 3 pieces of information about each logger:

  1. The class that contains the logger. It's any class that has a static field with the IInternalLogger type.
  2. The name of the field. This is the actually logger that we want to replace.
  3. The logger name. This value is the distinction between loggers, and when we ask the LoggerProvider for a logger, we have to provide this value.

For example, consider the code bellow taken from NHibernate. In this example the values are:

  1. ClassName:  NHibernate.Transaction.AdoNetWithDistributedTransactionFactory
  2. FieldName: logger
  3. LoggerName: NHibernate.Impl.AbstractSessionImpl

 

Logger

 

So, how do we get this values?

Our first take was to use NRefactory on the source code of NHibernate. Taking this approach I was able to easily take the ClassName and the FieldName of each logger but I couldn’t take the LoggerName. This is because that using NRefactory I couldn’t tell what AbstractSessionImpl full type name is actually is, as NRefactory looks on each file on their own. But what we actually need to look at is the NHibernate compiled assembly. This way we can tell what is exactly the actual logger type is.

In order to get those values from the compiled assembly, I can just use plain reflection. But in order to have more fun, I decided to use Mono.Cecil which was written specifically to inspect compiled assemblies. Using this approach I could just easily generate a list of all the static loggers in NHibernate.

But I did had one more problem though. Using this approach alone I couldn’t get the LoggerName easily, since this value is in the code that instantiate the logger. How would I get this value using reflection? Well, there is a way actually. If you think about it, what the C# compiler actually does when you instantiate a variable in the class level is to put the variable-initializer code in the default contactor. Take a look on the static constructor of the AdoNetWithDistributedTransactionFactory class using reflector, and you’ll see the following IL code:

ConstructorILCode

What it does here is fairly simple, it loads the token “NHibernate.Impl.AbstractSessionImpl” to the stack and than call the LoggerFor method of the LoggerProvider with this value. Well, I do can parse this IL code, and get the LoggerName. But it’s too complicated. I wished there is a better way to handle this.

Then we came up with a better idea. We can run NHibernate and just ask the logger instance what type is it. Well, I couldn’t do it with the default implementation of IInternalLogger as it don’t have a field with this value. But what I can do is to provide a custom logger, that will do just this task: provide the logger name. The code of this logger is fairly simple:

LoggerImplementation

So now we got a list of all the static loggers that we can now replace at runtime with our own logger. This was an easy task to do, and it means that we now fully supporting NHibernate 3. But what does it all means to you as the user of the profiler?

This is means that from now on, if you using NHibernate 3 and the latest build of the profiler, the NHibernate Profiler will catch every warn or error that NHibernate producing, and show you them. (One of the features that we’re considering to add to the next main version of the profiler is to add a detailed explanation of how to solve a common problems). We’re sure that this will help you a lot next time when you’ll need to debug your NHibernate 3 applications.

Posted by: Fitzchak Yitzchaki

Tags:

Published at

Scenes from the office

Posted by Ayende

That is me, working on a new feature for RavenDB:

WP_000167

Itamar is busy working on performance improvement for RavenDB (we are trying to avoid writing our own Json parser):

image

Alon is thinking about the website, it seems:

image

And Fitzchak is working on better Oracle support the secret feature for UberProf:

image

Tags:

Published at

Scenes from the office

Posted by Ayende

That is me, working on a new feature for RavenDB:

WP_000167

Itamar is busy working on performance improvement for RavenDB (we are trying to avoid writing our own Json parser):

image

Alon is thinking about the website, it seems:

image

And Fitzchak is working on better Oracle support the secret feature for UberProf:

image

Tags:

Published at