とある Rails / Unicorn サーバで perf top を眺めていたら、やたらと bcrypt_ext.so の BF_crypt が高いオーバーヘッドを示しているのを発見した。ひゃぁ
Samples: 168K of event 'cycles', Event count (approx.): 50386752987 Overhead Shared Object Symbol 36.61% bcrypt_ext.so [.] BF_crypt 🔥 7.83% ruby [.] vm_exec_core 3.66% ruby [.] st_lookup 3.55% ruby [.] mix_id_table_lookup 2.44% ruby [.] vm_search_method.isra.79 1.87% libc-2.17.so [.] _int_malloc
gdb で調査
BF_crypt の呼び出し元を探るべく gdb で unicorn にアタッチして rb_backtrace() でバックトレースを採取するのを試行錯誤していたが、ブレークする度にリクエストを止めていることに気がついたのでこりゃマズいと、採取方法を変えた。
続 gdb で調査
command を使って自動化した
$ sudo gdb -p <unicorn の pid> (gdb) b BF_crypt Breakpoint 1 at 0x7f8452663350: file crypt_blowfish.c, line 569. (gdb) command 1 Type commands for breakpoint(s) 1, one per line. End with a line saying just "end". >call rb_backtrace() >continue >end (gdb) c Continuing.
- BF_crypt で 停止する
- call rb_backtrace() でバックトレースを stderr に出力する
- gdb を 再開する
という command をセットした。 ブレークポイントで停止してバックトレースを出して自動で再開することで、停止時間を極力短くすることができる。
one more
更に自動化、手順をファイルに書き出して stdin から読み込ませて手作業を減らした
break BF_crypt command 1 call rb_backtrace() continue end continue
こんな感じで扱える
sudo gdb -p <unicorn worker の pid> < gdb-BF_crypt-of-unicorn
( これを実行すると unicorn worker プロセスが生きている限りバックトレースの採取が続いてしまう。「 n回 command を実行したら quit する」を実現するにはどうしたらよいのだろう? )
実行
gdb でアタッチして unicorn のログを tail していると、下記のようなバックトレースがバンバン採取できた
from /path/to/current/vendor/bundle/ruby/2.3.0/bin/unicorn:23:in `<main>'
from /path/to/current/vendor/bundle/ruby/2.3.0/bin/unicorn:23:in `load'
from /path/to/current/vendor/bundle/ruby/2.3.0/gems/unicorn-5.2.0/bin/unicorn:126:in `<top (required)>'
略 ...
from /path/to/releases/2016120******/app/controllers/concerns/foo.rb:32:in `block in bar'
from /path/to/releases/2016120******/vendor/bundle/ruby/2.3.0/gems/devise-4.2.0/lib/devise/models/database_authenticatable.rb:45:in `valid_password?'
from /path/to/releases/2016120******/vendor/bundle/ruby/2.3.0/gems/devise-4.2.0/lib/devise/encryptor.rb:18:in `compare'
from /path/to/current/vendor/bundle/ruby/2.3.0/gems/bcrypt-3.1.11/lib/bcrypt/engine.rb:51:in `hash_secret'
from /path/to/current/vendor/bundle/ruby/2.3.0/gems/bcrypt-3.1.11/lib/bcrypt/engine.rb:51:in `__bc_crypt'
( 大量のバックトレースがでてくるので、一部だけ )
採取できたバックトレースを比較してみて、とある concerrs 経由での呼び出しなのを特定できた。
アプリケーションをよく見知った人であれば Rails, BCrypt から devise の存在を連想してどこが怪しいかをポイントすることも可能だろう ( 実際にそういうレビューをもらえた 😊 )。デバッグツールによって推測を実証にできた。
rb_backtrace について
ruby のソース vm_backtrace.c を除くと下記のようなコードだった
void rb_backtrace(void) { vm_backtrace_print(stderr); }
vm_backtrace_print() は下記の通り
static void vm_backtrace_print(FILE *fp) { struct oldbt_arg arg; arg.func = oldbt_print; arg.data = (void *)fp; backtrace_each(GET_THREAD(), oldbt_init, oldbt_iter_iseq, oldbt_iter_cfunc, &arg); }
で、vm_backtrace.c を覗いていると rb_backtrace_print_as_bugreport() というのを見つけた
void rb_backtrace_print_as_bugreport(void) { struct oldbt_arg arg; int i = 0; arg.func = oldbt_bugreport; arg.data = (int *)&i; backtrace_each(GET_THREAD(), oldbt_init, oldbt_iter_iseq, oldbt_iter_cfunc, &arg); }
rb_backtrace_print_as_bugreport() を使ってみたらバックトレースのフォーマットが変わったのだった
-- Ruby level backtrace information ---------------------------------------- /path/to/current/vendor/bundle/ruby/2.3.0/bin/unicorn:23:in `<main>' /path/to/current/vendor/bundle/ruby/2.3.0/bin/unicorn:23:in `load' /path/to/current/vendor/bundle/ruby/2.3.0/gems/unicorn-5.2.0/bin/unicorn:126:in `<top (required)>' /path/to/releases/20161208******/vendor/bundle/ruby/2.3.0/gems/unicorn-5.2.0/lib/unicorn/http_server.rb:132:in `start' ... /path/to/20161208******/app/controllers/concerns/api/foo.rb:32:in `block in bar' /path/to/20161208******/vendor/bundle/ruby/2.3.0/gems/devise-4.2.0/lib/devise/models/database_authenticatable.rb:45:in `valid_password?' /path/toreleases/20161208******/vendor/bundle/ruby/2.3.0/gems/devise-4.2.0/lib/devise/encryptor.rb:18:in `compare' /path/to/current/vendor/bundle/ruby/2.3.0/gems/bcrypt-3.1.11/lib/bcrypt/engine.rb:51:in `hash_secret' /path/to/current/vendor/bundle/ruby/2.3.0/gems/bcrypt-3.1.11/lib/bcrypt/engine.rb:51:in `__bc_crypt'
右側の空白のオフセットが消えてログの最初にヘッダが一行入っていいるので、tail で追う際に見やすい。こっちでも問題ないだろうか
