We're hiring!

We're actively seeking developers and designers for our Ann Arbor & Detroit locations.

Is Your Application Running with Ruby – Slow?

The problem that this post describes has now been fixed in RVM stable (1.17.0). To diagnose performance issues, be sure to check the options that Ruby was compiled with:
ruby -rrbconfig -e 'puts RbConfig::CONFIG["CFLAGS"]'

The Situation

While working with Patrick Bacon, migrating a large Ruby (ruby-1.9.2) web application from an older Solaris system to a new Linux system (Ubuntu 12.04 LTS), we discovered that the migrated web application seemed to be responding rather sluggishly. Comparing the logs, we found that the application was running, generally, about twice as slow on the new system as on the old system.

My first thought was hardware — the new system must be slower. Both systems were cloud servers, but hosted with different companies. Even though the Linux system was hosted on a much newer cloud platform, there was no guarantee that the underlying hardware was new or fast. But, at the same time, I just could not believe that the new system would be twice as slow.


The Diagnosis

I decided to run some ultra-simple benchmarks on both the old Solaris system, and the new Linux system:

jk@linux ~ $ which ruby
/usr/local/rvm/rubies/ruby-1.9.2-p180/bin/ruby
jk@linux ~ $ time ruby -e "count = 0; while(count < 100000000); count = count + 1; end; puts count"                                                                                                         
100000000

real    0m9.019s
user    0m8.933s
sys     0m0.016s

solaris [~]# which ruby
/opt/ao_ruby192/bin/ruby
solaris [~]# time ruby -e "count = 0; while(count < 100000000); count = count + 1; end; puts count"                 
100000000

real    0m2.959s
user    0m2.928s
sys     0m0.011s

Clearly, Ruby was running much slower. However, I still doubted that it was really that much slower because of the hardware. I decided to run some of my simple benchmarks using Bash and Perl. (Note: The versions of Bash and Perl differed slightly between the Linux and Solaris systems, whereas the version of Ruby was the same between the two systems).

jk@linux ~ $ time perl -e '$count = 0; while ($count < 10000000) { $count ++; } print $count;'
10000000
real    0m0.856s
user    0m0.840s
sys     0m0.008s

solaris [~]# time perl -e '$count = 0; while ($count < 10000000) { $count ++; } print $count;'     
10000000
real    0m1.052s
user    0m1.035s
sys     0m0.006s

jk@linux ~ $ time bash -c 'i=0;while [ $i -le 1000000 ]; do i=$(($i+1)); done; echo $i;'
1000001

real    0m17.906s
user    0m15.677s
sys     0m2.212s

solaris [~]# time bash -c 'i=0;while [ $i -le 1000000 ]; do i=$(($i+1)); done; echo $i;'                 
1000001

real    0m18.061s
user    0m16.820s
sys     0m1.177s

Going by the results of my benchmark using Bash and Perl, the new Linux system was actually faster than the old Solaris system. Something was wrong with how Ruby was running. It was most likely compiled differently between the two systems… and it was compiled with RVM.

I decided to download Ruby directly (e.g. svn co), and compile from source by myself. I did so with no extra configuration options, only options necessary to get Ruby to successfully compile.

jk@linux /opt/ruby192 $ time bin/ruby -e "count = 0; while(count < 100000000); count = count + 1; end; puts count"
100000000

real    0m3.839s
user    0m3.816s
sys     0m0.028s

This self-compiled version ran consistently faster than the version compiled by RVM on the same system.

(8.933 – 3.816) / 8.933 = 0.5728

That’s a whopping 57.28% decrease in execution time.

So… what had happened to version of Ruby compiled by RVM? Why was it so slow?

The Solution

After conferring with John Van Enk and checking the make.log file, we found that the RVM version of Ruby had been compiled without any optimization. This explained the major performance difference. The solution was fairly simple — we instructed RVM to re-compile Ruby with some specific optimization flags: namely, -O3.

Unfortunately, RVM doesn’t seem to recognize CFLAGS options on the command line. Instead, I needed to add them to the local .rvmrc file as: rvm_configure_env=(CFLAGS=-O3). After adding this and re-compiling Ruby with RVM, I was able to achieve comparable performance to the Ruby I had compiled myself.

jk@linux ~ $ which ruby
/usr/local/rvm/rubies/ruby-1.9.2-p180/bin/ruby
jk@linux ~ $ time ruby -e "count = 0; while(count < 100000000); count = count + 1; end; puts count"
100000000

real    0m3.922s
user    0m3.908s
sys     0m0.020s

RVM seems to compile Ruby with optimizations on several other systems (including my local machine), but did not for this Linux system. I have no idea why this happens (would someone like to tell me?). But, at least I know that this is something that I can check and correct in the future when deploying production applications.

Justin Kulesza (46 Posts)

Justin is a DevOps practitioner at Atomic Object. He runs servers, troubleshoots the network, deploys apps, fixes bugs, manages backups, monitors monitoring, and does all manner of general problem solving for Atomic Object and our customers. He often works with configuration management tools like Chef and Puppet, and loves working with Linux.

