Upgrading to Rails 5 Beta - The Hard Way

Rails 5 has been brewing for more than a year. To take advantage of new features, and stay on the supported path, you'll need to upgrade. In this post, we'll look at the upgrade process for a production Rails app, codetriage.com. The codebase is open source so you can follow along. Special thanks to Prathamesh for his help with this blog post.

This post originally published to the Heroku blog Upgrading to Rails 5 beta.

How Stable is the Beta?

In Rails a beta means the API is not yet stable, and features will come and go. A Release Candidate (RC) means no new features; the API is considered stable, and RCs will continue to be released until all reported regressions are resolved.

Should you run your production app on the beta? There is value in getting a beta working on a branch and being ready when the RC or upcoming release is available. Lots of companies run Beta and RC releases of Rails in production, but it's not for the faint of heart. You'll need to be pretty confident in your app, make sure your test suite is up to par, and that manual quality control (QC) checks are thorough. It's always a relief to find and fix bugs before they arrive in production. Please report regressions and bugs you encounter -- the faster we uncover and report them, the faster these bugs get fixed, and the more stable Rails becomes. Remember, no one else is going to find and report the regressions in your codebase unless you do it.

Upgrade your Gemfile

Step zero of the process is changing your Rails dependency, after which you'll want to $ bundle install, see what is incompatible and update those dependencies.

If you want to run on Heroku, I recommend avoiding the beta1 release on rubygems.org. It doesn't include a fix to stdout logging that is available in master. CodeTriage is running with this SHA of Rails from master:

# Gemfile
gem "rails", github: "rails/rails", ref: "dbf67b3a6f549769c5f581b70bc0c0d880d5d5d1"

You'll need to make sure that you're running a current Ruby; Rails now requires Ruby 2.2.2 or greater. At the time of writing, I recommend 2.2.4 or 2.3.0. CodeTriage is running 2.3.0.

# Gemfile
ruby "2.3.0"

If you can't bundle, you'll need to modify your dependencies in your Gemfile, or bundle update <dependency>

Once you've completed a $ bundle install you're well on your way to getting the upgrade started.

Gems Gems Gems

Just because a gem installs correctly doesn't mean it's compatible with Rails 5. Most libraries that specify Rails as a runtime dependency do not specify an upper bounds in their gemspec (like a Gemfile for gems). If they said "this gem is valid for rails versions 3-4" then bundler would let you know that it couldn't install that gem. Unfortunately since most say something like "this is good for Rails version 3 to infinity," there's no way by versioning alone. You'll have to investigate which of your dependencies are compatible manually; don't worry, there are some easy ways to tell.

Rails Console

The first thing you'll want to do is boot a console:

$ rails console
Loading development environment (Rails 5.0.0.beta1)
irb(main):001:0>

Did that work? Great, skip to the next step. If not, use backtraces to see where errors came from, and which gems might be having problems.

When you get a problem with a gem, check https://rubygems.org and see if you're using the latest. If not, it's a good idea to try using the most recently released version. If you still get an error, try pointing at their master branch, some libraries have fixes for Rails 5 that haven't been released yet. Many libraries that depend on Rack have not released a version that supports Rack 2, however many of them have support for it in master or in another branch. When in doubt ask a gem maintainer.

Here's an example of an error that CodeTriage saw:

$ rails console
/Users/richardschneeman/.gem/ruby/2.3.0/gems/devise-3.5.3/lib/devise/failure_app.rb:9:in `<class:FailureApp>': uninitialized constant ActionController::RackDelegation (NameError)
  from /Users/richardschneeman/.gem/ruby/2.3.0/gems/devise-3.5.3/lib/devise/failure_app.rb:8:in `<module:Devise>'
  from /Users/richardschneeman/.gem/ruby/2.3.0/gems/devise-3.5.3/lib/devise/failure_app.rb:3:in `<top (required)>'
  from /Users/richardschneeman/.gem/ruby/2.3.0/gems/devise-3.5.3/lib/devise/mapping.rb:122:in `default_failure_app'
  from /Users/richardschneeman/.gem/ruby/2.3.0/gems/devise-3.5.3/lib/devise/mapping.rb:67:in `initialize'
  from /Users/richardschneeman/.gem/ruby/2.3.0/gems/devise-3.5.3/lib/devise.rb:325:in `new'
  from /Users/richardschneeman/.gem/ruby/2.3.0/gems/devise-3.5.3/lib/devise.rb:325:in `add_mapping'
  from /Users/richardschneeman/.gem/ruby/2.3.0/gems/devise-3.5.3/lib/devise/rails/routes.rb:238:in `block in devise_for'
  from /Users/richardschneeman/.gem/ruby/2.3.0/gems/devise-3.5.3/lib/devise/rails/routes.rb:237:in `each'
  from /Users/richardschneeman/.gem/ruby/2.3.0/gems/devise-3.5.3/lib/devise/rails/routes.rb:237:in `devise_for'
  from /Users/richardschneeman/Documents/projects/codetriage/config/routes.rb:9:in `block in <top (required)>'
  from /Users/richardschneeman/.gem/ruby/2.3.0/bundler/gems/rails-dbf67b3a6f54/actionpack/lib/action_dispatch/routing/route_set.rb:389:in `instance_exec'
  from /Users/richardschneeman/.gem/ruby/2.3.0/bundler/gems/rails-dbf67b3a6f54/actionpack/lib/action_dispatch/routing/route_set.rb:389:in `eval_block'
  from /Users/richardschneeman/.gem/ruby/2.3.0/bundler/gems/rails-dbf67b3a6f54/actionpack/lib/action_dispatch/routing/route_set.rb:371:in `draw'
  from /Users/richardschneeman/Documents/projects/codetriage/config/routes.rb:3:in `<top (required)>'
  from /Users/richardschneeman/.gem/ruby/2.3.0/bundler/gems/rails-dbf67b3a6f54/railties/lib/rails/application/routes_reloader.rb:40:in `block in load_paths'
  from /Users/richardschneeman/.gem/ruby/2.3.0/bundler/gems/rails-dbf67b3a6f54/railties/lib/rails/application/routes_reloader.rb:40:in `each'
  from /Users/richardschneeman/.gem/ruby/2.3.0/bundler/gems/rails-dbf67b3a6f54/railties/lib/rails/application/routes_reloader.rb:40:in `load_paths'
  from /Users/richardschneeman/.gem/ruby/2.3.0/bundler/gems/rails-dbf67b3a6f54/railties/lib/rails/application/routes_reloader.rb:16:in `reload!'
  from /Users/richardschneeman/.gem/ruby/2.3.0/bundler/gems/rails-dbf67b3a6f54/railties/lib/rails/application/routes_reloader.rb:26:in `block in updater'
  from /Users/richardschneeman/.gem/ruby/2.3.0/bundler/gems/rails-dbf67b3a6f54/activesupport/lib/active_support/file_update_checker.rb:75:in `execute'
  from /Users/richardschneeman/.gem/ruby/2.3.0/bundler/gems/rails-dbf67b3a6f54/railties/lib/rails/application/routes_reloader.rb:27:in `updater'
  from /Users/richardschneeman/.gem/ruby/2.3.0/bundler/gems/rails-dbf67b3a6f54/railties/lib/rails/application/routes_reloader.rb:7:in `execute_if_updated'
  from /Users/richardschneeman/.gem/ruby/2.3.0/bundler/gems/rails-dbf67b3a6f54/railties/lib/rails/application/finisher.rb:69:in `block in <module:Finisher>'
  from /Users/richardschneeman/.gem/ruby/2.3.0/bundler/gems/rails-dbf67b3a6f54/railties/lib/rails/initializable.rb:30:in `instance_exec'
  from /Users/richardschneeman/.gem/ruby/2.3.0/bundler/gems/rails-dbf67b3a6f54/railties/lib/rails/initializable.rb:30:in `run'
  from /Users/richardschneeman/.gem/ruby/2.3.0/bundler/gems/rails-dbf67b3a6f54/railties/lib/rails/initializable.rb:55:in `block in run_initializers'
  from /Users/richardschneeman/.rubies/ruby-2.3.0/lib/ruby/2.3.0/tsort.rb:228:in `block in tsort_each'
  from /Users/richardschneeman/.rubies/ruby-2.3.0/lib/ruby/2.3.0/tsort.rb:350:in `block (2 levels) in each_strongly_connected_component'
  from /Users/richardschneeman/.rubies/ruby-2.3.0/lib/ruby/2.3.0/tsort.rb:431:in `each_strongly_connected_component_from'
  from /Users/richardschneeman/.rubies/ruby-2.3.0/lib/ruby/2.3.0/tsort.rb:349:in `block in each_strongly_connected_component'
  from /Users/richardschneeman/.rubies/ruby-2.3.0/lib/ruby/2.3.0/tsort.rb:347:in `each'
  from /Users/richardschneeman/.rubies/ruby-2.3.0/lib/ruby/2.3.0/tsort.rb:347:in `call'
  from /Users/richardschneeman/.rubies/ruby-2.3.0/lib/ruby/2.3.0/tsort.rb:347:in `each_strongly_connected_component'
  from /Users/richardschneeman/.rubies/ruby-2.3.0/lib/ruby/2.3.0/tsort.rb:226:in `tsort_each'
  from /Users/richardschneeman/.rubies/ruby-2.3.0/lib/ruby/2.3.0/tsort.rb:205:in `tsort_each'
  from /Users/richardschneeman/.gem/ruby/2.3.0/bundler/gems/rails-dbf67b3a6f54/railties/lib/rails/initializable.rb:54:in `run_initializers'
  from /Users/richardschneeman/.gem/ruby/2.3.0/bundler/gems/rails-dbf67b3a6f54/railties/lib/rails/application.rb:350:in `initialize!'
  from /Users/richardschneeman/Documents/projects/codetriage/config/environment.rb:5:in `<top (required)>'
  from /Users/richardschneeman/.gem/ruby/2.3.0/bundler/gems/rails-dbf67b3a6f54/railties/lib/rails/application.rb:326:in `require_environment!'
  from /Users/richardschneeman/.gem/ruby/2.3.0/bundler/gems/rails-dbf67b3a6f54/railties/lib/rails/commands/commands_tasks.rb:157:in `require_application_and_environment!'
  from /Users/richardschneeman/.gem/ruby/2.3.0/bundler/gems/rails-dbf67b3a6f54/railties/lib/rails/commands/commands_tasks.rb:77:in `console'
  from /Users/richardschneeman/.gem/ruby/2.3.0/bundler/gems/rails-dbf67b3a6f54/railties/lib/rails/commands/commands_tasks.rb:49:in `run_command!'
  from /Users/richardschneeman/.gem/ruby/2.3.0/bundler/gems/rails-dbf67b3a6f54/railties/lib/rails/command.rb:20:in `run'
  from /Users/richardschneeman/.gem/ruby/2.3.0/bundler/gems/rails-dbf67b3a6f54/railties/lib/rails/commands.rb:19:in `<top (required)>'
  from bin/rails:4:in `require'
  from bin/rails:4:in `<main>'

The gem in the backtrace above is devise 3.5.3; we were able to get things working by pointing to master, which may be released by now.

Repeat this until your rails console works. If you're already on the master version of a gem and it's still failing to boot, it might not support Rails 5 yet. Try debugging a little, and see if there's any open issues about Rails 5 on the tracker. If you don't see anything, open a new issue giving your error message and description of what's going on, and try to be as instructive as possible. Before you do this, you might want to try using the master version of their gem in a bare-bones rails new app to see if you can reproduce the problem. If the problem doesn't reproduce it may be an issue with how you're using the gem instead of the gem itself. This will help you uncover differences there. If you do reproduce the problem, then push it up to Github and share it in the issue. The maintainer will be able to fix an easily reproducible example much faster.

When you're not able to upgrade around a fix, sometimes you might not need that gem, or you might want to remove it temporarily so you can work on upgrading the rest of your app while the maintainer works on a fix.

Shim Gems

Sometimes functionality is taken out of Rails but provided via smaller gems. For example. While upgrading we had to use record_tag_helper and rails-controller-testing to get the app working.

Rails Server

Once you've got your console working, try your server. Just like with console, get it to boot. Once it's booted try hitting the main page and some other actions. You'll be looking for exceptions as well as strange behavior, though not all bugs cause exceptions. In the case of CodeTriage, a strange thing was happening. An error was getting thrown, but there was nothing in the logs and no debug error page in development. When this happens it's usually a bug in a rack middleware. You can get a list of them by running

$ rake middleware
use Rack::Sendfile
use ActionDispatch::LoadInterlock
use ActiveSupport::Cache::Strategy::LocalCache::Middleware
use Rack::Runtime
use Rack::MethodOverride
use ActionDispatch::RequestId
use Rails::Rack::Logger
use ActionDispatch::ShowExceptions
use WebConsole::Middleware
use ActionDispatch::DebugExceptions
use ActionDispatch::RemoteIp
use ActionDispatch::Reloader
use ActionDispatch::Callbacks
use ActiveRecord::Migration::CheckPending
use ActiveRecord::ConnectionAdapters::ConnectionManagement
use ActiveRecord::QueryCache
use ActionDispatch::Cookies
use ActionDispatch::Session::CookieStore
use ActionDispatch::Flash
use Rack::Head
use Rack::ConditionalGet
use Rack::ETag
use Warden::Manager
use ActionView::Digestor::PerRequestDigestCacheExpiry
use Bullet::Rack
use OmniAuth::Strategies::GitHub
run CodeTriage::Application.routes

The request enters at the top and goes to each middleware until finally it hits our application on the bottom CodeTriage::Application.routes. If the error was being thrown by our app, then the ActionDispatch::DebugExceptions middleware outputs error logs and would show a nice exception page in development. In my case that wasn't happening, so I knew the error was somewhere before that point.

I bisected the problem by adding logging to call methods. If the output showed up in STDOUT then I knew it was being called successfully and I should go higher up the Rack stack (which is confusing, because it is lower on this middleware list). After enough debugging, I finally found the exception was coming from WebConsole::Middleware, which is naturally the last possible place an exception could occur before it gets caught by the DebugExceptions middleware. Upgrading to master on web-console gem fixed the error. It turns out that placement is not by accident and web-console inserts itself before the debug middleware. I opened an issue with web-console and @gsamokovarov promptly added some code that detects when an internal error is thrown by web-console and makes sure it shows up in the logs. My rule of thumb is if something takes me over an hour to fix that could have been made much easier by exposing the errant behavior (such as logging an exception), then I report it as an issue to raise awareness of that failure mode. Sometimes the bug is well known but often maintainers don't know what is difficult or hard to debug. If you have ideas on things to add to make using a piece of software easier, sharing it in a friendly and helpful way is good for everyone.

Keep manually testing your app until no errors and all errant behavior is gone. Once you've done this, you're on the home stretch.

Testing

Now the server and console are working, you want to get your test suite green $ rake test. Rails 5 now includes a nice test runner $ rails test; you can specify a particular file or a specific line to run $ rails test test/unit/users.rb:58.

This step was bad, resulting in cryptic failures. I recommend picking 1 failure or error and focusing on it. Sometimes you'll see 100 failures, but when you fix one, it resolves them all, as they were the same issue.

For CodeTriage, we were getting errors

UserUpdateTest#test_updating_the_users_skip_issues_with_pr_setting_to_true:
NoMethodError: undefined method `normalize_params' for Rack::Utils:Module
    test/integration/user_update_test.rb:50:in `block in <class:UserUpdateTest>'

A grep of my project indicated normalize_params wasn't being used. The error didn't have a long backtrace. On that line test/integration/user_update_test.rb:50 we are using a capybara helper:

click_button 'Save'

On a whim, I updated capybara and it resolved the error. Not sure why the backtrace was so short, that might be worth digging into later, as it would have made debugging faster.

Other gotchas

The Strong Params that you get in your controller have changed and are no longer inheriting from a hash. At the time, there was no deprecation, so I added one. It's just a deprecation, but you should still make sure you're only using the approved API.

There was a change to image_tag where it no longer takes nil as an argument, this wasn't used in production, but the tests (accidentally) depended on it.

With all of this together, we were ready for Rails 5 in the prime time. Here's the PR

After the Upgrade

We're almost done! The last thing we need to do is to look for deprecations. They'll show up in your logs like:

DEPRECATION WARNING: ActionController::TestCase HTTP request methods will accept only
keyword arguments in future Rails versions.

Or

DEPRECATION WARNING: `redirect_to :back` is deprecated and will be removed from Rails 5.1. Please use `redirect_back(fallback_location: fallback_location)` where `fallback_location` represents the location to use if the request has no HTTP referer information. (called from block in <class:RepoSubscriptionsControllerTest> at /Users/richardschneeman/Documents/projects/codetriage/test/functional/repo_subscriptions_controller_test.rb:63)

A good deprecation will include the fix in the message. While you technically don't have to fix every deprecation, you'll be glad you did when Rails 5.1 is released, because that upgrade will be even easier.

Regressions

As you rule out bugs coming from gems or your own code, you'll want to report any regressions to https://github.com/rails/rails/issues. Please check for existing issues first. Unfortunately the tracker is only for bugs and pull requests, we can't use it to help you with "my application won't work" type problems. Take those issues to Stack Overflow.

Deploy and You're Done

Once your code works locally and your tests pass, make sure you're happy with manually looking for regressions. I recommend either deploying to a staging app first or using Heroku's GitHub Review apps. -- That way you'll have a production-ish copy of your web app attached to your pull request that everyone involved can review. Once you're happy commit to git and then:

$ git push heroku master

Watch your logs or bug tracking add-on for exceptions, remember you can always rollback if a critical problem comes up.

Upgrading takes time and patience but isn't that complex. The earlier you upgrade the earlier bugs get found, reported, and fixed. Give it a try on a branch and see what happens.

Ruby Debugging Magic Cheat Sheet

This document is all about deciphering behavior of complicated Ruby code. I recommend you get familiar with a debugger like pry-debugger, this doc doesn't go into debuggers because they're not always available, and only focuses on Ruby's ability to introspect its own code.

Many of these techniques are pulled from my first popular Ruby Conf. talk Dissecting Ruby with Ruby. This doc is open source and a living doc, send suggestions in PR form to my blog. Unless otherwise stated, all techniques work for the last major release of Ruby. Some may work with older versions of Ruby, I don't want to maintain that list, you can if you want.

Figure out where a method was defined

object = Object.new
puts object.method(:blank?).source_location
=> ["/gems/activesupport-5.0.0.beta1/lib/active_support/core_ext/object/blank.rb", 14]

This method was defined on line 14 of the file active_support/core_ext/object/blank.rb.

Opening a dependency from a project

$ bundle open active_support

This will open the version of active_support you have in your Gemfile.lock. From here you can add debugging statements.

This command will use the value in your EDITOR environment variable. The default is vi or something. You can set this in your .bashrc file. For example I use Sublime text and have this in my .bashrc

export EDITOR="subl -w"

Google for the appropriate invocation for your editor

Un-debug a gem

If you've opened a gem and added debug statements but forget to remove them before closing the file, you'll get those debug statements every time you run your program, to reset everything to original state you can use, gem pristine. To reset Active Support:

$ gem pristine activesupport
Restoring gems to pristine condition...
Restored activesupport-3.2.21
Restored activesupport-3.2.22
Restored activesupport-4.0.0
Restored activesupport-4.1.1
Restored activesupport-4.2.0
Restored activesupport-4.2.1
Restored activesupport-4.2.3
Restored activesupport-4.2.5.rc1
Restored activesupport-4.2.5
Restored activesupport-5.0.0.beta1

To reset ALL gems you can run

$ gem pristine --all

Note this may take a LONG time, especially if you've got gems with c-extensions.

Figuring out how a method was called

To generate a backtrace without raising an exception use the caller method like:

class Project

  def foo
    puts "====================="
    puts caller
  end
end

Now when you generate a request you'll get a backtrace like:

=====================
/Users/richardschneeman/documents/projects/my_rails_app/app/controllers/projects_controller.rb:18:in `new'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/actionpack-5.0.0.beta1/lib/action_controller/metal/basic_implicit_render.rb:4:in `send_action'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/actionpack-5.0.0.beta1/lib/abstract_controller/base.rb:183:in `process_action'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/actionpack-5.0.0.beta1/lib/action_controller/metal/rendering.rb:30:in `process_action'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/actionpack-5.0.0.beta1/lib/abstract_controller/callbacks.rb:20:in `block in process_action'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/activesupport-5.0.0.beta1/lib/active_support/callbacks.rb:126:in `call'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/activesupport-5.0.0.beta1/lib/active_support/callbacks.rb:506:in `block (2 levels) in compile'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/activesupport-5.0.0.beta1/lib/active_support/callbacks.rb:455:in `call'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/activesupport-5.0.0.beta1/lib/active_support/callbacks.rb:101:in `__run_callbacks__'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/activesupport-5.0.0.beta1/lib/active_support/callbacks.rb:750:in `_run_process_action_callbacks'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/activesupport-5.0.0.beta1/lib/active_support/callbacks.rb:90:in `run_callbacks'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/actionpack-5.0.0.beta1/lib/abstract_controller/callbacks.rb:19:in `process_action'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/actionpack-5.0.0.beta1/lib/action_controller/metal/rescue.rb:27:in `process_action'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/actionpack-5.0.0.beta1/lib/action_controller/metal/instrumentation.rb:31:in `block in process_action'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/activesupport-5.0.0.beta1/lib/active_support/notifications.rb:164:in `block in instrument'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/activesupport-5.0.0.beta1/lib/active_support/notifications/instrumenter.rb:21:in `instrument'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/activesupport-5.0.0.beta1/lib/active_support/notifications.rb:164:in `instrument'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/actionpack-5.0.0.beta1/lib/action_controller/metal/instrumentation.rb:29:in `process_action'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/actionpack-5.0.0.beta1/lib/action_controller/metal/params_wrapper.rb:248:in `process_action'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/activerecord-5.0.0.beta1/lib/active_record/railties/controller_runtime.rb:18:in `process_action'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/actionpack-5.0.0.beta1/lib/abstract_controller/base.rb:128:in `process'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/actionview-5.0.0.beta1/lib/action_view/rendering.rb:30:in `process'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/actionpack-5.0.0.beta1/lib/action_controller/metal.rb:192:in `dispatch'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/actionpack-5.0.0.beta1/lib/action_controller/metal.rb:264:in `dispatch'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/actionpack-5.0.0.beta1/lib/action_dispatch/routing/route_set.rb:50:in `dispatch'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/actionpack-5.0.0.beta1/lib/action_dispatch/routing/route_set.rb:32:in `serve'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/actionpack-5.0.0.beta1/lib/action_dispatch/journey/router.rb:42:in `block in serve'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/actionpack-5.0.0.beta1/lib/action_dispatch/journey/router.rb:29:in `each'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/actionpack-5.0.0.beta1/lib/action_dispatch/journey/router.rb:29:in `serve'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/actionpack-5.0.0.beta1/lib/action_dispatch/routing/route_set.rb:715:in `call'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/actionview-5.0.0.beta1/lib/action_view/digestor.rb:14:in `call'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/rack-2.0.0.alpha/lib/rack/etag.rb:25:in `call'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/rack-2.0.0.alpha/lib/rack/conditional_get.rb:25:in `call'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/rack-2.0.0.alpha/lib/rack/head.rb:12:in `call'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/rack-2.0.0.alpha/lib/rack/session/abstract/id.rb:220:in `context'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/rack-2.0.0.alpha/lib/rack/session/abstract/id.rb:214:in `call'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/actionpack-5.0.0.beta1/lib/action_dispatch/middleware/cookies.rb:608:in `call'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/activerecord-5.0.0.beta1/lib/active_record/query_cache.rb:36:in `call'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/activerecord-5.0.0.beta1/lib/active_record/connection_adapters/abstract/connection_pool.rb:963:in `call'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/activerecord-5.0.0.beta1/lib/active_record/migration.rb:524:in `call'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/actionpack-5.0.0.beta1/lib/action_dispatch/middleware/callbacks.rb:29:in `block in call'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/activesupport-5.0.0.beta1/lib/active_support/callbacks.rb:97:in `__run_callbacks__'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/activesupport-5.0.0.beta1/lib/active_support/callbacks.rb:750:in `_run_call_callbacks'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/activesupport-5.0.0.beta1/lib/active_support/callbacks.rb:90:in `run_callbacks'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/actionpack-5.0.0.beta1/lib/action_dispatch/middleware/callbacks.rb:27:in `call'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/actionpack-5.0.0.beta1/lib/action_dispatch/middleware/reloader.rb:71:in `call'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/actionpack-5.0.0.beta1/lib/action_dispatch/middleware/remote_ip.rb:79:in `call'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/actionpack-5.0.0.beta1/lib/action_dispatch/middleware/debug_exceptions.rb:49:in `call'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/web-console-3.0.0/lib/web_console/middleware.rb:27:in `call'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/actionpack-5.0.0.beta1/lib/action_dispatch/middleware/show_exceptions.rb:31:in `call'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/railties-5.0.0.beta1/lib/rails/rack/logger.rb:42:in `call_app'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/railties-5.0.0.beta1/lib/rails/rack/logger.rb:24:in `block in call'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/activesupport-5.0.0.beta1/lib/active_support/tagged_logging.rb:70:in `block in tagged'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/activesupport-5.0.0.beta1/lib/active_support/tagged_logging.rb:26:in `tagged'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/activesupport-5.0.0.beta1/lib/active_support/tagged_logging.rb:70:in `tagged'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/railties-5.0.0.beta1/lib/rails/rack/logger.rb:24:in `call'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/actionpack-5.0.0.beta1/lib/action_dispatch/middleware/request_id.rb:24:in `call'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/rack-2.0.0.alpha/lib/rack/method_override.rb:22:in `call'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/rack-2.0.0.alpha/lib/rack/runtime.rb:22:in `call'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/activesupport-5.0.0.beta1/lib/active_support/cache/strategy/local_cache_middleware.rb:28:in `call'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/actionpack-5.0.0.beta1/lib/action_dispatch/middleware/load_interlock.rb:13:in `call'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/actionpack-5.0.0.beta1/lib/action_dispatch/middleware/static.rb:132:in `call'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/rack-2.0.0.alpha/lib/rack/sendfile.rb:111:in `call'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/railties-5.0.0.beta1/lib/rails/engine.rb:522:in `call'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/puma-2.15.3/lib/puma/server.rb:541:in `handle_request'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/puma-2.15.3/lib/puma/server.rb:388:in `process_client'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/puma-2.15.3/lib/puma/server.rb:270:in `block in run'
/Users/richardschneeman/.gem/ruby/2.3.0/gems/puma-2.15.3/lib/puma/thread_pool.rb:106:in `block in spawn_thread'

Ugh, long ugly backtrace. What does it mean? The top line is the last method that was run before our, puts caller was called. In this case

/Users/richardschneeman/documents/projects/my_rails_app/app/controllers/projects_controller.rb:18:in `new'

