Re: [tDiary-devel] ruby 1.9.1で動かすとProc#callが大量に呼びだされる

[Kazuhiko <kaz...@fd...>]

かずひこです。

On 12/06/2010 20:08, MATSUOKA Kohei wrote:
> ふと ruby-1.9.1 で動かしている tDiary の
> プロファイルを取ってみたら、
> Proc#callが10万回呼びだされて全体の半分以上を
> 占めていることに気がつきました。
> Kernel.respond_to?やString#encodingも相当な数が呼ばれています。
> なお、1.8系で動かしている場合は、このようなことはありません。
> 
> $ ruby -rprofile index.cgi "">  /dev/null 2>  profile.txt
>   %   cumulative   self              self     total
>   time   seconds   seconds    calls  ms/call  ms/call  name
>   53.68     6.79      6.79   122303     0.06     0.08  Proc#call
>   16.76     8.91      2.12        3   706.67  3846.67  Marshal.load
>    8.14     9.94      1.03   122378     0.01     0.01  Kernel.respond_to?
>    5.22    10.60      0.66    81576     0.01     0.01  BasicObject#==
>    4.90    11.22      0.62    81544     0.01     0.01  String#encoding
>    4.27    11.76      0.54        3   180.00   180.00  Thread#join
>    2.61    12.09      0.33    40795     0.01     0.01  String#force_encoding
> 
> 調べたところ、 misc/lib/compatible.rb で
> PStore#loadをオーバーロードしている箇所が原因だと分かりました。
> Marshal::loadへ渡しているload_procが大量に実行されています。
> （復元されるオブジェクトの数だけload_procが呼ばれます）

これはとても面白い。
http://jp.rubyist.net/magazine/?0027-WhatWeCanDo
執筆中にプロファイルを取ったときはそんなことなかったのになぁと思ったら、

>                 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

↑これが追加された2009/08/17は、ちょうどその記事を書いた頃なので、その変
更以降にプロファイルを取っていなかったみたいですね。遅くしてしまってごめ
んなさい。

> ここの処理はRuby1.8系から1.9系に移行するときに
> 最初の1回だけ呼び出せば良いと思っています。

では早速と、1.9系に移行して久しい私の日記でこの処理を削ってみると、いき
なりこんなエラーが出ました。

incompatible encoding regexp match (UTF-8 regexp with ASCII-8BIT string)
(Encoding::CompatibilityError)

(tdiary/lang/ja.rb):66:in `scan'
(tdiary/lang/ja.rb):66:in `shorten'
(plugin/recent_trackback3.rb):61:in `block (2 levels) in recent_trackback3'
(plugin/recent_trackback3.rb):53:in `each'
(plugin/recent_trackback3.rb):53:in `block in recent_trackback3'
/usr/local/ruby-trunk/lib/ruby/1.9.1/pstore.rb:332:in `block (2 levels)
in transaction'
/usr/local/ruby-trunk/lib/ruby/1.9.1/pstore.rb:331:in `catch'
/usr/local/ruby-trunk/lib/ruby/1.9.1/pstore.rb:331:in `block in transaction'
/usr/local/ruby-trunk/lib/ruby/1.9.1/pstore.rb:362:in `synchronize'
/usr/local/ruby-trunk/lib/ruby/1.9.1/pstore.rb:322:in `transaction'
(plugin/recent_trackback3.rb):51:in `recent_trackback3'
(TDiary::Plugin#eval_src):209:in `block in eval_src'
/home/tdiary/tdiary/core/tdiary.rb:795:in `eval'
/home/tdiary/tdiary/core/tdiary.rb:795:in `block in eval_src'
/home/tdiary/tdiary/core/tdiary.rb:115:in `safe'
/home/tdiary/tdiary/core/tdiary.rb:794:in `eval_src'
/home/tdiary/tdiary/core/tdiary.rb:1154:in `do_eval_rhtml'
/home/tdiary/tdiary/core/tdiary.rb:1086:in `eval_rhtml'
/home/tdiary/users/kazuhiko/index.rb:81:in `<main>'

data_dirのrecent_trackbacksを削除したら、もちろんエラーが出なくなりまし
た。まだ深追いしていませんが、ひとまず報告しておきます。

> 試しにこの処理を削除したところ、
> 4割以上も応答時間が速くなりました。
> ＃ この顛末は日記に書きました
> http://www.machu.jp/diary/20100612.html#p01

確かに、すごく速くなりました。本当にありがとうございます。
この速さなら、第二tDiary.Netを全部Ruby-1.9化するのが現実味を帯びそうで
す。もちろんFCGI使用で。

> ただし、これから1.9系へ移行する人のことを考えると、
> 単純にこの処理を削除する訳にはいきません。
> 
> UTF-8化のplugin/90migrate.rbでの @conf.tdiary_version のように、
> 移行フラグを用いて関連ファイルを初回のみ書き換えるのが
> よいと思ったのですが、独自プラグインが使うPStoreデータは
> アップデートする人に手動で削除してもらう必要があります。
> 
> キャッシュのように消してもいいデータだと
> 影響は少ないのですが、消すと復旧できないデータを
> PStoreに保存している場合は影響が大きそうですね。
> 
> なにかいいアイデアはないでしょうか。

migrateが走るタイミングで、ありえそうなPStoreデータを全部かたっぱしか
ら、上記のパッチみたいな感じでencodingを変更してしまうしかないのではない
かと思います。

かずひこ