I’ve been doing some ASP.NET MVC work recently, for a new client, and I just had to work on a site that we performing badly. It was a simple site for signing up to an event, but the admin page was taking a very long time to appear. A bit of database profiling suggested a lot of traffic to the database, which was my first suspicion.
But I wanted to get a bit more visibility on how much work the server was doing, so I thought I’d take the opportunity to try out Glimpse.
A simple nu-get install was all it took, and the next time I fired up the site to test it, I got the glimpse Head-Up Display at the bottom of the page showing some headline figures.
The HTTP section shows how long the request took in total, and broken down into server time, wire time (how long it took for the page to be sent over the internet) and Client time (how long it took for the browser to render the page once it received it).
On my page, the Client figure was quite high, as the page contained a big table of customers which was then being turned into a paged table by jQuery. But the server figure was still high – over 60 seconds.
I quickly found a large database query that, it turned out, wasn’t actually used to generate the page, and was only used to cache data for an ‘Export’ button. Since the Export was a little-used feature, I decided it was better to leave the export data fetching for when the user actually requested it. This made a big dent in the time taken – and removed about 1330 database requests.
But the page was still taking a fair amount of time – about 16 seconds – and now it wasn’t the database that was causing the delay – total database time was well under a second.
The Client processing time was still quite long, but the server was still slow, so I looked a the Host section, which breaks down the time taken in the Controller Action and the View. For this page, the view was taking way longer than the controller, despite there being no real data processing in the view, so clearly something was causing a lot of work in the view.
This might have taken a long time to diagnose, but Glimpse showed its value again, with the ability to drill down into the details of each part of the MVC engine. When you click the ‘g’ logo on the right, it opens the details window, which has tabs for all the different things Glimpse logs.
I wanted to see what the Views tab said – and sure enough, it showed a lot – there were hundreds of entries in that log for this single page, because the customer list was being rendered by an Editor Template.
Editor Templates are useful things. When you’ve got a complex class as your ViewModel, they allow you to write a template for the component objects, and the framework will do all the heavy lifting of calling the templates for the properties of the ViewModel.
The problem with my page is that I was using a template for over 500 objects in a collection, and what Glimpse was telling me was that the server was spending a lot of time finding the view for each of the objects, and it wasn’t caching this template.
Now, one of the reasons to use templates like this is so that your controller action can simply accept your model class as an argument, which keeps your code simple, but in this case, it was causing far too much server work.
Luckily, the controller that was handling the form data didn’t actually need the entire viewmodel – in fact, for my purposes, all I required was a single checkbox per item which contained the item ID.
This allowed me to remove the Html.EditorFor call that was generating all the template traffic, and put in my own loop.
At the same time, I simplified the code in the template. It was using Html.DisplayFor for textual fields, so I replaced those with just putting the literal fields in.
I had to change the signature of the controller action to simply accept an array of IDs, but that was the only information it was taking from the original model, so the rest of the code didn’t change. But it had a dramatic effect on the rendering time.
With these changes, the View rendering time plummeted, from around 8s to less than a second.
As a result of these changes, a page with over 500 customers in a paged table dropped from around 75 seconds down to around 4 seconds (half of which was the jQuery pagination happening).
Not a bad result, and it would probably have been much, much harder to track down the bottlenecks without a tool like Glimpse.