JRubyがCRubyに比べて遅すぎる件について

シングルプロセス・ローカル実行

課題は，ログのパースです．一ヶ月分のApache httpdのログをパースして，必要な情報のみを必要なフォーマットで出力するRubyのプログラムを，JRubyとCRubyで実行します．

[hadoop@hadoop_client]$ time cat access_log | ruby log_parser.rb | sort | md5sum -
241213aa784ff569b85a717b92ad27ee  -

real    54m13.262s
user    52m39.431s
sys     1m53.115s


[hadoop@hadoop_client]$ time cat access_log | jruby log_parser.rb | sort | md5sum - 
241213aa784ff569b85a717b92ad27ee  -

real    40m18.757s
user    41m15.511s
sys     1m44.323s

結果が同一であることをmd5で確認しています．
CRubyが54分でJRubyが40分なので，3割ほどJRubyの方が早いです．

Hadoop Streaming実行

特に最適化やオプションは付けずに，そのままHadoop Streamingで実行します．

[hadoop@hadoop_client]$ time hdfs dfs -put /var/log/access_log input/

real    2m29.479s
user    0m42.045s
sys     0m8.383s

[hadoop@hadoop_client]$ time hadoop jar /usr/local/hadoop/share/hadoop/tools/lib/hadoop-streaming-2.0.0-cdh4.4.0.jar -file log_parser.rb -mapper 'ruby log_parser.rb' -input input/access_log -output output 
14/01/16 12:26:47 WARN streaming.StreamJob: -file option is deprecated, please use generic option -files instead.
packageJobJar: [log_parser.rb, /home/hadoop/tmp/hadoop-hadoop/hadoop-unjar4342055864112442739/] [] /tmp/streamjob780153691860120701.jar tmpDir=null


14/01/16 12:33:10 INFO streaming.StreamJob: Output directory: output

real    6m23.114s
user    0m7.415s
sys     0m0.241s
[hadoop@hadoop_client]$ time hdfs dfs -cat output/part-00000 | sort | md5sum -
241213aa784ff569b85a717b92ad27ee  -

real    1m18.972s
user    1m20.522s
sys     0m1.504s

[hadoop@hadoop_client]$ time hadoop jar /usr/local/hadoop/share/hadoop/tools/lib/hadoop-streaming-2.0.0-cdh4.4.0.jar -file log_parser.rb -mapper '/usr/local/jruby/bin/jruby log_parser.rb' -input input/access_log -output output 
14/01/16 13:42:28 WARN streaming.StreamJob: -file option is deprecated, please use generic option -files instead.


14/01/16 13:50:25 INFO streaming.StreamJob: Output directory: output

real    7m57.466s
user    0m7.428s
sys     0m0.260s


[hadoop@hadoop_client]$ time hdfs dfs -cat output/part-00000 | sort | md5sum -
241213aa784ff569b85a717b92ad27ee  -

real    1m18.988s
user    1m20.450s
sys     0m1.555s

実行時間だけ見ると，ここでCRubyは6分23秒，JRubyは7分57秒になります．

JRubyのオプション設定

デフォルトで今のJRubyはCRuby 1.9互換なので，2.0互換にしてみます．

[hadoop@hadoop_client]$ time hadoop jar /usr/local/hadoop/share/hadoop/tools/lib/hadoop-streaming-2.0.0-cdh4.4.0.jar -file log_parser.rb -mapper '/usr/local/jruby/bin/jruby --2
.0 log_parser.rb' -input input/access_log -output output 

14/01/16 18:17:44 INFO mapred.FileInputFormat: Total input paths to process : 1
14/01/16 18:17:44 INFO mapreduce.JobSubmitter: number of splits:133


real    8m5.647s
user    0m7.524s
sys     0m0.268s

返って遅くなりました．7分57秒から，8分5秒になってしまいました．

次に，デフォルトのclientモードからserverモードに変えてみます．

[hadoop@hadoop_client]$ time hadoop jar /usr/local/hadoop/share/hadoop/tools/lib/hadoop-streaming-2.0.0-cdh4.4.0.jar -file log_parser.rb -mapper '/usr/local/jruby/bin/jruby --server log_parser.rb' -input input/access_log -output output        

14/01/16 18:28:41 INFO mapred.FileInputFormat: Total input paths to process : 1
14/01/16 18:28:41 INFO mapreduce.JobSubmitter: number of splits:133


real    7m57.703s
user    0m7.614s
sys     0m0.238s

7分57秒．CRubyの6分台には行きません．

-J-Xmx1024mとかヒープメモリのサイズを変えてもダメ，-Xcompile.mode=FORCEでJITコンパイルから事前コンパイルに変えてもダメ．

(´・ω・｀)