青木日記 2004-06-13

2004-06-13

■ 続disp_referrer2

http://zunda.freeshell.org/d/20040612.html#p01

うーむ、全然速くなりませんか。大口たたいたわりに役に立ってないですねえ。すみません。

前回も書いたとおり全体のプロファイルはとったことがあるし、 refctl.rb を作ったときの速度の上がりかたからしても、 parse_as_search が問題だというところまでは合ってるはずなんです。どこがボトルネックになっているんだろうなあ。

(19:23)

(追記)

あれ？ ja/disp_referrer.rb のパターン、一部しか変わってないのでは？ [^./]+ のほうが効果が大きいから、こっちを全部に適用しないと意味がないっす。

いややっぱり違う。マッチ回数自体が少なくなってるんだからどっちにしても意味はないんだ。やっぱりまずはボトルネック計測だな。これいじょう当て推量をやっても無駄っぽい。

■ 続disp_referrer2 (2)

データ集め

0. 環境

CPU: P4 2.4GHz
RAM: 1GB
ruby 1.9.0 (2004-05-21) [i686-linux]
nora なし
uconv あり
tDiary CVS HEAD ……と思ったらちょっと古かった
disp_referrer2 CVS HEAD

1. 実行時間 (高速な順)

素tDiary
2.35s user 0.01s system 100% cpu 2.357 total
　
refctl.rb
3.95s user 0.01s system 100% cpu 3.955 total
　
disp_referrer2.rb, with cache
9.75s user 0.11s system 100% cpu 9.833 total
　
disp_referrer2.rb, without cache
11.39s user 0.01s system 100% cpu 11.373 total

2. URL の種別傾向

all   =22346
search=21256 (fail=339)
other =1090

3. プロファイル (disp_referrer2 original)

  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
 20.45   125.30    125.30   320980     0.39     0.63  Array#<=>
 16.67   227.44    102.14    87027     1.17     5.35  Array#each
  8.13   277.27     49.83       11  4530.00 22780.00  Array#sort
  6.35   316.15     38.88   322328     0.12     0.12  Fixnum#<=>
  5.97   352.73     36.58   275366     0.13     0.13  String#<=>
  3.53   374.35     21.62    22346     0.97    11.42  #<Class:0x409ffa44>::DispRef2URL#parse_as_search
  3.36   394.92     20.57   363683     0.06     0.07  Hash#[]
  2.72   411.57     16.65    22533     0.74     1.94  TDiary::RefererManager.add_referer
  2.68   427.96     16.39    43521     0.38     0.80  #<TDiary::Config:0x40293864>.to_native
  2.50   443.28     15.32    90843     0.17     0.24  String#gsub
  2.34   457.60     14.32   163544     0.09     3.87  Class#new
  1.89   469.21     11.61       14   829.29  4305.00  String#each
  1.55   478.73      9.52    43521     0.22     0.35  Uconv.u8toeuc
  1.53   488.12      9.39   251846     0.04     0.04  Array#[]
  1.36   496.48      8.36   180744     0.05     0.05  String#split
(1% 以下略)

4. プロファイル (disp_referrer2改)

  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
 17.57    55.98     55.98    86915     0.64     1.21  Array#each
 10.96    90.90     34.92    21256     1.64     9.61  #<Class:0x409ffa44>::DispRef2URL#parse_as_search
  6.97   113.12     22.22   361772     0.06     0.07  Hash#[]
  5.16   129.55     16.43    22533     0.73     1.95  TDiary::RefererManager.add_referer
  4.93   145.25     15.70   163225     0.10     2.08  Class#new
  4.92   160.93     15.68    87984     0.18     0.25  String#gsub
  4.68   175.85     14.92    43520     0.34     0.79  #<TDiary::Config:0x40293864>.to_native
  3.54   187.14     11.29       14   806.43  4300.71  String#each
  3.16   197.22     10.08    43520     0.23     0.36  Uconv.u8toeuc
  3.12   207.15      9.93   180427     0.06     0.06  String#split
  2.76   215.96      8.81        6  1468.33 42170.00  Hash#each
  2.22   223.03      7.07    22346     0.32     1.11  #<Class:0x409ffa44>::DispRef2URL#lookup_hostspec
  2.17   229.94      6.91    22346     0.31    10.69  #<Class:0x409ffa44>::DispRef2URL#parse
  1.78   235.62      5.68    43520     0.13     0.92  #<Class:0x409ffa44>::DispRef2Setup#to_native
  1.59   240.70      5.08    20917     0.24     0.39  #<Class:0x409ffa44>::DispRef2String#normalize
  1.51   245.50      4.80   145479     0.03     0.03  Hash#default
  1.50   250.29      4.79    20919     0.23     3.97  #<Class:0x409ffa44>::DispRef2String#parse_query
  1.36   254.62      4.33   116091     0.04     0.04  Hash#[]=
  1.24   258.57      3.95    93843     0.04     0.04  Array#<<
  1.16   262.27      3.70    21174     0.17     0.51  #<Class:0x409ffa44>::DispRef2String#unescape
  1.15   265.93      3.66    42175     0.09     0.45  Enumerable.detect
  1.10   269.45      3.52    81168     0.04     0.04  String#delete
  1.09   272.92      3.47    87877     0.04     0.04  Regexp#=~
  1.07   276.34      3.42    22535     0.15     0.79  CGI#unescape
  1.05   279.69      3.35    93183     0.04     0.04  Array#initialize