This was called from the projects_controller line 18, in the new method in my app. We can trace this back all the way to the beginning of the request by looking at the first line

/Users/richardschneeman/.gem/ruby/2.3.0/gems/puma-2.15.3/lib/puma/thread_pool.rb:106:in `block in spawn_thread'

This is where puma instantiated the request. If you work from the bottom and go up, you can see exactly how Puma turns a request into code, and how rack and rails work together to get to your line of code. Run $ bundle open to your heart's content. Its kinda interesting to see that the backtrace matches our middleware (in reverse order), where the request starts from the bottom and goes down:

$ rake middleware
use Rack::Sendfile
use ActionDispatch::Static
use ActionDispatch::LoadInterlock
use ActiveSupport::Cache::Strategy::LocalCache::Middleware
use Rack::Runtime
use Rack::MethodOverride
use ActionDispatch::RequestId
use Rails::Rack::Logger
use ActionDispatch::ShowExceptions
use WebConsole::Middleware
use ActionDispatch::DebugExceptions
use ActionDispatch::RemoteIp
use ActionDispatch::Reloader
use ActionDispatch::Callbacks
use ActiveRecord::Migration::CheckPending
use ActiveRecord::ConnectionAdapters::ConnectionManagement
use ActiveRecord::QueryCache
use ActionDispatch::Cookies
use ActionDispatch::Session::CookieStore
use ActionDispatch::Flash
use Rack::Head
use Rack::ConditionalGet
use Rack::ETag
use ActionView::Digestor::PerRequestDigestCacheExpiry
run MyRailsApp::Application.routes

Find where Super is Calling

Let's say you have code that calls super you can find where that method is defined like this:

def foo
  puts method(:foo).super_method.source_location
  super
end

I love this one since I proposed its addition 😉. You can read more about super_method here: http://www.schneems.com/2015/01/14/debugging-super-methods-ruby-22.html

List all methods on an object

object.methods
# => [:instance_of?, :public_send, :instance_variable_get, :instance_variable_set, :instance_variable_defined?, :remove_instance_variable, :private_methods, :kind_of?, :instance_variables, :tap, :is_a?, :extend, :define_singleton_method, :to_enum, :enum_for, :<=>, :===, :=~, :!~, :eql?, :respond_to?, :freeze, :inspect, :display, :send, :object_id, :to_s, :method, :public_method, :singleton_method, :nil?, :hash, :class, :singleton_class, :clone, :dup, :itself, :taint, :tainted?, :untaint, :untrust, :trust, :untrusted?, :methods, :protected_methods, :frozen?, :public_methods, :singleton_methods, :!, :==, :!=, :__send__, :equal?, :instance_eval, :instance_exec, :__id__]

Get instance method location without an instance

User.instance_method(:github_url).source_location

Introspect method arguments

def parse(input, skip_code_comments: false, ignore_whitespace: true)
  # do stuff
end
method(:parse).parameters
#=> [[:req, :input], [:key, :skip_code_comments], [:key, :ignore_whitespace]]

Now you can see all available keyword arguments.

See where an argument is mutated

Originally on my "missing pieces" list, TLo documented it here https://tenderlovemaking.com/2016/02/05/i-am-a-puts-debuggerer.html#an-object-is-being-mutated-but-i-dont-know-where.

Often times, i'll instantiate a variable

config.thing = { "foo" => "bar" }

But later in my code sometimes it is changed

puts config.thing
# => {"foo" => "THIS VALUE IS DIFFERENT"}

You can see where the value was modified by first freeze-ing the value

config.thing.delete("foo")

# active_support/concurrency/share_lock.rb:151:in `delete': can't modify frozen Hash (RuntimeError)
#  from active_support/concurrency/share_lock.rb:151:in `yield_shares'
#  from active_support/concurrency/share_lock.rb:79:in `block in stop_exclusive'

