Measuring NHibernate's Queries Per Page
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)
Comments
Comment preview