Jul's blog

Musings from the news of web, roleplaying and technology

Y U RUBBY2 NO GO FASTER

| Comments

The day ruby 2.0.0 has been released, I wanted to use it. I have built it the day after on my notebook, but it took more than two times as much time to run all the specs for my recent rails project, than with 1.9.3-p327 with falcon-gc. I’m certainly getting the wrong results, don’t I? Sure I do. Yesterday I grabbed my pickaxe, to dig out the root of the problem.

My first thought was it’s a bug in my build. I have tried a lot of extra cflags, but no avail. I also installed the homebrew version. Same results:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
% payload=(bin/rspec spec --no-drb -o /dev/null);\
> for ver in 1.9.3-p327-perf 1.9.3-p429 2.0.0-p0 2.0.0-p195;\
> do ruby=~/.rbenv/versions/$ver/bin/ruby;\
> echo $ver; $ruby $payload; time $ruby $payload; done
1.9.3-p327-perf
Rack::File headers parameter replaces cache_control after Rack 1.5.
Rack::File headers parameter replaces cache_control after Rack 1.5.
$ruby $payload  25.70s user 1.90s system 97% cpu 28.240 total
1.9.3-p429
Rack::File headers parameter replaces cache_control after Rack 1.5.
Rack::File headers parameter replaces cache_control after Rack 1.5.
$ruby $payload  30.63s user 2.09s system 95% cpu 34.264 total
2.0.0-p0
Rack::File headers parameter replaces cache_control after Rack 1.5.
Rack::File headers parameter replaces cache_control after Rack 1.5.
$ruby $payload  79.17s user 2.70s system 65% cpu 2:04.50 total
2.0.0-p195
Rack::File headers parameter replaces cache_control after Rack 1.5.
Rack::File headers parameter replaces cache_control after Rack 1.5.
$ruby $payload  62.09s user 2.00s system 96% cpu 1:06.62 total

% ruby=/usr/local/opt/ruby/bin/ruby; echo `$ruby --version`' (homebrew)';\
> $ruby $payload; time $ruby $payload2.0.0-p0 (homebrew)
Rack::File headers parameter replaces cache_control after Rack 1.5.
Rack::File headers parameter replaces cache_control after Rack 1.5.
$ruby $payload  64.30s user 2.34s system 74% cpu 1:29.55 total

Or, with tables (sorry RedCloth markdown tables are just plain ugly):

1
2
3
4
5
6
7
version           | result
----------------- | -------
1.9.3-p327-perf   | 28.240s
1.9.3-p429        | 34.264s
2.0.0-p0          | 2.04.50s
2.0.0-p195        | 1:06.62s
2.0.0-p0 homebrew | 1.29.55s

This doesn’t look too good.

OK, what if it’s my computer? I’m using a late-2010 Macbook Air with 4GB RAM soldered on it. A better computer, a closer target (I’m deploying to 64bit ubuntu server), and more RAM would help. Thus, I have set up a development environment on a Ubuntu 12.04.02 box, with a 8-core i7 3660, with 32GB RAM, with no load whatsoever. I have ran the same tests (but with a bit different versions though) there too:

1
2
3
4
5
version            | result
------------------ | -------
1.9.3-p385-perf    | 10.66s
1.9.3-p429         | 16.44s
2.0.0-p195         | 11.81s

Hey, where is my big difference? It certainly shows what Funny Falcon has done with 1.9.3, but 2.0.0 results are just A-OK. I can live with this performance difference.

Ah well. What takes much more on my computer than it should? It’s time to put the chainsaw away, and get a plasma blaster.

My weapon of choice was ruby-prof. I wanted to profile my specs though, and it is not trivial to attach RubyProf to rspec. Fortunately, Colin MacKenzie IV wrote rspec-prof gem to grease the wheels. It’s just adding the gem, putting specs into a profile do ... end block, and looking at the generated files afterwards from profiles/ folder.

To make the long story short it turned out I have created a new user account for every single controller tests, which encrypted its password with bcrypt. For those who don’t know this, bcrypt is well known being resistant against brute-force, because its iteration count can be tuned to slow processing down.

Therefore the answer for my question why ruby 2 is slower is because I asked it to be slower.

Ask yourself: why your class spend precious time doing unnecessary stuff like encryption during tests? Of course you have to, if this is your core business. It’s not the case though in most situations though: patch through the slow method then:

1
2
3
4
5
6
# spec/support/devise.rb
module Devise::Models::DatabaseAuthenticatable
  def password_digest(password)
    password
  end
end

ActiveModel’s has_secure_password requires are not hard to find either (I haven’t tested it, sorry):

1
2
3
4
5
6
7
8
9
10
# spec/support/secure_password.rb
module ActiveModel::SecurePassword::InstanceMethodsOnActivation
  def authenticate(unencrypted_password)
    password_digest == unencrypted_password
  end

  def password=(unencrypted_password)
    self.password_digest = unencrypted_password
  end
end

The new results are stunning:

1
2
3
4
5
6
7
version           | result
----------------- | -------
1.9.3-p327-perf   | 17.850s
1.9.3-p429        | 23.829s
2.0.0-p0          | 36.012s
2.0.0-p195        | 18.179s
2.0.0-p0 homebrew | 19.581s

I don’t know what happened with rbenv’s 2.0.0-p0, but I don’t even care. All the other results are expected, it’s safe now to switch to 2.0.0-p195.

Comments