What is a recommended way to optimize my app given this server log?

Question

Here is my server log for loading my Dashboard#Index action:

Started GET "/" for 127.0.0.1 at 2014-10-27 03:26:56 -0500
  User Load (1.9ms)  SELECT  "users".* FROM "users"  WHERE "users"."id" = 1  ORDER BY "users"."id" ASC LIMIT 1
Processing by DashboardController#index as HTML
  FamilyTree Load (3.0ms)  SELECT  "family_trees".* FROM "family_trees"  WHERE "family_trees"."user_id" = $1 LIMIT 1  [["user_id", 1]]
  ReadMark Load (1.1ms)  SELECT  "read_marks".* FROM "read_marks"  WHERE "read_marks"."user_id" = $1 AND "read_marks"."readable_type" = 'PublicActivity::ORM::ActiveRecord::Activity' AND "read_marks"."readable_id" IS NULL  ORDER BY "read_marks"."id" ASC LIMIT 1  [["user_id", 1]]
  Membership Load (1.3ms)  SELECT  "memberships".* FROM "memberships"  WHERE "memberships"."user_id" = $1 LIMIT 3  [["user_id", 1]]
  Rendered shared/_profile_box.html.erb (3.2ms)
  Node Load (1.4ms)  SELECT "nodes".* FROM "nodes"  WHERE "nodes"."family_tree_id" = $1 AND "nodes"."is_comment" IS NULL  [["family_tree_id", 1]]
  User Load (1.5ms)  SELECT "users".* FROM "users" INNER JOIN "memberships" ON "users"."id" = "memberships"."user_id" WHERE "memberships"."family_tree_id" = $1  ORDER BY "users"."first_name" ASC  [["family_tree_id", 1]]
  Rendered shared/_upload.html.erb (13.2ms)
  User Load (1.3ms)  SELECT  "users".* FROM "users"  WHERE "users"."id" = $1 LIMIT 1  [["id", 1]]
  Video Load (1.3ms)  SELECT  "videos".* FROM "videos"  WHERE "videos"."id" = $1 LIMIT 1  [["id", 6]]
   (34.0ms)  SELECT COUNT(*) FROM "roles" INNER JOIN "users_roles" ON "roles"."id" = "users_roles"."role_id" WHERE "users_roles"."user_id" = $1 AND (((roles.name = 'admin') AND (roles.resource_type IS NULL) AND (roles.resource_id IS NULL)))  [["user_id", 1]]
DEPRECATION WARNING: [Best_in_place] :type is deprecated in favor of :as . (called from best_in_place_deprecated_options at /Users/marcgayle/.rvm/gems/ruby-2.0.0-p353@kordli/bundler/gems/best_in_place-0a0f62e19a8b/lib/best_in_place/helper.rb:152)
DEPRECATION WARNING: [Best_in_place] :type is deprecated in favor of :as . (called from best_in_place_deprecated_options at /Users/marcgayle/.rvm/gems/ruby-2.0.0-p353@kordli/bundler/gems/best_in_place-0a0f62e19a8b/lib/best_in_place/helper.rb:152)
  Participant Load (2.0ms)  SELECT "participants".* FROM "participants"  WHERE "participants"."video_id" = $1  [["video_id", 6]]
  Rendered shared/_box.html.erb (14247.4ms)
  Comment Load (1.4ms)  SELECT "comments".* FROM "comments"  WHERE "comments"."node_id" = $1  [["node_id", 1]]
  NodeComment Load (1.2ms)  SELECT "node_comments".* FROM "node_comments"  WHERE "node_comments"."node_id" = $1  [["node_id", 1]]
  CACHE (0.0ms)  SELECT  "users".* FROM "users"  WHERE "users"."id" = $1 LIMIT 1  [["id", 1]]
DEPRECATION WARNING: [Best_in_place] :type is deprecated in favor of :as . (called from best_in_place_deprecated_options at /Users/marcgayle/.rvm/gems/ruby-2.0.0-p353@kordli/bundler/gems/best_in_place-0a0f62e19a8b/lib/best_in_place/helper.rb:152)
  CACHE (0.0ms)  SELECT  "users".* FROM "users"  WHERE "users"."id" = $1 LIMIT 1  [["id", 1]]
