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
Then I added the following
before_filter within our application_controller.rb.
1 2 3 4 5 6 7 8 9 10
I ran the flamegraph against our homepage on Cedar-14 with the following url using the
pp query params.
Here is what came back.
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.
It all came down to this bit of code which is run on each request.
I ran this benchmark within rails console on both cedar-10 and cedar-14.
1 2 3
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.