SystemTap を使って Ruby プロセスの Copy-on-Write page faults を追う

SystemTap を使って Copy-on-Write page faults を追ってみた。


まえおき

resque という redis を使った ruby の job queue ライブラリがある。 公式的には worker の並列数を上げたい場合はresque.god のようにして、複数の resque worker プロセスを個別に立ち上げましょう、と言っている。

これだと全てのプロセス毎に rails アプリケーションをロードすることになってメモリを大量に使うので、あらかじめ Rails アプリケーションをロードしておき、resque worker は fork して起動するようにすることで CoW を有効に使ってメモリ節約を狙いたい。という目的で作ってみた resque_starter というものがある。

しかし、shared_memory_size.pl を利用して、メモリの共有率を調べて見たところ、30%程度しか効いておらず、原因を追跡しようと思った。

resque_starter (12487) + resque worker * 2 のメモリ共有率

  PID     VSZ     RSS PRIVATE  SHARED[KB]
12487  252144   94940   62584   32356 ( 34%)
12628  264552  107660   75288   32372 ( 30%)
12585  264552  107652   75464   32188 ( 29%)

何が原因で CoW page faults が発生したのかを追うには、SystemTap を使うとできるという情報を Aaron が StackOverflow で言っていたのでやってみた。

Rubyのバージョンは2.3.1


SystemTap を使って CoW page faults を追う

SystemTap に入門するには SystemTap Wikiにある SystemTap Beginner's Guide を読むのが一番良かった。 使える tapset (関数や probe 定義)は、/usr/share/systemtap/tapset/ においてあるので覗いてみるのが手っ取り早い。

結論としては、次のようにすると CoW page faults が発生したときのスタックトレースを取得することができた。

stap -d /path/to/ruby -e 'probe vm.write_shared_copy {
  if (execname() == "bundle") {
    printf("%s(%d) write_to_shared_page(%p)\n", execname(), pid(), address)
    print_ubacktrace()
  }
}'

probe vm.write_shared_copy で共有ページに書き込みをしてページのコピーが発生したイベントを追うことができる。ちなみに、他にも vm.pagefault で pagefault を追うこともできたりするようで興味深い。

print_ubacktrace() でユーザ空間のバックトレースをプリントできる。

bundle exec ruby で実行すると execname() が bundle になるようだったので、if (execname() == "bundle") として ruby プロセスのみに絞っている(他に起動している ruby プロセスは全部落とした)。ちなみに、if 文で絞らなくとも User-Space Stack Backtraces を使って process("bundle") のように最初から絞り込むことができるのか?とも思ったが、Kernel 3.5 以上でしか使えないようで弊社環境とは縁がなかった。

-d /path/to/ruby がなくとも動きはするのだが、詳細なスタットトレースが表示されない。


SystemTap の結果

次のようなイベントが延々と繰り返されて、共有ページの割合がどんどん減っていくことがわかった。

bundle(32533) write_to_shared_page(0x7f6893636110)
 0x7f6890691138 : gc_sweep_step+0x7a8/0xc70 [/path/to/ruby]
 0x7f6890691ab8 : heap_prepare+0x58/0x3d0 [/path/to/ruby]
 0x7f689069280e : newobj_slowpath_wb_protected+0x10e/0x160 [/path/to/ruby]
 0x7f6890736d1b : str_new0+0x4b/0x1b0 [/path/to/ruby]
 0x7f6890739de8 : rb_usascii_str_new_cstr+0x28/0x70 [/path/to/ruby]
 0x7f68906c91ce : fix_to_s+0x7e/0x160 [/path/to/ruby]
 0x7f68907a3954 : vm_call_cfunc+0x114/0x2e0 [/path/to/ruby]
 0x7f68907a8d2b : vm_exec_core+0x140b/0x6d80 [/path/to/ruby]
 0x7f68907ae70f : vm_exec+0x6f/0x750 [/path/to/ruby]
 0x7f68907af26c : invoke_block_from_c_0+0x29c/0x4c0 [/path/to/ruby]
 0x7f68907b162f : vm_call0_body+0x1ff/0x6a0 [/path/to/ruby]
 0x7f68907b200c : rb_call0+0xdc/0x210 [/path/to/ruby]
 0x7f68907b2231 : rb_funcall+0xd1/0xf0 [/path/to/ruby]
 0x7f68907375b3 : rb_obj_as_string+0x33/0xd0 [/path/to/ruby]
 0x7f68907a80a7 : vm_exec_core+0x787/0x6d80 [/path/to/ruby]
 0x7f68907ae70f : vm_exec+0x6f/0x750 [/path/to/ruby]
 0x7f68907af3a8 : invoke_block_from_c_0+0x3d8/0x4c0 [/path/to/ruby]
 0x7f68907b122c : rb_yield+0x6c/0xe0 [/path/to/ruby]
 0x7f68907d1f15 : rb_ary_each+0x45/0x90 [/path/to/ruby]
 0x7f68907a3954 : vm_call_cfunc+0x114/0x2e0 [/path/to/ruby]

