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 入れてもう１度取ってみよう、と指導を受けたので追試。 上のログの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 を防ぐような方策が必要みたい。
