Profiling MVC views in Umbraco 6

As you might know, Umbraco 6 includes the MiniProfiler out of the box. This is great, as it gives everyone a chance to figure out what parts of your site might not be performing as well as they could. However, I discovered that sometimes the results that you get can be somewhat misleading, and I decided to dig into it a bit further.

My solution looks like this:

image

When I ran the profiler on my page, it looked like this:

image

So, for some reason, it is taking almost 85 milliseconds just to find a view? So I started looking into why it might take time to look for views, and made sure that my application was in debug=”false” mode in order for the view engines caching to be enabled.

That didn’t help. I was still spending 85 ms for each request. But hey, who needs “TopNav” anyway, right? So I removed the surface controller from my Home view. Now it was just the “DisplayTemplates/Product” view taking time to be found. This is starting to smell.

After looking into the Umbraco source, I could see that it was adding it’s own viewengines to the mix, and they had some file IO code in there, so I thought, maybe that’s the problem. Then I created my own profiling view engine wrapper, and added it to my project.

Since Umbraco already wraps it’s view engines in the default profiler, I had to change it up a bit:

using System.Web.Mvc;
using Umbraco.Core;
using Umbraco.Web.Mvc;

namespace UmbMvcMiniProfiler
{
	public class Bootstrapper : ApplicationEventHandler
	{
		protected override void ApplicationStarting(UmbracoApplicationBase umbracoApplication, ApplicationContext applicationContext)
		{
			ViewEngines.Engines.Clear();
			ViewEngines.Engines.Add(new MyProfilingEngine(new RenderViewEngine()));
			ViewEngines.Engines.Add(new MyProfilingEngine(new PluginViewEngine()));
		}
	}
}

Great. Let’s see which one is the sinner!

image

WTF? So now it seems that almost no time is spent in the actual view engines? But there are some big jumps in the “from start” column, for each of the products. I’ll update my profiler to also wrap the views, and put a profiler step in the .Render call.

image

Allright, now we’re getting somewhere. What could be taking time in my Home view? Well, I’m iterating a list of products, maybe I should make sure that list is a Product[]?

image

And boom. Turns out that the view engines and the views aren’t really that slow. The problem was in my Index action where I was mapping my products. It had (conveniently for this example) a Thread.Sleep() for each product.

So there you go. A way to profile what i actually going on in you views and view engines. Full Gist with the profiling code is here.

I still do not know what the heck is going on with the default profiler, and what it is actually trying to do, but it sure confused me more than it needed to. Looking at the source of it, I still don’t know what it’s supposed to do?? But I thought this might be handy for others wondering why it takes so long to find their views.

Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s