おいちゃんと呼ばれています

ウェブ技術や日々考えたことなどを綴っていきます

Ruby 製バッチ処理を省メモリ化した

Ruby

少し前に Ruby 製のバッチ処理を省メモリ化したときの話をメモしておきます。

どのようなバッチ処理だったか

動画共有サイトにアップされた動画がオトナの事情によって削除されることがしばしばあるということは周知のことだと思う。そこで、一定時間おきに配信元サイトをチェックして、もし動画が配信元から削除されていたら、当該動画をこちらのサイトでも動画一覧に表示させないようにする、検索に引っ掛からないようにする、ということをやっていた。

便宜上、そのバッチ処理のことを「（動画の）存在確認くん」と呼ぶ。

oom-killer に殺されていた

彼は非常にデキる子だったが、なんか最近、動画の落とし漏れがあるなーと感じた。原因を調べたら、メモリを食い過ぎて oom-killer に殺されていた。

cat /var/log/messages
Apr  6 12:46:45 xxx001 kernel: Out of memory: Kill process 24085 (ruby) score 730 or sacrifice child

まあたしかに存在確認くんがメモリ大食いだとは認識していたが、チェック対象の動画数増加に伴いメモリ使用量もどんどん増えていって、とうとう限界に達したということか。

動画の存在確認くんのコード

仕方ないので省メモリ化することにした。簡単にコードを示しておく（ただし、コードはイメージなのでそのままでは動かない）

# 存在確認くん（バッチ処理。コードはイメージです）
Video.find_each do |video|
  video.delete! unless video.existing?
end

# コードはイメージです
class Video < ActiveRecord::Base
  def deleted?
    match_removed? || match_deleted?
  end

  def doc
    # 動画配信元ページの HTML をキャッシュ
    @doc ||= Nokogiri::HTML(open(source_url))
  end

  def existing?
    !deleted?
  end

  private

  def match_deleted?
    doc.at_css('.message').try(:text).try(:match, 'This video has been deleted')
  end

  def match_removed?
    doc.title.match 'Removed'
  end
end

ポイントは下記あたり。

  • 動画の配信元ページのタイトルまたは特定の要素が、指定の文字列とマッチすれば、動画は削除されたと判断する
  • 1回の存在確認で動画配信元ページへ数回アクセスしたくないので、取得した動画配信元ページの HTML をキャッシュしておく

どの行がどのくらいメモリを消費しているか？

どこがメモリを消費しているのだろう？動画配信元ページの HTML を保持する箇所がメモリを消費しているのかなと思ったんだけど、経験上、そういった当てずっぽうな予想に基づいて対応すると痛い目に遭うことが多いのできちんと計測してみた。

（A の箇所がメモリ食っているとか、遅いとかで対応して、後で、あー、A だけではなく B の箇所もだったわー、とかよくある）

どの行がどのくらいメモリを消費しているか ObjectSpace を使って出力するようにした。このあたり、下記が詳しい。

# 存在確認くん（バッチ処理。コードはイメージです）
require 'objspace'

ObjectSpace.trace_object_allocations_start

Video.find_each do |video|
  video.delete! unless video.existing?
end

ObjectSpace.trace_object_allocations_stop

ObjectSpace.each_object do |object|
  file    = ObjectSpace.allocation_sourcefile(object)
  line    = ObjectSpace.allocation_sourceline(object)
  memsize = ObjectSpace.memsize_of(object)

  next if memsize < 10_000
  next if file.nil?

  puts "#{memsize} #{file}:#{line}:#{object.class}"
end

ObjectSpace.trace_object_allocations_clear

結果

51199 /opt/rubies/2.1.5/lib/ruby/2.1.0/net/http/response.rb:334:String とか 16385 /opt/rubies/2.1.5/lib/ruby/2.1.0/net/protocol.rb:153:String とかが表示されたのでだいたい予想は当たっていそうだけど、他にも下記のようなものが表示された。

51199 /opt/rubies/2.1.5/lib/ruby/2.1.0/delegate.rb:343:String
10024 /opt/rubies/2.1.5/lib/ruby/gems/2.1.0/gems/activesupport-4.1.8/lib/active_support/dependencies.rb:443:RubyVM::InstructionSequence
12496 /opt/rubies/2.1.5/lib/ruby/gems/2.1.0/gems/activerecord-4.1.8/lib/active_record/associations/association.rb:97:RubyVM::InstructionSequence
14064 /Users/inouetakuya/Projects/my_application/app/models/video.rb:1:RubyVM::InstructionSequence
14424 /opt/rubies/2.1.5/lib/ruby/gems/2.1.0/gems/activerecord-4.1.8/lib/active_record/base.rb:321:RubyVM::InstructionSequence

バッチ全体のメモリ使用量の推移（Before）

バッチ全体のメモリ使用量の推移を調べた。結果的にここの数字が下がるようにしなければならないので。

  • ObjectSpace.memsize_of_all を使った
  • メモリの断片化の影響なども含めて OS からみたメモリ使用量もみたかったので ps の rss の値をみるようにした
# 存在確認くん（バッチ処理。コードはイメージです）
require 'objspace'

GC.start
logger.info "[BEFORE] memsize_of_all: #{ObjectSpace.memsize_of_all / 1000} KB, rss: #{`ps -o rss= #{Process.pid}`.chomp} KB"
i = 0

