ruby1.9.1はまだ鬼門？
仕事中 EventMachine を使った ruby のコードを書いていて、ある部分がかなり遅いことに気付いた。
リクエストを非同期で投げるのに em-http-request を使っている部分。
その場はとりあえずやり過ごして、家に帰ってきてから改めて調べてみた。
その結果、
require 'em-http'
の部分だけやたらと時間がかかっている。
で、調べていくうちに em-http-request が遅いんじゃなくてそれが利用している addressable の読み込みが遅いというところまでわかった。
この addressable モジュールのうち、idna.rb というファイルの中で、
UNICODE_DATA = { 0x0041 => [0, 0, nil, nil, nil, 0x0061, nil], 0x0042 => [0, 0, nil, nil, nil, 0x0062, nil], 0x0043 => [0, 0, nil, nil, nil, 0x0063, nil], 0x0044 => [0, 0, nil, nil, nil, 0x0064, nil], ....同じような感じで4k行以上
という部分と、この UNICODE_DATA を
COMPOSITION_TABLE = {} for codepoint, data in UNICODE_DATA canonical = data[UNICODE_DATA_CANONICAL] exclusion = data[UNICODE_DATA_EXCLUSION] if canonical && exclusion == 0 COMPOSITION_TABLE[canonical] = codepoint end end
としてぶん回している部分に異常に時間を取られている。
ひょっとして 1.9.1 だから？とすぐに思いついてプロファイラで計測してみた。
$ cat test-reqidna.rb require './idna.rb' $ ruby1.9.1 -r profile test-reqidna.rb % cumulative self self total time seconds seconds calls ms/call ms/call name 64.50 1.49 1.49 1 1490.00 1760.00 Hash#each 23.38 2.03 0.54 1 540.00 2310.00 Kernel.require 6.49 2.18 0.15 16932 0.01 0.01 Array# 2.16 2.23 0.05 4233 0.01 0.01 Array#length 1.73 2.27 0.04 5544 0.01 0.01 Fixnum#== 0.87 2.29 0.02 4233 0.00 0.00 Kernel.kind_of? 0.43 2.30 0.01 7 1.43 1.43 String#+ 0.43 2.31 0.01 918 0.01 0.01 Hash#= 0.00 2.31 0.00 1 0.00 0.00 Fixnum#<< 0.00 2.31 0.00 20 0.00 0.00 BasicObject#singleton_method_added 0.00 2.31 0.00 2 0.00 0.00 Fixnum#* 0.00 2.31 0.00 17 0.00 0.00 Module#private 0.00 2.31 0.00 3 0.00 0.00 Class#inherited 0.00 2.31 0.00 4 0.00 0.00 IO#set_encoding 0.00 2.31 0.00 1 0.00 2310.00 #toplevel $ ruby1.8 -r profile test-reqidna.rb % cumulative self self total time seconds seconds calls ms/call ms/call name 62.34 0.48 0.48 1 480.00 710.00 Hash#each 27.27 0.69 0.21 8466 0.02 0.02 Array# 7.79 0.75 0.06 1 60.00 770.00 Kernel.require 1.30 0.76 0.01 918 0.01 0.01 Hash#= 1.30 0.77 0.01 1311 0.01 0.01 Fixnum#== 0.00 0.77 0.00 2 0.00 0.00 Fixnum#* 0.00 0.77 0.00 3 0.00 0.00 Class#inherited 0.00 0.77 0.00 20 0.00 0.00 Kernel.singleton_method_added 0.00 0.77 0.00 17 0.00 0.00 Module#private 0.00 0.77 0.00 1 0.00 0.00 Fixnum#<< 0.00 0.77 0.00 7 0.00 0.00 String#+ 0.00 0.77 0.00 1 0.00 770.00 #toplevel
1.8に較べてやっぱりすげー遅くなってる。
gprof でもうちょっと深めに追ってみようかとも思ったんだけど、1.8 と 1.9.1 をコンパイルするのが面倒で trunk をリポジトリから持ってきて神頼み的に計測（結局コンパイル）。
$ ruby-trunk --version ruby 1.9.3dev (2010-07-08 trunk 28577) [x86_64-linux] $ ruby-trunk -r profile test-reqidna.rb % cumulative self self total time seconds seconds calls ms/call ms/call name 53.52 0.38 0.38 1 380.00 610.00 Hash#each 23.94 0.55 0.17 16932 0.01 0.01 Array# 12.68 0.64 0.09 1 90.00 710.00 Kernel.require 5.63 0.68 0.04 4233 0.01 0.01 Kernel.kind_of? 1.41 0.69 0.01 7 1.43 1.43 String#+ 1.41 0.70 0.01 5544 0.00 0.00 Fixnum#== 1.41 0.71 0.01 4233 0.00 0.00 Array#length 0.00 0.71 0.00 918 0.00 0.00 Hash#= 0.00 0.71 0.00 17 0.00 0.00 Module#private 0.00 0.71 0.00 20 0.00 0.00 BasicObject#singleton_method_added 0.00 0.71 0.00 8 0.00 0.00 Hash#default 0.00 0.71 0.00 1 0.00 0.00 Fixnum#<< 0.00 0.71 0.00 2 0.00 0.00 Fixnum#* 0.00 0.71 0.00 3 0.00 0.00 Class#inherited 0.00 0.71 0.00 4 0.00 0.00 IO#set_encoding 0.00 0.71 0.00 1 0.00 710.00 #toplevel
trunk ではかなり改善されている模様。
次に time コマンドと benchmark モジュールでも比較してみた。
$ time ruby1.9.1 test-reqidna.rb real 0m1.359s user 0m1.340s sys 0m0.010s $ time ruby1.8 test-reqidna.rb real 0m0.083s user 0m0.080s sys 0m0.000s $ time ruby-trunk test-reqidna.rb real 0m0.101s user 0m0.060s sys 0m0.040s $ irb1.9.1 irb(main):001:0> require 'benchmark' irb(main):002:0> puts Benchmark.measure{require './idna.rb'} 1.350000 0.000000 1.350000 ( 1.354746) $ irb1.8 irb(main):001:0> require 'benchmark' irb(main):002:0> puts Benchmark.measure{require './idna.rb'} 0.070000 0.000000 0.070000 ( 0.066070) $ /usr/local/ruby-trunk/bin/irb irb(main):001:0> require 'benchmark' irb(main):002:0> puts Benchmark.measure{require './idna.rb'} 0.070000 0.010000 0.080000 ( 0.079105)
ということで ruby 本体にバリっと patch あてられるほど技術力のない自分が取るべき選択肢は
- 1.8で運用
- trunkで運用
- em-http-request 使わない
- em-http-request で addressable/uri を使わないようにpatchあてる
のどれかで、ただ 1.8 系を使うにしてもリポジトリから最新のものを取ってこないと NKF の utf 周りに悩まされてしまうはずでいずれにしても手はかかりそう・・・ぐわー。
追記：同じように addressable/uri の読み込みの遅さに苦しめられている人がいるのを発見しました。
http://d.hatena.ne.jp/kitamomonga/20100316/ruby_gem_addressable_howto
追記２：1.9.2 のプロファイル結果
速い！
$ /usr/local/ruby_1_9_2/bin/ruby -r profile test-reqidna.rb % cumulative self self total time seconds seconds calls ms/call ms/call name 56.60 0.30 0.30 1 300.00 460.00 Hash#each 16.98 0.39 0.09 16932 0.01 0.01 Array# 11.32 0.45 0.06 1 60.00 530.00 Kernel.require 3.77 0.47 0.02 4233 0.00 0.00 Kernel.kind_of? 3.77 0.49 0.02 5544 0.00 0.00 Fixnum#== 3.77 0.51 0.02 4233 0.00 0.00 Array#length 1.89 0.52 0.01 3 3.33 3.33 Class#inherited 1.89 0.53 0.01 918 0.01 0.01 Hash#= 0.00 0.53 0.00 17 0.00 0.00 Module#private 0.00 0.53 0.00 20 0.00 0.00 BasicObject#singleton_method_added 0.00 0.53 0.00 236 0.00 0.00 Hash#default 0.00 0.53 0.00 1 0.00 0.00 Fixnum#<< 0.00 0.53 0.00 7 0.00 0.00 String#+ 0.00 0.53 0.00 2 0.00 0.00 Fixnum#* 0.00 0.53 0.00 4 0.00 0.00 IO#set_encoding 0.00 0.53 0.00 1 0.00 530.00 #toplevel