This entry was posted in Ruby and tagged , , . Bookmark the permalink. Both comments and trackbacks are currently closed.

20 Comments

  1. Posted November 6, 2012 at 12:32 pm

    Other versions of ruby have this issue w/ rvm as well. The latest version of rvm, when building 1.9.3p194 or 1.9.3p286 will use cflags by default. Here’s a some info on getting the falcon patch w/ the cflags patch: http://serverfault.com/questions/442595/ruby-installed-on-ubuntu-10-10-slow-on-one-machine-but-not-other

  2. Andrei Lisnic
    Posted November 22, 2012 at 6:23 am

    Also, you might want to get better compiler flags for your processor from gentoo wiki

  3. Posted November 22, 2012 at 7:08 am

    Wow. Thank you. Thank you thank you thank you.

    We just switched a site from Apache + ruby 1.9.2 to nginx + ruby 1.9.3 a few days ago and I noticed that somehow the site speed has noticably dropped on the ruby side of things and I just couldn’t understand why. Then today I found this article and sure enough:


    /opt/nginx/logs# rvm use 1.9.3
    Using /usr/local/rvm/gems/ruby-1.9.3-p327
    /opt/nginx/logs# time ruby -e "count = 0; while(count < 100000000); count = count + 1; end; puts count"
    100000000

    real 0m7.655s
    user 0m7.632s
    sys 0m0.012s

    /opt/nginx/logs# rvm use 1.9.2
    Using /usr/local/rvm/gems/ruby-1.9.2-p320
    /opt/nginx/logs# time ruby -e "count = 0; while(count < 100000000); count = count + 1; end; puts count"
    100000000

    real 0m4.716s
    user 0m4.716s
    sys 0m0.000s

    Checking make.log showed that 1.9.3 was indeed compiled w/o any optimizations. After I hand-compiled a 1.9.3, I got this:


    /opt/ruby193opt/bin# ./ruby -v
    ruby 1.9.3p327 (2012-11-10 revision 37606) [x86_64-linux]
    /opt/ruby193opt/bin# time ./ruby -e "count = 0; while(count < 100000000); count = count + 1; end; puts count"
    100000000

    real 0m4.641s
    user 0m4.628s
    sys 0m0.008s

    /opt/ruby193opt/bin# ruby -v
    ruby 1.9.2p320 (2012-04-20 revision 35421) [x86_64-linux]
    puck352:/opt/ruby193opt/bin# time ruby -e "count = 0; while(count < 100000000); count = count + 1; end; puts count"
    100000000

    real 0m4.634s
    user 0m4.624s
    sys 0m0.012s

    Now it performs on par with 1.9.2. Thanks again for your article, it really helped us.

    • Justin Kulesza
      Posted November 23, 2012 at 11:39 am

      Glad to have been a help!

  4. Posted November 22, 2012 at 8:34 am

    (what I still don’t get is why rvm is installing 1.9.3-p327 without the optimizations, even though it’s supposedly fixed)

  5. Posted November 22, 2012 at 9:40 am

    Well, I’ve reinstalled it with RVM and it apparently got fixed sometime last week, I guess, because now it installs correctly.

  6. Posted November 22, 2012 at 3:02 pm

    It worked for me on 1.9 but not on 1.8, I will dig deeper.
    Thanks for your article, these are my numbers:

    fer@hecate ~ $ echo "rvm_configure_env=(CFLAGS=-O3)" > ~/.rvmrc

    fer@hecate ~ $ time ruby -e "count = 0; while(count < 100000000); count = count + 1; end; puts count"
    100000000

    real 0m6.324s
    user 0m6.146s
    sys 0m0.004s

    fer@hecate ~ $ rvm reinstall ruby-1.9.3-head
    (...)

    fer@hecate ~ $ time ruby -e "count = 0; while(count < 100000000); count = count + 1; end; puts count"
    100000000

    real 0m2.730s
    user 0m2.718s
    sys 0m0.007s

    fer@hecate ~ $ rvm use ree-1.8.7-2012.02
    Using /home/fer/.rvm/gems/ree-1.8.7-2012.02
    fer@hecate ~ $ time ruby -e "count = 0; while(count < 100000000); count = count + 1; end; puts count"
    100000000

    real 0m23.993s
    user 0m23.955s
    sys 0m0.002s

    fer@hecate ~ $ rvm reinstall ree-1.8.7-2012.02
    (...)

    fer@hecate ~ $ time ruby -e "count = 0; while(count < 100000000); count = count + 1; end; puts count"
    100000000

    real 0m23.934s
    user 0m23.897s
    sys 0m0.002s

  7. Michael Pearson
    Posted November 22, 2012 at 8:46 pm

    Confirmed that it’s a problem for our Ubuntu systems. I’ve filed a bug with RVM: https://github.com/wayneeseguin/rvm/issues/1326

  8. Posted November 22, 2012 at 9:27 pm

    I use rvm stable version and instlal ruby-1.9.3-p327, and test it, it use 7 seconds.
    I found rvm use ‘-O3′ to compile the ruby. So I try to download the p327 source and ./configure, make, make install, test it, I use only 2.7 seconds which equal the p194(compiled with rvm).
    I don’t know why…so, when I deploy the rails production, I think I would use the manual compile version of the ruby source.

  9. Michael Pearson
    Posted November 22, 2012 at 9:47 pm

    Right, so after talking with @mpapis (RVM release manager), he’s fixed this issue in RVM head and will be releasing a new RVM stable version later today.

    • Justin Kulesza
      Posted November 23, 2012 at 11:41 am

      Very cool! Thanks for filing the issue. I can confirm that it is fixed for me in RVM 1.17.0 and latest ruby (1.9.3-p327) on my Ubuntu system (12.04 LTS).

  10. RichKe
    Posted November 23, 2012 at 7:56 am

    ubuntu@:~$ which ruby
    /home/ubuntu/.rvm/rubies/ruby-1.9.3-p194/bin/ruby
    ubuntu@:~$ time bin/ruby -e “count = 0; while(count < 100000000); count = count + 1; end; puts count"
    -bash: bin/ruby: No such file or directory

    real 0m0.004s
    user 0m0.004s
    sys 0m0.000s

    i don't add "rvm_configure_env=(CFLAGS=-O3)" to .rvmrc

    why so fast

    • Justin Kulesza
      Posted November 23, 2012 at 11:43 am

      It looks like your benchmark command needs to be adjusted. In my example, I used ‘bin/ruby’ because it was located there. You’ll want to use something like:

      time /home/ubuntu/.rvm/rubies/ruby-1.9.3-p194/bin/ruby -e “count = 0; while(count < 100000000); count = count + 1; end; puts count"

  11. Posted November 24, 2012 at 2:10 pm

    This is excellent. Thank you so much for publishing your findings. Things are so much faster now. Your test case (ruby iterator) took 7.5s before, and only 3.2s after. Other things show similar speedup. ‘rails runner’ from 12.4s down to 6.6s, ‘rake routes’ from 12.5s down to 6.8s, and ‘rspec spec’ from 5m 53s down to 3m 17s. So an amazing savings. Thank you so much!

    • Justin Kulesza
      Posted November 24, 2012 at 5:15 pm

      Glad to have helped out!

  12. Mathias
    Posted November 26, 2012 at 4:08 am

    We also discovered a slow ruby on our machines. Our test suite ran two times longer. Luckily we did the same with a ruby benchmark script. Thanks to you for a confirmation of this issue :)

  13. Posted November 26, 2012 at 6:32 pm

    You made my day, Justin! Everything now is at least 30% faster! On production, the time to first byte immediately dropped from 1.5s to 1.0s for the root page of one of my projects. Integration specs now almost twice the previous speed. Thank you so much indeed!

  14. Dmitry Dudin
    Posted November 27, 2012 at 2:13 am

    Show your CFLAGS:

    ruby -r rbconfig -e 'puts RbConfig::CONFIG["CFLAGS"]'
    deployer@n01:~$ ruby -r rbconfig -e 'puts RbConfig::CONFIG["CFLAGS"]'
     -O3 -ggdb -Wextra -Wno-unused-parameter -Wno-parentheses -Wno-long-long -Wno-missing-field-initializers -Werror=pointer-arith -Werror=write-strings -Werror=declaration-after-statement -Werror=implicit-function-declaration -fPIC
    
  15. Uma Mahesh
    Posted November 28, 2012 at 3:03 am

    Thank for sharing the Useful information ….

