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.

Conversation
  • Aaron Jensen says:

    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

  • Andrei Lisnic says:

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

  • KTamas says:

    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.

  • KTamas says:

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

  • KTamas says:

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

  • Oinak says:

    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

  • Michael Pearson says:

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

  • slackcode says:

    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.

  • Michael Pearson says:

    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 Justin Kulesza says:

      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).

  • RichKe says:

    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 Justin Kulesza says:

      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"

  • Kieran P says:

    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!

  • Mathias says:

    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 :)

  • borama says:

    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!

  • Dmitry Dudin says:

    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
    
  • Uma Mahesh says:

    Thank for sharing the Useful information ….

  • Comments are closed.