Video.find_each do |video|
  video.delete! unless video.existing?
  logger.info "[#{format('% 6d', i)}] memsize_of_all: #{ObjectSpace.memsize_of_all / 1000} KB, rss: #{`ps -o rss= #{Process.pid}`.chomp} KB" if (i % 50).zero?
  i += 1
end

logger.info "[AFTER] memsize_of_all: #{ObjectSpace.memsize_of_all / 1000} KB, rss: #{`ps -o rss= #{Process.pid}`.chomp} KB"

結果

memsize_of_all の値はときおり減少しているが、ps の rss の値のほうは怒濤の勢いで増え続けている！！！

I, [2015-04-08T19:01:54.578874 #54321]  INFO -- : [BEFORE] memsize_of_all: 62464 KB, rss: 114772 KB
I, [2015-04-08T19:01:56.485631 #54321]  INFO -- : [     0] memsize_of_all: 72261 KB, rss: 123000 KB
I, [2015-04-08T19:03:27.527892 #54321]  INFO -- : [    50] memsize_of_all: 84207 KB, rss: 152252 KB
I, [2015-04-08T19:04:54.920088 #54321]  INFO -- : [   100] memsize_of_all: 70339 KB, rss: 231368 KB
I, [2015-04-08T19:06:56.643725 #54321]  INFO -- : [   150] memsize_of_all: 79597 KB, rss: 321488 KB
I, [2015-04-08T19:09:54.851015 #54321]  INFO -- : [   200] memsize_of_all: 83443 KB, rss: 415800 KB
I, [2015-04-08T19:12:08.230988 #54321]  INFO -- : [   250] memsize_of_all: 86268 KB, rss: 491844 KB
I, [2015-04-08T19:29:33.526412 #54321]  INFO -- : [   300] memsize_of_all: 87477 KB, rss: 553316 KB
I, [2015-04-08T19:32:18.692708 #54321]  INFO -- : [   350] memsize_of_all: 87328 KB, rss: 640488 KB
...

この結果から推測したこと:

コードのメモ化に関する注意

rss の値が増え続けているのは、Video についてのイテレータの中で、ガーベジコレクションされていないオブジェクトが増え続けている

と推測したので、その "ガーベジコレクションされていないオブジェクト" について明示的にクリアする必要があると考えた。で、このあたりについて下記の本が非常に参考になったので長めに引用する。

Effective Ruby

Effective Ruby

メモ化を使ったときに浮上する微妙な問題に注意を注ぐことにしよう。まず、メソッドの結果をどれくらいの間キャッシングすべきだろうか。current_user の例では、メモ化はウェブ要求ごとにリセットされる。しかし、ほかの使い方では、結果はかなり長い間残る。プログラムが終了するまで残る場合さえあるだろう。メソッドをどれくらいの間メモ化するか、キャッシング変数に nil をセットしてメモ化をリセットするメソッドを用意すべきかどうかを検討すべきだ。

コードのメモ化をリセット

キャッシング変数に nil をセットしてメモ化をリセットするメソッドを用意すべきかどうかを検討すべきだ。

というアドバイスに基づいてメモ化をリセットしてみた（コードは変更した箇所のみ抜粋）

Video.find_each do |video|
  video.delete! unless video.existing?
  video.clear_cache
end

class Video < ActiveRecord::Base
  def doc
    # 動画配信元ページの HTML をキャッシュ
    @doc ||= Nokogiri::HTML(open(source_url))
  end

  def clear_cache
    @doc = nil
  end
end

バッチ全体のメモリ使用量の推移（After）

コードのメモ化をリセットするようにして再度メモリ使用量の推移を調べてみた。ps の rss の値が増え続けていない！やった！！！

I, [2015-04-08T19:38:08.907721 #54519]  INFO -- : [BEFORE] memsize_of_all: 62462 KB, rss: 113076 KB
I, [2015-04-08T19:38:10.339837 #54519]  INFO -- : [     0] memsize_of_all: 72307 KB, rss: 121076 KB
I, [2015-04-08T19:39:29.367451 #54519]  INFO -- : [    50] memsize_of_all: 80730 KB, rss: 141600 KB
I, [2015-04-08T19:41:02.980132 #54519]  INFO -- : [   100] memsize_of_all: 77585 KB, rss: 170548 KB
I, [2015-04-08T19:43:09.312620 #54519]  INFO -- : [   150] memsize_of_all: 71928 KB, rss: 170996 KB
I, [2015-04-08T19:46:12.389644 #54519]  INFO -- : [   200] memsize_of_all: 77397 KB, rss: 172648 KB
I, [2015-04-08T19:48:44.221965 #54519]  INFO -- : [   250] memsize_of_all: 76182 KB, rss: 172820 KB
I, [2015-04-08T19:50:38.114557 #54519]  INFO -- : [   300] memsize_of_all: 70948 KB, rss: 172820 KB
I, [2015-04-08T19:53:23.965943 #54519]  INFO -- : [   350] memsize_of_all: 86286 KB, rss: 172820 KB
...

スパイクが消えて平和が訪れた munin の様子。

f:id:inouetakuya:20150726201803p:plain

というわけで省メモリ化に成功し、存在確認くんが無事に働いてくれるようになったのでした。いぇい！

参考

今回の対応を終えても、Ruby のメモリ管理についてまだまだよく分かっていないところが多くて、下記の本も読んでみたけど、なかなか理解が難しい...

Rubyのしくみ -Ruby Under a Microscope-

Rubyのしくみ -Ruby Under a Microscope-