tDiary + Ruby1.9 環境での応答時間を40%以上高速化
タイトルはやや釣りっぽく。
まずは結果から。 この日記の場合、最新表示の時間が1.31秒から0.75秒まで短縮された。 体感的にも速くなったように感じる。
計測方法
timeコマンドによる計測（rubyコマンドの起動から終了までの時間）。
$ time ruby index.rb "" > /dev/null
環境
- tDiary 2.3.3.20100326
- Ruby 1.9.1-p378
- CentOS 5.2 final
- サーバ: CPI VPSスケーラブルプラン)
手順
あくまで参考として。オフィシャルに対応されるまでは、実際にやっちゃダメ。
- compatible.rb.patchを適用するだけ。
【6/13 追記】 GitHub にトピックブランチ (auto_convert_1.9を切って作業中。 議論はtdiary-develのメーリングリストにて。
なぜ高速化されるのか
ruby1.8系と1.9系の互換性を確保するための misc/lib/compatible.rb に、 PStore の互換性を確保するための処理が入っている。 この処理は最初に1.9系にアップデートした時のみ必要になる。処理を省略することで無駄なオーバーヘッドを削減できる。
副作用
ruby1.8.x系で動かしていたときの PStore データが残っていた場合、1.9.1の環境ではそのデータが読めなくなる。
高速化までの経緯
ふと tDiary + ruby-1.9.1 の環境でプロファイルを取ってみたところ、気になる結果が表示された。
$ ruby -rprofile index.cgi "" > /dev/null 2> profile.txt
% cumulative self self total time seconds seconds calls ms/call ms/call name 52.91 7.00 7.00 122270 0.06 0.08 Proc#call 18.90 9.50 2.50 3 833.33 4016.67 Marshal.load 6.80 10.40 0.90 122341 0.01 0.01 Kernel.respond_to? 5.59 11.14 0.74 81527 0.01 0.01 String#encoding 4.69 11.76 0.62 81559 0.01 0.01 BasicObject#== 4.38 12.34 0.58 3 193.33 193.33 Thread#join 2.19 12.63 0.29 40779 0.01 0.01 String#force_encoding 1.89 12.88 0.25 207 1.21 5.07 Kernel.require （以下省略）
Proc#callが10万回以上も呼ばれ、全体の半分以上の時間を占めている。 他にも Kernel.respond_to?, String#encoding, BasicObject#==, String#force_encoding が高い頻度で呼ばれている。 いくらなんでもこれはおかしいと思い、処理を調べてみることに。
1.8系で動かしていた頃はこんなことはなかったし、呼ばれているメソッド名から1.9関連の処理だと推測。 compatible.rb を開いてみたら、それっぽいコードを発見した。
# Auto convert ASCII_8BIT pstore data (created by Ruby-1.8) to UTF-8.
if "".respond_to?('force_encoding')
require 'pstore'
class PStore
private
def load(content)
load_proc = proc {|obj|
if obj.respond_to?('force_encoding') && obj.encoding == Encoding::ASCII_8BIT
obj.force_encoding('UTF-8')
end
obj
}
Marshal::load(content, load_proc)
end
end
end
コメントと処理内容から、 ruby 1.8 系で PStore に保存したオブジェクト（文字列）を 1.9 系に対応させようとしているコードだと判断。 そうか。1.8系は文字列がエンコーディング情報を持たないから、1.9系で取り出すとUTF-8と判定されなくなるのか。
推測した後は、お約束の print デバッグをつかって、呼び出し元や呼び出し回数を確認。 この変換処理は PStore でロードされるすべてのオブジェクトに適用されるため、10万回以上もメソッドが呼ばれる原因になっていたことが分かった。 1つのメソッドの実行時間はたいしたことないけど、10万回呼ばれるとかなりのオーバーヘッドになる。
print デバッグで確認したところ、以下の箇所から呼び出されていた。
- カテゴリプラグイン
- tDiaryのキャッシュ (*.parser)
- my-sequel.rb
- section_footer2.rb の add_delicious
- profile.rb
- my_hotentry.rb
- recent_list.rb
特に tDiary のキャッシュにはリファラ情報も保存されているので、リファラが多い場合は呼び出し回数も多くなっていた。
対処後
最初に書いたようにこの変換処理を削除したところ、プロファイルの結果も改善された。
% cumulative self self total time seconds seconds calls ms/call ms/call name 39.00 0.39 0.39 3 130.00 130.00 Thread#join 24.00 0.63 0.24 206 1.17 4.08 Kernel.require 6.00 0.69 0.06 3 20.00 20.00 Marshal.load 5.00 0.74 0.05 109 0.46 2.29 BasicObject#instance_eval 4.00 0.78 0.04 3446 0.01 0.01 Module#method_added 3.00 0.81 0.03 70 0.43 0.43 IO#read 2.00 0.83 0.02 49 0.41 5.31 IO#open 1.00 0.84 0.01 49 0.20 0.41 Module#class_eval
ちゃんとした対処策
今回はすでに 1.9 へ移行済みだったので、変換処理を削除した。 でも、これから1.8から1.9に移行する人のことを考えると、変換処理を削除するのは乱暴すぎる。
tDiary が UTF-8 対応したときはどうやったんだろうと調べてみたら、 plugin/90migrate.rb に UTF-8 への変換処理が書いてあった
unless @conf.tdiary_version # ファイルの中身をUTF-8に書き換える処理 # 同時にキャッシュファイルを削除 end
うーん。 @conf.tdiary_version と同じように @conf.ruby_version を用意するのがいいのかな。 メーリングリストに投げてみよう。