This won't work for cases where a variable is assigned instead of mutated, but it's a worth while technique. You can use the same technique to see where a constant is modified (assuming you can find where it is first instantiated)

See where a constant is created

Again, originally a "missing piece" i got this debugging technique thanks to https://tenderlovemaking.com/2016/02/05/i-am-a-puts-debuggerer.html#i-need-to-find-where-this-object-came-from

You can use object space to see where a constant or object was created.

require 'objspace'
ObjectSpace.trace_object_allocations_start

WORLD = "hello"

puts "#{ ObjectSpace.allocation_sourcefile(WORLD) }:#{ ObjectSpace.allocation_sourceline(WORLD) }"

Missing Pieces Wish List

Warning These things don't exist, but I wish they did. Don't try to use them, they won't work.

Here's broad things I want to do from time to time but haven't found a way to yet. I want to see where a constant was defined. Some of these might not be possible due to limitations in the VM. When a "missing piece" is found it is removed from this section and given it's own heading above.

  • Find where a variable is over-written with a different value. While we can use the freeze trick to see where a value is modified, we won't see when it is replaced.
config.thing = { "foo" => "bar" }.freeze

config.thing = nil
# No error is raised as the hash isn't being mutated, the variable is being assigned a different value

The Definitive Guide to Ruby Heap Dumps, Part I & II

