Tracking Common Rails Performance Issues with Skylight

Today I am going to introduce you Skylight – a smart and easy to use online tool for profiling Rails, Sinatra, and Grape applications. While discovering its main features, we will discuss common Rails performance issues along with ways to fix them.

Skylight is somewhat similar to the popular service called New Relic, but it was designed specifically for Rails apps with a goal to make interacting with the dashboard easier. Skylight’s team believes that New Relic has too many features and not all of them are really useful. Therefore, the Skylight team are focusing on core components that provide immediate value. Skylight is free for up to 100k requests per month and you also receive a free 30-day trial to test its functionality. Not bad, eh?

The source code for the sample application can be found on GitHub.

Preparations

To see Skylight in action, we need a sample Rails application. It is going to be very simple, but that’ll be enough for this introductory article:

$ rails new SkylightDiag -T

I am using Rails 5.0.0.1, but Skylight works with versions 3 and 4 as well.

Suppose, in this application, we want to list musical albums and their tracks. All data will be completely fake, but that does not really matter. Create an Album and a Song model:

$ rails g model Album title:string musician:string
$ rails g model Song title:string duration:integer album:belongs_to
$ rails db:migrate

Make sure associations are set up properly:

models/album.rb

[...]
has_many :songs, dependent: :delete_all
[...]

models/song.rb

[...]
belongs_to :album
[...]

Add a controller and the root route (the view will be added later):

albums_controller.rb

class AlbumsController < ApplicationController
  def index
    @albums = Album.all
  end
end

config/routes.rb

[...]
root 'albums#index'
[...]

Instead of populating sample data by hand, let’s rely on db/seeds.rb and the Faker gem that returns random data of various kind:

Gemfile

[...]
gem 'faker'
[...]

Don’t forget to run

$ bundle install

This gem was recently updated and now includes even more types of sample data (beer and Star Wars heroes’ names included). Prepare the seeds.rb file:

db/seeds.rb

50.times do
  album = Album.create({title: Faker::Book.title, musician: Faker::StarWars.character})
  30.times do
    album.songs.create({title: Faker::Book.title, duration: rand(500)})
  end
end

Well, if you are a fan of “Game of Thrones”, you may take its characters’ names instead…

Lastly, run

$ rails db:seed

to populate the database. Now our lab environment is prepared and we can proceed to the next step.

Integrating Skylight

Before diving into the code, let’s quickly discuss which environments Skylight supports. It works with Ruby 1.9.2 and higher, but 2.1+ is recommended to take full advantage of the services’ tools. As I already said before, it works with Rails 3+, but Sinatra 1.2+, and even Grape 0.10+ are supported, as well (but you’ll have less detailed info). Lastly, Skylight should work with any *nix server, no special configuration is needed even for Heroku. The tracking client is written in Rust and C so it should not consume much memory.

To start off, grab your 30-day trial here (you’ll also receive a $50 credit as a little bonus from me :) ). Populate the basic information about yourself and your application, then add a new gem into the Gemfile:

Gemfile

[...]
gem "skylight"
[...]

Run

$ bundle install

Also note that Skylight’s setup wizard asks you to run a command looking like:

$ bundle exec skylight setup SOME_KEY

This command finalizes the integration by creating a config/skylight.yml file. After that, you are good to go. Note that a private token used to share application’s data was presented to you. It can be regenerated in your account’s settings page. Also don’t forget that Skylight won’t send any data in the development environment, so your application has to be deployed somewhere to start tracking its performance. For example, when deploying on Heroku, you may set Skylight’s token using the following command:

$ heroku config:add SKYLIGHT_AUTHENTICATION='123abc'

This page provides the complete overview of Skylight’s integration process with other platforms and explains how to track services outside of Rails, like Net::HTTP, Moped, Redis, and others.

N+1 Query Problem

Once you are done setting everything up, let’s emulate the first and probably the most well-known problem, called an “N+1 query”. To see it in action, list all the albums and their tracks on the main page of the app:

views/albums/index.html.erb

<h1>Albums</h1>
<ul>
  <%= render @albums %>
</ul>

views/albums/_album.html.erb

<li>
  <strong><%= album.title %></strong> by <%= album.musician %>
  <ul>
    <% album.songs.each do |song| %>
      <li><%= song.title %> (<%= song.duration %>s)</li>
    <% end %>
  </ul>
