CSC/ECE 517 Spring 2015/oss E1510 FLP

Expertiza - Fix Instructor Login Performance Issue

Expertiza is a web application where students can submit and peer-review learning objects (articles, code, web sites, etc). It is used in select courses at NC State and by professors at several other colleges and universities.<ref>Expertiza on GitHub</ref>

Project Description

Currently when an Instructor logs into Expertiza,there a lot of select* from assignments queries being fired on database which would have an adverse effect on performance. We analyzed the source of this issue and made some changes, which reduced the number of select queries executed. The performance is high improved. The mission involved is tracing the source of the issue and modify the code to fix the issue.

Performance issue before modification

Before we made the improvement, each time an instructore logs into the Expertiza, there would be several database queries, which are more than needed and take it longer to render the view. Below is the console outputs when an instructor logs in.

  Assignment Load (0.1ms)  SELECT  `assignments`.* FROM `assignments`  WHERE `assignments`.`id` = 1 LIMIT 1
  CACHE (0.0ms)  SELECT  `assignments`.* FROM `assignments`  WHERE `assignments`.`id` = 1 LIMIT 1  [["id", 1]]
  CACHE (0.0ms)  SELECT  `assignments`.* FROM `assignments`  WHERE `assignments`.`id` = 1 LIMIT 1  [["id", 1]]
  CACHE (0.0ms)  SELECT  `assignments`.* FROM `assignments`  WHERE `assignments`.`id` = 1 LIMIT 1  [["id", 1]]
  CACHE (0.2ms)  SELECT  `assignments`.* FROM `assignments`  WHERE `assignments`.`id` = 1 LIMIT 1  [["id", 1]]
  CACHE (0.1ms)  SELECT  `assignments`.* FROM `assignments`  WHERE `assignments`.`id` = 1 LIMIT 1  [["id", 1]]
  CACHE (0.1ms)  SELECT  `assignments`.* FROM `assignments`  WHERE `assignments`.`id` = 1 LIMIT 1  [["id", 1]]
  Rendered tree_display/_row_header.html.erb (17.4ms)

  CACHE (0.0ms)  SELECT  `assignments`.* FROM `assignments`  WHERE `assignments`.`id` = 1 LIMIT 1  [["id", 1]]
  Assignment Load (0.2ms)  SELECT  `assignments`.* FROM `assignments`  WHERE `assignments`.`id` = 1 LIMIT 1
  CACHE (0.0ms)  SELECT  `assignments`.* FROM `assignments`  WHERE `assignments`.`id` = 1 LIMIT 1  [["id", 1]]
  Rendered tree_display/actions/_shared_actions.html.erb (2.6ms)

  CACHE (0.0ms)  SELECT  `assignments`.* FROM `assignments`  WHERE `assignments`.`id` = 1 LIMIT 1  [["id", 1]]
  SignUpTopic Load (0.1ms)  SELECT  `sign_up_topics`.* FROM `sign_up_topics`  WHERE (assignment_id = 1)  ORDER BY `sign_up_topics`.`id` ASC LIMIT 1
  CACHE (0.0ms)  SELECT  `assignments`.* FROM `assignments`  WHERE `assignments`.`id` = 1 LIMIT 1  [["id", 1]]
  Rendered tree_display/actions/_assignments_actions.html.erb (8.8ms)

we can see that there are 7 assignment queries after load _row_header.html.erb, 3 assignment queries after load _shared_actions.html.erb, 3 assignment queries after load _assignments_actions. All these have an adverse effect on the performance.

Locate bug

To locate the files that generate the bug, we use a Gem called QueryReviewer<ref>https://github.com/nesquena/query_reviewer</ref> to help trace the datebase queries. QueryReviewer is an advanced SQL query analyzer<ref>https://github.com/nesquena/query_reviewer</ref>. It accomplishes the following goals:

• View all EXPLAIN output for all SELECT queries to generate a page
• Rate a page's SQL usage into one of three categories: OK, WARNING, CRITICAL
• Attach meaningful warnings to individual queries, and collections of queries
• Display interactive summary on page

Install query_reviewer

Installing query_reviewer is simple. All you have to do to install it into your Rails 2 or 3 project is

  gem install query_reviewer

Right now if you use bundler, simply add this to your Gemfile:

  # Gemfile
  gem "query_reviewer"

or to use the latest from github:

  # Gemfile
  gem "query_reviewer", :github => "nesquena/query_reviewer"

After installing and running this Gem on the Rails application, it would pop-up database query information on the webpage, as is shown below.

We can following the trace of this query reviewer page, and locate the bug in assignment_node.rb

Analyze code

We log into Expertiza as an instructor with the QueryReviewer activate and watch the output of QueryReviewer. [figure *] shows the tracing result of the QueryReviewer and it tells us that we should pay more attention to the three files: assignment_node.rb, _row_header.html.erb and _entry.html.erb.

_assignment_actions.html.erb

In file _assignment_actions.html.erb, we can find in 3 places use Assignment.find(node.node_object_id), which is actually a database query request.

