CRubyとLink Time Optimizationについて

 最近、夜寝る前にRubyベンチマークを眺めたり、仕事の障害時のログを眺めるっていう悪趣味極まりない習慣がついてしまった。まぁ、草木も眠る丑三つ時にこの世の真理を求めて何かを読みふけるって言うのは、この業界にいる人間なら誰しもがやることなんじゃ無いかと思う。それと同じで現場百遍とも言うとおり、何度もprofileやログを眺めれば何か気付くこともあるんじゃないかと思って読んでいる……というわけではなくて、ふと見たくなる衝動に従っているだけだけど。

 さて、Rubyのprofileを取るときに便利なのがRubyKaigi 2015でこさきさんも紹介していたperf。あまりに便利なせいで、プライベートでLinuxを触る時間が何千倍にも増えたくらい。あの発表はもっぱらperf-topの紹介だったけど、perfの使い方とかを見ると他にも色々な機能があることがわかる。例えば、昨日話題になったひたすらblockを実行するコードを見たくなったら、

% perf record ./miniruby --disable-gem -e'100_000_000.times{}'
% perf report

とすると、

Samples: 8K of event 'cycles', Event count (approx.): 13538619277
 27.11%  miniruby  miniruby            [.] vm_exec_core
 24.59%  miniruby  miniruby            [.] invoke_block_from_c_0
 12.85%  miniruby  miniruby            [.] vm_push_frame.isra.69
 12.76%  miniruby  miniruby            [.] vm_exec
 10.25%  miniruby  miniruby            [.] rb_yield_1
  9.72%  miniruby  miniruby            [.] vm_callee_setup_block_arg
  2.39%  miniruby  miniruby            [.] int_dotimes
  0.22%  miniruby  [kernel.kallsyms]   [k] 0xffffffff8104f45a
  0.01%  miniruby  miniruby            [.] rb_ivar_get
  0.01%  miniruby  miniruby            [.] rb_frozen_class_p
  0.01%  miniruby  miniruby            [.] st_clear
  0.01%  miniruby  miniruby            [.] mix_id_table_insert
  0.01%  miniruby  miniruby            [.] mix_id_table_lookup
  0.01%  miniruby  miniruby            [.] rb_add_method_cfunc
  0.01%  miniruby  miniruby            [.] coderange_scan
  0.01%  miniruby  libc-2.19.so        [.] __libc_calloc
  0.01%  miniruby  miniruby            [.] hash_id_table_insert_key.part.19
  0.01%  miniruby  miniruby            [.] ruby_sip_hash24
  0.01%  miniruby  miniruby            [.] mix_id_table_foreach
  0.01%  miniruby  miniruby            [.] rb_enc_symname_type
  0.00%  miniruby  libc-2.19.so        [.] _int_malloc
  0.00%  miniruby  miniruby            [.] rb_define_method
  0.00%  miniruby  miniruby            [.] fstr_update_callback
  0.00%  miniruby  libc-2.19.so        [.] _IO_file_fopen@@GLIBC_2.2.5
  0.00%  miniruby  miniruby            [.] ruby_init_stack
  0.00%  miniruby  libpthread-2.19.so  [.] pthread_setname_np

Press '?' for help on key bindings

という画面になる。こっからさらにカーソル[→]で各関数についての詳細を見れる。

Annotate vm_exec_core
Zoom into miniruby(26888) thread
Zoom into miniruby DSO
Browse map details
Run scripts for samples of thread [miniruby]
Run scripts for samples of symbol [vm_exec_core]
Run scripts for all samples
Switch to another data file in PWD
Exit

けど、Rubyのprofileを見るって観点だとあまり使えない項目ばかりなので、"Annotate vm_exec_core"を選んで逆アセンブル結果を表示します。

