at posts/single.html

tDiary + Ruby1.9 環境での応答時間を40%以上高速化

タイトルはやや釣りっぽく。

まずは結果から。 この日記の場合、最新表示の時間が1.31秒から0.75秒まで短縮された。 体感的にも速くなったように感じる。

tDiaryの応答時間改善

計測方法

timeコマンドによる計測(rubyコマンドの起動から終了までの時間)。

$ time ruby index.rb "" > /dev/null

環境

手順

あくまで参考として。オフィシャルに対応されるまでは、実際にやっちゃダメ。

【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 を用意するのがいいのかな。 メーリングリストに投げてみよう。

関連する日記