One of the things that makes working with the profiler easier is the fact that it gives you not just information, but information in context.

I was working with an app using Rhino Service Bus, and it really bothered me that I couldn’t immediately figure out what was the trigger for a session. When using ASP.Net or WCF, the profiler can show the URL that triggered the request, but when we are not using a url based mechanism, that turns out to be much harder.

So I set out to fix that, you can see the results below:

This session was generated by a message batch containing messages for MyBooks, MyQueue, etc.

The integration is composed of two parts, first, from the profiler perspective, you now have the ProfilerIntegration.CurrentSessionContext property, which allows you to customize how the profiler detects the current context.

The second part is the integration from the application framework itself, you can see how I did that for Rhino Service Bus, which will dynamically detect the presence of the profiler and fill the appropriate values. The result makes it a lot easier to track down what is going on.

I got several requests for this, so I am making Uber Prof itself available for purchasing.

What is Uber Prof?

It is a short hand way of saying: All the OR/M profilers that we make.

An Uber Prof license gives you the ability to use:

• NHibernate Profiler
• Hibernate Profiler
• Linq to SQL Profiler
• Entity Framework Profiler

And it will automatically give you the ability to use any additional profilers that we will create. And yes, there is an upgrade path if you already purchased a single profiler license and would like to upgrade to Uber Prof.

One of the things that I began doing since starting to work on multiple OR/M Profilers is to compare how all of them are handling a particular task. This is by no means a comparative analysis, but it is an interesting data point.

The scenario in question is loading a blog with all its posts and comments.

Let us start with NHibernate:

var blogs = s.CreateQuery(
    @"from Blog b 
        left join fetch b.Posts p 
        left join fetch p.Comments 
    where b.Id = :id")
    .SetParameter("id", 1)
    .List<Blog>();

Will generate the following SQL 

select blog0_.Id             as Id7_0_,
       posts1_.Id            as Id0_1_,
       comments2_.Id         as Id2_2_,
       blog0_.Title          as Title7_0_,
       blog0_.Subtitle       as Subtitle7_0_,
       blog0_.AllowsComments as AllowsCo4_7_0_,
       blog0_.CreatedAt      as CreatedAt7_0_,
       posts1_.Title         as Title0_1_,
       posts1_.Text          as Text0_1_,
       posts1_.PostedAt      as PostedAt0_1_,
       posts1_.BlogId        as BlogId0_1_,
       posts1_.UserId        as UserId0_1_,
       posts1_.BlogId        as BlogId0__,
       posts1_.Id            as Id0__,
       comments2_.Name       as Name2_2_,
       comments2_.Email      as Email2_2_,
       comments2_.HomePage   as HomePage2_2_,
       comments2_.Ip         as Ip2_2_,
       comments2_.Text       as Text2_2_,
       comments2_.PostId     as PostId2_2_,
       comments2_.PostId     as PostId1__,
       comments2_.Id         as Id1__
from   Blogs blog0_
       left outer join Posts posts1_
         on blog0_.Id = posts1_.BlogId
       left outer join Comments comments2_
         on posts1_.Id = comments2_.PostId
where  blog0_.Id = 1 /* @p0 */

This result in a fairly simple query plan:

However, you should note that this also result in a Cartesian product, which may not be what you wanted.

Linq to SQL doesn’t really provide a good way to express what I wanted, but it does get the job done:

var dataLoadOptions = new DataLoadOptions();
dataLoadOptions.LoadWith<Blog>(x => x.Posts);
dataLoadOptions.LoadWith<Post>(x => x.Comments);
using (var db = new BlogModelDataContext(conStr)
{
    LoadOptions =  dataLoadOptions
})
{
    db.Blogs.Where(x => x.Id == 1).ToList();
}

Interestingly enough, this does not generate a single query, but two queries:

-- statement #1
SELECT [t0].[Id],
       [t0].[Title],
       [t0].[Subtitle],
       [t0].[AllowsComments],
       [t0].[CreatedAt]
FROM   [dbo].[Blogs] AS [t0]
WHERE  [t0].[Id] = 1 /* @p0 */

-- statement #2
SELECT   [t0].[Id],
         [t0].[Title],
         [t0].[Text],
         [t0].[PostedAt],
         [t0].[BlogId],
         [t0].[UserId],
         [t1].[Id]       AS [Id2],
         [t1].[Name],
         [t1].[Email],
         [t1].[HomePage],
         [t1].[Ip],
         [t1].[Text]     AS [Text2],
         [t1].[PostId],
         (SELECT COUNT(* )
          FROM   [dbo].[Comments] AS [t2]
          WHERE  [t2].[PostId] = [t0].[Id]) AS [value]
FROM     [dbo].[Posts] AS [t0]
         LEFT OUTER JOIN [dbo].[Comments] AS [t1]
           ON [t1].[PostId] = [t0].[Id]
WHERE    [t0].[BlogId] = 1 /* @x1 */
ORDER BY [t0].[Id],
         [t1].[Id]

The interesting bit is that while there are two queries here, this method does not generate a Cartesian product, so I have to consider this a plus. What I would like to know is whatever this is intentionally so or just a result of the way Linq to SQL eager loading is structured.

The query plan for this is simple as well:

Finally, Entity Framework (both 3.5 and 4.0), using this code:

db.Blogs
    .Include("Posts")
    .Include("Posts.Comments")
    .Where(x => x.Id == 1)
    .ToList();

This code will generate:

SELECT   [Project2].[Id]             AS [Id],
         [Project2].[Title]          AS [Title],
         [Project2].[Subtitle]       AS [Subtitle],
         [Project2].[AllowsComments] AS [AllowsComments],
         [Project2].[CreatedAt]      AS [CreatedAt],
         [Project2].[C1]             AS [C1],
         [Project2].[C4]             AS [C2],
         [Project2].[Id1]            AS [Id1],
         [Project2].[Title1]         AS [Title1],
         [Project2].[Text]           AS [Text],
         [Project2].[PostedAt]       AS [PostedAt],
         [Project2].[BlogId]         AS [BlogId],
         [Project2].[UserId]         AS [UserId],
         [Project2].[C3]             AS [C3],
         [Project2].[C2]             AS [C4],
         [Project2].[Id2]            AS [Id2],
         [Project2].[Name]           AS [Name],
         [Project2].[Email]          AS [Email],
         [Project2].[HomePage]       AS [HomePage],
         [Project2].[Ip]             AS [Ip],
         [Project2].[Text1]          AS [Text1],
         [Project2].[PostId]         AS [PostId]
FROM     (SELECT [Extent1].[Id]             AS [Id],
                 [Extent1].[Title]          AS [Title],
                 [Extent1].[Subtitle]       AS [Subtitle],
                 [Extent1].[AllowsComments] AS [AllowsComments],
                 [Extent1].[CreatedAt]      AS [CreatedAt],
                 1                          AS [C1],
                 [Project1].[Id]            AS [Id1],
                 [Project1].[Title]         AS [Title1],
                 [Project1].[Text]          AS [Text],
                 [Project1].[PostedAt]      AS [PostedAt],
                 [Project1].[BlogId]        AS [BlogId],
                 [Project1].[UserId]        AS [UserId],
                 [Project1].[Id1]           AS [Id2],
                 [Project1].[Name]          AS [Name],
                 [Project1].[Email]         AS [Email],
                 [Project1].[HomePage]      AS [HomePage],
                 [Project1].[Ip]            AS [Ip],
                 [Project1].[Text1]         AS [Text1],
                 [Project1].[PostId]        AS [PostId],
                 CASE 
                   WHEN ([Project1].[C1] IS NULL) THEN CAST(NULL AS int)
                   ELSE CASE 
                          WHEN ([Project1].[Id1] IS NULL) THEN CAST(NULL AS int)
                          ELSE 1
                        END
                 END AS [C2],
                 CASE 
                   WHEN ([Project1].[C1] IS NULL) THEN CAST(NULL AS int)
                   ELSE CASE 
                          WHEN ([Project1].[Id1] IS NULL) THEN CAST(NULL AS int)
                          ELSE 1
                        END
                 END AS [C3],
                 [Project1].[C1]            AS [C4]
          FROM   [dbo].[Blogs] AS [Extent1]
                 LEFT OUTER JOIN (SELECT [Extent2].[Id]       AS [Id],
                                         [Extent2].[Title]    AS [Title],
                                         [Extent2].[Text]     AS [Text],
                                         [Extent2].[PostedAt] AS [PostedAt],
                                         [Extent2].[BlogId]   AS [BlogId],
                                         [Extent2].[UserId]   AS [UserId],
                                         [Extent3].[Id]       AS [Id1],
                                         [Extent3].[Name]     AS [Name],
                                         [Extent3].[Email]    AS [Email],
                                         [Extent3].[HomePage] AS [HomePage],
                                         [Extent3].[Ip]       AS [Ip],
                                         [Extent3].[Text]     AS [Text1],
                                         [Extent3].[PostId]   AS [PostId],
                                         1                    AS [C1]
                                  FROM   [dbo].[Posts] AS [Extent2]
                                         LEFT OUTER JOIN [dbo].[Comments] AS [Extent3]
                                           ON [Extent2].[Id] = [Extent3].[PostId]) AS [Project1]
                   ON [Extent1].[Id] = [Project1].[BlogId]
          WHERE  1 = [Extent1].[Id]) AS [Project2]
ORDER BY [Project2].[Id] ASC,
         [Project2].[C4] ASC,
         [Project2].[Id1] ASC,
         [Project2].[C3] ASC

The query plan for this seems overly complicated:

If you’ll look closely, you’ll see that it generate a join between Blogs, Posts and Comments, essentially creating a Cartesian product between all three.

I am not going to offer commentary on the results, but open a discussion on them.

The profiler could do session diffs (showing the difference between executed statements between two sessions) for a while now, but we got some requests for changing it to follow a more traditional source control diff style.

This is now done, and it should make it easier to understand the changes between two sessions:

This is a new feature available for NHibernate Profiler*, Linq to SQL Profiler and Entity Profiler. Basically, it detects when the same query is executed with different parameter sizes, which generate different query plan in the query cache.

Let us say that we issue two queries, to find users by name. (Note that I am using a syntax that will show you the size of the parameters, to demonstrate the problem).

We can do this using the following queries.

exec sp_executesql 
      N'SELECT * FROM Users WHERE Username = @username',
      N'@username nvarchar(3)',
      @username=N'bob'
exec sp_executesql 
      N'SELECT * FROM Users WHERE Username = @username',
      N'@username nvarchar(4)',
      @username=N'john'

This sort of code result in two query plans stored in the database query cache, because of the different parameter sizes. In fact, if we assume that the Username column has a length of 16, this single query may take up 16 places in the query cache.

Worse, if you have two parameters whose size change, such as username (length 16) and password (length 16), you may take up to 256 places in the query cache. Obviously, if you use more parameters, or if their length is higher, the number of places that a single query can take in the query cache goes up rapidly.

This can cause performance problems as the database need to keep track of more query plans (uses more memory) may need evict query plans from the cache, which would result in having to rebuild the query plan (increase server load and query time).

* Please note that detecting this in NHibernate requires the trunk version of NHibernate. And it is pretty useless there, since on the trunk, NHibernate will never generate this issue.

For a long time, most of the work in the profiler (NH Prof, HProf, L2S Prof & EF Prof) could be done only with the use of the mouse. That annoyed a bunch of people, but it didn’t really bother me.  Rob fixed this recently, and I cannot believe what kind of a difference it makes.

Here are the shortcuts:

Using those, you can use the common functionality of the profiler without touching the mouse.

Well… I am still working done the list of stuff people request for the profiler (NH Prof, HProf, L2S Prof & EF Prof) , and one of the things that popped into the head of the list was wanting to have programmatic access to the profiler output. We aren’t talking about just the XML reports that are available, but to be able to get the data in a way that is easy to work with.

Well, here it is:

There is a new DLL in the profiler distribution, HibernatingRhinos.Profiler.Integration, where you can find the CaptureProfilerOutput class. That class will let you start the profiler, capture whatever happens in the middle, and finally stop and return you an instance of a report, containing all the data about what actually happened.

This is perfect if you want to use the profiler as part of your integration tests library. As an aside, you can also use the new DLL to programmatically parse (by using XML Serialization) the XML reports that you generate as part of your build, so you get very easy way to build rules around that report.

One of the most annoying things about doing the TekPub episodes is finding the right session, because NH Prof will detect any session opening. This means that it usually looks like this:

Which also means that it is pretty hard to figure out. I got annoyed enough with that to add a specific filter to filter all of those in one shot (you could already do it, but it meant creating several filters):

Which results in a much better experience:

One of the features that keep popping up for ÜberProf is that people want to use that in CI scenarios, usually to be able to programmatically check that they don’t have things like SELECT N+1 popping up, etc.

With build 562 of ÜberProf, this is now possible. How does this works? We now have a command line interface for ÜberProf, with the following options:

/CmdLineMode[+|-]         (short form /C)
/File:<string>            (short form /F)
/ReportFormat:{Xml|Html}  (short form /R)
/Port:<int>               (short form /P)
/Shutdown[+|-]            (short form /S)

Starting up with no options will result in the usual UI showing up, but you have a new mode available for you. Let us say that you want to output the results of your integration tests into a format that you can easily work with programmatically. Here is how it can be done:

nhprof.exe /CmdLineMode /File:Output.xml /ReportFormat:Xml <-- starts listening to applications
xunit.console.exe Northwind.IntegrationTests.dll
nhprof.exe /Shutdown <-- stop listening to applications and output the report

The example is using NH Prof, but the same holds for all the other variants.

The way it works is very simple and should be pretty easy to integrate into your CI process. The XML output can give you programmatic access to the report, while the HTML version is human readable.

One thing that you might want to be aware of, writing the report file is done in an async manner, so the shutdown command may return before writing the file is done. If you need to process the file as part of your build process, you need to wait until the first profiler instance is completed. Using PowerShell, this is done like this:

nhprof.exe /CmdLineMode /File:Output.xml /ReportFormat:Xml
xunit.console.exe Northwind.IntegrationTests.dll
nhprof.exe /Shutdown
get-Process nhprof | where {$_.WaitForExit() } <-- wait until the report export is completed

Please note that from a licensing perspective, the CI mode is the same as the normal GUI mode. On one hand, it means that you don’t need to do anything if you have the profiler already. On the other, if you want to run it on a CI machine, you would need an additional license for that.

I got up this morning and the following showed up in my tweeter search:

I would say that from the “is the profiler helping customers?”, we are in a pretty good position.