Basic tutorial rails app very slow loading views

Question

I'm new to rails, having just finished Michael Hartl's excellent Rails Tutorial. I'm building out another project app loosly following that framework, but with differences.

I'm partway in and have already run into an issue where many parts of my app seem unusually slow, and I don't see an obvious reason why. I've put details of my users index page below, because that is the slowest. As shown below, it takes 9.1s to load, of which ~8.7s is loading the views. This is on the dev environment (AWS Cloud9), but even when deployed on Heroku it takes ~5s to render the page with only 13 users in the database!

5s is pretty bad at this limited scale, and the rails tutorial sample app renders the users index page in 447ms total with 50 users shown! (running on a similar AWS EC2 instance) I don't see where my app is different enough to cause a 20x increase in load time.

Render /users server output:

Started GET "/users" for 24.85.170.222 at 2023-01-29 21:52:03 +0000
Cannot render console from 24.85.170.222! Allowed networks: 127.0.0.0/127.255.255.255, ::1
Processing by UsersController#index as HTML
  User Load (0.3ms)  SELECT "users".* FROM "users" WHERE "users"."id" = ? LIMIT ?  [["id", 2], ["LIMIT", 1]]
  ↳ app/helpers/sessions_helper.rb:12:in `current_user'
  Rendering layout layouts/application.html.erb
  Rendering users/index.html.erb within layouts/application
  User Count (1.1ms)  SELECT COUNT(*) FROM "users"
  ↳ app/views/users/index.html.erb:5
  User Load (0.6ms)  SELECT "users".* FROM "users" LIMIT ? OFFSET ?  [["LIMIT", 30], ["OFFSET", 0]]
  ↳ app/views/users/index.html.erb:8
  Rendered users/index.html.erb within layouts/application (Duration: 7719.3ms | Allocations: 280179)
  Rendered layouts/_rails_default.html.erb (Duration: 7.6ms | Allocations: 6444)
  Rendered layouts/_shim.html.erb (Duration: 0.0ms | Allocations: 9)
  Company Load (0.1ms)  SELECT "companies".* FROM "companies" INNER JOIN "company_users" ON "companies"."id" = "company_users"."company_id" WHERE "company_users"."user_id" = ? AND "company_users"."employee" = ? LIMIT ?  [["user_id", 2], ["employee", 1], ["LIMIT", 1]]
  ↳ app/views/layouts/_header.html.erb:35
  Rendered layouts/_header.html.erb (Duration: 963.3ms | Allocations: 1473)
  Rendered layouts/_footer.html.erb (Duration: 0.2ms | Allocations: 73)
  Rendered layout layouts/application.html.erb (Duration: 8693.9ms | Allocations: 289996)
Completed 200 OK in 9147ms (Views: 8697.1ms | ActiveRecord: 2.2ms | Allocations: 291862)

users_controller.rb:

class UsersController < ApplicationController
  before_action :logged_in_user, only: [:index, :edit, :update, :destroy, :show]
  before_action :correct_user, only: [:edit, :update]

  def index
    @users = User.paginate(page: params[:page])
  end

end

/models/user.rb:

class User < ApplicationRecord

  before_save :downcase_email

  VALID_EMAIL_REGEX = /\A[\w+\-.]+@[a-z\d\-]+(\.[a-z\d\-]+)*\.[a-z]+\z/i

  validates :email, presence: true, length: { maximum: 255 },
                    format: { with: VALID_EMAIL_REGEX },
                    uniqueness: true

  #Returns true if given token matches the digest
  def authenticated?(token)
    #debugger
    return false if session_digest.nil?
    BCrypt::Password.new(session_digest).is_password?(token)
  end


  # Returns the hash digest of the given string. 
  def User.digest(string)
    cost = ActiveModel::SecurePassword.min_cost ? BCrypt::Engine::MIN_COST :
                                                  BCrypt::Engine.cost
    BCrypt::Password.create(string, cost: cost)
  end

  #returns a session token to prevent session hijacking
  def set_session_token
    @session_token = SecureRandom.urlsafe_base64
    update_attribute(:session_digest, User.digest(@session_token))
    return @session_token
  end

  private

    def downcase_email
      email.downcase!
    end
end

sessions_helper.rb:

module SessionsHelper

  def log_in(user)
    session[:user_id] = user.id
    #guard against session replay attacks
    session[:session_token] = user.set_session_token
  end

  def current_user
    if (user_id = session[:user_id])
      @sess_user ||= User.find_by(id: user_id)
      if @sess_user && @sess_user.authenticated?(session[:session_token])
        @current_user = @sess_user
      end
    end
  end

  def current_user?(user)
    user && user == current_user
  end

  def logged_in?
    !current_user.nil?
  end

  #confirms a logged in user
  def logged_in_user
    unless logged_in?
      store_location                    #store requested URL in a cookie for friendly forwarding
      flash[:danger] = "Please log in"
      redirect_to root_url, status: :see_other
    end
  end

end

/views/users/index.html.erb:

<% provide(:title, 'All users') %>

<h1>All users</h1>

<%= will_paginate %>

<ul class="users">
  <% @users.each do |user| %>
    <li>
        <%= link_to user.display_name, user %>
        <% if current_user.superadmin? && !current_user?(user) %>
          | <%= link_to "delete", user, data: { "turbo-method": :delete, turbo_confirm: "Delete #{user.email}?" } %>
        <% end %>
    </li>
  <% end %>
</ul>

<%= will_paginate %>

views/layouts/application.html.erb:

<!DOCTYPE html>
<html>
  <head>

    <title><%= full_title(yield(:title)) %></title>
    <meta name="viewport" content="width=device-width,initial-scale=1">
    <meta charset="utf-8">

    <%= render 'layouts/rails_default' %>
    <%= render 'layouts/shim' %>
    <%= javascript_importmap_tags %>
  </head>

  <body>
    <% flash.each do |message_type, message| %>
      <%= content_tag(:div, message, class: "alert alert-#{message_type}") %>
    <% end %>
        <%= render 'layouts/header' %>
    <div class="container">
      <%= yield %>
      <%= render 'layouts/footer' %>
      <%= debug(params) if Rails.env.development? %>
    </div>
  </body>
</html>

My views/layouts/_header.html.erb file also hits is_logged_in? and current_user a few times.

I am using all the same Gems as the railstutorial.org sample app, so a Gem shouldn't be the issue.

At first I thought that current_user was hitting the database multiple times based on the log. So I memoized it with the @sess_user ||= User.find_by(id: user_id) line. But this didn't affect load times hardly at all, and when I compared with the sample I app I realized this wasn't it as the db hits were cached: CACHE User Load (0.0ms)

I feel like there's something obvious that I'm missing. I've read up on N+1 queries and using .includes, especially as there are some other models on my site for which that might be relevant, but the fact that the issue occurs even on the very plain users index page perplexes me.

I'm still only partway through development, but I want to try and figure out this issue before I get too far ahead and things get only more complex. Would be very appreciative of any insights!

Answer 1

Alex's first comment on this question drove straight to the heart of the issue. I refactored current_user as shown below to memoize the return value so that is_password? is only called once per view. Instant relief - page load times are now sub-400ms.

All credit to Alex. He nailed it. His comment should really be "the answer", but I feel like I should post this here so the question shows as "answered".

  def current_user
    #memoize current user so authenicated? only runs once per page (its very slow @ 200ms ea)
    @current_user ||= begin
      if (user_id = session[:user_id])
        user ||= User.find_by(id: user_id)
        if user && user.authenticated?(session[:session_token])
          user
        end
      end
    end
  end