Ayende @ Rahien

Hi!
My name is Oren Eini
Founder of Hibernating Rhinos LTD and RavenDB.
You can reach me by phone or email:

ayende@ayende.com

+972 52-548-6969

, @ Q c

Posts: 6,124 | Comments: 45,473

filter by tags archive

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,

Comments

Comment preview

Comments have been closed on this topic.

FUTURE POSTS

  1. RavenDB 3.5 whirl wind tour: You want all the data, you can’t handle all the data - about one day from now
  2. The design of RavenDB 4.0: Making Lucene reliable - 3 days from now
  3. RavenDB 3.5 whirl wind tour: I’ll find who is taking my I/O bandwidth and they SHALL pay - 4 days from now
  4. The design of RavenDB 4.0: Physically segregating collections - 5 days from now
  5. RavenDB 3.5 Whirlwind tour: I need to be free to explore my data - 6 days from now

And 14 more posts are pending...

There are posts all the way to May 30, 2016

RECENT SERIES

  1. RavenDB 3.5 whirl wind tour (14):
    29 Apr 2016 - A large cluster goes into a bar and order N^2 drinks
  2. The design of RavenDB 4.0 (13):
    28 Apr 2016 - The implications of the blittable format
  3. Tasks for the new comer (2):
    15 Apr 2016 - Quartz.NET with RavenDB
  4. Code through the looking glass (5):
    18 Mar 2016 - And a linear search to rule them
  5. Find the bug (8):
    29 Feb 2016 - When you can't rely on your own identity
View all series

RECENT COMMENTS

Syndication

Main feed Feed Stats
Comments feed   Comments Feed Stats