(1% 以下略)

5. 各メソッドの消費時間配分 (sec)

DispRef2Refs#to_long_html        0.01
DispRef2Refs.new                 8.75
  DispRef2URL#parse                   8.57
    DispRef2URL#parse_as_other              0.15
    DispRef2URL#lookup_hostspec             1.31
    DispRef2URL#parse_as_search                  7.87
              ivar set                                2.21
              query analyse                           4.36
                query setup                                2.53
                keyword setup                              2.24

6. parse_as_search HotSpot

keys.empty?                5
keys.kind_of?(String)      0
query=nil                  5
cache URL                257
else                   20651

■ 続disp_referrer2 (3) 考察

現在の実装の延長でがんばる場合

(総合)

まず、DispRef2URL#parse がボトルネックになっていることは明らかである。次にリスト 2 からリファラの 95% 以上が検索エンジンだとわかるので、検索エンジンに最適化する。また検索エンジンからのリファラの 95% 以上は !keys.empty? かつ kind_of?(Array) かつ非キャッシュエントリなので、このパターンで最小手数になるように最適化すべき。

(方針)

頻出エントリに合わせてデータ構造を改善する。
CGI query の解析を軽くする。
to_native をできる限り減らす。

(詳細)

検索エンジンのディスクリプタは独自クラスにして、固有の最適化情報を最大限に利用する。例えば Google 以外では site: を sub する必要はない。 ie/oe を見れば charset がわかるので、必要なければ uconv を呼ばない。とにかく uconv は可能な限り減らすべきである。

現在は CGI query を一度ハッシュに展開しているが、これをもうちょっと軽くする。これも検索エンジンごとにコードを変更できればかなり最適化できそう。

■ 続disp_referrer2 (4) 結論？

ところで、今回の調査で実行時間のほとんどは parse であることがはっきりわかった。ということは、キャッシュがちゃんと効いていれば parse のコストはほとんどなくなって大幅に効率が改善できるはずだ。しかし実際には実行時間は 25% しか減っていないわけで、何かがおかしい。

……ちょ、ちょっと待って、なんで検索エンジンだけキャッシュしてないんですか？それでキャッシュヒット率が異様に低かったのか！

あ、そうか。検索エンジン抜きでキャッシュが 25MB ということは、全部キャッシュすると 200MB を超えるんだな。家のサーバじゃキャッシュをロードしただけでメモリがなくなる。最低でもキャッシュデータベースを月ごとに分けないとまずいな。

あるいは、何か情報をあきらめるか。検索キーワードは残して URL を捨てれば軽くならないかな。ならないな。だめだ。

うーん。こりゃちょっといじっただけじゃ速くならないな。やっぱ工夫して全部キャッシュしちゃうのがお手軽でしょう。粘ったわりにつまらない結論だ。

(03:52)

■ 深夜カキコ

RHG 読書会で笑い死にそうになったネタが思い出せなくて気になってたんだけども、期待に違わず誰かが書いておいてくれた。首都国家東京だった。やっとすっきりした。

そしてそんなこととは全然まったく関係なく、明日提出のレポートがまだ書けていません！わーい！

(04:10)

本日のツッコミ(全1件) [ツッコミを入れる]

■ zunda (2004-06-13 21:38)

プロファイル取ってみたのですが→http://zunda.freeshell.org/d/20040613.html#p01
とりあえず帰って寝ることにします。ぉぃ。

ツッコミ・コメントがあればどうぞ! メールアドレスは公開されません。