</li>

Boot the server and navigate to http://localhost:3000. Inside the terminal you’ll see output similar to this one:

Album Load (1.0ms)  SELECT "albums".* FROM "albums" ORDER BY published DESC
Song Load (0.0ms)  SELECT "songs".* FROM "songs" WHERE "songs"."album_id" = ?  [["album_id", 301]]
Song Load (1.0ms)  SELECT "songs".* FROM "songs" WHERE "songs"."album_id" = ?  [["album_id", 300]]
Song Load (1.0ms)  SELECT "songs".* FROM "songs" WHERE "songs"."album_id" = ?  [["album_id", 299]]
Song Load (0.0ms)  SELECT "songs".* FROM "songs" WHERE "songs"."album_id" = ?  [["album_id", 298]]
....
.... many similar stuff goes here

Basically, for each parent record (the album) we send a separate query to fetch its children (songs) and effectively spam the database. Deploy your application to a production environment, open its main page, and then after a couple of minutes refresh Skylight’s dashboard.

The dashboard itself is really nice and neat, and you can read this document to get to know it better and learn about Skylight’s main concepts. It presents information about requests per minute, typical and problem response times, as well as general information about endpoints. In our case, the endpoint will be the AlbumsController#create method. At the bottom of the page you can choose the time range to display – that’s pretty much it.

The red database icon near the endpoint’s name means that it has a number of repeating SQL queries, whereas the pie indicates it has high object allocations. Also note the “Agony” column that is being calculated by Skylight’s special algorithm to find out which endpoint is having the most adverse affect on the app’s users. Suppose you have two endpoints: one has the response time of 600ms but receives loads of requests, whereas the second one has the response time of 3s but has nearly no requests. Obviously, 600ms is much better than 3s, but as long as the first endpoint gets way more requests, it should be top priority to further reduce its response time.

Now if you click on the AlbumsController#create endpoint, you’ll see something like this:

Those two cycled red arrows near the green SQL row means that the query is not optimal and most likely has a N+1 problem (though it’s not always the case and in the later section we’ll see an example on this).

So, the fix for this problem is very simple. All you have to do is implement a so-called “eager loading” that greatly reduces the number of queries. This is done by employing the includes method:

albums_controller.rb

[...]
def index
  @albums = Album.includes(:songs)
end
[...]

Now in the terminal you’ll see

Album Load (1.0ms)  SELECT "albums".* FROM "albums"
Song Load (13.0ms)  SELECT "songs".* FROM "songs" WHERE "songs"."album_id" IN (202, 203, 204, 205, 206, ...)

which if of course much better. After deploying the updated version of the app to the server, Skylight no longer reports that problem:

Great!

Enabling Fragment Caching

Another very common technique to speed up your application is enabling caching. In this demo we’ll utilize the nested fragment caching method. First, enable it for the parent collection:

views/albums/index.html.erb

<%= render @albums, cached: true %>

Next for the children records:

views/albums/_album.html.erb

<li>
  <strong><%= album.title %></strong> by <%= album.musician %>
  <ul>
    <% album.songs.each do |song| %>
      <% cache song do %>
        <li><%= song.title %> (<%= song.duration %>s)</li>
      <% end %>
    <% end %>
  </ul>
</li>

Don’t forget that you have to set up caching on your server in order for this to work properly. As for Heroku, the setup is very simple. Enable the Memcachier addon (the free version):

$ heroku addons:create memcachier:dev

Drop in the Dalli gem

Gemfile

[...]
gem 'dalli'
[...]

install it

$ bundle install

and tweak the configuration for the production environment:

config/environment/production.rb

[...]
config.cache_store = :dalli_store,
    (ENV["MEMCACHIER_SERVERS"] || "").split(","),
    {:username => ENV["MEMCACHIER_USERNAME"],
     :password => ENV["MEMCACHIER_PASSWORD"],
     :failover => true,
     :socket_timeout => 1.5,
     :socket_failure_delay => 0.2,
     :down_retry_delay => 60
    }
[...]

After deploying to production, Skylight will show additional information about working with the cache store, while response time will notably decrease:

Grouping Transactions