In this two part series I talk about the in and outs of debugging Ruby memory with heap dumps. The first section covers what a heap dump is, how to get one, and how to analyze it. The second section focuses on getting a heap dump off of a Heroku dyno. We then use that data to debug a production memory problem. These were originally published in December 2015, sorry for the delay in linking. Enjoy!

The Definitive Guide to Ruby Heap Dumps, Part I

The Definitive Guide to Ruby Heap Dumps, Part II

SemVer for Library Maintainers

SemVer is simple. Well...until you start publishing libraries, and accidentally break a metric ton of apps on accident. I've never caused any mass scale melt downs, however I've made my fair share of screw-ups. I maintain gems with over 200 million downloads. I wish I had this guide available to me when I first got in the library authorship game. Let's take a look at what SemVer is and how to use it as a maintainer.

SemVer is...

SemVer is a way to communicate the stability of your project that computers can understand. It is communicated by numbers like Rails 4.1.7. This means

Major: 4
Minor: 1
Teeny: 7
Patch: nil

This version is greater than 3.2.1 and less than 4.1.8. If SemVer is done properly, computers can resolve your application's dependencies in ways that don't break when you upgrade versions. The short version is that teeny patches are always backwards compatible, minor patches are for new features (that are still backwards compatible) and major versions are for breaking changes.