DEPRECATION WARNING: [Best_in_place] :type is deprecated in favor of :as . (called from best_in_place_deprecated_options at /Users/marcgayle/.rvm/gems/ruby-2.0.0-p353@kordli/bundler/gems/best_in_place-0a0f62e19a8b/lib/best_in_place/helper.rb:152)
  User Load (1.3ms)  SELECT  "users".* FROM "users"  WHERE "users"."id" = $1 LIMIT 1  [["id", 2]]
DEPRECATION WARNING: [Best_in_place] :type is deprecated in favor of :as . (called from best_in_place_deprecated_options at /Users/marcgayle/.rvm/gems/ruby-2.0.0-p353@kordli/bundler/gems/best_in_place-0a0f62e19a8b/lib/best_in_place/helper.rb:152)
  CACHE (0.0ms)  SELECT  "users".* FROM "users"  WHERE "users"."id" = $1 LIMIT 1  [["id", 1]]
DEPRECATION WARNING: [Best_in_place] :type is deprecated in favor of :as . (called from best_in_place_deprecated_options at /Users/marcgayle/.rvm/gems/ruby-2.0.0-p353@kordli/bundler/gems/best_in_place-0a0f62e19a8b/lib/best_in_place/helper.rb:152)
  CACHE (0.0ms)  SELECT  "users".* FROM "users"  WHERE "users"."id" = $1 LIMIT 1  [["id", 2]]
DEPRECATION WARNING: [Best_in_place] :type is deprecated in favor of :as . (called from best_in_place_deprecated_options at /Users/marcgayle/.rvm/gems/ruby-2.0.0-p353@kordli/bundler/gems/best_in_place-0a0f62e19a8b/lib/best_in_place/helper.rb:152)
  CACHE (0.0ms)  SELECT  "users".* FROM "users"  WHERE "users"."id" = $1 LIMIT 1  [["id", 1]]
DEPRECATION WARNING: [Best_in_place] :type is deprecated in favor of :as . (called from best_in_place_deprecated_options at /Users/marcgayle/.rvm/gems/ruby-2.0.0-p353@kordli/bundler/gems/best_in_place-0a0f62e19a8b/lib/best_in_place/helper.rb:152)
  CACHE (0.0ms)  SELECT  "users".* FROM "users"  WHERE "users"."id" = $1 LIMIT 1  [["id", 1]]