対応する Ruby レベルのソースコードの場所がわかると良いのだが、追い方がわからなかったので(情報求む)、ピンと来た場所をコメントアウトするなどして調べて見たところ、Resque::Worker#work の loop 処理のところであることがわかった。

lib/resque/worker.rb#L224-L233

      loop do
        break if shutdown?

        unless work_one_job(&block)
          break if interval.zero?
          log_with_severity :debug, "Sleeping for #{interval} seconds"
          procline paused? ? "Paused" : "Waiting for #{queues.join(',')}"
          sleep interval
        end
      end

ここで作った文字列を開放するためにGCが走って、などを繰り返していくと、どんどん共有ページの割合が減っていき、最終的に30%まで落ちてしまうようだ。コメントアウトすると CoW page faults が減った。ただ、他にも work_one_job の中で色々処理をやっているので、frozen-string-literal: trueにすれば解決するというような簡単な話ではなかった。


おわりに

解決できていないのだが、SystemTap を使って Ruby プロセスの Copy-on-Write page faults を追うことができた。

vm と gc にまで来てしまうとちょっと手が出せなくなってしまうなぁ。

追記

@nalsh さんに ko1/nakayoshi_fork 入れてもう1度取ってみよう、と指導を受けたので追試。 上のログのgc_sweep_stepのものはfork前に作ったオブジェクトをsweepしていて共有が外れてしまっている事例だろうとのこと。nakayoshi_forkはそれを防ぐために前もって young objects が昇格するように何回かGCを実行してからforkするやつ。

なお、nakayoshi_fork でも、共有ページが30%に落ちるまでの時間が長くはなるが、最終的に30%まで落ち込んでしまうというのは変わらなかった。

SystemTapログ全体(でかい)
https://gist.github.com/sonots/faf93ccc18c9856ad650381191aac037

一部

bundle(2444) write_to_shared_page(0x7f6b04018fa8)
 0x7f6b016caf75 : rb_wb_protected_newobj_of+0x25/0x60 [/path/to/ruby]
 0x7f6b0176ec9b : str_new0+0x4b/0x1b0 [/path/to/ruby]
 0x7f6b016d8aec : rb_readwrite_syserr_fail+0x1c/0x100 [/path/to/ruby]
 0x7f6b016e3598 : io_read_nonblock+0x3d8/0x3f0 [/path/to/ruby]
 0x7f6b017db8d4 : vm_call_cfunc+0x114/0x2e0 [/path/to/ruby]
 0x7f6b017e0cab : vm_exec_core+0x140b/0x6d80 [/path/to/ruby]
 0x7f6b017e668f : vm_exec+0x6f/0x750 [/path/to/ruby]
 0x7f6b017e7328 : invoke_block_from_c_0+0x3d8/0x4c0 [/path/to/ruby]
 0x7f6b017e91ac : rb_yield+0x6c/0xe0 [/path/to/ruby]
 0x7f6b01809e95 : rb_ary_each+0x45/0x90 [/path/to/ruby]
 0x7f6b017db8d4 : vm_call_cfunc+0x114/0x2e0 [/path/to/ruby]
 0x7f6b017e0bdc : vm_exec_core+0x133c/0x6d80 [/path/to/ruby]
 0x7f6b017e668f : vm_exec+0x6f/0x750 [/path/to/ruby]
 0x7f6b017e7328 : invoke_block_from_c_0+0x3d8/0x4c0 [/path/to/ruby]
 0x7f6b017e8ed3 : loop_i+0x53/0x70 [/path/to/ruby]
 0x7f6b016a7665 : rb_rescue2+0xd5/0x2d0 [/path/to/ruby]
 0x7f6b017db8d4 : vm_call_cfunc+0x114/0x2e0 [/path/to/ruby]
 0x7f6b017e83cb : vm_call_method+0xab/0x140 [/path/to/ruby]
 0x7f6b017e0bdc : vm_exec_core+0x133c/0x6d80 [/path/to/ruby]
 0x7f6b017e668f : vm_exec+0x6f/0x750 [/path/to/ruby]

