Measuring NHibernate's Queries Per Page

time to read 10 min | 1984 words


One of the biggest problems with abstractions is that they may allow you to do stupid things without them being obvious. In OR/M-land, that usually means SELECT N+1 issues.
The problem is that you often develop a certain functionality first, and only then realize that while you tested, all was fine and dandy on the five items that you had, but on the real system, you have 5,000, and the DBA is on its way to ER...

Anyway, I am currently working with Web Applications, and I wanted to get a good indication about what pages are troublesome.
Being who I am, I immediately began to design a framework that would correlate page requests to trace data from SQL Server, and then another system that would analyze it and spit out a report saying: "Wow, that ScaryReport.aspx page is making 30% of the calls in the application, take a look at that".

Not wishing to spent the next two years on this project, I decided to do something a bit more modest, and utilize the already existing infrastructure.
In this case ,the infrastructure is NHibernate and lot4net.

The secret tidbit is that NHibernate logs all queries to a log4net logger named "NHibernate.SQL". From there, it was a simple matter of adding a logging helpers to Rhino Commons that would output the current page and the current request id (the request hash code, basically).
Then, It was a matter of defining the following table:

CREATE TABLE [dbo].[NHibernatePerPageQueries](
   
[Id] [int] IDENTITY(1,1) PRIMARY KEY NOT NULL,
   
[RequestId] [int] NOT NULL,
   
[Date] [datetime] NOT NULL,
   
[Message] [nvarchar](max)  NOT NULL,
   
[PageURL] [nvarchar](max)  NOT NULL
)


Then, to define the appender:

<appender name="NHibernatePerPageAppender"
            
type="log4net.Appender.AdoNetAppender">
    
<
bufferSize value="10" />
    
<
connectionType value="System.Data.SqlClient.SqlConnection,
System.Data, Version=2.0.0.0, Culture=neutral,
PublicKeyToken=b77a5c561934e089
" />
    
<
connectionString value="Data Source=localhost;Initial
Catalog=Logs;User ID=logger;Password=logger;
" />
    
<
commandText value="INSERT INTO dbo.[NHibernatePerPageQueries]
([Date],[Message],[PageUrl],[RequestId]) VALUES (@log_date, @message,
@pageUrl,@currentRequestId)
" />
    
<
parameter>
           <
parameterName value="@log_date" />
          
<
dbType value="DateTime" />
          
<
layout type="log4net.Layout.RawTimeStampLayout" />
    
</
parameter>
     <
parameter>
           <
parameterName value="@message" />
          
<
dbType value="String" />
          
<
size value="4000" />
          
<
layout type="log4net.Layout.PatternLayout">
               
<
conversionPattern value="%message" />
          
</
layout>
     </
parameter>
     <
parameter>
           <
parameterName value="@pageUrl" />
          
<
dbType value="String" />
          
<
size value="2000" />
          
<
layout type="log4net.Layout.PatternLayout">
               
<
conversionPattern value="%property{nhibernate_page_url}" />
          
</
layout>
     </
parameter>
     <
parameter>
           <
parameterName value="@currentRequestId" />
          
<
dbType value="String" />
          
<
size value="2000" />
          
<
layout type="log4net.Layout.PatternLayout">
               
<
conversionPattern value="%property{current_request_id}" />
          
</
layout>
     </
parameter>
</
appender>


And defining the logger:

<logger name="NHibernate.SQL">
    
<
level value="DEBUG" />
    
<
appender-ref ref="NHibernatePerPageAppender" />
</
logger>


We are still not done, though, we need the following in the Application_Start():

GlobalContext.Properties["nhibernate_page_url"] = WebLoggingHelper.CurrentPage;
GlobalContext
.Properties["current_request_id"] = WebLoggingHelper.CurrentRequestId;


This is it, now I can correlate the number of queries per page hits, and act accordingly.
Normally, I think that the following queries should be enough:

-- Get pages ordered by number of total queries made from them

SELECT COUNT(*) [Number Of Queries In Page], PageUrl
FROM
NHibernatePerPageQueries
WHERE
substring(Message,1,1) != '@' -- remove parameters logs
GROUP
BY PageUrl ORDER BY COUNT(*)

 

-- Get pages ordered by number of queries per page

SELECT AVG(countOfQueries) [Number Of Queries In Page Per Request], PageUrl FROM (
    
SELECT COUNT(*) countOfQueries, PageUrl
     FROM NHibernatePerPageQueries
     WHERE substring(Message,1,1) != '@' -- remove parameters logs
    
GROUP BY PageUrl, RequestId ) innerQuery
GROUP
BY PageUrl ORDER BY AVG(countOfQueries)

 

Enjoy,