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 allSELECT
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.
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
methodparent_node.get_directory
methodparent_node.get_creation_date
methodparent_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/>