Logs and performance

I was recently assigned to monitor and report on some issues with performance. I was told to log some information about how long different requests on pages took. Here I stumbled upon two things that I didn’t find all that well documented on SDN5.

1. Logging with log4net. I needed a separate log file, as I didn’t want all my entries to mess up the standard log file.
2. There are performance counters in Sitecore, but I didn’t know where I could find these.

So I thought I’d just report my findings on my blog to the help of others.

1:
Creating a separate log in log4net is actually quite simple. Go to the log4net section in the web.config. Here you can add a new appender that writes to a separate file:

If you look at the LevelRangeFilter, you’ll see, that you can specify a min and max level. There are different levels and you can specify which levels to write to the given logfile. The level ranges from DEBUG to FATAL. There are as default these levels: ALL, DEBUG, INFO, WARN, ERROR, FATAL.
In this case I only want the DEBUG information written and keep that level out of the Sitecores log file. Therefore I changed the Sitecore appender to range from the level INFO to FATAL:

  <appender name="PerformanceFileAppender" type="log4net.Appender.SitecoreLogFileAppender, Sitecore.Logging">

    <file value="D:/MyPath/Data/logs/Performance.{date}.txt" />

    <filter type="log4net.Filter.LevelRangeFilter">

      <levelMin value="DEBUG"/>

      <levelMax value="DEBUG"/>

    </filter>

    <appendToFile value="true" />

    <layout type="log4net.Layout.PatternLayout">

      <conversionPattern value="%-21t %d %-5p %m%n" />

    </layout>

  </appender>

I then altered the root element to include my appender and altered the level requirements to ALL:

<root>

<priority value="ALL" />

<appender-ref ref="LogFileAppender" />

<appender-ref ref="PerformanceFileAppender" />

</root>

Now I can write to my custom log file by using the ILog interface and use the method Debug:

ILog perfLog = LogManager.GetLogger("PerformanceFileAppender");
perfLog.Debug(”Hello world!”);

You can read more about it at log4nets page. Here you can also read about different types of appenders and much more.

2:
So now I had a log I could use for debugging. Now I just needed the performance counters. So I looked at the HttpRequestBegin pipeline. There I found a processor called StartMeasurements. Thanks to Lutz Roeder’s Reflector I found that Sitecore starts a timer and stores it like this:

Context.Items["SC_REQUEST_MEASUREMENT_TIMER"] = new HighResTimer(true);
And the requested URL like this:

Context.Items["SC_REQUEST_MEASUREMENT_URL"] = args.Context.Request.RawUrl;

Now all I had to do, was to hook in on the httpRequestEnd pipeline and add my own processor that would log the time elapsed. So I added this just before the StopMeasurements processor:

<processor type="MyNameSpace.MeasurementLogger, MyNameSpace">
I then created a new class and added the debug logging:

public class MeasurementLogger

{

#region private properties

private static readonly ILog perfLog = LogManager.GetLogger("PerformanceFileAppender");

#endregion

public class MeasurementLogger

{

#region private properties

private static readonly ILog perfLog = LogManager.GetLogger("PerformanceFileAppender");

#endregion

public void Process(HttpRequestArgs args)

{

HighResTimer timer = Sitecore.Context.Items["SC_REQUEST_MEASUREMENT_TIMER"] as HighResTimer;

string timeElapsed = timer.Elapsed().ToString();

string requestedUrl = Sitecore.Context.Items["SC_REQUEST_MEASUREMENT_URL"] as string;

perfLog.Debug("HTTPRequest time: " + timeElapsed + " Url: " + requestedUrl + " Domain: " + args.Context.Request.Url.Host);

}

}

And that’s it. Now you’ll write the elapsed time on all requests to the performance.{date}.txt log file.
Some might see this as overkill, as you can use the stats.aspx or IIS log files etc., but none the less this gives an introduction using log4net as well as hooking into a pipeline.

P.S.
There will come more posts about relational data, I just haven’t finished them yet.

Posted by Jens Mikkelsen
Source:-http://sitecorejm.blogspot.com/2008/01/logs-and-performance.html