期待通りgc_sweep_stepはいなくなりましたな。rb_wb_protected_newobj_of は共有しているページの隙間に新規オブジェクトつっこんじゃった事例。vm_exec_coreはフレームやPCの変化でこっちは不可避

とのこと。rb_wb_protected_newobj_of を防ぐような方策が必要みたい。

/proc/[pid]/stat からプロセスの起動時間を取得する

プロセスの起動時間は /proc/[pid]/statの22番目の要素である starttime から取得することができる

$ awk '{print $22}' /proc/27947/stat
4787662015

この値は、OSがブートしてから、タイマーが割り込んだ回数になっている。

秒数を得るには、1秒あたりのクロック数 (getconf CLK_TCKの値)で割る。

$ getconf CLK_TCK
100

OSがブートした時刻は /proc/uptime から取得できる

% awk '{print $1}' /proc/uptime
49951043.92

この値はOSがブートしてからの経過時間(seconds)になっているので、現在時刻から引けば、ブート時刻が得られる。

ブート時刻から、プロセスが起動するまでの秒数を足せば、プロセスが起動した時刻がわかる。

ref. http://d.hatena.ne.jp/hiroppon/20130509/1368061417
ref. https://gist.github.com/hirose31/1668178

ruby 実装

書いた > https://github.com/sonots/get_process_start_time

ruby >= 2.2 なら1秒あたりのクロック数を

require 'etc'
Etc.sysconf(Etc::SC_CLK_TCK)

のように取れるのだが、2.2 未満のバージョンだと取れないようなので、C拡張を書いて対応した。

Released mysql_getlock gem

Released mysql_getlock gem to provide distributed locking using mysql get_lock().
Unlike distributed locking using redis, this ensures releasing orphaned lock.


How It Works

This gem uses MySQL get_lock().

Simple ruby codes which describes how it works are as follows:

mysql.query(%Q[select get_lock('db_name.key', -1)])
puts 'get lock'
begin
  # do a job
ensure
  mysql.query(%Q[select release_lock('db_name.key')])
end

MySQL get_lock() has a characteristic that the lock is implicitly released when your session terminates (either normally or abnormally). 


NOTICE

Note that

  1. Before 5.7.5, only a single simultaneous lock can be acquired in a session, and GET_LOCK() releases any existing lock. This gem raises MysqlGetlock::Error on such situation.
  2. The key name is global in a mysql instance. It is advised to use database-specific or application-specific lock names such as db_name.str or app_name.environment.str


Installation

Add this line to your application's Gemfile:

gem 'mysql_getlock'

And then execute:

$ bundle

Or install it yourself as:

$ gem install mysql_getlock


Usage

Similarly with ruby standard library mutex, following methods are available:

  • lock
    • Attempts to grab the lock and waits if it isn’t available.
  • locked?
    • Returns true if this lock is currently held by some.
  • synchronize {}
    • Obtains a lock, runs the block, and releases the lock when the block completes.
  • unlock
    • Releases the lock.

Options of MysqlGetlock.new are:

  • mysql2
    • Provide a mysql2 instance
  • key
    • Key name for a distributed lock
  • timeout
    • The timeout of trying to get the lock. A negative value means infinite timeout (default: -1)
  • logger
    • Provide a logger for MysqlGetlock (for debug)


Example

require 'mysql2'
require 'mysql_getlock'

mysql2 = Mysql2::Client.new # Mysql2::Client.new(options)
mutex = MysqlGetlock.new(mysql2: mysql2, key: 'db_name.lock_key')

mutex.lock
begin
  puts 'get lock'
ensure
  mutex.unlock
end

mutex.synchronize do
  puts 'get lock'
end
A Ruby and Fluentd committer working at DeNA. 記事本文および記事中のコード片は引用および特記あるものを除いてすべて修正BSDライセンスとします。 #ruby #fluentd #growthforecast #haikanko #yohoushi #specinfra #serverspec #focuslight
はてぶ人気エントリー

Google