7 Trackbacks

  1. By Making your ruby fly | Andrei Lisnic blog on November 22, 2012 at 8:58 am

    [...] this nice blog post by Justin Kulesza, the author points out that ruby interpreter is compiled by RVM wthout any [...]

  2. By Nebulent on November 22, 2012 at 9:53 am

    [...] this nice blog post by Justin Kulesza, the author points out that ruby interpreter is compiled by RVM wthout any [...]

  3. By Ускоряем ruby и Rails on November 23, 2012 at 4:14 am

    [...] мой взор на днях на две статьи: г-на alisnic и г-не Justin Kulesza. Решил проверить, что там и как, поэксперементировать [...]

  4. [...] Is Your Application Running with Ruby – Slow? Two developers moved a large Ruby webapp between two machines and experienced a 50% drop in performance. Why? Clue: It was something to do with RVM. [...]

  5. [...] http://spin.atomicobject.com/2012/11/06/is-your-application-running-with-ruby-slow/ Share this:TwitterFacebookLike this:LikeBe the first to like this. This entry was posted in Uncategorized. Bookmark the permalink. ← Google Takeout – https://www.google.com/takeout/ [...]

  6. [...] сегодня «Ruby Inside», наткнулся на статью Justin Kulesza Is Your Application Running with Ruby – Slow?. Статья от 6 ноября, но Хабре об этой ситуации ни слова. [...]

  7. [...] сегодня «Ruby Inside», наткнулся на статью Justin Kulesza Is Your Application Running with Ruby – Slow?. Статья от 6 ноября, но на Хабре об этой ситуации ни [...]