Personal Blog of Matt McInnis

Is Rails 4 slower than Rails 3?

 Jan 26, 2016
7 minute read

In describing their process upgrading from Rails 3.2 to Rails 4.2 at February’s Ruby Lightning Talks T.O., Canadian startup 500px experienced significant drops in performance. To underscore the issue, they shared the following example:

# Rails 3.2
Benchmark.measure { 
  1_000_000.times { 
    (0..5).each { |i| 
    } 
  } 
}
=> 0.370000 0.000000 0.370000 ( 0.371422)
# Rails 4.2.5
Benchmark.measure { 
  1_000_000.times { 
    (0..5).each { |i| 
    } 
  } 
}
=> 1.620000 0.030000 1.650000 ( 1.649495)

Wait a minute. Rails 4 is slower???

Sure seems that way. This simple test shared by Kevin at 500px sure seems clear: (0..5).each { |i| } is 4 times faster on Rails 3.2 compared to Rails 4.2. This is a significant drop in performance. Lets find out why.

Isolating the problem

This was my approach to try to find out what’s wrong:

  1. Replicate the problem. We’ll setup skinny applications of both Rails 3.2 and Rails 4.5.2 to investigate and run the code above to make sure we get similarly shitty results.
  2. Eliminate Ruby as a culprit. Lots of ways to do this, most simply I’ll compare my benchmarks with that obtained in a pure ruby environment (ie irb, no Rails).
  3. Dig into the Range and Enumerator classes. There are lots of ways to do looping in Ruby, are they all benchmarking so poorly between versions? This should help us figure out which docs we need to dig into.
  4. Dig into documentation between versions to figure out what’s happening.

Setting up an environment

# Some setup
mkdir rails-speed-test
cd rails-speed-test

# Install the gems we need
gem install rails -v 3.2.0
gem install rails -v 4.5.1 

# Generate our rails environments 
rails _3.2.0_ new rails-3.2.0
rails _4.5.1_ new rails-4.5.1

# Run bundle install in each directory

From here, I would suggest opening three terminal tabs:

  • One tab in each of our new rails applications. Run rails c to enter the console.
  • One tab running irb for pure ruby comparisons.

Setting up our environments

Making sure we can replicate the results:

# irb
require 'benchmark'
Benchmark.measure { 
  1_000_000.times { 
    (0..5).each { |i| 
    } 
  } 
}.total
=> 0.38

# Rails 3.2.0
Benchmark.measure { 
  1_000_000.times { 
    (0..5).each { |i| 
    } 
  } 
}.total
=> 0.39

# Rails 4.5.1
Benchmark.measure { 
  1_000_000.times { 
    (0..5).each { |i| 
    } 
  } 
}.total
=> 1.43

Summary: Rails 3.2 and No Rails (irb) are approximately equal, Rails 4.5 is ~4 times slower. All three environments are running the same version of Ruby, so this is definitely a Rails issue.

Is it just Enumerator?

Running (0..5).each.class returns an Enumerator object. I decided to test whether other loops/objects would produce similar slowdowns. Here is a sample of some of the tests I ran and their results:

# What about just a boolean? 
Benchmark.measure { 
  1_000_000.times { 
    (0..5).each { 
      true 
    } 
  } 
}.total
# result: Rails 4 is much slower

# What about a different type of loop? 
Benchmark.measure { 
  1_000_000.times { 
    i = 0
    while i < 6
      i += 1
    end
  } 
}.total
# result: No difference between Rails 3 and Rails 4

So it seems the damage might be limited to the Enumerator class. Since this class can be created in a number of ways, lets see if all objects of class Enumerator are experiencing the slow down, regardless of how they were created:

# A few different ways to define an Enumerator:
[].each.class
4.times.class
Range.new(0,5).each  #  <- The "bad one"
# etc.

# Testing some out:
# How about defining an Enumerator with an array? 
Benchmark.measure { 
  1_000_000.times { 
    [1,2,3,4,5,6].each do 
      true 
    end
  } 
}.total
# No difference between Rails 3 (0.71s) and Rails 4 (0.75s)

# How about defining an Enumerator with Integer.times? 
Benchmark.measure { 
  1_000_000.times { 
    6.times do 
      true 
    end
  } 
}.total
# No difference between Rails 3 (0.42s) and Rails 4 (0.42s)

Very surprising. Both [].each and 6.times create an Enumerator object, yet neither experience the major slow down that we’re experiencing when instantiating an Enumerator object from the Range class (ie (0..5).each).

This is a big hint. Since both irb and Rails 3.x are not experiencing the same slow down that’s happening in Rails 4, and the Array and Fixnum classes seem to be working well it’s reasonable to assume that Rail’s Range#each method has been overwritten. ActiveSupport is the Rails library that extends these methods. Lets take a look.

ActiveSupport

In rails/activesupport/lib/active_support/core_ext, switching to version 4.2.5, we find range/each.rb. First, note that if we switch to version 3.2 on GitHub there’s now each.rb file - good sign. Here’s the code:

require 'active_support/core_ext/module/aliasing'

class Range #:nodoc:

  def each_with_time_with_zone(&block)
    ensure_iteration_allowed
    each_without_time_with_zone(&block)
  end
  alias_method_chain :each, :time_with_zone

  def step_with_time_with_zone(n = 1, &block)
    ensure_iteration_allowed
    step_without_time_with_zone(n, &block)
  end
  alias_method_chain :step, :time_with_zone

  private
  def ensure_iteration_allowed
    if first.is_a?(Time)
      raise TypeError, "can't iterate from #{first.class}"
    end
  end
end

Notice the line alias_method_chain :each, :time_with_zone? From the documentation, the following are equivalent:

alias_method_chain :foo, :feature
# and:
alias_method :foo_without_feature, :foo
alias_method :foo, :foo_with_feature

This means that the Range#each instance method is being overwritten presumably with a much, much slower version, since:

alias_method_chain :each, :time_with_zone
# equivalent to: 
alias_method :each_without_time_with_zone, :each
alias_method :each, :each_with_time_with_zone

Final test

Lets jump into our Rails-free console (irb) and see if we can duplicate the problem. First lets get a baseline benchmark:

require 'benchmark'
Benchmark.measure { 
  1_000_000.times { 
    (0..5).each { |i| 
    } 
  } 
}.total
=> 0.39

Next, lets overwrite the the Range#each method in the same way that ActiveSupport is doing. Note that I’ve commented the call to the private function ensure_iteration_allowed and replaced alias_method_chain with its functionally equivalent two-line version described above:

class Range
  def each_with_time_with_zone(&block)
    # ensure_iteration_allowed
    each_without_time_with_zone(&block)
  end
  alias_method :each_without_time_with_zone, :each
  alias_method :each, :each_with_time_with_zone
end

Finally, lets run our benchmark:

Benchmark.measure { 
  1_000_000.times { 
    (0..5).each { |i| 
    } 
  } 
}.total
=> 1.23

Again, our benchmark has gone from 0.39 seconds to 1.23 seconds. We’ve found our culprit.

Conclusion

It’s possible that a large amount of the slow down experienced by 500px is caused by ineffiencies created by the update to ActiveSupport and in particular the Range#each instance method. Creating an Enumerator object from a range is a very common procedure.

As long as a comprehensive test suite is in place, it would be interesting to replace this method with its previous version to compare benchmarks in a production application to assess how much of the slow down it causes. As for the decrease in response times that is not explained by this change, lets hope the Rails Core Team places more emphasis on benchmark testing in future versions.