Another less common technique to boost app performance is grouping multiple transactions into one. Suppose that users can add additional albums into the application by uploading a CSV file. Of course, we won’t perform the actual parsing of the file – let’s just mimic it by introducing a simple cycle:

albums_controller.rb

  [...]
  def create
    50.times do
      Album.create({title: Faker::Book.title, musician: Faker::StarWars.character})
    end
    redirect_to root_path
  end
  [...]

Add the route

config/routes.rb

[...]
resources :albums, only: [:create]
[...]

and place the button on the main page to run the import process:

views/albums/index.html.erb

[...]
<%= link_to 'add more albums', albums_path, method: :post %>
[...]

When this button is pressed you’ll see that each operation is done in its own transaction (yes, Yoda is now a musician):

(0.0ms)  begin transaction
SQL (4.0ms)  INSERT INTO "albums" ("title", "musician", "created_at", "updated_at") VALUES (?, ?, ?, ?)  [["title", "The Far-Distant Oxus"], ["musician", "Yoda"], ["created_at", 2016-09-13 13:09:29 UTC], ["updated_at", 2016-09-13 13:09:29 UTC]]
(81.0ms)  commit transaction

We spend 4ms for the INSERT operation whilst the transaction’s commitment lasts 20 times more! This is the Skylight’s visualization:

Instead, it’s better to group all these INSERT instructions into one transaction and apply it only once:

albums_controller.rb

  [...]
  def create
    Album.transaction do
      50.times do
        Album.create({title: Faker::Book.title, musician: Faker::StarWars.character})
      end
    end
    redirect_to root_path
  end
  [...]

Now the output is:

(1.0ms)  begin transaction
SQL (1.0ms)  INSERT INTO "albums" ("title", "musician", "created_at", "updated_at") VALUES (?, ?, ?, ?)  [["title", "A Handful of Dust"], ["musician", "Yoda"], ["created_at", 2016-09-13 13:14:26 UTC], ["updated_at", 2016-09-13 13:14:26 UTC]]
...
many other INSERTs here
...
(133.0ms)  commit transaction

That’s also better when you wish to abort the import process if an error is raised, as the transaction cannot be partly applied.

Here is the graphical representation:

Those red cycled arrows are still there because we really do have queries performed in a cycle.

Adding an Index

Another very simple, but sometimes overlooked performance optimization technique is the addition of a database index. It is absolutely necessary to make all your columns with foreign and primary keys indexed; columns with boolean values (like admin, banned, or published) are good candidates as well. The lol_dba gem can scan your models and present a list of columns that should be indexed.

Let’s introduce a new published column that says whether an album was already released or not:

$ rails g migration add_published_to_albums published:boolean

Modify migration a bit

def change
  add_column :albums, :published, :boolean, default: false
end

and apply it:

$ rails db:migrate

“Publish” 20 random albums:

db/seeds.rb

Album.all.shuffle.take(20).each {|a| a.toggle!(:published)}

$ rails db:seed

Now, let’s use this new column to either display a list of released albums or a full ordered list:

albums_controller.rb

def index
  if params[:published] == 't'
    @albums = Album.includes(:songs).where(published: true)
  else
    @albums = Album.includes(:songs).order('published DESC')
  end
end

Here are the results from Skylight’s dashboard:

Of course, as you’ve guessed, the published column is a great candidate for adding an index, so let’s do it now:

$ rails g migration add_missing_index_to_albums

migrations/xyz_add_missing_index_to_albums.rb

[...]
def change
  add_index :albums, :published
end
[...]

Apply the migration:

$ rails db:migrate

and observe the results on Skylight:

The performance boost may not be that high but when performing many operations involving a column, but the presence of an index can make a big difference.

Conclusion

In this article we’ve discussed Skylight – a smart profiler for Rails, Sinatra, and Grape apps. While exploring its main features we had a chance to take a look at some of the most common performance issues in Rails apps. Of course, our sample application is not very representative, but you’ve got at least a basic idea of what Skylight is capable of, so be sure to try it for a real project.

Hopefully, you enjoyed reading this article and now will care a bit more about the performance of your apps. I thank you for staying with me. Until next time!

Frequently Asked Questions (FAQs) about Tracking Common Rails Performance Issues with Skylight