Ruby 2.5 の SEGV と闘った話

Ubiregi Advent Calendar 2018 の 5 日目です。

同僚が「Ruby 2.5 が SEGV するんだけど」というので調べて見たときの話です。結論から言うと Ruby 2.6 では直っています。

クラッシュログ

同僚の変更内容を手元の macOS で動かすと確かに SEGV して以下の様なクラッシュログが出力されていました。

Crashed Thread:        0  Dispatch queue: com.apple.main-thread

Exception Type:        EXC_BAD_ACCESS (SIGABRT)
Exception Codes:       KERN_INVALID_ADDRESS at 0x0000000000000000
Exception Note:        EXC_CORPSE_NOTIFY

VM Regions Near 0:
--> 
    __TEXT                 000000010a37d000-000000010a610000 [ 2636K] r-x/rwx SM=COW  /Users/USER/*

Application Specific Information:
abort() called

Thread 0 Crashed:: Dispatch queue: com.apple.main-thread
0   libsystem_kernel.dylib          0x00007fff77f36b86 __pthread_kill + 10
1   libsystem_pthread.dylib         0x00007fff77fecc50 pthread_kill + 285
2   libsystem_c.dylib               0x00007fff77ea01c9 abort + 127
3   ruby                            0x000000010a3f3a99 die + 9
4   ruby                            0x000000010a3f3cd4 rb_bug_context + 564
5   ruby                            0x000000010a4eb5f1 sigsegv + 81
6   libsystem_platform.dylib        0x00007fff77fe1b3d _sigtramp + 29
7   ???                             000000000000000000 0 + 0
8   ruby                            0x000000010a3b729c ibf_dump_iseq + 876
9   ruby                            0x000000010a3d0192 ibf_dump_code + 402
10  ruby                            0x000000010a3b717b ibf_dump_iseq + 587
11  ruby                            0x000000010a3d0192 ibf_dump_code + 402
12  ruby                            0x000000010a3b717b ibf_dump_iseq + 587
13  ruby                            0x000000010a3d0192 ibf_dump_code + 402
14  ruby                            0x000000010a3b717b ibf_dump_iseq + 587
15  ruby                            0x000000010a3b6add iseq_ibf_dump + 397
16  ruby                            0x000000010a44163a iseqw_to_binary + 74
17  ruby                            0x000000010a56fb77 vm_call_cfunc + 295
18  ruby                            0x000000010a557cb3 vm_exec_core + 12419
19  ruby                            0x000000010a56a200 vm_exec + 144
20  ruby                            0x000000010a3fdd31 ruby_exec_internal + 177
21  ruby                            0x000000010a3fdc28 ruby_run_node + 56
22  ruby                            0x000000010a37de7f main + 79
23  libdyld.dylib                   0x00007fff77df808d start + 1

デバッグシンボルが取り除かれていてデバッグするのが大変すぎる状況でしたが、あいにく 100 % の確立で再現していたのでデバッグシンボルが出力されるように Ruby をビルドすれば道が見えそうでした。

デバッグシンボル + DTrace を有効にしてビルド

このとき初めて知ったのですが、rbenv が用意してくれる $HOME/.rbenv/versions/ ディレクトリ内に自分でビルドした Ruby をインストールするように configure を実行すると、rbenv が管理してくれるようです。すごく便利。あとデバッグするときに DTrace が使えると個人的には何かと便利です。

$ CFLAGS="-O0 -ggdb" ./configure --enable-dtrace --prefix=$HOME/.rbenv/versions/2.5.3-debug --with-openssl-dir=$(brew --prefix openssl)
$ make -j
$ make install

$ rbenv shell 2.5.3-debug

デバッグ

上記の Ruby で実行したところ SEGV はおさまり、例外が発生するようになりました。

Traceback (most recent call last):
    1: from xxxxx.rb:xx:in `<main>'
xxxxx.rb:xx:in `load_from_binary': object index out of range: 21474836482 (IndexError)

lldb でデバッグし始めてもよかったのですが、最小の再現コードが用意できる方がデバッグしやすいですし issue tracker書きやすいので、まずはどのメソッド呼び出しで例外が発生するのか調べて見ました。

DTrace でメソッドを探す

今回は例外が発生するようになったので、そのメッセージを読めば大分手がかりがあるのですが、DTraceで遊んでみます。

DTrace を利用すると Ruby のコードに手を加えずに、いろいろ調べることができます。以下のスクリプトを x.d という名前で保存して実行すると、どんなメソッドが呼び出されているか簡単に調べることができます。

ruby$target:::method-entry
{
  printf("%s#%s\n", copyinstr(arg0), copyinstr(arg1));
}

ruby$target:::cmethod-entry
{
  printf("%s#%s\n", copyinstr(arg0), copyinstr(arg1));
}

実行した結果は以下の様になります。

$ sudo dtrace -q -s x.d -p `pgrep ruby`
dtrace: system integrity protection is on, some features will not be available

(略)
RubyVM::InstructionSequence#compile_file
RubyVM::InstructionSequence#to_binary
RubyVM::InstructionSequence#load_from_binary
Class#new
Exception#initialize
Exception#exception
Exception#message
Exception#to_s

例外メッセージにあった load_from_binary は RubyVM::InstructionSequence#load_from_binary っぽいことが特定できました。ファイル名と行番号も取得できたり他にもメソッドの実行時間やGCの挙動を調べたりいろいろ出来そうです。

probes.d にRubyのDTraceプローブがリストアップされているので遊んで見てください。

再現コード

最終的に以下のコードでクラッシュすることがわかりました。

# ファイル名：crash.rb
class Worker < ApplicationWorker
  def import!
    lock(@menu) do
      if false
        @menu.account.update!(editable: true)
      end
    end
  end
end

# ファイル名：compile.rb
iseq = RubyVM::InstructionSequence.compile_file("crash.rb")
RubyVM::InstructionSequence.load_from_binary(iseq.to_binary)

$ ruby -v compile.rb
ruby 2.5.3p105 (2018-10-18 revision 65156) [x86_64-darwin18]
compile.rb:2: [BUG] Segmentation fault at 0x0000000000000000
ruby 2.5.3p105 (2018-10-18 revision 65156) [x86_64-darwin18]

-- Crash Report log information --------------------------------------------
   See Crash Report log file under the one of following:
     * ~/Library/Logs/DiagnosticReports
     * /Library/Logs/DiagnosticReports
   for more details.
Don't forget to include the above Crash Report log file in bug reports.

-- Control frame information -----------------------------------------------
c:0003 p:---- s:0012 e:000011 CFUNC  :to_binary
c:0002 p:0030 s:0008 E:0006b8 EVAL   compile.rb:2 [FINISH]
c:0001 p:0000 s:0003 E:001d60 (none) [FINISH]

-- Ruby level backtrace information ----------------------------------------
compile.rb:2:in `<main>'
compile.rb:2:in `to_binary'

-- Machine register context ------------------------------------------------
 rax: 0x00007ffee98ef7d0 rbx: 0x0000000000000000 rcx: 0x0000000000000000
 rdx: 0x00007ffee98ef7e0 rdi: 0x0000000000000000 rsi: 0x0000000000000000
 rbp: 0x00007ffee98ef860 rsp: 0x00007ffee98ef7c0  r8: 0x00007fd02be00000
  r9: 0x000000000000000c r10: 0x0000000000000018 r11: 0x0000002ebda4ff30
 r12: 0x0000000000000000 r13: 0x00007fd02be9f200 r14: 0x0000000000000000
 r15: 0x00007fd02be9f280 rip: 0x000000010636293e rfl: 0x0000000000010246
....

RubyVM::InstructionSequence.compile_file と RubyVM::InstructionSequence.load_from_binary はbootsnap gem で利用されていました。

ちなみに Ruby 2.6 では SEGV しなかったので、issue tracker へ報告はしませんでした。

$ ruby -v compile.rb
ruby 2.6.0dev (2018-12-03 trunk 66140) [x86_64-darwin18]

まとめ

あまり DTrace を活用されている事例を聞きませんが、Rubyのコードをいじらなくても雑にメソッド呼び出しを調べたりできて重宝します。

弊社では Ruby の SEGV にめげないメンバーも募集しております(\( ⁰⊖⁰)/)

追記

以下の変更により Ruby 2.6 では直っていたようです。

github.com

すでに backport 済みだったようなので Ruby 2.5.4 では直りそうです。