vm_exec_core  /home/naruse/ruby/miniruby
       │          SET_GLOBAL((VALUE)entry, val);
       │        vzerou
       │        callq  rb_gvar_set
       │        jmpq   ffffffffffa33d50
       │        nop
       │      {
       │        VALUE val;
       │
       │
       │        DEBUG_ENTER_INSN("putnil");
       │        ADD_PC(1+0);
       │        lea    0x8(%r14),%rax
       │        mov    %r14,%rcx
  1.66 │        mov    %rax,(%r15)
  0.09 │        mov    %rax,%r14
       │      #line 267 "insns.def"
       │          val = Qnil;
       │
       │      #line 382 "vm.inc"
       │        CHECK_VM_STACK_OVERFLOW_FOR_INSN(REG_CFP, 1);
       │        PUSH(val);
  0.30 │        mov    0x8(%r15),%rax
  0.13 │        movq   $0x8,(%rax)
  8.82 │        add    $0x8,%rax
  0.04 │        mov    %rax,0x8(%r15)
       │        jmpq   ffffffffffa33d50
       │        nop
       │      {
       │        VALUE val;
       │
       │
       │        DEBUG_ENTER_INSN("putself");
       │        ADD_PC(1+0);
       │        lea    0x8(%r14),%rdx
       │        mov    %r14,%rcx
       │      putself
       │      ()
       │      ()
       │      (VALUE val)
       │      {
       │          val = GET_SELF();
       │        mov    0x20(%r15),%rsi
       │        mov    %rdx,(%r15)
       │        mov    %rdx,%r14
       │      #line 281 "insns.def"
       │          val = GET_SELF();
       │
Press 'h' for help on key bindings

この日記の読者は、Cは読めてもアセンブラは読めない人が多いと思うけど、大丈夫、わたしも読めない。いつもぐぐって出てきたページとかを見ながら眺めてます。

さて、この8.82(vm_exec_core中の8%がここ)って出てるところでちょっと時間を食ってるみたいなんだけど、加算命令であるaddでそんなに時間がかかるはずはなくて、たぶん前後のメモリ書き込み命令movを待ってるんじゃ無いかと思う。つまり、わたしごときでは何か出来ることはない。

気を取り直して[←]を押し、他の関数……rb_yield_1を見てみよう。

rb_yield_1  /home/naruse/ruby/miniruby
  5.86 │      sub    $0x18,%rsp
       │      mov    %rdi,0x8(%rsp)
 14.30 │      mov    ruby_current_thread,%rdi
  2.70 │      mov    0x30(%rdi),%rax
  1.69 │      mov    0x28(%rax),%rax
  2.48 │      mov    (%rax),%rsi
 10.70 │      test   $0x2,%sil
       │      jne    35
       │      nop
       │28:   and    $0xfffffffffffffffc,%rsi
       │      mov    (%rsi),%rsi
       │      test   $0x2,%sil
       │      je     28
  3.38 │35:   and    $0xfffffffffffffffc,%rsi
       │      je     59
  3.15 │      mov    (%rsi),%rdx
 28.83 │      pushq  $0x1
       │      xor    %r9d,%r9d
       │      mov    $0x1,%ecx
       │      pushq  $0x0
  4.62 │      lea    0x18(%rsp),%r8
       │      callq  invoke_block_from_c_0
 22.18 │      add    $0x28,%rsp
  0.11 │      retq
       │59:   lea    pathname_too_long.9784+0x500,%rdi
       │      xor    %edx,%edx
       │      mov    $0x8,%esi
       │      callq  rb_vm_localjump_error

短いですね。[s]を押すとCのソースが消えてアセンブラだけになり、30行無いことがわかります。

二桁の数値がいくつも踊っているけど、単に短いからなのでそこは気にするところではなくて、気にするのはこの長さならinlineしてよくね?ってとこですね。inlineされていない理由は簡単は、単にrb_yield_1()はvm_eval.cにあって、それを呼んでるint_dotimes() ——この関数が何者かわかりますね?—— はnumeric.cにいるからですね。

じゃあinline化したら速くなるのかな?というのは気になるところで、int_dotimesをvm_eval.cに持ってきてもいいんだけど(よくないけど)、最近のコンパイラにはリンク時にオブジェクトファイルをまたいでinline化とかをしてくれる超技術Link Time Optimizationってのがついているので使って見ましょう。optflags='-O3 -fno-fast-math -march=native -flto'などと追加してビルドし、profileを取ってみます。

BEFORE:
 Performance counter stats for './miniruby --disable-gem -e100_000_000.times{}':

       5153.515293 task-clock (msec)         #    0.997 CPUs utilized
               123 context-switches          #    0.024 K/sec
                 1 cpu-migrations            #    0.000 K/sec
               873 page-faults               #    0.169 K/sec
       14894914453 cycles                    #    2.890 GHz
        5256063515 stalled-cycles-frontend   #   35.29% frontend cycles idle
   <not supported> stalled-cycles-backend
       37123557344 instructions              #    2.49  insns per cycle
                                             #    0.14  stalled cycles per insn
        5304912019 branches                  # 1029.377 M/sec
            202652 branch-misses             #    0.00% of all branches

       5.170935973 seconds time elapsed

AFTER:
 Performance counter stats for './miniruby --disable-gem -e100_000_000.times{}':

       4456.424594 task-clock (msec)         #    0.997 CPUs utilized
               269 context-switches          #    0.060 K/sec
                 2 cpu-migrations            #    0.000 K/sec
               823 page-faults               #    0.185 K/sec
       13179265879 cycles                    #    2.957 GHz
        3793118960 stalled-cycles-frontend   #   28.78% frontend cycles idle
   <not supported> stalled-cycles-backend
       36422695065 instructions              #    2.76  insns per cycle
                                             #    0.10  stalled cycles per insn
        5004776248 branches                  # 1123.047 M/sec
            147323 branch-misses             #    0.00% of all branches

       4.471030258 seconds time elapsed

2割ほど速くなったようです。 ついでにint_dotimesを見てみると、さっきはrb_yield_1()の中にいた、rb_yieldやinvoke_block_from_c_0()を呼ぶコードがinline化されていることがわかりますね。

int_dotimes  /home/naruse/ruby/miniruby
       │       mov    %rbp,%rbx                                                                    ▒
       │       sar    %rbx                                                                         ▒
       │       test   %rbx,%rbx                                                                    ▒
       │       jle    a9                                                                           ▒
       │       lea    0x8(%rsp),%r12                                                               ▒
       │       xor    %r13d,%r13d                                                                  ▒
       │       nop                                                                                 ▒
  5.38 │ 40:   mov    ruby_current_thread,%rdi                                                     ▒
       │       lea    0x1(%r13,%r13,1),%rax                                                        ▒
       │       mov    %rax,0x8(%rsp)                                                               ▒
 16.46 │       mov    0x30(%rdi),%rax                                                              ▒
       │       mov    0x28(%rax),%rax                                                              ▒
  0.67 │       mov    (%rax),%rsi                                                                  ▒
 14.33 │       test   $0x2,%sil                                                                    ▒
  7.39 │       jne    7d                                                                           ▒
       │       data32 data32 data32 data32 nopw %cs:0x0(%rax,%rax,1)                               ▒
       │ 70:   and    $0xfffffffffffffffc,%rsi                                                     ▒
       │       mov    (%rsi),%rsi                                                                  ▒
       │       test   $0x2,%sil                                                                    ◆
       │       je     70                                                                           ▒
  6.61 │ 7d:   and    $0xfffffffffffffffc,%rsi                                                     ▒
       │       je     13a                                                                          ▒
  0.11 │       mov    (%rsi),%rdx                                                                  ▒
 23.07 │       pushq  $0x1                                                                         ▒
       │       xor    %r9d,%r9d                                                                    ▒
       │       mov    %r12,%r8                                                                     ▒
       │       pushq  $0x0                                                                         ▒
  6.49 │       mov    $0x1,%ecx                                                                    ▒
       │       add    $0x1,%r13                                                                    ▒
       │       callq  invoke_block_from_c_0.lto_priv.567                                           ▒
 18.81 │       pop    %rax                                                                         ▒
  0.11 │       pop    %rdx                                                                         ▒
  0.56 │       cmp    %r13,%rbx                                                                    ▒
       │       jne    40                                                                           ▒
       │ a9:   add    $0x18,%rsp                                                                   ▒
       │       mov    %rbp,%rax                                                                    ▒
       │       pop    %rbx                                                                         ▒
       │       pop    %rbp                                                                         ▒
       │       pop    %r12                                                                         ▒
       │       pop    %r13                                                                         ▒
       │       retq                                                                                ▒
       │       nop                                                                                 ▒
       │ c0:   mov    %rbx,%rdi                                                                    ▒
       │       callq  rb_yield                                                                     ▒
       │       mov    %rbx,%rdi                                                                    ▒
       │       mov    $0x3,%ecx                                                                    ▒
       │       xor    %eax,%eax                                                                    ▒
Press 'h' for help on key bindings

ちなみに、スピード狂の方々はご存じでしょうが、Rubyでループを最速に回せるのはwhileで、その場合の結果は以下のような感じでした。

 Performance counter stats for './miniruby --disable-gem -ei=0;while i<100_000_000;i+=1;end':

       2071.648179 task-clock (msec)         #    0.998 CPUs utilized
                35 context-switches          #    0.017 K/sec
                 2 cpu-migrations            #    0.001 K/sec
               878 page-faults               #    0.424 K/sec
        6041423503 cycles                    #    2.916 GHz
        2493938546 stalled-cycles-frontend   #   41.28% frontend cycles idle
   <not supported> stalled-cycles-backend
       14520079387 instructions              #    2.40  insns per cycle
                                             #    0.17  stalled cycles per insn
        1504280501 branches                  #  726.127 M/sec
            116788 branch-misses             #    0.01% of all branches

       2.076396582 seconds time elapsed

Samples: 3K of event 'cycles', Event count (approx.): 6014184501
 99.69%  miniruby  miniruby           [.] vm_exec_core
  0.25%  miniruby  [kernel.kallsyms]  [k] 0xffffffff8104f45a
  0.02%  miniruby  miniruby           [.] rb_class_foreach_subclass
  0.01%  miniruby  miniruby           [.] st_lookup
  0.01%  miniruby  miniruby           [.] ruby_sip_hash24
  0.01%  miniruby  miniruby           [.] rb_wb_protected_newobj_of
  0.01%  miniruby  miniruby           [.] rb_freeze_singleton_class
  0.01%  miniruby  miniruby           [.] fc_i
  0.00%  miniruby  miniruby           [.] thread_timer

バイトコードコンパイルする際にエスケープ解析とかすればJITを導入しなくてもまだ倍速くする余地があるってことですかね……。これをやるのは読者の宿題に残しておくのでぜひ頑張って欲しい。