いらないキャッシュを消すことでRubyスクリプトが倍速で動作するようになった話です。

先日、るりまサーチをRackspaceのクラウドサーバー（メモリ1GB）からさくらのVPS 512（メモリ512MB）に移行しました。理由はRackspaceのサーバーが遠くにあるのでレスポンスがもっさりするからです。最速検索がウリなのにこれでは遅いのでないかと誤解されてしまいます。さくらのVPSにしたら近くにあるためサクサクとレスポンスが返ってくるようになりました。しかも、リソース（主にメモリ量）はスケールダウンしているのにです。

るりまサーチはバックエンドの全文検索エンジンgroongaが高速に動作するのとそれほどアクセスがない（！）ため、CPUやI/Oがネックになることはありません。それよりも、ほとんどメモリを搭載していないマシンで動かしているため、ボトルネックになるとすればメモリです。実メモリ以上にメモリを使おうとしてスワップを使い始めると遅くなります。

るりまサーチに一番負荷がかかるのは1日1回のるりまデータの更新です。もう少し言うとBitClustでHTMLを生成する処理が一番負荷が高いのです。このとき、BitClustのHTML生成プロセスはCPUを100%使い¹、500MB程度のメモリを使用します²。Rackspaceのときのように1GBのメモリが載っているサーバーであれば耐えられますが、さくらのVPS 512のように512MBしかメモリが載っていないサーバーでは致命的です。スワップを使いはじめてI/O待ちが多発し、システムの応答性が著しく悪化します。

ということで、BitClustがHTMLを生成するときのメモリ使用量を改善したのですが、そのときに2倍くらい高速に動作するようになりました。その高速化の方法を一言でいうと「いらないキャッシュを消す」です。具体的な変更点でいうとr4873（4行）とr4874（1行）です。

いらないキャッシュを消して高速化

キャッシュはメモリを通常より使って処理時間を短くする方法なので、キャッシュを消すことでメモリ使用量が減るのは納得できます。しかし、処理時間も短くなるのは意外ですよね。

なお、メモリ使用量と実行時間は以下のようになりました。Ruby 1.8.7の場合も1.9.3の場合もメモリ使用量は半分以下、実行時間はほぼ半分になっています。

メモリ使用量が減って速くなった場合はだいたいGCに関係していると相場が決まっています。では、こんなときはどうやって確認したらよいでしょうか。Ruby 1.9.2以降にはGC::Profilerという便利なモジュールが追加されているのでこれを使います。

GCがどんな感じで実行されているかを調べたい処理の前でGC::Profiler.enableをし、処理を実行した後にGC::Profiler.reportで結果を表示します。

GC::Profiler.enable
# ... GCについて調べたい処理 ...
GC::Profiler.report

GC::Profiler.reportは以下のようにGCの統計結果を表示してくれます。

GC 445 invokes.
Index    Invoke Time(sec)       Use Size(byte)     Total Size(byte)         Total Object                    GC Time(ms)
    1               0.092               964640              2257680                56442         0.00000000000000000000
...

まず、いらないキャッシュを消さない場合の結果を見てみましょう。

GC 341 invokes.
Index    Invoke Time(sec)       Use Size(byte)     Total Size(byte)         Total Object                    GC Time(ms)
    1               0.080               964600              2257680                56442         0.00000000000000000000
...
   27               0.348              1893800              4057280               101432         4.00100000000003230838
...
   50               0.764              3283520              7296560               182414         8.00100000000003674927
...
   73               1.588              6627960             13120720               328018        12.00099999999992839150
...
  106               3.720             11035000             23607480               590187        32.00199999999986744115
...
  124               5.532             19510200             42486920              1062173        56.00399999999972067144
...
  151               9.741             36667720             44008400              1100210        96.00600000000092393293
...
  187              16.541             50259800             62249800              1556245       128.00800000000123191057
...
  237              28.470             61845360             72409360              1810234       176.01100000000258205546
...
  328              53.351             63548120             80262160              2006554       148.00900000000183354132

オブジェクト数が増える毎にGCにかかる時間が増えています。

次に、いらないキャッシュを消した場合の結果を見てみましょう。

GC 445 invokes.
Index    Invoke Time(sec)       Use Size(byte)     Total Size(byte)         Total Object                    GC Time(ms)
    1               0.092               964640              2257680                56442         0.00000000000000000000
...
   27               0.376              1893800              4057280               101432         8.00099999999997990585
...
   50               0.824              3283520              7296560               182414        12.00100000000004030198
...
   73               1.644              6627400             13120720               328018        12.00099999999992839150
...
  106               3.928              6736400             13120720               328018        20.00100000000015754154
...
  256              14.061             10642920             23607480               590187        32.00199999999853162080
...
  302              18.561             18979640             42486920              1062173        52.00299999999913325155
...
  432              36.330             25030040             42486920              1062173        48.00300000000135014488

トータルのGC回数は増えていますが、オブジェクト数の最大値が増えていかないため、1回のGCにかかる時間が短くなっています。この差が全体の実行時間に効いてきているんですね。

まとめ

速くするためにやみくもにキャッシュしていると、生きているオブジェクト数が多くなるためにGC時間が長くなってしまい、逆に遅くなることがあります。キャッシュしたのに思ったより速くならなかった場合は必要なくなったキャッシュを持ち続けていないか確認し、いらないキャッシュを消すことを試してみましょう。ただし、ある程度のオブジェクト数をキャッシュしていない場合はあまり関係がないでしょう。

ツイートする

フォローする