While developing a new site, I ran into some performance issues.
I figured that it was probably caused by one of the pipeline processors, but had no idea which one it could be.
In order to figure out how long each pipeline is taking to process, I created a simple performance monitoring system.

First I created two generic processors that can be used for every pipeline and will write a log entry at the start of the pipeline and at the end:
PerformanceMonitor.Start and PerformanceMonitor.End

These processors will add a line to a log file when they are executed. The result is a log file, named performance.20130322.txt (each day a new file), containing these kind of lines:

[11:05:15.048] pipelineName start
[11:05:15.057] pipelineName end

The resulting log file can be used to determine how long it took for a pipeline to complete.
In the above example, the pipeline took 9 miliseconds to complete.

Now we have a way to log the duration of each pipeline, we still have to do some configuration so that all existing pipelines are monitored.
We do this by patching the web.config using an include config file.
To activate the performance monitor for a pipeline, you add the following configuration for each pipeline (please not that I've used the pipeline as an example):

<httpRequestBegin>
  <processor x:before="*[1]" type="ParTech.Pipelines.PerformanceMonitor.Start, ParTech.Library">
    <param desc="pipelineName">httpRequestBegin</param>
  </processor>
  <processor x:before="*[999]" type="ParTech.Pipelines.PerformanceMonitor.End, ParTech.Library">
    <param desc="pipelineName">httpRequestBegin</param>
  </processor>
</httpRequestBegin>

Some pipelines provide custom arguments with the Process() method.
If you want to use those, just add an extra Process() method to the Start and End processors, like I've done for the pipeline:

public void Process(RenderFieldArgs args)
{
    Start(args.FieldName);
}

Okay, so now we have the basics setup.
After this I created the configuration for each existing pipeline, monitoring the duration of all of them.
The resulting log file looks something like this:

[11:36:57.111] preprocessRequest start
[11:36:57.113] preprocessRequest end
[11:36:57.114] httpRequestBegin start
[11:36:57.142] renderField [Logo] start
[11:36:57.144] renderField [Logo] end
[11:36:57.178] renderField [Content title] start
[11:36:57.180] renderField [Content title] end
[11:36:57.182] renderField [Content body] start
[11:36:57.183] renderField [Content body] end
[11:36:57.185] renderField [Footer link] start
[11:36:57.186] renderField [Footer link] end
[11:36:57.509] httpRequestProcessed start
[11:36:57.510] httpRequestProcessed end
[11:36:57.512] httpRequestEnd start
[11:36:57.513] httpRequestEnd end
[11:36:57.515] httpRequestBegin end

All that's missing now is a script to parse the log file and create a nice overview of pipeline statistics.
I'm still working on that one and I promise it will come soon!

Until then, you can grab the code for this little toy here: ParTech.Pipelines.PerformanceMonitor.zip or check out the GitHub repository: https://github.com/ParTech/Pipeline-Performance-Monitor.
It includes a configuration include file that activates the monitor for all existing pipelines.

Update 27-03-2013:
Just released version 1.0.1 that implements the idea suggested by Mike Edwards.
It also fixes a bug in the configuration and incorrect naming of the assembly.

2 Comments

  • By Ruud van Falier on 3/26/2013 at 1:39 PM

    That is an excellent suggestion, Mike!
    I expect to make changes to this module while I'm using it during development and I will definitely keep this idea in mind.

  • By Mike Edwards on 3/26/2013 at 1:33 PM

    Another solution would be to use the Sitecore profiler.

    In the PerformanceMonitor.Start add Sitecore.Diagnostics.Profiler.StartOperation(key);

    And in the end:

    Sitecore.Diagnostics.Profiler.EndOperation(key);

    You will then see the processing time outputted into the Sitecore Debug tool.

Leave a comment