DEPRECATION WARNING: [Best_in_place] :type is deprecated in favor of :as . (called from best_in_place_deprecated_options at /Users/marcgayle/.rvm/gems/ruby-2.0.0-p353@kordli/bundler/gems/best_in_place-0a0f62e19a8b/lib/best_in_place/helper.rb:152)
  Rendered shared/_comments.html.erb (23.9ms)
  Rendered dashboard/index.html.erb within layouts/application (14295.0ms)
  Rendered shared/_nav.html.erb (0.4ms)
  Rendered shared/_search.html.erb (0.5ms)
  Rendered devise/registrations/_edit.html.erb (12.8ms)
  Rendered shared/_edit_account_popup.html.erb (13.5ms)
   (1.8ms)  SELECT COUNT(*) FROM "activities" LEFT JOIN read_marks as read_marks ON read_marks.readable_type  = 'PublicActivity::ORM::ActiveRecord::Activity'
                                   AND read_marks.readable_id    = activities.id
                                   AND read_marks.user_id        = 1
                                   AND read_marks.timestamp     >= activities.created_at WHERE "activities"."owner_id" = 1 AND (read_marks.id IS NULL)
  Notification Load (2.4ms)  SELECT "activities".* FROM "activities" LEFT JOIN read_marks as read_marks ON read_marks.readable_type  = 'PublicActivity::ORM::ActiveRecord::Activity'
                                   AND read_marks.readable_id    = activities.id
                                   AND read_marks.user_id        = 1
                                   AND read_marks.timestamp     >= activities.created_at WHERE "activities"."owner_id" = 1 AND (read_marks.id IS NULL)
  Rendered public_activity/node/_create.html.erb (0.1ms)
  Rendered public_activity/node/_create.html.erb (0.1ms)
  Rendered public_activity/node/_create.html.erb (0.1ms)
  Rendered public_activity/comment/_create.html.erb (0.2ms)
  Rendered public_activity/node/_destroy.html.erb (0.2ms)
  Rendered public_activity/comment/_destroy.html.erb (0.1ms)
  Rendered public_activity/comment/_create.html.erb (0.1ms)
  Rendered public_activity/node/_create.html.erb (0.1ms)
  Rendered public_activity/node/_destroy.html.erb (0.1ms)
  Rendered public_activity/comment/_destroy.html.erb (0.1ms)
  Rendered public_activity/comment/_create.html.erb (0.1ms)
  Rendered public_activity/comment/_create.html.erb (0.1ms)
  Rendered public_activity/comment/_create.html.erb (0.1ms)
  Rendered public_activity/comment/_create.html.erb (0.1ms)
  Rendered public_activity/comment/_create.html.erb (0.1ms)
  Rendered public_activity/participant/_create.html.erb (0.1ms)
  Rendered public_activity/participant/_create.html.erb (0.1ms)
  Rendered public_activity/comment/_destroy.html.erb (0.1ms)
  Rendered public_activity/comment/_destroy.html.erb (0.1ms)
  Rendered public_activity/comment/_create.html.erb (0.1ms)
  Rendered public_activity/comment/_create.html.erb (0.1ms)
  Rendered public_activity/comment/_destroy.html.erb (0.1ms)
  Rendered public_activity/comment/_create.html.erb (0.1ms)
  Rendered public_activity/comment/_create.html.erb (0.1ms)
  Rendered public_activity/comment/_destroy.html.erb (0.1ms)
  Rendered public_activity/comment/_destroy.html.erb (0.1ms)
  Rendered public_activity/comment/_destroy.html.erb (0.1ms)
  Rendered public_activity/comment/_create.html.erb (0.1ms)
  Rendered public_activity/comment/_create.html.erb (0.1ms)
  Rendered public_activity/comment/_create.html.erb (0.1ms)
  Rendered public_activity/comment/_destroy.html.erb (0.1ms)
  Rendered public_activity/comment/_destroy.html.erb (0.1ms)
  Rendered public_activity/comment/_create.html.erb (0.1ms)
  Rendered public_activity/comment/_create.html.erb (0.1ms)
  Rendered public_activity/comment/_create.html.erb (0.1ms)
  Rendered public_activity/comment/_create.html.erb (0.1ms)
  Rendered public_activity/comment/_destroy.html.erb (0.1ms)
  Rendered public_activity/comment/_destroy.html.erb (0.1ms)
  Rendered public_activity/comment/_destroy.html.erb (0.1ms)
  Rendered public_activity/comment/_create.html.erb (0.1ms)
  Rendered public_activity/comment/_create.html.erb (0.1ms)
  Rendered public_activity/comment/_create.html.erb (0.1ms)
  Rendered public_activity/comment/_create.html.erb (0.1ms)
  Rendered public_activity/comment/_create.html.erb (0.1ms)
  Rendered public_activity/comment/_destroy.html.erb (0.1ms)
  Rendered public_activity/comment/_destroy.html.erb (0.1ms)
  Rendered public_activity/comment/_destroy.html.erb (0.1ms)
  Rendered public_activity/comment/_destroy.html.erb (0.1ms)
  Rendered public_activity/comment/_destroy.html.erb (0.1ms)
  Rendered public_activity/comment/_create.html.erb (0.1ms)
  Rendered public_activity/comment/_create.html.erb (0.1ms)
  Rendered public_activity/comment/_create.html.erb (0.1ms)
  Rendered public_activity/comment/_create.html.erb (0.1ms)
  Rendered public_activity/comment/_create.html.erb (0.1ms)
  Rendered public_activity/comment/_destroy.html.erb (0.1ms)
  Rendered public_activity/comment/_destroy.html.erb (0.1ms)
  Rendered public_activity/comment/_create.html.erb (0.1ms)
  Rendered public_activity/comment/_create.html.erb (0.1ms)
  Rendered shared/_notifications.html.erb (127.8ms)
  Rendered shared/_profile.html.erb (143.7ms)
  Rendered devise/registrations/_edit.html.erb (15.2ms)
  Rendered shared/_edit_account_popup.html.erb (16.0ms)
  CACHE (0.0ms)  SELECT "users".* FROM "users" INNER JOIN "memberships" ON "users"."id" = "memberships"."user_id" WHERE "memberships"."family_tree_id" = $1  ORDER BY "users"."first_name" ASC  [["family_tree_id", 1]]
  Rendered shared/_upload_video_popup.html.erb (7.2ms)
  Rendered shared/_navbar.html.erb (173.1ms)
  Rendered shared/_footer.html.erb (0.9ms)
