Performance Logging

time to read 10 min | 1834 words


I just added a small http module to Rhino Commons. It is a very simple module that times how long it takes to process a page.
It only times the server-side processing, of course, but it is a great way to tell you where you need to pay attention.
It is using log4net to log the data, so you can redirect the output to a database, and from there, you can get all the data you want.

Configurating the module is very simple. Create the following table:

CREATE TABLE [dbo].[PagePerformance](
    
[Id] [int] PRIMARY KEY IDENTITY(1,1) NOT NULL,
    
[Date] [datetime] NOT NULL,
    
[Message] [nvarchar](max) NOT NULL,
    
[PageURL] [nvarchar](max) NOT NULL,
    
[Duration] [nvarchar](50) NOT NULL,
    
[StartRequest] [datetime] NOT NULL
)

Now, add the following to your <httpModules> tag in web.config:

<httpModules>
     <
add name="PagePerformanceModule"
          
type="Rhino.Commons.HttpModules.PagePerformanceModule"/>
</
httpModules>


Finally, we define in log4net.config the appender configuration:

<appender name="PagePerfAppender"
            
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.PagePerformance
([Date],[Message],[PageUrl],[Duration],[StartRequest]) VALUES (@log_date, @message, @pageUrl, @duration, @startRequest)
" />
    
<
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{page_url}" />
          
</
layout>
    
</
parameter>
     <
parameter>
           <
parameterName value="@duration" />
          
<
dbType value="String" />
          
<
size value="50" />
          
<
layout type="log4net.Layout.PatternLayout">
               
<
conversionPattern value="%property{page_duration}" />
          
</
layout>
     </
parameter>
     <
parameter>
           <
parameterName value="@StartRequest" />
          
<
dbType value="DateTime" />
           
<
layout type="log4net.Layout.PatternLayout">
               
<
conversionPattern value="%property{start_request}" />
          
</
layout>
     </
parameter>
</
appender>

The page_duration, start_request and page_url properties are added to log4net configuration by the http module.
Then, all that is left is defining the logger itself:

<logger name="Rhino.Commons.HttpModules.PagePerformanceModule">
    
<
level value="DEBUG" />
    
<
appender-ref ref="PagePerfAppender" />
</
logger>

If everything went well, you have now got yourself a table in the DB that measures
how much it takes to serve each page.

Note: There is a small buffer (10 page requests) defined, to reduce the cost of the logging, so you would need to hit refresh a couple of time before you see the results in the table.