【負荷対策】rubyの思わぬ落とし穴、putsについて

この記事はアピリッツの技術ブログ「DoRuby」から移行した記事です。情報が古い可能性がありますのでご注意ください。

こんにちは。アピリッツの本多です。

久しぶりにruby関連の記事を書きたいと思います。

putsという、rubyの中ではメジャーな部類の関数がありますが、今日はこれに関する話題です。

ruby on rails案件にて、ループ処理系のバッチを実行する際に、進捗状況を確認するためにこんな書き方をしているケースがあると思います。

items.each_with_index do |item, i|
  （何かの処理）
  puts "#{i + 1} / #{items.size}"
end

この場合、展開するデータの件数が多くない場合は良いですが、例えば数十万件のデータを処理する場合などは

putsの処理時間が無視できないレベルになってきます。

例えば、弊社で公開しているエレコマというパッケージでは、住所マスタの取込バッチが実装されています。

ECサイト構築パッケージ「エレコマ」

elecoma/README at master ・ elecoma/elecoma ・ GitHub

================================================================================
* エレコマの住所マスタ更新
================================================================================
エレコマの住所マスタは郵便事業株式会社の郵便番号マスタを利用しています。
登録はコンソールから以下のように行ないます。

$ ruby script/runner -e production Zip.import

郵便番号マスタは以下のサイトにて配布されているものを自動的に取り込みます。
http://www.post.japanpost.jp/zipcode/download.html

住所マスタ更新機能はLhaLibに依存しています。
LhaLibの詳細については以下のサイトをご確認ください。
http://www.artonx.org/collabo/backyard/?LhaLibEn

このバッチですが、上記例と同様ループ処理中にputsで進捗状況を出力しているのですが、

いかんせんデータ数が2013年1月31日時点で123,385＋22,087＝145,472件と非常に多いです。

そしてデータ量が多いということは、イコールループ処理中のputsの影響も大きいという事ですね。

実際に動かして検証

私の環境（スペックは公開出来かねます。すみません）で実行してみます。

３回実行してみて、時間は

379.116285

389.899668

384.368132

⇒平均384.46秒（6分24.46秒）

でした。

結構長いですね。

ではputsをコメントアウトしてみましょう。

エレコマの郵便番号マスタのputsは２箇所あるので、両方をコメントアウトします。

コメントアウトしたら、再度同じバッチを実行します。

先ほどと同様に３回実行し、時間は

320.188456

315.7741

320.52054

⇒平均318.83秒（5分18.83秒）

でした。

１分以上の短縮です。かなり効果が出ましたね。

しかし、進捗状況が分からないと正常に動いているか不安ですね。

では間を取って、「1000処理毎にputsする」ようにしてみましょう。

実行時間は

298.578724

314.859872

323.760253

⇒平均312.40秒（5分12.40秒）

でした。

逆に若干puts無しより速い結果が出ましたが、まぁ…誤差の範囲という事で。

まとめ

ループ処理中の画面出力はほどほどに控えましょう。

実はこれらはrubyに限った話では無いですが、画面出力系の処理は意外に「重い」です。

そのため、今回のようなループ処理等、必ずしもputsが無いと困るわけではない場合に、思い切って処理を削る事で

パフォーマンスが改善する場合があります。

ちなみに後日談ですが、上記内容を社内のエレコマチームに報告し、2013/2/22現在は負荷改善対応がなされています。