Note: I'm adding an extra version (teeny) not in the semver.org 2.0 spec. Ruby uses this in Rubygems so that 2.0.0-rc1 would become 2.0.0.rc1 for example Rails 4.2.0.rc1.

Humans are squishy, machines are not

The numbering of SemVer is meant to communicate to computers the backwards compatibility of code. The biggest problem is that this number is generated via a human. Maybe the author didn't realize you were using that interface, removed it, then only bumped the teeny version.

Bug and Security fixes can also mess up SemVer. Sometimes people will rely on incorrect behavior. For example Ruby recently removed SSLv3 support from the NetHTTP library. While this development will protect users of the code, it will also break the code. Just because you fixed a bug doesn't mean you get to call it a teeny version bump.

When to Rev

If you're maintaining code, it helps to understand when to increment which version and when. I write Ruby primarily but most of the examples should apply to all languages.

Rev Patch

Patch levels are used for betas and release candidates:

$ gem install rack --pre
Successfully installed rack-1.6.0.beta2

This way the maintainers of Rack can try new things out without saying "this is compatible". The biggest caveat here is that when they release a patch version, no one will try it by default, they have to manually specify.

Really popular projects do this to get feedback. It really helps for you to add ruby-head to your Travis CI matrix and to manually try out Rails betas and other library pre versions. If no one tries it, no one gets feedback and a potentially broken version may be released.

Rails has used the convention that a beta means unstable. This means that the interface of beta2 is not guaranteed to be the same as beta1. A release candidate or an "rc" is slightly more stable but may have bugs. A release candidate is the maintainers saying "we think this is a totally fine version but we still want cautious people to test it out". Interfaces should be stable at this point and only bugfixes applied to later release candidates.

Note: This is the same behavior as semver.org's patch with a non integer field (i.e. 1.0.1-beta) if your language doesn't have a "teeny".

Rev Teeny

The teeny version gets revved any time a bugfix or security release comes out. If you added a feature that didn't break anything, should you rev the teeny version? Nope. You should rev the minor version. The key to a correct teeny SemVer is backwards-compatible. If a user upgrades their teeny version and something breaks, welp you didn't use SemVer correctly.