Completed 200 OK in 14510ms (Views: 14448.1ms | ActiveRecord: 55.1ms)

I am tempted to do ActiveRecord optimizations, using eager loading and all this jazz....but given the difference in times between the Views time and ActiveRecord time, that approach seems silly.

This is my Dashboard#Index Controller:

  def index
    @family_tree = current_user.family_tree
    @nodes = @family_tree.nodes.includes(:comments)
    @video = Video.new
    @videos = Video.all.where(:is_complete => true)
    @node = current_user.nodes.new
    @memberships = current_user.memberships.limit(3)    

    if params[:search]
      @nodes = Node.node_search(params[:search])
    else
      @videos = Video.all.order('created_at DESC')
      # flash[:notice] = "No results found"
    end
  end

This is my Dashboard/index.html.erb:

<% if !resource.errors.messages.empty? %>
    <!-- <div><%#= resource.errors.inspect %></div> -->
    <div><%= devise_error_messages2! %></div>
<% end %>

<!-- Content -->
<div id="content">
  <% if current_user.sign_in_count == 1 %>
    <div class="hidden" id="new-user"></div>
  <% end %>
  <div class="container">
        <div class="row">
            <!-- Profile -->
                <%= render "shared/profile_box" %>
                <!-- // Profile -->
            </div> <!-- //row -->
      <!-- Video -->
      <div id="video">
          <!-- Box Add -->
          <div class="box add-video" data-popup="add-video-step-1" data-step="3" data-intro="To upload a video simply click in this box or the upload a video button in the main bar.">
                        <a class="upload popupbox" href="#" data-popup="add-video-step-1">
              <%= image_tag("buttons/upload-video.gif")%>
                        </a>
          </div>
          <!-- Box -->
          <% @nodes.each do |node| %>
                <!-- Upload Video Comment Popup -->
           <%= render partial: "shared/upload", locals: {node: node} %>

          <div class="box">
              <%= render partial: "shared/box", locals: {node: node} %>

              <%= render partial: "shared/comments", locals: {node: node} %>
          </div>
          <% end %> <!-- node -->
      </div>
  </div>
</div>

Rather than cluttering the question with code from my partials, I figured I would just leave it be and if you guys request it, I will add them later.

I suspect that there are one or two things I can do to drastically reduce that views render time. It is ridiculously high.

I am also using Turbolinks, but no caching.

Would Russian Doll caching be recommended here, given my use of Turbolinks? Also is my analysis correct, i.e. that I am better served focusing on the view rendering than AR queries? Or should I go ahead and optimize those too?

I don't necessarily need ABSOLUTE 100% efficiency, I just don't want a load time of 14+ seconds. That seems crazy to me.

score 0 · Accepted Answer · edited May 23 '17 at 10:25

So it turns out that the biggest impact change I had was getting rid of the N+1 problem, which I did with this eager loading assignment:

@nodes = @family_tree.nodes.includes(:comments => :user)

These are the results. The original loading time was this:

Completed 200 OK in 14510ms (Views: 14448.1ms | ActiveRecord: 55.1ms)

This is a random sample of 3 homepage refreshes now:

Completed 200 OK in 1125ms (Views: 1093.1ms | ActiveRecord: 24.6ms)

Completed 200 OK in 994ms (Views: 963.3ms | ActiveRecord: 23.8ms)

Completed 200 OK in 1428ms (Views: 1375.8ms | ActiveRecord: 47.5ms)

Average

Completed 200 OK in 1182.3ms (Views: 1144.07ms | ActiveRecord: 31.97ms)

Improvement

Completed: 91% improvement overall

Views: 92.1% improvement

ActiveRecord: 41.97% improvement.

Thanks to Fer in this answer - https://stackoverflow.com/a/26625454/91970 - for providing clarity with how to tackle this.

What is a recommended way to optimize my app given this server log?

1 Answers1