1  <% owner_id = Object.const_get('Assignment').find(node.node_object_id).instructor_id %>
...
11 <% @assignment = Assignment.find(node.node_object_id) %>
...
52 <% if Assignment.find(node.node_object_id).course_id %>
...

_row_header.html.erb and assignment_node.rb

In _row_header.html.erb:

26  <% if parent_node.get_name == 'Courses'&& session[:user].role_id == 6 %>
27  <%else%>
28    <%= parent_node.get_name %>
29    <% if parent_node.get_directory != nil%>
30      <BR/><I>Directory:</I> <%= parent_node.get_directory %>
31    <% end %>
32    <% if parent_node.get_creation_date != nil %>
33      <BR/><I>Creation Date:</I> <%= parent_node.get_creation_date %>
34    <% end %>
35    <% if parent_node.get_modified_date != nil %>
36      <BR/><I>Updated Date:</I> <%= parent_node.get_modified_date %>
37    <% end %>
38  <%end%>

we can see in this view, parent_node is a AssignmentNode object, it execute:

• parent_node.get_name method
• parent_node.get_directory method
• parent_node.get_creation_date method
• parent_node.get_modified_date method

However, in assignment_node.rb:

6  class AssignmentNode < Node
   ...   
58   # Gets the name from the associated object
59   def get_name
60     Assignment.find(self.node_object_id).name
61   end
62 
63   # Gets the directory_path from the associated object
64   def get_directory
65     Assignment.find(self.node_object_id).directory_path
66   end
67 
68   # Gets the created_at from the associated object
69   def get_creation_date
70     Assignment.find(self.node_object_id).created_at
71   end
72
73   # Gets the updated_at from the associated object
74   def get_modified_date
75     Assignment.find(self.node_object_id).updated_at
76   end
   ...
82 end

We find all these method called Assignment.find(self.node_object_id) method, which is actually a database query request. These 'find's are actually redundant for a specific Assignment instance. So we will figure out a way to eliminate those redundant method calls.

Modifications

_assignment_actions.html.erb

An instance variable @assignment is used here instead of multiple times of calling .find method, thus reducing database queries.

+ <% @assignment = Assignment.find(node.node_object_id) %>
- <% owner_id = Object.const_get('Assignment').find(node.node_object_id).instructor_id %>
+ <% owner_id = @assignment.instructor_id %>
...
- <% @assignment = Assignment.find(node.node_object_id) %>
...
- <% if Assignment.find(node.node_object_id).course_id %>
+ <% if @assignment.course_id %>
...

assignment_node.rb

In this class, we define a new variable @assign_node, and in every get_ method, instead of using Assignment.find(self.node_object_id) to find the AssignmentNode object, we first search if @assign_node variable exist, if not, we define @assign_node = Assignment.find(self.node_object_id), else we directly use @assign_node. Because _row_header.html.erb file has many get_ method, after modification, the number of assignment queries decreases much.

class AssignmentNode < Node
# Gets the name from the associated object
  def get_name
    unless @assign_node
    	@assign_node = Assignment.find(self.node_object_id)
    end
    @assign_node.name
  end

  # Gets the directory_path from the associated object
  def get_directory
    #Assignment.find(self.node_object_id).directory_path
    unless @assign_node
    	@assign_node = Assignment.find(self.node_object_id)
    end
    @assign_node.directory_path
  end

  # Gets the created_at from the associated object
  def get_creation_date
    #Assignment.find(self.node_object_id).created_at
    unless @assign_node
    	@assign_node = Assignment.find(self.node_object_id)
    end
    @assign_node.created_at
  end

  # Gets the updated_at from the associated object
  def get_modified_date
    #Assignment.find(self.node_object_id).updated_at
    unless @assign_node
   	@assign_node = Assignment.find(self.node_object_id)
    end
    @assign_node.updated_at
  end
end

Performance Improvment

Originally there are 13 queries after loading these related pages, and now there are only 5 of them, as can been seen from the console output result below. Thus the performance is improved and the total rendering time consumption is reduced.

  Assignment Load (1.7ms)  SELECT  `assignments`.* FROM `assignments`  WHERE `assignments`.`id` = 1 LIMIT 1
  Rendered tree_display/_row_header.html.erb (3.0ms)

  CACHE (0.1ms)  SELECT  `assignments`.* FROM `assignments`  WHERE `assignments`.`id` = 1 LIMIT 1  [["id", 1]]
  Assignment Load (0.2ms)  SELECT  `assignments`.* FROM `assignments`  WHERE `assignments`.`id` = 1 LIMIT 1
  CACHE (0.0ms)  SELECT  `assignments`.* FROM `assignments`  WHERE `assignments`.`id` = 1 LIMIT 1  [["id", 1]]
  Rendered tree_display/actions/_shared_actions.html.erb (4.0ms)

  SignUpTopic Load (0.1ms)  SELECT  `sign_up_topics`.* FROM `sign_up_topics`  WHERE (assignment_id = 1)  ORDER BY `sign_up_topics`.`id` ASC LIMIT 1
  Rendered tree_display/actions/_assignments_actions.html.erb (11.9ms)

References

<references/>