Jaa

Understanding View Rendering Performance in ASP.NET MVC

  • Artikkeli

Recently I was working with a customer who wanted to understand where the time was spent during rendering for their ASP.NET MVC application. To solve this they had added tracing to their views to capture how long each view took to render. This was conceptually similar to the code below (they had some additional helpers to simplify the code slightly)

@{
var stopwatch = Stopwatch.StartNew();
Trace.WriteLine("View Index - rendering...");
}

<h3>Page Title</h3>
<!-- standard view rendering goes here -->

@{
stopwatch.Stop();
Trace.WriteLine(string.Format("View Index - rendered: {0} ms", stopwatch.ElapsedMilliseconds));
}

You can see from this sample that the top of the view logs the view name, and the bottom logs the time taken. The output looks like this:

View Index - rendering...
View Index - rendered: 57 ms

[Aside: it is worth noting that Glimpse and MiniProfiler allow you to capture this information (and a lot more), but in this case, the customer already had a logging solution that they wanted this to integrate with]

The problem with this approach is that you need to instrument each view. This takes time for a large number of views, and it is easy to miss some.

An alternative approach is to take advantage of the ViewEngine extensibility. In ASP.NET MVC, view engines are used to find and execute views. In the code below, we can implement a ViewEngine that wraps an existing view engine and adds the timing and tracing functionality automatically for each view. The code for this is shown below:

public class TracingViewEngine : IViewEngine
{
private readonly IViewEngine _innerViewEngine;

        public TracingViewEngine(IViewEngine innerViewEngine)
{
_innerViewEngine = innerViewEngine;
}

        public ViewEngineResult FindPartialView(ControllerContext controllerContext, string partialViewName,
bool useCache)
{
var result = _innerViewEngine.FindPartialView(controllerContext, partialViewName, useCache);
return CreateTracingViewEngineResult(result, partialViewName);
}

        public ViewEngineResult FindView(ControllerContext controllerContext, string viewName, string masterName,
bool useCache)
{
var result = _innerViewEngine.FindView(controllerContext, viewName, masterName, useCache);
return CreateTracingViewEngineResult(result, viewName);
}

        public void ReleaseView(ControllerContext controllerContext, IView view)
{
TracingView tracingView = (TracingView)view;
_innerViewEngine.ReleaseView(controllerContext, tracingView.InnerView);
}

        public ViewEngineResult CreateTracingViewEngineResult(ViewEngineResult result, string name)
{
if (result.View == null)
{
return result; // no view to wrap
}
return new ViewEngineResult(new TracingView(result.View, name), this);
}
}

This view engine decorates the inner engine that is wrapping. When it returns a View, is wraps it in a TracingView (code below).

public class TracingView : IView
{
private readonly string _name;
public IView InnerView { get; private set; }

    public TracingView(IView innerView, string name)
{
InnerView = innerView;
_name = name;
}

    public void Render(ViewContext viewContext, TextWriter writer)
{
var stopwatch = Stopwatch.StartNew();
Trace.WriteLine(string.Format("View {0} - rendering...", _name));
InnerView.Render(viewContext, writer);
stopwatch.Stop();
Trace.WriteLine(string.Format("View {0} - rendered: {1} ms", _name, stopwatch.ElapsedMilliseconds));
}
}

You can see from this code that we are surrounding the InnerView.Render call with the same timing and tracing code that we manually put in the view. 

To wire up the TracingViewEngine, we can put the following code in Application_Start (in global.asax.cs):

// wrap existing view engines in the TracingViewEngine
for (int i = 0; i < ViewEngines.Engines.Count; i++)
{
ViewEngines.Engines[i] = new TracingViewEngine(ViewEngines.Engines[i]);
}

An advantage of this approach is that all views will automatically be traced so we don’t need to worry. You can see in the sample output below that we are now capturing some partial view executions:

View Index - rendering...
View _LoginPartial - rendering...
View _LoginPartial - rendered: 0 ms
View _Featured - rendering...
View _Featured - rendered: 0 ms
View Index - rendered: 6 ms

It would also be quite easy to read a configuration setting to determine whether to apply wrap view engines in the TracingViewEngine. This would make it easy to enable or disable in different environments.

Enjoy!

Comments

  • Anonymous
    November 16, 2013
    Couldn't you just use a ResultFilter?

  • Anonymous
    November 17, 2013
    @Alex - you could certainly use a ResultFilter to get the total rendering time. Using the custom ViewEngine approach above lets you get the time taken inside partial views etc as well

  • Anonymous
    November 17, 2014
    Thank you, this was helpful. Combining this with MiniProfiler is really nice!

  • Anonymous
    November 17, 2014
    Thank you, this was helpful. Combining this with MiniProfiler is really nice!

  • Anonymous
    April 13, 2017
    What a handy code. Thank you sir!