Rev Minor

When you add features, bump the minor version. If your change broke any existing tests or require that you modify existing documentation, it likely should be a major bump instead.

It took me a while to realize why, if our change is still backwards compatible, we shouldn't be able to simply rev a teeny version. There are two reasons for this. First is the ability to downgrade. If there are two versions, SemVer says that 0.0.9 and 0.0.8 are equivalent but the higher version may have bug fixes. If you start developing with 0.0.9 and it has an extra method (a different API), now you can no longer downgrade your app to use the 0.8 version because it will break. This might not happen that often, but when it does, it will be painful.

The second reason is a bit more pragmatic. Even though you think your new API is backwards compatible it may require a future change or bug fix that makes it incompatible. Instead of waiting until that happens to rev a minor version, it is safer to rev it when you introduce the new API.

For me this is one of the harder pills to swallow. I know I should rev minor version more, however what is a new feature? If I add compatibility for my gem to work with a newer dependency, is that a feature or a bug fix? A good rule of thumb could be backwards compatibility test. Would code written in this version work in the previous version? If the answer is yes go for a teeny bump; otherwise it's time to bump a minor version.

Rev Major

Breaking changes is the major version rallying cry. If you modify an interface, remove a public method, or break any existing tests via your change, then it's most certainly a major version bump. The hardest thing about breaking backwards compatibility isn't revving the version number though, it's about communicating those changes. Before you break, communicate.

The best breaking change communication we've got is deprecations. Add a deprecation and cut a teeny release. A deprecation should emit a warning, letting users know what is breaking and why. Deprecations can be simple:

def foo
  puts "DEPRECATION WARNING: Method `foo` will be removed in version 2+. Please use method `bar` instead: #{caller_locations.first}"
end

Or they can be sophisticated using built in logging. From the semver.org docs:

there should be at least one [...] release that contains the deprecation so that users can smoothly transition to the new API.

In a deprecation, say what is going away, the replacement (if there is one), and point to the location in code where the deprecated code was called. Don't forget to update your documentation. While SemVer is for computers it helps to keep a changelog for humans.

There is no going back

In Rubygems any versions are released for good, you can't update them later. If you mess up a release, you can yank a gem which removes the gem permanently. This should be avoided at all costs, only in cases where the gem would actively do irreversible harm (such as accidentally deleting critical files). Even when your version has a security bug, you shouldn't yank. Instead of yanking, you can release a newer gem with the fixes included. While this leaves little room for mistakes, computers need consistency. Version 1.1.0 of your gem should always behave the same way in 30 seconds or 30 years.

What about Security?

This is important enough to spell out. When a security fix is backwards compatible you should port it to every supported version and bump the TEENY version. If it's not backwards compatible, release a new TEENY version with a deprecation, it should state that the current version is insecure and also state what feature is changing behavior:

puts "Versions 3.5.7 and before of <library name> have a backwards incompatible security vulnerability <link>."

State what versions are affected and what versions are safe. This way you won't accidentally break a user's application and if they need to run the insecure code until they can upgrade then they'll be aware of the issue.

If the security vulnerability is bad, you should look into issuing a CVE, and notify users if you can.

Maintaining Multiple Releases

If your library is popular enough for you to need to actively maintain multiple releases, then you can't really use SemVer due to the backwards incompatible security release problem. That being said, if your two maintained releases are under Major versions (i.e. 4 and 5) instead of minor versions (i.e. 4.1 and 4.2) you can use the minor version for backwards incompatible security updates, and deprecate in the teeny versions. While it's not technically SemVer, it's pretty close and it prevents you from releasing backwards incompatible changes into the teeny version number.

Versioning is Hard

This all may look simple or even border-line on "common sense", but based on the number of breaking changes in teeny versions I've seen: it's much harder in practice. When in doubt of any versioning, ask around. Ask your friends and co-workers. Get people to help triage your github issues with CodeTriage and open up an issue stating your intentions. The golden rule is to not break anything in a teeny release. The silver rule is to deprecate and communicate before you break anything.

If you see a library breaking SemVer, be nice, provide them with resources (like a link to this post), and volunteer to help with versioning in the future. In the end versioning is supposed to make your life easier instead of harder. Don't let versioning scare you. Try your best and you'll get it over time. Happy versioning friends.


If you like writing code, or versioning arbitrary things follow @schneems on twitter.

SQL statements in Rails logs

Sometimes in programming, the smallest things are the most helpful. I remember wowing a co-worker when I hit CTRL+A and my cursor jumped to the beginning of a long terminal command. Since then, I've vowed that no tip is too small to share. Today, my tip is for getting Rails SQL statements and Cache behavior in production logs locally. It's pretty simple. If you're using rails_12factor gem to output your logs to standard out, then all you need to do is boot up your server with LOG_LEVEL=debug, like this:

$ RAILS_ENV=production LOG_LEVEL=debug rails s

Now you'll get all your SQL statements in the output:

