Building VTS

The Official VTS Engineering Blog

Adventures in Upgrading to Heroku Cedar-14

By Karl Baum

Heroku has deprecated their old Cedar-10 stack and the time came for us to ugrade to Cedar-14. The problem was that when we tried it out within our staging environment, our homepage response time went from 50ms to around 8000ms. That’s just the homepage which did practically nothing. Nate Berkopec recently wrote a great post on rack-mini-profiler and the flamegraph jumped out at me as a great tool to dig into this issue.

First I had to make mini profiler available within our staging environments on Heroku. I know mini profiler can run within production, but it was a bit much for my stomach to handle. For now, I made the following gems generally available in all environments within our Gemfile.

1
2
3
4
gem 'flamegraph'
gem 'rack-mini-profiler'
gem 'stackprof'
gem 'memory_profiler'

Then I added the following before_filter within our application_controller.rb.

1
2
3
4
5
6
7
8
9
10
before_filter :check_rack_mini_profiler

private

def check_rack_mini_profiler
  #allow for rack mini profiler in staging with a param
  if params[:rmp] && !Rails.env.production?
    Rack::MiniProfiler.authorize_request
  end
end

I ran the flamegraph against our homepage on Cedar-14 with the following url using the rmp and pp query params.

1
http://test.herokuapp.com/?rmp=t&pp=flamegraph

Here is what came back.

Flame Graph on Cedar-14

When studying the flamegraph I concentrate on wide rectangles on the top of the stack. The low parts of the stack are methods that contain calls to all the other methods. The fact these methods are wide does not tell us much. Following this approach I noticed a significant portion of the highest part of the stack was being spent creating a unique identifier with uuid gem.

Sure enough, when I compared these results to a flamegraph generated on Cedar-10, the uuid performance bottleneck was no longer present.

Flame Graph on Cedar-10

It all came down to this bit of code which is run on each request.

1
  UUID.new.generate

I ran this benchmark within rails console on both cedar-10 and cedar-14.

1
2
3
bm = Benchmark.measure do
  25.times { UUID.new.generate }
end

On cedar-10, this code ran in 0.000845 seconds compared to a whopping 91.889272 seconds on cedar-14. That’s about 100,000 times slower on cedar-14! Being the lazy developer that I am, I immediately opened up a ticket with Heroku to alert them to the problem. Of course I had grandiose plans of using ruby-prof to pinpoint the exact problem myself, but before I could get around to it, the Engineers at Heroku beat me to the punch. Turns out the uuid gem made use of the macaddr gem. On the cedar-10 stack, the macaddr gem had ben using /sbin/ifconfig to determine the MAC address which in turn was used by the uuid library for uniqueness. The problem was that cedar-14 had removed /sbin/ifconfig and now macaddr was using another method called pseudo_mac_address to come up with a MAC address. Obviously, this was much slower.

To fix the issue I changed from using the uuid library to the SecureRandom#uuid method which comes with ruby. One less gem within our Gemfile and the performance problem is gone. I could have also just upgraded the uuid and macaddr gems as well since the issue is fixed within the latest version.