読者です 読者をやめる 読者になる 読者になる

デバッグ: gdb で ruby のバックトレースを自動で採取

とある Rails / Unicorn サーバで perf top を眺めていたら、やたらと bcrypt_ext.soBF_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 の呼び出し元を探るべく gdbunicorn にアタッチして 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.

gdbunicorn にアタッチして

  • 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 で追う際に見やすい。こっちでも問題ないだろうか