MarkUs Blog

MarkUs Developers Blog About Their Project

Student table load analysis

with one comment

Since the next issue I’m going to be looking into is trying to make the users/students table load more quickly, I thought it might be useful to document what I feel is slowing it down, and what might help to optimize it.

First I’ll break down the steps that are taken when the Students page first loads.  The page first loads without any actual student data in the table, and a javascript file “_boot.js.erb” which is rendered into the view, creates an ajax call to the server for the data that will populate the table.  Populating and sorting the table, is handled by a javascript object FilterTable.

As the first step in figuring out where in the process most of the work is taking place, we’ll first look at the Chrome debugger, to look at the actual ajax request.  Under the “Network” tab, we can select “XHR” at the bottom, which will only display ajax calls.  We see one to “http://localhost:3000/en/students/populate” which is the call that retrieved the table data.  We can also see that the call itself returned 333.83kb of data, in 5.16 seconds.  This should right away look pretty bad.  This single request took 5.16 seconds to pull data from the database, render the view(s) and send it back to the client (it’s a local server, so we can expect that data transfer time will be higher on the demo server).  Additionally, looking at the page, we have only about 150 records returned, with on average less than 40 characters per line.  At 333,830 bytes, we’ve probably got a lot of formatting overhead coming back as well, which we might not necessarily need.

With Chrome, we can click on this request, and then choose “Response” to see the actual rendered response packet.  The first thing I notice, is that there is a lot of escaped characters, and double escaped characters, and triple escaped characters.  Things like: id=\\\\\\\”notes_highlight_9\\\\\\\”  is most likely overkill.  We also have a lot of redundant formatting, the entire rendered table content is in the response, as well as all of the data in a hash.  It would make sense that if we’re sending the hash of data, we could probably do something on the client side to render all of this into the table using a template instead.

Looking at the server in the console, we can also get an idea of what is happening on the server side, how long sql queries are taking, how much time is spent rendering views.  The first thing I notice, is that we have 2 lines of :

Started POST "/en/students/populate" for 127.0.0.1 at Sun Nov 25 14:33:06 -0600 2012
Started POST "/en/students/populate" for 127.0.0.1 at Sun Nov 25 14:33:06 -0600 2012

 

This might be indicating that the ajax call is being sent twice. Since the first one has likely been cancelled, this shouldn’t cause too much problem, though we really should only be sending one request and following through with it.

Next we can see all of the sql requests that are being used to retrieve data for the request.  There are quite a few of them, all around 1-3ms each, so this isn’t a big deal.  Adding some indices might help to speed this up though.

Finally, we can see how much time is being spent rendering views, which is probably where the inefficiency is coming from.  This request pulls some data out of the tables, and then renders view partials in a loop, so we have output that looks like:

Rendered users/table_row/_filter_table_row.html.erb (27.1ms)
Rendered users/table_row/_filter_table_row.html.erb (6.7ms)
Rendered users/table_row/_filter_table_row.html.erb (6.6ms)
Rendered users/table_row/_filter_table_row.html.erb (214.6ms)
Rendered users/table_row/_filter_table_row.html.erb (8.1ms)
Rendered users/table_row/_filter_table_row.html.erb (7.5ms)
Rendered users/table_row/_filter_table_row.html.erb (7.5ms)
Rendered users/table_row/_filter_table_row.html.erb (6.9ms)
Rendered users/table_row/_filter_table_row.html.erb (7.7ms)
Rendered users/table_row/_filter_table_row.html.erb (6.8ms)
...

You can see that there is one line for each record in the table, and some of them take around 1/4 of a second to render others are 5-30ms.  I didn’t think this would cause problems in rails, as the views would all be cached, but for some reason this is causing an awful lot of slowdown.  At the end of the views, we get a summary:

Rendered students/populate.rjs (538.1ms)
Completed 200 OK in 4796ms (Views: 558.7ms | ActiveRecord: 21.6ms)

 

Which is telling us that the entire request took 4.7 seconds to render and send to the client, spending 558.7ms of that (this doesn’t seem accurate) rendering views, and 21.6ms loading data from tables.  The sql queries aren’t a problem right now, but the view rendering definitely needs some optimization, and the amount of data being sent back to the client needs to be optimized.

So now that we have a better idea of where all this extra time is coming from, we can start looking at what parts would benefit the most from optimization.  Starting with the views seems like the obvious first choice, to try and see why rendering a partial in a loop is slowing things down so much.  Second, look at where characters are being escaped, and what the format of the data is, and try to slim this down so we can send less data in the response.  Likely I will try to remove all of the rendered data, and just send a hash of the table data, to be used to populate the table using a template of some kind.

Given that the FilterTable is used on almost every page, and they are all being populate roughly the same way, I’m hoping that if I can make any progress on the Students page, it could somehow by applied to others as well.  Wish me luck!

Written by Joey Perry

November 25th, 2012 at 4:58 pm

Posted in Uncategorized

One Response to 'Student table load analysis'

Subscribe to comments with RSS or TrackBack to 'Student table load analysis'.

  1. As an update on what I’ve been able to optimize yet:
    – no longer using the populate.rjs file, which generates javascript that is sent back to the server and executed. It was basically a try/catch block, with the full json data twice, the 2nd time used to print out in an alert for debugging, with extra escaped characters, and only to call the “populate” function. Now the function that initiated the ajax call will call “populate” and only one clean json string is sent back.
    – modified the FilterTable to instead of tokenize the rendered row by the elements to re-build the row and populate the table, it will read the correct hash value from the json data, since the names of each column are specified in the FilterTable constructor, we can use these. Doing this allowed me to remove the rendered row completely from the json response.
    – This reduced the json data from ~400k to less than 100k, but only reduced the rendering time about half a second.
    – The function that is taking the most time, is a “render_to_string” call, that renders a partial to a string that is populated in the json, for the “Notes | Edit” field, that I still need to send back. I’m not entirely sure why this is so slow, since it’s a very small partial, and there’s not much concatenation going on at all. I’m still looking for an alternative here that will still let me take advantage of url building methods that the view has access to.

    Joey Perry

    3 Dec 12 at 9:46 pm

Leave a Reply