mswin32版のRuby 1.8.7-p160が遅すぎる件

　こんにちは。那由多屋の加藤です。

　悩んでいます。mswin32版のRuby 1.8.7-p160でRuby on Railsを動作させると、なぜだかとてつもなく動作が遅く、悩んでいます。

　そしてまだ、解決には至っていません。情報を求む！

きっかけ

　Windows環境にてRailsアプリケーションを開発していて、ふと気づきました。こんなに動作が遅かったかな？と。

　数値で確認するためにFirebugの「接続」タブを見てみると、シンプルなアクションにも関わらず、応答を返すまでに9.6秒も要しています。なんと！

原因の切り分け

　いつの時点で遅くなったのかを探るために、初めてgit bisectを使い、原因の切り分けに挑戦・・・するも、そもそもいくら遡っても動作が遅い。

　自分の作業履歴を遡ってみると、開発環境のRuby インタプリタを1.8.7-p72から同p160にアップデートしていたことが判明。すっかり忘れていました。

　試しに、開発環境に残っていたp72でRailsアプリケーションを動作させると、さくさく動作します。これですか！

各環境の検証

　開発環境にインストールしているp72/p160はどこから入手したのか忘れてしまったため、新しい環境を構築して検証してみました。使用したバイナリは下記の通り。

　上記のバイナリに、依存ライブラリを加え、さらにRubyGems 1.3.4、Rails 2.3.2をインストールしました。

　そして、シンプルなRailsアプリケーションを作成しました。

rails -d sqlite3 simple
cd simple
ruby script\generate controller home index
ruby script\server webrick

　準備が整ったので、計測してみます。下表の単位はミリ秒。まずは、静的ファイルであるpublic/index.htmlにアクセスしてみます。

Ruby インタプリタ	1回目	2回目	3回目	平均
1.8.7-p72-i386-mswin32	25	24	21	23
1.8.7-p160-i386-mswin32	785	766	757	769

　この時点で明らかです（汗）。次にHome#indexアクションにアクセスしてみます。

Ruby インタプリタ	1回目	2回目	3回目	平均
1.8.7-p72-i386-mswin32	46	44	45	45
1.8.7-p160-i386-mswin32	1730	1860	1750	1780

　静的ファイルで33倍、テンプレートをレンダリングするだけのアクションでは39倍もの時間を要していることが判明。遅すぎます。

プロファイラで計測

　次に、プロファイラを使ってどの処理に時間が掛かっているのかを調べてみました。使用したプロファイラはruby-prof。

　まずは、p72にて計測してみます。出力結果の上5行は下記の通り。

 %self     total     self     wait    child    calls  name
 69.21      3.20     2.81     0.39     0.00        7  <Class::IO>#select
 14.23      4.06     0.58     0.00     3.48        1  WEBrick::GenericServer#start_thread
  2.68      0.27     0.11     0.00     0.16       23  Kernel#gem_original_require-1
  1.18      0.20     0.05     0.00     0.16       12  Kernel#gem_original_require
  0.79      0.03     0.03     0.00     0.00      118  Symbol#to_s

　次に、p160にて計測してみます。

 %self     total     self     wait    child    calls  name
 15.84     13.42     2.58    10.84     0.00        7  <Class::IO>#select
 10.98      8.84     1.79     0.00     7.05      515  Kernel#gem_original_require-1
  1.14      0.34     0.19     0.00     0.16      228  Module#class_eval
  0.67      0.11     0.11     0.00     0.00     3463  Module#constants
  0.49      0.13     0.08     0.00     0.05     1027  Array#map

　IO.selectのself、childは同等ですが、waitがやたら長いですね。

ソースコードを調査

　IO.selectが怪しいとの目星をつけ、ソースコードを眺めてみました。

　p72とp160における、mswin32関連かつIO関連の相違を見てみると、rb_w32_select関数が変更されていました。タイムアウト関係の変更の様です。

　・・・が、修正内容の意味がわかりません。そしてちょっと疲れてしまいました。（いまここ）

那由多屋開発日誌