Tests Still Slow? Might be bcrypt!

UPDATE Thanks to Trevor Turk, in Rails master, ActiveSupport::SecurePassword now speeds itself up when in test mode! https://github.com/rails/rails/pull/8216

I’ve been working in a test suite lately that has for a while felt strangely slow. I made sure that there are no external service requests, and while the tests do talk to the database a lot, it felt even slower than that. It was time to break out the profiling tools.

My current favorite profiler for any Ruby app is perftools.rb. This gem wraps up Google’s perftools library for use in Ruby. You can read more about it on Ilya Grigorik’s post Profiling Ruby With Google’s Perftools. So with that installed, I ran my tests and turned there results into a dot graph in PDF:

gem install perftools.rb
CPUPROFILE=profiled RUBYOPT="-r`gem which perftools | tail -1`" rspec spec/
pprof.rb --pdf profiled > profiled.pdf

When I opened the PDF it was very obvious what the problem was.

Whoops is right! Almost half of the test time is stuck in Bcrypt! This doesn’t mean there’s a problem in bcrypt, on the contrary the library working as designed. Bcrypt is designed to be slow, very slow, to make cracking its hashes exponentially more difficult for computers. Modern GPUs can process SHA1 hashes at rates exceeding 1 billion a second, making the format almost as secure as plain text. To fight this increase in computational power, modern crypto algorithms like bcrypt instead force the computer to take time building the hash. Ruby’s bcrypt wrapper defaults to ~100ms per hash, and you can configure the time constraint to be even in the seconds. Now you’re back down to processing 5 - 10 hashes per second, no matter how fast the hardware in question is.

Tests, however, don’t need this security measure. There’s nothing worse in a test than a sleep(), and in a normal Rails app you can end up with hundreds, if not thousands, of bcrypt hashes being generated over the course of a test suite, so lets turn off this wait time entirely:

# Put at the top of your test_helper.rb
require 'bcrypt'
Kernel.silence_warnings {
  BCrypt::Engine::DEFAULT_COST = 1
}

And just like that, tests are now significantly faster. How much faster?

Before:

Finished in 17 minutes 50.69 seconds
2471 examples, 0 failures, 3 pending

After:

Finished in 7 minutes 49.72 seconds
2471 examples, 0 failures, 3 pending
jason.roelofs@collectiveidea.com

Comments

  1. November 13, 2012 at 10:45 AM

    See also: https://github.com/rails/rails/pull/285

  2. November 13, 2012 at 11:01 AM

    Trevor Turk: Wow, I didn’t realize there had been that much discussion around that. Such an obvious setting IMHO.

  3. November 13, 2012 at 15:13 PM

    If you use Devise, you get this for free in the default initializer:

    config.stretches = Rails.env.test? ? 1 : 10

  4. November 13, 2012 at 15:53 PM

    Just tried this. Got up to making the PDF then it fails because ‘dot’ and ‘ps2pdf’ is missing. On Mac using homebrew: ‘brew install graphviz ghostscript’ fixes this.

    The BCrypt issue wasn’t an issue since I turned off Devise’s password encryption fairly early on. The biggest one for me was the Garbage Collector at 45.5% followed by PG Connection#exec at 24.7%. So I gotta figure out how to decrease GC’s during tests and how to speed up database connection executions.

  5. November 13, 2012 at 15:56 PM

    Eric: I keep trying to tell Jason that Devise rocks. Thanks for the extra ammo!

  6. November 16, 2012 at 10:21 AM

    Kieran P Yeah Devise has had this setting for a while. I also wanted to help people get a start on perftools, as it’s a fantastic library, so I’m glad I was able to help you with that.

    Update: Thanks to Trevor Turk, in Rails master, ActiveSupport::SecurePassword now speeds itself up when in test mode! https://github.com/rails/rails/pull/8216