Hatena::ブログ(Diary)

I am Bad at Math

2010-07-08

ruby1.9.1はまだ鬼門?

00:13 |

仕事中 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

追記2: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

nursenurse 2010/07/09 09:40 ども、1.9.1は未完成なので、業務では使えませんよ。
ほぼプレビューであった1.9.0とは違って、機能的にはほぼ出来上がっているんですが、
速度や安定性が実運用に投入できるレベルではありません。

というわけで、1.9.2を使うか、1.8.7を使うのが正解でしょう。

badatmathbadatmath 2010/07/10 05:03 コメントありがとうございます。
結局、スピードも速いしリリースも近い 1.9.2 で行くことに決めました。
助かりました!

Connection: close