Monitor the duration of all pipelines

22 maart 2013 om 00:00 by Ruud van Falier - Post a comment

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):

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

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)

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: or check out the GitHub repository:
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.