[729e4a51-f83c-4862-bc68-a1842e806696] Started GET "/repotag/rjgit" for ::1 at 2015-10-21 11:47:34 -0500
[729e4a51-f83c-4862-bc68-a1842e806696] Processing by ReposController#show as HTML
[729e4a51-f83c-4862-bc68-a1842e806696]   Parameters: {"full_name"=>"repotag/rjgit"}
[729e4a51-f83c-4862-bc68-a1842e806696]   Repo Load (1.0ms)  SELECT  "repos".* FROM "repos" WHERE "repos"."full_name" = $1 LIMIT 1  [["full_name", "repotag/rjgit"]]
[729e4a51-f83c-4862-bc68-a1842e806696]   Issue Load (83.2ms)  SELECT "issues".* FROM "issues" WHERE "issues"."repo_id" IN (988)
[729e4a51-f83c-4862-bc68-a1842e806696]    (2.0ms)  SELECT COUNT(*) FROM "users" INNER JOIN "repo_subscriptions" ON "users"."id" = "repo_subscriptions"."user_id" WHERE "repo_subscriptions"."repo_id" = $1  [["repo_id", 988]]
[729e4a51-f83c-4862-bc68-a1842e806696]   User Load (1.7ms)  SELECT  "users".* FROM "users" INNER JOIN "repo_subscriptions" ON "users"."id" = "repo_subscriptions"."user_id" WHERE "repo_subscriptions"."repo_id" = $1 AND ("users"."private" != 't') LIMIT 27  [["repo_id", 988]]
[729e4a51-f83c-4862-bc68-a1842e806696]   Rendered subscribers/_avatars.html.slim (7.4ms)
[729e4a51-f83c-4862-bc68-a1842e806696]   CACHE (0.0ms)  SELECT COUNT(*) FROM "users" INNER JOIN "repo_subscriptions" ON "users"."id" = "repo_subscriptions"."user_id" WHERE "repo_subscriptions"."repo_id" = $1  [["repo_id", 988]]
[729e4a51-f83c-4862-bc68-a1842e806696]    (1.6ms)  SELECT COUNT(count_column) FROM (SELECT  1 AS count_column FROM "users" INNER JOIN "repo_subscriptions" ON "users"."id" = "repo_subscriptions"."user_id" WHERE "repo_subscriptions"."repo_id" = $1 AND ("users"."private" != 't') LIMIT 27) subquery_for_count  [["repo_id", 988]]
[729e4a51-f83c-4862-bc68-a1842e806696]   Issue Load (80.4ms)  SELECT  "issues".* FROM "issues" WHERE "issues"."repo_id" = $1 AND "issues"."state" = $2  ORDER BY created_at DESC LIMIT 20 OFFSET 0  [["repo_id", 988], ["state", "open"]]
[729e4a51-f83c-4862-bc68-a1842e806696]   Rendered repos/show.html.slim within layouts/application (132.3ms)
[729e4a51-f83c-4862-bc68-a1842e806696]   Rendered application/_head.html.slim (6.5ms)
[729e4a51-f83c-4862-bc68-a1842e806696]   Rendered application/_flashes.html.slim (3.5ms)
[729e4a51-f83c-4862-bc68-a1842e806696]   Rendered application/_logo.html.slim (9.4ms)
[729e4a51-f83c-4862-bc68-a1842e806696]   Rendered application/_nav.html.slim (21.1ms)
[729e4a51-f83c-4862-bc68-a1842e806696]   Rendered application/_thoughtbot.html.slim (3.2ms)
[729e4a51-f83c-4862-bc68-a1842e806696]   Rendered application/_footer.html.slim (13.3ms)
[729e4a51-f83c-4862-bc68-a1842e806696] Completed 200 OK in 375ms (Views: 121.2ms | ActiveRecord: 178.6ms)

So, what can you do with that? You get the timing information with each SQL call and each partial render, isolate one that is slow and dig in. You can use EXPLAIN ANALYZE on sql queries to see if you're missing indexes (though, note that the syntax at the end isn't valid SQL, you'll need to manually substitute values). You can use noisey SQL calls to find N+1 queries. There's a wealth of speed info right there in your logs.

You'll even get cache hit information:

[94ff47da-4ce1-4635-a351-1933801e340c] Started GET "/" for ::1 at 2015-10-21 14:10:16 -0500
[94ff47da-4ce1-4635-a351-1933801e340c] Processing by PagesController#index as HTML
[94ff47da-4ce1-4635-a351-1933801e340c]    (2.4ms)  SELECT COUNT(*) FROM "users"
[94ff47da-4ce1-4635-a351-1933801e340c]    (0.9ms)  SELECT COUNT(*) FROM "repos"
[94ff47da-4ce1-4635-a351-1933801e340c]   Rendered application/_github.html.slim (1.9ms)
[94ff47da-4ce1-4635-a351-1933801e340c]   Rendered application/_down.html.slim (3.0ms)
[94ff47da-4ce1-4635-a351-1933801e340c]   Repo Load (1.1ms)  SELECT DISTINCT language FROM "repos"
[94ff47da-4ce1-4635-a351-1933801e340c]   Repo Load (1.3ms)  SELECT  "repos".* FROM "repos" WHERE (issues_count > 0)  ORDER BY issues_count DESC LIMIT 10 OFFSET 0
[94ff47da-4ce1-4635-a351-1933801e340c]    (0.6ms)  SELECT COUNT(*) FROM "repos" WHERE (issues_count > 0)
[94ff47da-4ce1-4635-a351-1933801e340c]   Cache digest for app/views/repos/_repo.html.slim: aa8c513a57bfdcd94630b4f9de18efe2
[94ff47da-4ce1-4635-a351-1933801e340c]   Cache digest for app/views/pages/_repos_with_pagination.html.slim: c5aef60bba7aa653b57beb58f58905ef
[94ff47da-4ce1-4635-a351-1933801e340c] Cache read_multi: ["views/repos/696-20150302152054739843000/c5aef60bba7aa653b57beb58f58905ef", "views/repos/1224-20150302161524469739000/c5aef60bba7aa653b57beb58f58905ef", "views/repos/297-20150302144607625400000/c5aef60bba7aa653b57beb58f58905ef", "views/repos/987-20150302155234667489000/c5aef60bba7aa653b57beb58f58905ef", "views/repos/186-20150302143211298695000/c5aef60bba7aa653b57beb58f58905ef", "views/repos/839-20150302153126399409000/c5aef60bba7aa653b57beb58f58905ef", "views/repos/845-20150302153500118622000/c5aef60bba7aa653b57beb58f58905ef", "views/repos/1240-20150302161400575160000/c5aef60bba7aa653b57beb58f58905ef", "views/repos/28-20150302140547910840000/c5aef60bba7aa653b57beb58f58905ef", "views/repos/47-20150302141042221265000/c5aef60bba7aa653b57beb58f58905ef"]

Remember, if you're debugging speed issues, you should be running in production mode so that all of your caching is enabled. Otherwise you might spend a good amount of time "fixing" something that is already cached. Oh, and while you're at it, add the bullet gem to your project. You'll be glad you did. That's all. Short and sweet.